The VideoLAN Forums

Hi, All,

I'm running VLC 1.1.9 on Kubuntu 11.04 beta 2 (KDE 4.6.2) x86-64. I use an i5-based Dell laptop (6GB RAM).

VLC takes around 30 seconds to display its initial window. In other words, if I run 'vlc' from a shell or click on the 'VLC Media Player' icon, I don't see the player window for 30+ seconds.

I've had this problem from VLC 1.1.7 up on Maverick and Natty beta 1.

I strace'd an invocation and saw something interesting:

3321 24.951875 <... poll resumed> ) = 1 ([{fd=3, revents=POLLIN}]) <24.964024>

Yes, this line indicates that it was 25 SECONDS from the previous syscall to the current. No application wastes 25 seconds without making a syscall! So something's going on, but I don't know what.

I did run with '-vvv' and can see it hang during the output. Here's some of the surrounding messages where it hangs:

vlc -vvv output:
...
[0x269ae20] main playlist debug: Activated
[0x269ae20] main playlist debug: rebuilding array of current - root Playlist
[0x269ae20] main playlist debug: rebuild done - 0 items, index -1
[0x269ce90] main interface debug: using interface module "dbus"
[0x269ce90] main interface debug: TIMER module_need() : 1.199 ms - Total 1.199 ms / 1 intvls (Avg 1.199 ms)
[0x269ce90] main interface debug: thread (interface) created at priority 0 (interface/interface.c:160)
[0x269ce90] main interface debug: thread started
---> [0x7f0bf4000a50] main interface debug: looking for interface module: 1 candidate
[0x7f0bf4000a50] main interface debug: using interface module "notify"
[0x7f0bf4000a50] main interface debug: TIMER module_need() : 25012.068 ms - Total 25012.068 ms / 1 intvls (Avg 25012.068 ms)
[0x26d7f60] main interface debug: looking for interface module: 1 candidate
[0x26d7f60] main interface debug: using interface module "hotkeys"
...

It hangs after displaying the line marked with '--->'.

I also turned on dbus-monitor for fun. Here's some output from that:

dbus-monitor --profile output:
...
mc 1302833434 703413 1 :1.105 /org/freedesktop/DBus org.freedesktop.DBus Hello
sig 1302833434 714133 46 /org/freedesktop/DBus org.freedesktop.DBus NameOwnerChanged
mc 1302833434 714183 3 :1.105 /org/freedesktop/DBus org.freedesktop.DBus RequestName
sig 1302833434 715011 4 /Player org.freedesktop.MediaPlayer CapsChange
mc 1302833434 715072 1330 :1.16 /Player org.freedesktop.MediaPlayer GetCaps
mc 1302833434 726941 5 :1.105 /org/freedesktop/DBus org.freedesktop.DBus AddMatch
mc 1302833434 727041 6 :1.105 /org/freedesktop/DBus org.freedesktop.DBus AddMatch
mc 1302833434 727052 7 :1.105 /org/freedesktop/DBus org.freedesktop.DBus GetNameOwner
mc 1302833434 727155 8 :1.105 /org/freedesktop/Notifications org.freedesktop.Notifications GetServerInformation
---> mc 1302833459 715708 1331 :1.16 /Player org.freedesktop.MediaPlayer GetMetadata
mr 1302833459 727265 9 1330 :1.16
mr 1302833459 727291 10 1331 :1.16
mc 1302833459 727707 1332 :1.16 /Player org.freedesktop.MediaPlayer GetStatus
mc 1302833459 728041 11 :1.105 /org/freedesktop/DBus org.freedesktop.DBus RequestName
sig 1302833459 728354 12 /Player org.freedesktop.MediaPlayer CapsChange
mr 1302833459 728550 13 1332 :1.16
...

