| Summary: | Probable race condition: commit d41f5217 2012-05-15 | ||
|---|---|---|---|
| Product: | TDE | Reporter: | Darrell <darrella> |
| Component: | tdebase | Assignee: | Timothy Pearson <kb9vqf> |
| Status: | NEW --- | ||
| Severity: | minor | CC: | bugwatch, darrella, kb9vqf, slavek.banko |
| Priority: | P5 | ||
| Version: | R14.0.x [Trinity] | ||
| Hardware: | Other | ||
| OS: | Linux | ||
| Compiler Version: | TDE Version String: | ||
| Application Version: | Application Name: | ||
| Attachments: |
Debug the notifier daemon
Add basic debugging to KDED |
||
|
Description
Darrell
2013-09-07 18:44:50 CDT
We more or less beat to death bug report 760. I don't want to reopen that report. Yet this bug affects exit times. I do not always witness the problem when exiting Trinity, but I observe the delay often enough. Bumping to Critical. I believe I can trigger the bug in a repeatable manner. I witness the exit delay on a remote system after connecting to the remote system with krdc. 1. At a "remote" computer, start Trinity. Ensure the monitor DPMS options are enabled to allow the system to power off the monitor. On my "remote" system: Screen saver: 10 minutes Standby: 12 minutes Suspend: 15 minutes Power off: 20 minutes I suspect these values can be changed for debugging purposes (for example, 1, 2, 3, 4 minutes). 2. After allowing sufficient time for the remote system to DPMS power off the monitor, from another computer connect to the remote system using krdc. As noted in bug report 1583 "[Regression] krdc issues," when attempting to connect to the remote system the screen saver refuses to stop running. I don't know yet how that is related to this bug report. I'm only providing that information here as a warning to overall behavior. After closing the krdc session at the "local" computer, walk to the remote system. The monitor will still be in DPMS power off mode, despite the krdc connection. Move the remote system mouse to restore the display. Then exit Trinity. There will be a delay. After exiting, review the user's xsession-error log and notice the numerous "[systemdirnotify] SystemDirNotify::init(mInited)" messages. I have not tried to debug this entire sequence of events. I am bumping this report to Major and removing from the etherpad R14 road map. I suspect there are other scenarios where this suspected race condition occurs, but I opened this bug report based upon personal observations that I now have identified in comment 2. Therefore, despite other possible triggers, I think for now we can keep this report limited to the corner case I have described in comment 2. Now that my attention has been drawn to this bug report this afternoon, I am noticing another instance when the "[systemdirnotify] SystemDirNotify::init(mInited)" messages appear in my xsession-error log that does not include the aforementioned corner case. I have not yet noticed any clue as to the cause. I see these messages almost routinely now when exiting Trinity. I have not yet determined the trigger because a login and then immediate logout does not cause the messages. Something in my daily routine triggers the messages (in addition to the trigger mentioned on comment 2: krdc). Not conclusive but possibly a clue. I have had the KDED System Base URL Notifier disabled for several days. I have not see the "[systemdirnotify] SystemDirNotify::init(mInited)" messages when I exit Trinity. Definetely KDED System Base URL Notifier is involved. Generally, the longer my Trinity session the longer Trinity takes to exit and the longer the message spew in the session-error log. Confirmed. Today I am use working machine with R14-nightly a little over 11 hours and at logout I noticed a few mesages "[systemdirnotify] SystemDirNotify::init(mInited)". And logout was conducted relatively slowly. Is there a test patch we can create to spew out some messages to help us debug? The problem is definately related to the KDED System Base URL Notifier. Created attachment 1608 [details]
Debug the notifier daemon
Try the attached patch (for debug only). It might help to determine what is causing the notifier slave to aberrantly reload.
>Try the attached patch (for debug only).
I'll rebuild tdebase and report later in the day.
The exected message pew in the middle of my Trinity session looks sane. I was more interested in the messages that appear when I end the session. I captured xsession-error logs from three sessions. As far as I can tell, this is what the common results looks like: ================================================== [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(file:///home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sda3/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sda3/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sda8/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sda8/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb1/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb1/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::FilesRemoved(system:/media/sda3/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::FilesRemoved(system:/media/sda8/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::FilesRemoved(system:/media/sdb1/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::FilesAdded(home:/smbguest/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/) [systemdirnotify] SystemDirNotify::toSystemURL(home:/smbguest/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sda3/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sda8/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb1/builds/slackware/trinity/zz_pkg_14.0_32_git/build-errors.log) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::FilesAdded(system:/users/smbguest/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/) [systemdirnotify] SystemDirNotify::toSystemURL(system:/users/smbguest/home/public/builds/slackware/trinity/zz_pkg_14.0_32_git/) [systemdirnotify] SystemDirNotify::init(mInited) [tdeinit] Got EXEC_NEW 'tdeio_media' from launcher. [tdeinit] Got EXEC_NEW 'tdeio_media' from launcher. [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sda5) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb1) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [tdeinit] Got EXEC_NEW 'tdeio_file' from launcher. [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb5) [systemdirnotify] SystemDirNotify::FilesRemoved(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb5) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) undecodable token: \001b(hex)[?1015h undecodable token: \001b(hex)[?1015l ================================================== I did not write a journal of what I was doing immediately previous to ending my Trinity sessions. Therefore a few of the messages might be legitimate. One curious part is the 'undecodable token' messages. Another saved log has dozens of these messages. Another curious part are the files paths of smbguest. I am running samba but no such path here. Yes, I have more mount points than most people. :-) Interesting. One of the patches of the past couple of days seems to have stopped the problem. I no longer see the SystemDir notify messages at all at the end of my xsession-errors log when exiting Trinity. (In reply to comment #13) > Interesting. One of the patches of the past couple of days seems to have > stopped the problem. I no longer see the SystemDir notify messages at all at > the end of my xsession-errors log when exiting Trinity. A bisect might be revealing. ;-) I'd limit the bisect to tdelibs/tdebase however. Tim (Odpověď na komentář #14)
> (In reply to comment #13)
> > Interesting. One of the patches of the past couple of days seems to have
> > stopped the problem. I no longer see the SystemDir notify messages at all at
> > the end of my xsession-errors log when exiting Trinity.
>
> A bisect might be revealing. ;-) I'd limit the bisect to tdelibs/tdebase
> however.
>
> Tim
I have tdelibs e757d3d6 and SystemDir notify messages occurs a lot.
My mistake, the messages are still there when I exit. Fuzzy brain the past couple of days.... I have little to update. Seems the amount of spew when exiting Trinity is determined by how recent konqueror was used before exiting. Seems the original slowdown when exiting is gone. When I build tdebase without the debugging patch I still see the original FIXME message ([systemdirnotify] SystemDirNotify::init(mInited)). The log spew looks something like this with the debugging patch and konqueror not being used soon before exiting: [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sda5) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb1) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sda5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb1) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb5) [systemdirnotify] SystemDirNotify::FilesRemoved(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(media:/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURLList(system:/media/sdb5) [systemdirnotify] SystemDirNotify::FilesChanged(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::init(mInited) [systemdirnotify] SystemDirNotify::toSystemURL(system:/media/sdb5) [systemdirnotify] SystemDirNotify::init(mInited) [starttde] Shutting down Trinity... [tdeinit] Terminating Trinity. [tdelauncher] Exiting on signal 1 [starttde] Running Trinity shutdown scripts... [starttde] Running /home/users/slacky/.trinity/shutdown/deletefiles. [starttde] Trinity shutdown complete. So, to clarify, did the debugging patch have the side effect of resolving the shutdown delay? Good question. I don't know. :-) I have been running tdebase mostly with the debugging patch. I'll have to run tdebase several days without the debugging patch to determine whether the delay reappears. If the delay reappears, does that provide you information about what to fix? Possibly. Right now I'm leaning toward the shutdown process terminating the tdeioslave too early, forcing it to respawn during the logout process. This, in turn, would mean the newly spawned process does not receive a termination signal from the logout process, instead waiting for the timed termination handler and holding up the logout in the mean time. The debug patch would have slowed the tdeioslave down, *possibly* keeping it alive just long enough to not be forced to respawn later. Tim Makes sense. I'm rebuilding now without the debugging patch. I will report again in a few days. Short report: Without the debugging patch I don't see any of the additional spew. Without the patch seems everything is back to where we started with a series of [systemdirnotify] SystemDirNotify::init(mInited) messages at the end of the xsession-error log. How many of those messages I see varies. Great! That means that: 1.) there is a race condition 2.) We can probably remove the printf and associated text from the tdeioslave 3.) This bug needs to be dealt with in the ksmserver, by ensuring that this particular tdeioslave is terminated last (similar to how kompmgr, twin, and kdesktop are already handled) Okeydokey. I lack the skills to know how you concluded all of that. :-) When you wrote "remove the printf," did you mean the FIXME Work around in tdebase/tdeioslave/system/kdedmodule/systemdirnotify.cpp? If yes, how will we know in the future when a similar race condition exists? Or is there only one cause? (In reply to comment #24) > Okeydokey. I lack the skills to know how you concluded all of that. :-) > > When you wrote "remove the printf," did you mean the FIXME Work around in > tdebase/tdeioslave/system/kdedmodule/systemdirnotify.cpp? If yes, how will we > know in the future when a similar race condition exists? Or is there only one > cause? Yes. If a race condition recurs, we will know by the long logout times. Created attachment 1695 [details]
Add basic debugging to KDED
Darrell, can you please apply the attached patch to tdelibs and post the ~/.xsession_errors output from a stalled logout?
I can finally reproduce the "inited" messages by loading Konqueror with system:/media/sda1/home/<logged on username>, but have not yet been able to replicate the logout stall. My tests indicate that the systemdirnotify module never unloads (!), but I need confirmation from your system.
Thanks!
(Odpověď na komentář #26)
> Vytvořena příloha 1695
> Add basic debugging to KDED
>
> Darrell, can you please apply the attached patch to tdelibs and post the
> ~/.xsession_errors output from a stalled logout?
>
> I can finally reproduce the "inited" messages by loading Konqueror with
> system:/media/sda1/home/<logged on username>, but have not yet been able to
> replicate the logout stall. My tests indicate that the systemdirnotify module
> never unloads (!), but I need confirmation from your system.
>
> Thanks!
I observed the same behavior - the more I was active in Konqueror, the more it systemdirnotify modules during closing session.
>can you please apply the attached patch to tdelibs and post the
>~/.xsession_errors output from a stalled logout?
I can and will.
I haven't seen a "stalled" logout in a while. Possibly a second slower is the worst I've seen in a while. As Slavek mentioned, I confirm the more active I am with konqueror before logging out the more cluttered is the tail end of my xsession-error log with "SystemDirNotify::init(mInited)" messages.
Just a wild thought, could this be related to a preloaded konqueror? I have not tried testing any of this with konqueror not preloaded.
Question: Do I need both patches enabled or only the latest?
>Question: Do I need both patches enabled or only the latest?
Never mind. I'll rebuild both tdelibs and tdebase. The last couple of runs I disabled the first patch in my tdebase build.
>post the ~/.xsession_errors output from a stalled logout?
For exactly what am I watching?
I flushed the Trinity cache, started Trinity, opened Firefox, read one RSS feed, closed Firefox, and exited Trinity. This is all I saw:
[starttde] Shutting down Trinity...
[tdeinit] Terminating Trinity.
[tdelauncher] Exiting on signal 1
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(mediamanager)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(remotedirnotify)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(kdetrayproxy)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(konqy_preloader)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(tdewalletd)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(kinetd)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(medianotifier)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(systemdirnotify)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(homedirnotify)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(kpasswdserver)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(networkstatus)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(favicons)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(kwrited)
[debug] [KDEDModule] In ~KDEDModule::KDEDModule(khotkeys)
Interesting; you have this line: [debug] [KDEDModule] In ~KDEDModule::KDEDModule(systemdirnotify) That line indicates that the systemdirnotify module was unloaded, yet I do not see that line on my test system even though I know the module was loaded during startup. If you aren't seeing the stall any more, try reversing the tdebase debugging patch and removing the FIXME printf from systemdirnotify.cpp. Let me run a while as is. I only started and exited Trinity. I haven't done anything intensive with konqueror. (In reply to comment #32) > Let me run a while as is. I only started and exited Trinity. I haven't done > anything intensive with konqueror. OK. I'm interested in any place there are "[debug] [KDEDModule]" lines referring to systemdirnotify in ~/.xsession_errors. Thanks! Tim, I don't know whether this is repeatable: Start Trinity. Open Konqueror with the file manager profile. Press F6 to place th cursor in the Location bar. Type /usr/lib Drum fingers waiting for the directory listing to populate. Close Konqueror Exit Trinity On one of my systems I did just that and the systemdirnotify did not unload. I tested a second time with Konqueror not preloaded. Same results. Another clue that konqueror is involved? Sigh. Never mind. Insufficient sleep last night. I did not have the systemdirnotify service enabled on that specific system. (In reply to comment #35) > Sigh. Never mind. Insufficient sleep last night. I did not have the > systemdirnotify service enabled on that specific system. No problem, take your time. The build farm is still working on building the RC1 packages anyway, and it looks like there were some other small bugs introduced in the past few weeks anyway. Tim Any progress on replicating this bug with the most recent debug patch in place? No progress. I'm at a loss as to what got fixed or how. I think I will return to square one: not apply any of the test patches and watch how things unfold for a while. I do not consider this report a blocker to R14. OK. Lowering priority as this doesn't seem to affect very many people at all. |