How to debug two things

Wed Feb 3 20:04:43 UTC 2016

On Tuesday 02 Feb 2016 13:59:42 Mitch Golden wrote:
> On Tue, 2 Feb 2016, Achim Bohnet wrote:
> > Valorie reminded me ...
> > 
> > On Monday 18 Jan 2016 11:42:48 Mitch Golden wrote:
> >> I have been using KDE5 since the 14.10 dual release, and there are two
> >> bugs that persist that I would like to tackle.
> >> 
> >> 1) Most though not all of the time when I log out/shut down and then log
> >> in again, if I had a konsole open in the old session it will not be there
> >> in the new.  I am fairly sure that this is due to a crash in konsole when
> >> it receives the shutdown signal.  I believe this because once or twice I
> >> have seen the crash reporter open just before the system turned off.
> > 
> > I've once read a long analysis what goes wrong with konole session
> > management and session management in general.  Worth reading, saves you
> > lots of time I'm sure but could not find it right now. Good luck with
> > google ;-)
> 
> Thanks - I will look.  I did google around some before but didn't find
> anything other than the link I posted before

Ah, it's in kde-core-devel.  All the details at:

Subject:    Causes of session management problems in Plasma 5
From:       Andreas Hartmetz <ahartmetz () gmail ! com>

https://marc.info/?l=kde-core-devel&m=144832700109449&w=2

> 
> >> http://unix.stackexchange.com/questions/117421/how-to-close-all-apps-befo
> >> re-> x-server-goes-down
> If you can recall anything let me know.  Would really love to fix this.
> Whatever it is that's wrong wasn't happening with 14.04 so it's probably a
> change that was made somewhere in kde5.
> 
> >> 2) During login, there is a long delay when the bar is mostly though not
> >> always all the way across.  If I open a second terminal I can see via top
> >> that nothing much is happening during the long delay.  Is there some way
> >> to turn off the bar and see exactly what the process is during startup?
> > 
> > I almost sure this is akonadi (at least here it is).  To test:
> > 
> > Logout from your plasma session.  Login on an virtual console
> > 
> > 	sudo  ln -s /bin/true  /usr/local/bin/akonadiserver
> > 
> > Login into plasma session.
> > 
> > Here login time is down from ~ 30 sec to ~ 5 sec.  Don't forget to
> > 
> > 	sudo  rm  /usr/local/bin/akonadiserver
> > 
> > to get an working akonadi back.
> > 
> > Achim
> 
> So are all users seeing this delay?  I would think that before LTS is

My impression from #kubuntu-devel was that several people had this problem.

Other way round:  Question: Anyone on this list using akonadi and login is fast?  < 10 sec?

> released it should probably be cleaned up.  What is the issue with akonadi
> that causes the delay without any cpu?

Maybe you can ping dvratil on #akonadi. I'm too busy at the moment to keep an eye
on the problem.  My last interaction with him was long ago:

[00:00:00] - {Day changed to Friday, 6 November 2015}
[11:07:57] <-> einar77 is now known as einar77_work
[11:45:38] <allee> dvratil:  do you have better internet access again?  Care to install kubuntu in a vm to debug the ~ 10 - 25 ... sec delay on login?   Or another hint how I can provide further input to help fixing it?
[11:46:12] <dvratil> right, I do :) I'll try after lunch
[12:57:16] <allee> dvratil:  thx, maybe I have another hint for you.  I've found right now that  with akonadictl stop, then logout, login takes ~ 6 sec until the empty desktop.  When akonadi is still running (e.g. start/stop kaddressbook) at logout  I'm back to 30 sec login time.   
[12:57:33] <allee> Wasn't there something with akonadi and QApp versus AkApp?
[12:59:24] <dvratil> allee: yeah, that was a fix for systems that use systemd to start session bus and reuse it upon relogin
[12:59:34] <dvratil> is that the case for ubuntu too?
[12:59:35] <allee> Per logout I also get a kuiserver5 running.  Logged out I'm now the proud owner of 14 such processes
[13:00:48] <allee> dvratil: yes, systemd is used in 15.04 and now 15.10, I'll try to find out if systemd start dbus now too 
[13:00:51] <allee> lunch, bbl
[13:48:12] <allee> dvratil: AFAIU it no.   Parent of session dbus-daemon is PID 1.  https://paste.kde.org/ptfptwcvo. 
[14:17:42] <dvratil> allee:  well PID1 is systemd, isn't it
[14:19:34] <allee> dvratil: yes, but there's no dbus-daemon with my pid running after logout.  So the proc not shared between sessions 
[14:19:44] -*- allee has the feeling to miss something important 
[14:19:55] <dvratil> ok
[14:22:24] <allee> dvratil:  Is there a backport of this patch for 15.08(.2)? Maybe it's nevertheless related?
[14:23:02] <dvratil> no, it only went to master
[14:26:42] <dvratil> installing kubuntu 15.10 now
[14:28:17] <allee> thx
[19:05:46] <-> einar77_work is now known as einar77
[22:37:34] <-> antlarr is now known as antlarr_away
[00:00:00] - {Day changed to Saturday, 7 November 2015}

My guess is that akonadi during logout does not stop properly and has
to recover every resource on login.

Achim
> 
>    - Mitch Golden

First chat with dvratil:

