Bug 353203 - 20 seconds delay on kde login with kservice 5.14.3
Summary: 20 seconds delay on kde login with kservice 5.14.3
Alias: None
Product: frameworks-kservice
Classification: Frameworks and Libraries
Component: general (show other bugs)
Version: unspecified
Platform: Arch Linux Linux
: NOR major
Target Milestone: ---
Assignee: David Faure
Depends on:
Reported: 2015-09-26 07:10 UTC by empire
Modified: 2020-06-13 18:07 UTC (History)
17 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:

syslog (44.61 KB, text/x-log)
2015-09-26 08:05 UTC, empire
new log with updated patch (62.90 KB, text/x-log)
2015-10-04 22:19 UTC, empire
journalctl (191.96 KB, text/plain)
2015-10-08 14:43 UTC, raphael.cazenave
~/.xsession-errors with export QT_MESSAGE_PATTERN='%{time} %{appname}(%{pid})/%{category} %{function}: %{message}' (3.70 KB, text/plain)
2015-10-10 14:17 UTC, raphael.cazenave
Diff to show fedora packages that were updated after the update on Dec 12, 2015 (4.90 KB, text/plain)
2015-12-12 23:24 UTC, Tom Canavan

Note You need to log in before you can comment on or make changes to this bug.
Description empire 2015-09-26 07:10:27 UTC
After upgrading to kservice 5.14.3 from 5.13.0 I experienced an extra delay (with pause) of 20+ seconds when logging in from sddm to kde. In that pause the system has no activity (disk or cpu) it just waits.

Reproducible: Always

Steps to Reproduce:
1. Login
2. count the time it takes for the desktop to appear

Actual Results:  
more than 2-25 seconds delay

Expected Results:  
2-3 seconds delay
Comment 1 empire 2015-09-26 08:05:33 UTC
Created attachment 94724 [details]

Notice the 20+ seconds delay in the log at line 156 and how meanwhile nothing was happening.
Comment 2 David Faure 2015-09-28 07:25:10 UTC
I assume kbuildsycoca5 is running all the time during that time?

It would then be the same as https://bugs.kde.org/show_bug.cgi?id=353036 probably.
Comment 3 David Faure 2015-10-02 22:34:51 UTC
Can you try the patch at https://git.reviewboard.kde.org/r/125497/ ?
Comment 4 empire 2015-10-03 10:41:14 UTC
The latest kservice package in Arch is 5.14.3 and the patch doesn't work against that code. I can't use the git version because I have to reinstall and recompile many KDE packages for this. So nope I can't sorry.
Comment 5 David Faure 2015-10-03 11:27:59 UTC
You could use the git version of just kservice and hack KF5_DEP_VERSION (in the toplevel CMakeLists.txt) back to 5.14 (actually it was like that until 1h ago).
Comment 6 empire 2015-10-04 20:06:36 UTC
I managed to compile and install it. I had to also change the find_package(ECM 5.15.0  NO_MODULE) to find_package(ECM 5.14.0  NO_MODULE) to compile.

I tried it and unfortunately the 20 seconds delay is still happening with the patch too. I can provide more detailed info and logs if you want me to.
Comment 7 David Faure 2015-10-04 21:44:19 UTC
There's still one pending patch (in case you have directories with a modification time in the future), it's the one at https://git.reviewboard.kde.org/r/125497/

You could try applying it.

Otherwise, then I don't know at all what the issue is. The logs don't say much. Can you use kdebugsettings to enable all areas, especially those containing kf5?

Another idea is, during the 20 seconds where nothing seems to be happening, to inspect the processes (e.g. is one using 100% cpu or I/O? is kbuildsycoca5 running?) by running top and iotop from a ssh session.
Comment 8 empire 2015-10-04 22:15:52 UTC
I just tried the new patch and still get the delay. I have everything enabled and set to "All" in kdebugsettings. 

