Nepomuk / Virtuoso-t causing delayed logout.
Tags:
None
Registered Member 
|
A solution would be nice, but primarily I'm looking for ideas to try.
Recently upgraded openSUSE 12.3 to 13.1 (with KDE 4.11.3) which is when this problem appeared. Upgraded KDE to 4.12.0 and problem still persists. Logout from the KDE desktop (timed from 'logout' to reappearance of kdm login) has increased by approximately 20 seconds. I've narrowed it down to Nepomuk/Virtuoso-t. With the semantic desktop disabled logout is typically 5-6 seconds, when enabled it rises to 25-26 seconds. I suspect KDE is waiting for something to timeout... Prior to logout I've obtained the PIDs of nepomukserver, nepomukstorage and virtuoso-t. Logged in to a VT as another user and set top to monitor only those PIDs. If I then return to my own graphical session, initiate logout, then imediately switch back to the VT I'm able to see that; as far as I can tell, nothing happens at all to those processes, until, around the 20 second mark, they terminate. They appear as in this screenshot. (Click for full size) [url=http://postimg.org/image/z5iohiyuz/][img]http://s17.postimg.org/z5iohiyuz/vt_top.jpg[/img][/url] Edit... OK so the thumbnail's vanished... here's the direct link. http://postimg.org/image/z5iohiyuz/ There's no change in order, no apparent CPU activity, no change in memory usage, and no change in the time the process has ran for. I've repeated this several times and tried with much shorter top update intervals - I'm convinced there is no activity from those three processes during the 20 second wait. These are the current versions of nepomuk/virtuoso - I've re-installed them, I've tried with a different user, and with a new user, all to no avail. paul@Orion-1:~$ rpm -qa | grep -i virtuoso soprano-backend-virtuoso-2.9.4-4.1.x86_64 virtuoso-server-6.1.6-7.1.2.x86_64 virtuoso-drivers-6.1.6-7.1.2.x86_64 paul@Orion-1:~$ rpm -qa | grep -i nepomuk python3-kde4-nepomuk-4.12.0-132.1.x86_64 libnepomukwidgets4-4.12.0-47.1.x86_64 nepomuk-core-4.12.0-85.1.x86_64 python-kde4-nepomuk-4.12.0-131.1.x86_64 Thanks Guys... |
Administrator
|
20 seconds is a rather unusual timeout period, as the default D-Bus timeout is 30 seconds. Do you see anything changing in ~/.xsession-errors during the time it takes to timeout?
Also, can you check to see if any Disk I/O is taking place during this 20 seconds?
KDE Sysadmin
[img]content/bcooksley_sig.png[/img] |
|
Registered Member
|
It's definitely 20s, so I guess that rules out any D-Bus problems...
As an aside, openSUSE 13.1 uses X.Org X Server 1.14.3.901 (1.14.4 RC 1) "This is a pre-release version of the X server from The X.Org Foundation. It is not supported in any way." I even checked the repos to make sure I'd not accidentally pulled in something from "Factory"...  ... Anyway, ".xsession-errors" now appears to be created differently ... at each login a file named ".xsession-errors-:0" is created afresh, overwriting the previous file.This is the last few (relevant) lines written on a delayed logout:
If prior to logout I disable nepomuk in system settings, this is what is written:
After which I am able to logout normally with no delay. Would I be correct in thinking I have a recalcitrant "nepomukstorage" that, for some reason does not close down at logout? Also, I don't see the relevance of the "kwin" timeout... this is getting above my skill level  Using iotop from a VT I'm not able to observe any disk I/O - but I'm sure there's a better way to check for that  Thanks... |
|
Administrator
|
Based on the log excerpts, it appears that Nepomuk is either hanging in the last moments of it's shutdown - leading to the 20 second timeout, or it is simply taking that long to finalise things.
It also appears that KWin is involved in this. As KWin uses Activities, and Activities uses Nepomuk, this is a plausible suspect for why your system might be taking longer than expected to shutdown. Could you try exiting KWin prior to initiating a logout (or simply exit kactivitymanagerd by running "kquitapp kactivitymanagerd") to see if that has any effect?
KDE Sysadmin
[img]content/bcooksley_sig.png[/img] |
|
Registered Member
|
Things I've tried...
Disabled all indexing. Backed up existing nepomukstrigirc and all data below virtuosobackend. Configured nepomuk to only index a single subdirectory containing 15 text files. Re-enabled indexing and checked that only those files were indexed. Logout - 20 second delay... Disable indexing and logout - no delay... As this is consistently 20 seconds I can't see it's nepomuk simply taking that length of time closing down. It would vary surely on each closedown? 17, 21, etc... "kquitapp kactivitymanagerd" before logout makes no difference. 20s still (actually timed, using the stopwatch function on a mobile phone...) I have other applications running at logout - Thunderbird, Dropbox and Yawp. Closing those before logout makes no difference. Using "kdebugdialog --fullmode" I've set "nepomuk (storage service)" and "kwin" to log info, warning and error to separate files - the file names I used are not being created, so I assume, no errors (?)... There doesn't appear to be anything relevant in /var/log... The only place anything is written is .xsession-errors-:0 --- Although almost identical to the previous log I posted this is a second, more complete. From cold boot, I logged in to the GUI, waited for a few minutes for startup activity to complete, then: copied .xsession-errors-:0 -> ~/prelogout.txt (using dolphin) logged out from GUI logged in from VT2 moved .xsession-errors-:0 -> ~/postlogout.txt Comparing prelogout to postlogout, the following lines were added:
Seeing that kmix got a mention, and finding the "Thou shalt..." mildly amusing, I tried closing that before logout. I didn't expect it to make any difference - and it didn't... I've googled, searched forums and various bugzillas - no sign of anyone else reporting this... I may have to live with this one... (just as I was thinking that nepomuk was finally really usable!) - Thanks so far 
|
|
Default dbus timeout is 25 secs.
Whatever blocks nepomuk, ksmserver will after 10 secs log clients that refused to die, kill the WM (granting it 5 seconds for that) and exit. Apparently "nepomukstorage" and "kwin" don't go down in time and this is related to nepomuk indexing, despite "nepomukfilewatch" and "nepomukfileindexer" terminate cleanly. Since the kactivitymanagerd is apparently out of the game and kwin does no other dbus calls, it'll not be blocking dbus (you can try running a simple "qdbus" while the logout hangs, if dbus blocks, it'll timeout) However, kwin will store session data to disk when exiting with the session, so i assume "something" will block disk I/O. -> What filesystem is your $HOME on? -> try running "iotop" (as root) to see whether and what stresses your HDD. |
|
Registered Member
|
Able to run qdbus several times (from VT2) whilst logout is in progress (GUI on VT7) My ignorance - what session data are you referring to? Session Management is set to "End current / Start with empty" ... but I feel you may mean something else. ext4, separate partition, only 11% used. (4GB memory, adequate for my needs, very very seldom see swap partition used) I'd tried that earlier, didn't look disk I/O was slowing things down. I've just repeated that several times, here's a typical log file created during logout. ( As another user on VT2: 'sudo/usr/sbin/iotop -btoqqq --delay=0.2 --iter=300 > ~/iotop-logout.log' ) http://paste.opensuse.org/bcbaf7e0 Relating to that particular log, there's some initial stuff when I switched back to the GUI. Then at 13:05:11 "Leave", 13:05:24 "Logout", 13:05:41 process kdm_greet is active. That correlates well with my timings for that log. Start iotop and timer, 00:00:15 "Leave", 00:00:25 "Logout", 00:00:48 KDM login screen appears. Thanks |
|
Ok, dbus is not generally blocked.
No, exactly that (positions and states of windows, stuff like that). I'm not 100% whether the information would just be stored regardless of the SM settings (would have to try whether it's called) Other than that, kwin would of course talk to X11 (should be no problem) and sync any config (eg. remember rule) changes to disk, however ...
Ok, I just wondered about nfs/smb blocking things here.
Mostly jbd2 (ext4 journal) and "mostly" is rather not "massively" Let's say: no general dbus block (and kwin isn't supposed to dbus on exit anyway), no local nor network I/O blocks. Let's ignore kwin for the moment. Whyever it doesn't stop, it seems related to whatever causes file indexing causes and i'd rather bet on /usr/bin/nepomukstorage here. I just tried to run it (usually no file indexing here, mlocate is still fine  directly and it didn't respond to ctrl+c for seconds; when telling it to SIGTERM, i get "nepomukstorage(18627)/nepomuk (storage service): "Failed to start Virtuoso""iow: "suspicious enough" You could gdb attach the process and check what it does while not exiting. Is virtuoso-t still running while the logout hangs? |
|
Registered Member
|
 Did some very swift reading on gdb. That's higher up the learning curve than I've reached. If it's going to help solve this I'll happily give it a go... but I'll probably need the odd pointer along the way.  Yes, it would appear so... Prior to logout:  Almost immediately after logout is initiated:  Which, by repeating the command from VT2 until I'm returned to the GUI on VT7, is how it stays... Thanks once more. Appreciate the help. Won't be around for a day or two now. If you're celebrating the New Year, do have a good one! 