[00:00:00] - {Day changed to Tuesday, 20 October 2015}
...
[20:31:39] <allee> dvratil: Hi Dan, at least in (k)buntu we see a long delay on login due to akonadi startup: 4 sec without,  ~ 12 .. 30 sec with akonadi depending on  # of resources/agents.   (See my few msg yesterday in this channel).     Is there a way to do this asynchrous?  Is it only kubuntu?
[20:41:33] <dvratil> allee: it's not just kubuntu, we already heard about this problem from various users
[20:41:51] <allee> :-(
[20:42:24] <einar77> dvratil: funnily enough I don't see this much recently (my auto backup script at login is probably slower)
[20:42:42] <dvratil> I don't know how this can be though, Akonadi started on-demand - usually by korgac - but it does not block korgac start (that should be fast)
[20:43:39] <allee> dvratil:  if korgan is running akonadi is started later in login process stop at ~ 80 %.  If one diables and quits korgan it happens ~ 60 %
[20:43:52] <einar77> but something must be requesting akonadi
[20:44:04] <einar77> it doesn't start up on its own unless there's an application requesting it
[20:44:23] <dvratil> it could just be the IO - starting Plasma session is IO intensive on it's own - if Akonadi starts lunching a database and loading the additional resource processes, it's a lots of additional IO slowing down everything
[20:44:33] <allee> seems that something in kcm init is triggering akonadi.  It's starting and quiting but this takes ~ 8 sec for a config that does not use akonadi
[20:45:33] <allee> dvratil: what puzzels me is:  akonadictl stop  and in kmail I start akonadi -> 2 sec.   But during login akonadi startup consumed 8 sec
[20:46:19] <allee> ^^ with an SSD.  And akonadi stop/started several times before
[20:46:32] <allee> I don
[20:46:46] <dvratil> oh
[20:46:47] <dvratil> SSD
[20:46:51] <dvratil> ok, so it's not IO :)
[20:47:00] <allee> 't remember seeing this with 4.14.*  Started with KF5 port of KDEPIM
[20:47:49] <allee> yeap.  3 year old mac air. So can't be CPU either ;-)
[20:51:35] <allee> dvratil: as I mention yesterday: the log entries are between 'ksmserver: Autostart 1 done ... Kcminit phase 2 done'.   If you have any tip hint how trace it down further, lemme know.   I've no idea how to continue 
[20:52:45] <dvratil> hmm, I just got a fresh install (on SSD ;-)) of Fedora with PIM from master, le me try if it hangs too...I did not log out since I built PIM
[20:54:06] <allee> thx
[21:05:24] <dvratil> so: the irony
[21:05:33] <dvratil> first login got stuck on 50% for a very long time
[21:05:58] <dvratil> but then I found that the Akonadi wasn't actually started 
[21:06:26] <dvratil> so I made sure kalarm/korgac is started after login, relogged and te logging was fast
[21:21:09] <dvratil> allee: sorry, really can't reproduce here...:/
[21:23:43] <allee> dvratil:  uhm, how many resources are configured?  Here it's 4 imaps+4 smtp + 3 caldav + 4 carddav + ldap
[21:24:20] <dvratil> 15 agents in total (qdbus | grep org.freedesktop.Akonadi.Agent | wc -l)
[21:25:01] <dvratil> I can try to pimp my setup 
[21:26:29] <allee> dvratil: I doubt  that changes much I've 18 and see almost 25 sec delay only by akonadi.
[21:28:50] <allee> I'll ask if CI experts if there's an easy way to just install KDEPIM pkgs from CI from master. If it the delay goes away it should hopefully not be that hard to pin the guilty code between 15.08 and master 
[21:29:13] <allee> Thx. I'll keep you posted ...
[21:35:48] <-> helios99 is now known as helios21
[21:37:24] <allee> dvratil: curious could you pastebin the output of  grep -i akonadi  the output of startkde.  Maybe I can spot a difference to  my output https://paste.kde.org/pmxuc8prq  
[21:37:52] <dvratil> allee: what's your QT_LOGGING_RULES?
[21:39:00] <dvratil> I turned on "* = true\n qt.* = false" and the output is literally tons of debug
[21:44:49] <allee> dvratil: whatever is the default in kubuntu.  If QT_LOGGING_RULES is an env var, then it's not set here
[21:48:26] <allee> dvratil : when you stop korgan event daemon & applet and all KDEPIM Apps is in your case akonadi nevertheless  nevertheless started on login just to quit immediately again?
[21:51:55] <pursuivant> kdepimlibs (master) v15.08.2-185-g5f27299 * Weng Xuetian: akonadi/src/core/connectionthread.cpp
[21:51:56] <pursuivant> Catch the exception when Akonadi::Protocol::deserialize fails.
[21:51:57] <pursuivant> CCBUG: 351097
[21:51:57] <pursuivant> REVIEW: 125731
[21:51:58] <pursuivant> http://commits.kde.org/kdepimlibs/5f272998af641c40761cbe43c76d10b7a00e851c
[21:54:14] <dvratil> allee: akonadi never shuts down on it's own
[21:54:19] <dvratil> its
[21:57:16] <dvratil> allee: for me akonadi is as well started between "Autostart 1 done" and "Kcminit phase 2 done" - but there's only 3 seconds between those
-- 
  To me vi is Zen.  To use vi is to practice zen. Every command is
  a koan. Profound to the user, unintelligible to the uninitiated.
  You discover truth everytime you use it.
                                      -- reddy at lion.austin.ibm.com