Also I used ssh to monitor with top while I was loggin in but it was completely 0% cpu and no activity with disks that I could tell (I have an SSD so even if it was disk seeking it shouldn't take near as much as 20 seconds).

I'll add the new log. Notice that it always stops after this line:

Οκτ 05 01:07:09 nekhomeworkstation dbus-daemon[838]: Successfully activated service 'org.gnome.GConf'

Maybe there's some kind of compatibility issue with gconf?
Comment 9 empire 2015-10-04 22:19:50 UTC
Created attachment 94846 [details]
new log with updated patch
Comment 10 empire 2015-10-06 20:12:45 UTC
I did a manual git bisection and managed to find the exact commit that introduces this bug. It's the commit 1d7eb96791ae385b05c0fa5c2363902741489e1b. I tested it thoroughly with multiple reboots per commit to make sure. Note that it needs at least 2 reboots for the bug to manifest.

From the commit's comments I understand and guess that probably the issue is with the new code for Ksycoca that checks the directories.

I hope I have helped. I can further help by doing some debugging if you would need it. Just show me how.
Comment 11 Rex Dieter 2015-10-07 17:09:06 UTC
Several fedora users experienced similar symptoms of delayed login too (including me).

Seems the problem went away us (2 users so far), by :
1.  end plasma session
2. delete any existing ksysoca5 cache (rm -f ~/.cache/ksycoca5* )
3.  re-login

Speculation:  upgrading to kservice 5.13 -> 5.14 while an active plasma session is already running may have caused kbuildsycoca5 to create a bad/invalid ~/.cache/ksycoca5 and/or ~/.cache/ksysoca5stamp , that wasn't fixed by simply re-runing kbuidsycoca5 (I even tried, kbuildsycoca5 --noincremental previously without success)
Comment 12 Rex Dieter 2015-10-07 17:16:49 UTC
Dang, just occurred to me I had also tested downgrading/upgrading kservice 5.14->5.13->5.14, which may also inadvertantly bumped directory timestamps, which may have played a role in the problem going away.

(The 2nd user I referenced only did the steps I outlined in my prior comment though)
Comment 13 raphael.cazenave 2015-10-08 10:56:22 UTC
I'm affected too on Archlinux. 
I'm using BTRFS, but I doubt that this could be causing the KService problem.

I tried to downgrade to kservice-5.13.0-1, bug still there.
I also tried to remove '~/.cache/ksycoca5*', bug still there.

@RexDieter, Could you specify the url of the thread of fedora users affected by this bug?
@DavidFaure, I think the bug affects Fedora users too, so 'Platform:Archlinux Packages Linux' can be changed.
Comment 14 David Faure 2015-10-08 12:12:26 UTC
Can someone try with karchive git, or the v5.15.0-rc2 tag? There is a bugfix in there (the last commit in v5.15.0-rc2) which might very well fix this.
Comment 15 Rex Dieter 2015-10-08 12:23:00 UTC
I  assume you mean kservice (not karchive), I don't see any relevant commits in karchive
Comment 16 empire 2015-10-08 12:45:27 UTC
(In reply to raphael.cazenave from comment #13)
> I tried to downgrade to kservice-5.13.0-1, bug still there.

Are you absolutely certain that downgrade didn't fix the problem? Because I did a thorough test and found the exact commit that causes this bug for me. Can you double check?
Comment 17 raphael.cazenave 2015-10-08 14:43:47 UTC
Created attachment 94896 [details]

Freeze from 16:36:08 to 16:36:30 (22 seconds)
Comment 18 raphael.cazenave 2015-10-08 14:49:47 UTC
(In reply to empire@adslgr.com from comment #16)
>Are you absolutely certain that downgrade didn't fix the problem? Because I did a thorough test and found the exact commit that causes this bug for me. Can you double check?

I just did it again. From Arch Rollback Machine, at http://seblu.net/a/arm/2015/08/25/extra/os/x86_64/, I downloaded and installed the following packages:
[2015-10-08 16:29] [ALPM] transaction started
[2015-10-08 16:29] [ALPM] downgraded kservice (5.14.3-1 -> 5.13.0-1)
[2015-10-08 16:29] [ALPM] downgraded kdesu (5.14.0-1 -> 5.13.0-1)
[2015-10-08 16:29] [ALPM] downgraded kemoticons (5.14.0-1 -> 5.13.0-1)
[2015-10-08 16:29] [ALPM] downgraded kpeople (5.14.0-1 -> 5.13.0-1)
[2015-10-08 16:29] [ALPM] downgraded ktextwidgets (5.14.0-1 -> 5.13.0-1)
[2015-10-08 16:29] [ALPM] downgraded kwallet (5.14.0-1 -> 5.13.0-4)
[2015-10-08 16:29] [ALPM] downgraded telepathy-kde-approver (15.08.1-1 -> 15.08.0-1)
[2015-10-08 16:29] [ALPM] transaction completed
After that plasma got unresponsible, I had go to TTY, closed the sddm, and 'rm ~/.cache/ksycoca5*' to be sure.

After multiples reboot, the bug is still present, as you can see in journalctl logs : https://bugsfiles.kde.org/attachment.cgi?id=94896 (freeze from 16:36:08 to 16:36:30)
Comment 19 raphael.cazenave 2015-10-08 15:54:38 UTC
(In reply to David Faure from comment #14)
> Can someone try with karchive git, or the v5.15.0-rc2 tag? There is a bugfix
> in there (the last commit in v5.15.0-rc2) which might very well fix this.

I just installed kservice-git (r408.0a39ba6-1), and the issue still exist. :(
The version I tried is 
* commit a39ba6ec01600efeb9e334fa457dd725e2e3749                                                                                     
| Author: Xuetian Weng >wengxt@gmail.com>                                                                      
| Date:   Tue Oct 6 23:36:39 2015 +0200    

Are we sure that kservice is the cause of this issue ?
Comment 20 luminoso 2015-10-08 18:08:24 UTC
For me, to fix this issue i downgraded in Fedora these packages:
plasma-desktop 5.4.1-2
plasma-workspace 5.4.1-3

to their downgrade version which are:

in this downgrade the following dependencies are also downgraded:

However, to test if the problem was solved I've installed plasma-workspace-5.4.2-1 (from 5.4.1 to 5.4.2) and the bug was still present.

However, with a full 5.4.2 plasma-desktop installed I had to perform just one downgrade to fix all the delays, even without downgrading from plasma-desktop 5.4.2 to 5.3.0.

I've downgraded kf5-kservice-5.14.3-1 to kf5-kservice-5.9.0-1 and the problem was completely solved. No hangs at all when loading the session.

What I cant make a connection is why downgrading plasma-workstation solved the problem, but so did kf5-kservice did. 

For anyone testing, be careful perform kbuildsycoca (with noincremental), because it can crash after downgrading and introduce new variables to the tests.
Comment 21 David Faure 2015-10-10 09:32:45 UTC
(sorry, I meant kservice instead of karchive indeed).

journalctl doesn't tell us much, I would suggest to look at ~/.xsession-errors* instead.

To get timing information in there, create a file like ~/.config/plasma-workspace/env/debug.sh (the base filename doesn't matter, the extension does matter) and put this line into it :

 export QT_MESSAGE_PATTERN='%{time} %{appname}(%{pid})/%{category} %{function}: %{message}'
Comment 22 raphael.cazenave 2015-10-10 14:17:26 UTC
Created attachment 94932 [details]
~/.xsession-errors with export QT_MESSAGE_PATTERN='%{time} %{appname}(%{pid})/%{category} %{function}: %{message}'
Comment 23 raphael.cazenave 2015-10-10 14:19:43 UTC
(In reply to David Faure from comment #21)
> (sorry, I meant kservice instead of karchive indeed).
> journalctl doesn't tell us much, I would suggest to look at
> ~/.xsession-errors* instead.
> To get timing information in there, create a file like
> ~/.config/plasma-workspace/env/debug.sh (the base filename doesn't matter,
> the extension does matter) and put this line into it :
>  export QT_MESSAGE_PATTERN='%{time} %{appname}(%{pid})/%{category}
> %{function}: %{message}'

In the https://bugsfiles.kde.org/attachment.cgi?id=94932 attachment, sadly the logging start after the ~20-30sec delay. '2015-10-10T16:14:21' in my logs is the moment when the delay end.
Comment 24 raphael.cazenave 2015-10-10 14:22:57 UTC
I think it can be usefull to see if the bug occurs on a fresh install of Archlinux.
To exclude malfunction originating from a bad update of KService / kbuildsycoka.
Comment 25 AnAkkk 2015-10-11 14:36:03 UTC
Fixed for me by updating to 5.15.
Comment 26 David Faure 2015-10-27 07:40:46 UTC
Git commit 0f816ab3fada9f57e836da78470003dd24d26a27 by David Faure.
Committed on 27/10/2015 at 07:40.
Pushed by dfaure into branch 'master'.

KBuildSycoca: always save, even if no change in .desktop file was noticed.

This fixes the case where a directory is "touched", so when KSycoca
compares directory timestamps it decides to rebuild, but then KBuildSycoca
doesn't find any real change and doesn't save. This can then happen
all over again at the next timestamp check.
REVIEW: 125803

M  +3    -0    autotests/ksycocatest.cpp
M  +5    -7    src/sycoca/kbuildsycoca.cpp
M  +1    -1    src/sycoca/ksycoca.cpp

Comment 27 raphael.cazenave 2015-10-31 15:25:10 UTC
@AnAkkk, I still have the issue after upgrading to 5.15 (on Archlinux) :/
I tried on a fresh Archlinux, the problem is the same.
@David Faure, this bug may be related to https://bugs.kde.org/show_bug.cgi?id=352779
Comment 28 David Faure 2015-11-04 08:09:44 UTC
Does this bug still happen, with commit 0f816ab3fada9f mentionned above?
This commit will be in KF 5.16.
  (but if someone with the bug can test before the 5.16 release, then we can be sure 5.16 will fix it...)
Comment 29 Mister Ypsilon 2015-11-08 22:03:56 UTC
The mentioned commit does NOT fix the delay on my machine, the login animation still freezes for ~25 seconds and the PC does seemingly nothing...
Comment 30 raphael.cazenave 2015-11-10 22:38:24 UTC
I just did a fresh install of archlinux, opensuse 42.1 LEAP in virtualbox and I noticed an interesting fact.

With the same virtual machine, in relatively close load state, I got
openSUSE 42.1 login time: 9seconds
Archlinux login time: 28seconds

openSUSE 42.1 uses kservice 5.15.0-2.1
Archlinux uses kservices 5.15.0-1

So it seems to only affect Archlinux packages.

@David Faure, like @Mister Ypsilon, I can confirm that the mentioned commit does NOT fix the delay on my machine :/
Comment 31 szymon.pysz@gmail.com 2015-11-11 09:28:19 UTC

I am also using Arch Linux and SDDM has delay on startup. Approx. 30 seconds.
After upgrade to extra/kservice 5.15.0-1 problem still exists.

Comment 32 David Faure 2015-11-11 13:58:29 UTC
Raphael, thanks for your testing. Could you do an additional test, bringing the exact same version of kservice on both systems? If you can see a difference with the exact same version of KService, then the problem isn't in KService at all.

(Also your .xsession-errors has very little in it, you need to enable all debug output with kdebugsettings for this to be useful)
Comment 33 raphael.cazenave 2015-11-11 16:46:38 UTC
@David Faure,
Yesterday, in my quest to return to plasma after several weeks (happily) spent on gnome-shell, I just tried everything to understand the source of this annoying login delay.

It turns out that akonadi is the origin of the delay.

On previous tests, those who produce consistently a login duration of 28 seconds, I installed plasma and kde-meta-meta-applications.

And comparing it with openSUSE 42.1 LEAP, I compared processes after login:
On openSUSE 42.1 LEAP, akonadi is not running when we arrive on the Plasma desktop. It is launched on demand, if it launches an application that requires akonadi.
On a fresh Archlinux with plasma-meta-meta packages and meta-kde-applications installed, akonadi launches automatically.
For two reasons.
1 / ~ / .config / akonadi / akonadiserverrc contains `StartServer =true` (whereas openSUSE set it to` false`).
2 / Too many services are launched.

I notice also that in the default configuration, Akonadi is trowing a lot of errors about mariaDB, maybe the actual version of mairaDB conflict with the akonadi API ?

So I decided to try again on a clean Arch virtual machine, I just installed `plasma-desktop` and sddm`, akonadi not installed, but I'll have probably need later, so I' specify `StartServer = false` in ~/.config/akonadi/akonadiserverrc.
The result is clear: ~ 2 seconds after pressing the button login, I have a functional plasma desktop.

So I really doubt that the concerns which many people speak either on KService, although it must be completely sure before concluding.

Sorry for the lack of brevity.
Comment 34 Valdas 2015-11-11 17:19:26 UTC
I'm using Kubuntu 15.10.
"StartServer = false" didn't help.
Comment 35 Mister Ypsilon 2015-11-11 17:48:13 UTC
"StartServer = false" also didn't help here, neither did uninstalling akonadi.

As nobody else mentioned this yet:
Does the login animation also freeze for the other affected persons?
It seems like whatever is causing the delay is also locking some rendering thread on my system...
Comment 36 Valdas 2015-11-11 18:27:13 UTC
For me: login screen bar goes to 100% (~3 seconds), then long pause (~20 seconds) with freezed  login screen, then desktop appears. But strange: during login screen freeze I can Alt+Tab -> Empty desktop is showed for me as possibility to switch in (when I do that I get same freezed login screen).

After I upgraded to Kubuntu 15.10 I experience graphical glitches: screen often fails to update ("ghosts" from past, "where that application's window which I started?",...), then I must Alt+Tab twice to get correct picture (Asus N56VZ notebook with Intel graphics on i7).
Comment 37 David V 2015-11-16 23:34:06 UTC
How many of you are using Nvidia GPUs with Nouveau drivers?

I was also experiencing a long delay between the login screen and desktop appearance on two different machines with fully upgraded Fedora 22 (kernel 4.2.5-201) with KDE/Plasma 5, SDDM display manager.  I tried some of the solutions here, but none worked.  However, I installed Nvidia's proprietary drivers via dnf from RPMFusion (akmod-nvidia-340xx / GeForce 210) and the delay went away.

I don't know enough about the inner-workings of KDE to know if the Nouveau driver could be the culprit, but hopefully this information is of some use.
Comment 38 Tom Canavan 2015-12-12 04:24:06 UTC
FWIW, this is happening also Fedora 23.  I am using kf5-plasma-5.16.0-4.

Symptoms are,  It's down to a matter of luck whether plasma shows me my panel with icons and the icons on the desktop.  It has gone on for at least two minutes sometimes. After that I usually give up and reboot Sometimes everything will show up after a couple minutes, and sometimes it will not. Sometimes if I let it go long enough, things will show up little by little.  Like he said, about 50/50 chance

I am getting the "autoStart2Done timedout, this is a BUG!"
message in /~.xsession-errors.

I am using Intel onboard graphics and only one monitor on my tower system.  So whatever it is, it is probably not limited to Nvidia graphics.

I could post copies of this stuff, but it is rather long. 
This is a rather serious problem and costs a lot of time. Hope this helps.
Comment 39 Tom Canavan 2015-12-12 21:01:09 UTC
This problem seems to be fixed after the updates Sat. Dec. 12.  Login is very quick.  About 6 seconds.  I am no longer getting the  "autoStart2Done timedout, this is a BUG!" message in /~.xsession-errors.  Seems the update to 5.5 packages fixed it.  Thank you.
Comment 40 raphael.cazenave 2015-12-12 21:58:29 UTC
@David V, i use on both computer the driver for Intel. Your observation seems disburting.
@ Tom Canavan, good to see the issue is gone for you :), you mention an update. To be useful for other distros, can you tell more about wich packages got updated on your Fedora and the from to version ? Thanks
Comment 41 Tom Canavan 2015-12-12 23:24:38 UTC
Created attachment 96023 [details]
Diff to show fedora packages that were updated after the update on Dec 12, 2015

Output of diff -y --suppress-common-lines to show fedora packages updated by the update on Dec. 12, 2015
Comment 42 Tom Canavan 2015-12-12 23:43:40 UTC
I think I spoke too soon.  The update helped, but it didn't solve the problem completely.  After the update, I rebooted and logged in 3 times and each time, it logged me in in about 6-10 seconds.  Then I went away for awhile and came back.  booted and it took 2:30 to log in and I got that
"autoStart2Done timedout, this is a BUG!" message in /~.xsession-errors again.  This last time, it logged me in in 1:50 seconds and I did NOT get the error.  Strange.  It seems to happen a little differently each time I log in.  But at least it doesn't seem to hang completely like it did before.  (knock on wood).  I'm posting a file to show the fedora packages that were updated.  Hope this helps.
Comment 43 Mister Ypsilon 2015-12-16 10:12:49 UTC
After upgrading Frameworks to version 5.17, the problem went away for me. Login is super fast now, like 3-5 seconds.
Comment 44 OlafLostViking 2015-12-17 08:55:20 UTC
I can not confirm that completely. While it seems to be true that the login is faster (but no guarantees for now ;-) ), a lot of autostarted programs (be it by explicit autostart or by session restoration) now take this time to finally start up. The desktop/plasmashell is (partly?) there and seems to be useable, but a lot of the programs are just starting much later (and in case of programs showing dialogs, pop up all together - like a restored kontact with open mails or the CopyAgent from copy.com).
Comment 45 microcai 2016-01-28 09:35:50 UTC
guys, the exact reason is in startkde

dbus-update-activation-environment --systemd --all

this line. blocks 25~ and then print

dbus-update-activation-environment: warning: error sending to systemd: 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.
Comment 46 David Faure 2016-01-30 11:01:48 UTC
microcai, can you create a different bug report for this, and assign it to jan.steffens@gmail.com who introduced the use of dbus-update-activation-environment in commit 90081cb0483ffc3ad46af3b99de171ed38716ac0 (plasma-workspace git repo) ?

Everyone else: if you comment out the call to dbus-update-activation-environment from your startkde, does the issue go away? If yes, we can close this, if not, then there are two separate issues.
Comment 47 Valdas 2016-01-30 19:51:05 UTC
If I comment in "startkde" like this:
# At this point all environment variables are set, let's send it to the DBus session server to update the activation environment
#if which dbus-update-activation-environment >/dev/null 2>/dev/null ; then
#    dbus-update-activation-environment --systemd --all

then issue remains.

I must mention: during that pause I can "Alt+F2" then type "firefox" with following Enter and then with "Alt+Tab" I can see started Firefox window in Application switcher visualization.
Comment 48 Andreas T 2016-01-31 11:46:35 UTC
I'm on Ubuntu 15.10 and startkde does not contain a call to dbus-update-activation-environment - there is only a call to ksyncdbusenv. So I don't think that this is the root cause of the delay on startup :(
Comment 49 microcai 2016-02-01 03:42:31 UTC
you should not remove  dbus-update-activation-environment --systemd --all

just remove --systemd

leave it as dbus-update-activation-environment  --all

the all problem solved.

if you delete the call to dbus-update-activation-environment then it will still delay 25 seconds.
Comment 50 Valdas 2016-02-01 11:02:48 UTC
If I remove "--systemd" then after login screen I get graphical window (like messagebox) with text "Could not sync environment to dbus.", and if click "OK" then graphics freezes and KDE not loads (but I still can switch in to text console by Alt+Ctrl+F1).
Comment 51 Søren Holm 2016-03-08 22:50:47 UTC
Removing dbus-update-activation-environment from startkde did not solve it or me. skipping "--systemd" was no luck either.

Interestingly enough, the first login running completely without dbus-update-activation-environment but with /usr/lib/x86_64-linux-gnu/libexec/ksyncdbusenv instead work well for ONE login. After that it made no difference.
Comment 52 Søren Holm 2016-04-19 05:17:16 UTC
This bug has - for kubuntu 16.04 - been completely solved until a few days ago. Can anyone confirm that?
Comment 53 microcai 2016-04-28 07:19:25 UTC
if you have problem with dbus-update-activation-environment, then you must be using ArchLinux and you must have dbus-daemon activated by systemd user instance. please check if you had once refer to the Arch wiki and tweaked the dbus user daemon activation mechanism. revert to upstream method then  dbus-update-activation-environment won't block anymore.
Comment 54 Valdas 2016-04-28 07:34:53 UTC
 My findings: I'm freshly installed Kubuntu 16.04 and I was experienced no delay in login until I was paired system with my phone (using Bluetooth). Now that delay comes back.
 Maybe my experience related to another bug?
Comment 55 David Faure 2020-06-13 18:07:22 UTC
This issue seems to have become a catch-all for all sorts of different issues on different systems with different KF5 versions for different reasons, over many different years...

The problems with KService, which is what this issue was supposed to be about, ar fixed by now (for quite some time).

Please open different bug reports for different issues.