|
|
you can also redirect gdb output (helpful from eg. VT1)
if gdb yells a warning about ptrace and not allowed, you want (as root)
|
|
Registered Member
|
Hmmm... OK
There is apparently no output from the "bt" command -- until a fraction of a second before I'm returned to the kdm login screen. This is the result. ( The entire output log is here: http://pastebin.kde.org/p3b83ffc9 ) Backtrace:
Now, I have no experience of interpreting a backtrace  The mention of "waitForFinished" and 30000ms on lines #3 and #4 caught my eye... probably irrelevant though. Thanks yet again... |
|
Soprano::VirtuosoController::shutdown() sends a SIGINT to virtuoso-t and then wants to wait up to 30 seconds until virtuoso-t has synced data and exited - apparently that's the issue.
try "pkill -SIGINT virtuoso-t" before shutting down and see how long virtuoso-t remains afterwards: while true; do ps ax | grep virtuoso; sleep 0.5; done |
|
Registered Member
|
Issuing that doesn't seem to have any effect. [1] I'm getting (pid) "tty2 S+ 0:00 grep --color=auto virtuoso" creeping in... so the while loop never terminates  Nonetheless, repeating it a few times this is typical of the result. 28-30 lines output where virtuoso-t is running, so around 14-15 seconds.
1. Independent of this test I also tried sending an INT whilst watching from System Monitor. No apparent activity at all. Sending either TERM or KILL simply results in nepomukstorage spawning another virtuoso-t to replace the TERM/KILL one. Just to restate a couple of earlier comments: Upgraded openSUSE 12.3 to 13.1 (with KDE 4.11.3) which is when this problem appeared. Upgraded KDE to 4.12.0 and problem still persists. I've tried with a new freshly created database, indexing only a handful of files, and the delay is unchanged. Thanks for sticking with me on this one
|
|
The result of sending the INT is the termination after 14-15 seconds, what is > the 10 seconds that the sessionmanager grants you and likely the cause of the logout hang.
So the next question would be why virtuoso-t takes so long to quit (while "long" is relative, given that the controller grants it 30 seconds) Do you have stuff like "virtuoso-t:12345 blocked for more than 120 seconds" in dmesg (12345 being a fake PID) |
|
Registered Member
|
"dmesg | grep virtuoso" -- returns nothing.
I had at an early stage looked at the log files in /var/log and found nothing of relevance; just checked again... nothing. ".xsession-errors-:0" is the only file being written to. "soprano-virtuoso.log" only has the odd "checkpoint whilst atomic" message. An interesting(?) discovery...  I intended going over a few things, late last night when closing down the PC I'd (unintentionally) left nepomuk disabled. Today, realising that, on next startup I re-enabled nepomuk. Logging out a while later did NOT have the delay. Login again, logout and the delay returns. I'm able to consistently reproduce this. If I disable nepomuk, logout, re-login, enable nepomuk, and then logout; this initial logout is NOT delayed. Subsequent login/logouts have the logout delay. I repeated it to confirm that nepomuk/virtuoso WAS running. Here's an extract from xsession-errors for one of those initial logouts.
I've discovered the "X Error: BadWindow" occurs when I close System Monitor. Which is what I had then done, followed by leave/logout. The three nepomuk processes all exited normally and there was no delay. Other stuff just for information: I don't use Akonadi. (StartServer=false in akonadiserverrc) There are 19,752 files indexed, and the current soprano-virtuoso*.* file sizes are: *.db 262.0 MiB *temp.db 2.0 MiB *.trx 8.9 KiB Using a new database of only 10 MiB and 15 indexed files behaved identically. I wondered if the OS/KDE update resulted in virtuoso's .ini file being altered... However I can only find (lots of) old ones in /tmp - is there a virtuoso*.ini file, or is it created dynamically by nepomukstorage/soprano whatever. This is the "Parameters" section of one from /tmp - they're all identical. Haven't got a pre update one, so unable to see if anything changed. I think it's irrelevant anyway.
Again -- Thanks for the help.
|
Bookmarks
Who is online
Registered users: Bing [Bot], Google [Bot], Sogou [Bot], Yahoo [Bot]
