Thanks for this information. Does this only happen after booting the computer, or also when you log out and log in again?

 
OK, to answer you, it happens every time I log in, not only the first.

But, my bad, after some test, it seems that's the «volume restore»
function is not  responsible for the slow session start. It's, in fact,
the «Enable docking» option. The problem appears when I check the box
for «Dock in System Tray», not «volume restore».

In my opinion, it may be related to klauncher. But it's not a klauncher
bug, since kmixer is the only one to have such behaviour.

Probably it is related to KMix being a "KUniqueApplication". But it doesn't seem to make sense, because this is independent from docking.

I'm experiencing the same issue with kmix 4.0.3 on x86_64. I had this problem with 4.0.2 as well.

Same thing here (kmix 4.0.3 on amd64 as well). Whenever kmix is not in a previous session KDE starts up without any delay. I can use the mouse but not the keyboard.

Created attachment 24667 [details]
kmix stack trace

stack trace from the initial load of kmix. Subsequent loads do not exhibit the
slow loading.

Sorry, I wasn't very clear in my first response. I'm seeing this same behavior in Gentoo as well. I managed to snag a bit of a stack trace. It looks to me like it's hanging when trying to communicate with dbus. I haven't looked at the code yet so I could be wrong.

Dan,

your trace is very helpful. I suspect the following. If KMix runs before the Global Keyboard Manager ist up, there might be an issue. I just have not yet an idea why it should happen.

  Christian

I just noticed, that all bug reports differ:

Damien "happens every time I log in"
Pete: "Whenever kmix is not in a previous session KDE starts up without any delay."
Damien's and Pete's report might be the same.

Dan's report says "Subsequent loads do not exhibit the slow loading.".
Dan, what does "Subsequent loads" exactly mean? Does this apply to "Quit Kmix, start Kmix", or (also) to "Logout-Login".

Christian,

Let me clarify. If I quit kmix and start it up there is no problem. However, whenever I login and kmix is restoring a previous session (kmix -session) there is a noticeable delay, 10s-20s, and the keyboard is blocked during this time. 

OK, thanks for the feedback.

Work note: As long as there is no further feedback from Dan Lange, lets focus on the issue as reported by Damien and Pete.

I have done some tests on my openSUSE 11.0 Beta 3 (KDE 4.0.4). After Plasma appears, ksmserver launches Amarok 1.4. The keyboard is not frozen at this point: I can click on Amarok's icon to get the playlist and then navigate in it by keyboard.

After some 10 seconds, the other tray applications start to appear. These include KDE 4 applications (e.g. Klipper) and KDE 3 apps (e.g. KNetworkManager).

For a test, I pressed Alt-F2 during this 10 seconds. I noticed that the keyboard then freezed until KRunner appeared, then the other input events were handled.

As for any other one, this quirky behavior does not occur when KMix is not autostarted.

Here is a reaction of the kde-core-devel mailing list:

Christian Esken wrote:
>writev(3,
> [{"l\1\0\1\21\0\0\0\6\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"...,
> 144}, {"\f\0\0\0org.kde.kmix\0", 17}], 2) = 161 poll([{fd=3,
> events=POLLIN, revents=POLLIN}], 1, 25000) = 1
>read(3, "l\2\1\1\n\0\0\0\7\0\0\0=\0\0\0\6\1s\0\5\0\0\0:1.19\0\0\0"...,
> 2048) = 90 read(3, 0x61bdb0, 2048)                 = -1 EAGAIN
> (Resource temporarily unavailable) writev(3,
> [{"l\1\0\1\0\0\0\0\7\0\0\0{\0\0\0\1\1o\0\20\0\0\0/MainApp"..., 144},
> {"", 0}], 2) = 144 poll([{fd=3, events=POLLIN}], 1, 25000) = ?
> ERESTART_RESTARTBLOCK (To be restarted)
>
>My guess was that it is related to KMix being a "KUniqueApplication" or
> KMix accesing the global keyboard shorcut service. It's hard to find,
> as it only happens during session start. Does anybody has a idea what
> is going on, or how to debug this?

Thiago Macieira wrote:
> Can you run this again with -s 2048? If you can include timestamps too, it 
> would be great.

Could somebody do this please? I cannot reproduce it (or my computer is simply too fast to recognize any issues). 

How to do it.

1) Change the Exec value in the global KMix start file in the KDE installation
KDE4_BASE_DIR/share/applications/kde4/kmix.desktop like this:

[Desktop Entry]
Exec=bash -c "/usr/bin/strace -s 2048 /opt/kde4head/bin/kmix 2> /tmp/kmix.strace"

2) Logout, login again. After everything is up, quit KMix.
3) bzip2 /tmp/kmix.strace
4) Attach the /tmp/kmix.strace.bz2 here.

Created attachment 24826 [details]
strace -s 2048 Output of KMix during session start

Created attachment 24827 [details]
My Strace

This is my trace. I did as you told me to but notice I'm now using KDE 4.0.3 on
a Fedora 9.

Created attachment 24828 [details]
two strace -s 2048 outputs from kmix regular and session startup

Christian,

Are you sure that strace will capture a kmix session startup?

Attached are two straces, one from a regular startup and another per your
request. They look very similar to me, so I might have done something wrong.
Anyway, you have other straces available too, maybe this will be useful or not.

OK, this was my fault. I forgot one thing:

Exec=bash -c "/usr/bin/strace -tt -T -s 2048 /usr/kde/4.0/bin/kmix --nofork 2> /tmp/kmix.strace" 

Please add "--nofork" (this was the issue) and also "-tt -T" (for timestamps), as shown above.

 

Created attachment 24837 [details]
new strace of kmix

Seems quite bigger !

All right, this looks more like it. Hope it helps. 

Created attachment 24841 [details]
new strace output from kmix session startup

and the attachment...

OK, lets look at attachment 34837 [details] first:

23:47:26.942054 read(10, 0x9d4fc5c, 4096) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>

As far as I see 10 is the FD of a socket, but it is just the UDS to X11. So the read() might just be the Qt event loop.

23:47:25.406859 socket(PF_FILE, SOCK_STREAM, 0) = 10 <0.000026>
23:47:25.406939 connect(10, {sa_family=AF_FILE, path=@/tmp/.X11-unix/X0}, 110) = 0 <0.000157>


So it looks like KMix ist started at 23:47:25.068176 and up and running at 23:47:26.942054, which is less than 2 seconds.

Doesn't explain a 10 - 20 second delay ... 

Now attachment 24841 [details]:

The following line ist very interesting:

19:50:49.494632 poll([{fd=4, events=POLLIN}, {fd=6, events=POLLIN}, {fd=11, events=POLLIN}, {fd=10, events=POLLIN, revents=POLLIN}, {fd=3, events=POLLIN}, {fd=15, events=POLLIN}, {fd=14, events=POLLIN}], 7, 29150) = 1 <16.824485>

So the poll() took 16.8 seconds. Wow!

This poll is not the regular soundcard poll() (via ALSA API), as this has a timeout if 10 ms:

50:48.917710 poll([{fd=14, events=POLLIN|POLLERR|POLLNVAL}], 1, 10) = 0 <0.012548>

So lets enumerate the FD's:

fd 3 : DBUS    # 19:50:47.937040 connect(3, {sa_family=AF_FILE, path=@/tmp/dbus-L0cS8eqCDP}, 23)

fd 4 : ??? # open("/usr/share/locale/locale.alias", O_RDONLY) 

fd 6 : ???

fd 11: X11 ICE # 19:50:48.382468 connect(11, {sa_family=AF_FILE, path="/tmp/.ICE-unix/2262"}, 21)

fd 10: X11 UDS # 19:50:47.986597 connect(10, {sa_family=AF_FILE, path="/tmp/.X11-unix/X0"}, 19)

fd 14: ALSA    # 19:50:48.678884 open("/dev/snd/controlC0", O_RDWR) = 14 <0.000012>

fd 15: DBUS    # 19:50:48.682836 connect(15, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) 

I am not 100%, but it looks like we wait for something from DBUS. Shortly after the poll() returns, we see:

19:51:08.045944 read(15, "...org/freedesktop/DBus...")

Yes, something I belive was mentioned elsewhere and by Dan (#7).

I also see this in my .xsession-errors:
<unknown program name>(3069)/: Communication problem with  "kxkb" , it probably crashed.
...
Error message was:  "org.freedesktop.DBus.Error.NoReply" : " "Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken." "
...
QDBusConnection received a message of type 3 that it shouldn't have
(Soprano::PluginManager) loading all plugin
...
QDBusConnection received a message of type 2 that it shouldn't have
...

Perhaps a dbus configuration issue?

Some news. It might be useful if you could try again to disable "volume restauration", with either KDE4.1 or KDE4.0.6 (once available). Due to Bug 160506, you can't really disable it at the moment.

Sorry about the long delay in response. Apparently this bugs system doesn't like to e-mail you when there is a reply. 

The problem still exists in 4.0.5. To clarify, this only occurs when kmix is autostarted during the initial login. After that you can quit kmix and reopen and it loads almost instant. If you logout and back in, kmix will take 30-45 seconds to start. I tried to grab more straces but I realized my earlier trace may have been wrong. It seems that when kmix is autostarted it ignores the fact that it was previously started with strace. It also ignores the kmix.desktop file which specifies to use strace. I'm unfamiliar with kde4 and dbus. How is this app being called and why would it ignore all my hints to use strace?

I also tried to manually "fix" the file you changed in bug 160506 and disable volume restoration. Unfortunately this had no affect on the problem.

I can confirm fixed in 4.1.0.

Any news on this ? Have anyone experienced this bug again with a recent KDE version? (4.1.3 / 4.2beta2 / 4.2svn) ?  Thanks :) 

(In reply to comment #27)
> Any news on this ? Have anyone experienced this bug again with a recent KDE
> version? (4.1.3 / 4.2beta2 / 4.2svn) ?  Thanks :) 
> 

I haven't had any issues since 4.1.0 (see earlier post). Latest tested under 4.1.3 and 4.2svn a while back.

Thanks for the information, Pete. OK, I propose we wait for a confirmation after.
Dario, Damien, Dan: What are your possiblities to test this with KDE4.1 or the KDE4.2 reelase (latter planned for January 27th, 2009).

@Christian: I never experienced this bug when using KDE4.1 / KDE4.2 svn or now using KDE4.3 
I just asked for more information (comment 27) :)

OK, reading back the post I now understand. it should be safe to assume that the issue has gone away. I will thus close the bug report.

I don't have the opportunity to test the bug with newer version of KDE.

Regards

Marking as WORKSFORME: Reopen if anyone else experience this again. Thanks