If I understand this output format, the line preceded by '--->' shows that there was a delay of 25s from the previous dbus event to the current dbus event. (I'm pretty sure the second field is seconds since the epoch.)

Here's a snippet from a (very long) strace output on vlc:

strace -frT -ttt -o vlcout vlc:
...
3321 0.000139 open("/usr/share/locale/locale.alias", O_RDONLY) = 4 <0.000029>
3321 0.000077 fstat(4, {st_mode=S_IFREG|0644, st_size=2570, ...}) = 0 <0.000014>
3321 0.000072 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8752fa8000 <0.000017>
3321 0.000056 read(4, "# Locale name alias data base.\n#"..., 4096) = 2570 <0.000022>
3321 0.000138 read(4, "", 4096) = 0 <0.000016>
3321 0.000055 close(4) = 0 <0.000016>
3321 0.000052 munmap(0x7f8752fa8000, 4096) = 0 <0.000023>
3321 0.000109 brk(0x9bf000) = 0x9bf000 <0.000016>
3321 0.000408 pipe2([4, 5], O_CLOEXEC) = 0 <0.000024>
3321 0.000093 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 <0.000016>
3321 0.000078 fcntl(3, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000015>
3321 0.000289 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\211\0\0\0\5\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\204\0\0\0type='signal',sender='org.fr"..., 137}], ms
g_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 281 <0.000034>
3321 0.000169 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\255\0\0\0\6\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\250\0\0\0type='signal',sender='org.fr"..., 173}], ms
g_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 317 <0.000021>
3321 0.000251 clock_getres(CLOCK_MONOTONIC, {0, 1}) = 0 <0.000017>
3321 0.000086 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\"\0\0\0\7\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\35\0\0\0org.freedesktop.Notification"..., 34}], msg_co
ntrollen=0, msg_flags=0}, MSG_NOSIGNAL) = 178 <0.000026>
3321 0.000262 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\10\0\0\0\225\0\0\0\1\1o\0\36\0\0\0/org/fre"..., 168}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL)
= 168 <0.000027>
3321 0.000129 poll([{fd=3, events=POLLIN}], 1, 25000) = 1 ([{fd=3, revents=POLLIN}]) <0.000022>
3321 0.000099 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\230\4\0\0n\0\0\0\1\1o\0\7\0\0\0/Player\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_
CLOEXEC) = 218 <0.000022>
3321 0.000131 recvmsg(3, 0x7fff4f2ff390, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000016>
3321 0.000066 poll([{fd=3, events=POLLIN}], 1, 25000 <unfinished ...>
3327 0.011912 <... clock_nanosleep resumed> {0, 50000000}) = 0 <0.050282>
3327 0.000100 futex(0x889654, FUTEX_WAIT_BITSET_PRIVATE, 1, {814, 85606000}, ffffffff) = -1 ETIMEDOUT (Connection timed out) <0.000037>
3327 0.000102 futex(0x889590, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000012>
3327 0.000064 futex(0x889654, FUTEX_WAIT_PRIVATE, 3, NULL <unfinished ...>
---> 3321 24.951875 <... poll resumed> ) = 1 ([{fd=3, revents=POLLIN}]) <24.964024>
3321 0.000104 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\0\1\0\0\0\0\231\4\0\0v\0\0\0\1\1o\0\7\0\0\0/Player\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 136 <0.000031>
3321 0.000157 recvmsg(3, 0x7fff4f2ff390, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000026>
3321 0.000098 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 <0.000021>
3321 0.000088 fcntl(3, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000019>
3321 0.000080 futex(0x889654, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x889650, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
3327 0.000043 <... futex resumed> ) = 0 <24.952432>
3321 0.000033 <... futex resumed> ) = 1 <0.000059>
3327 0.000026 futex(0x889590, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
3321 0.000025 futex(0x889590, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
3327 0.000016 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000028>
3321 0.000023 <... futex resumed> ) = 0 <0.000028>
3327 0.000021 futex(0x889590, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
3321 0.000026 futex(0x889654, FUTEX_WAIT_BITSET_PRIVATE, 5, {839, 72389000}, ffffffff <unfinished ...>
3327 0.000021 <... futex resumed> ) = 0 <0.000032>
3327 0.000034 poll([{fd=3, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=3, revents=POLLOUT}]) <0.000018>
3327 0.000074 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\2\1\1\4\0\0\0\t\0\0\0\37\0\0\0\6\1s\0\5\0\0\0:1.16\0\0\0"..., 48}, {"@\0\0\0", 4}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 52 <0.000143>
3327 0.000247 futex(0x889654, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x889650, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000023>
3321 0.000056 <... futex resumed> ) = 0 <0.000417>
...

Again, the '--->' marked line shows a 24.9s delay between the two syscalls.

Interestingly, I don't experience this problem on a vanilla installation of beta 2 running under Virtualbox. I downloaded the desktop .ISO, fired it up in Virtualbox, installed VLC... and it comes up in less than a second. ::sigh::

Thanks for your time in reading this, and if you have any suggestions... I'm all eyes (ears)! Help!

---Jason

As far as we know, this is caused by a bug in Qt that is triggered by KDE.

Has anyone found a fix for this bug? I cant get VLC to start up quickly either. Version 1.1.11

Hi,

i like to report the same issue here, a slow start.
I'm using Xubuntu11.10

Qt does not care about the bug and we are not even sure what the problem really is.

And VLC definitely cannot fix a bug in Qt. It does not help that VLC developers cannot reproduce it.

thanks for your answer.
I'll ask the Qt developpers about, maybe it can help them to locate the bug. You never know...

bye
tjingboem