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
