[Userland-team] [OpenIndiana Distribution - Bug #1987] dbus taking 100% of cpu
illumos project
devnull at illumos.org
Wed May 23 10:18:49 UTC 2012
Issue #1987 has been updated by Richard PALO.
interesting messages from gdm debug during a session logout that resulted in the famous dbus process eating cpu...
<pre>
May 23 11:59:38 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.421
May 23 11:59:38 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.421', old_service_name=':1.421' new_service_name=''
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get current session
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get session for unix process: 3508
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get session for cookie
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:42 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: Found session '/org/freedesktop/ConsoleKit/Session66'
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get current session
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get session for unix process: 3508
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: get session for cookie
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: uid = 202
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: pid = 3508
May 23 11:59:43 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: CkManager: Found session '/org/freedesktop/ConsoleKit/Session66'
May 23 11:59:44 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.418
May 23 11:59:44 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.418', old_service_name=':1.418' new_service_name=''
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.416
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.416', old_service_name=':1.416' new_service_name=''
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: child (pid:3508) done (status:0)
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: Calling SessionExited
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): session_message_handler: destination=(null) obj_path=/org/gnome/DisplayManager/Session interface=org.gnome.DisplayManager.Session method=SessionExited
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionDirect: Emitting 'session-exited' signal with exit code '0'
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): Writing logout record
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_type DEAD_PROCESS
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_tv time 1337767195
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_pid 3508
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_id ::ff
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: uninitializing PAM
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_host ::ffff:127.0.0.1::ffff:127.0.0.1:0
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): using ut_line dtremote
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): Writing wtmp logout record to /var/adm/wtmpx
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): Removing utmp record
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSimpleSlave: session exited with code 0
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Copying user dmrc file to cache
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Trying script /etc/gdm/PostSession/::ffff:127.0.0.1:0
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script /etc/gdm/PostSession/::ffff:127.0.0.1:0 not found; skipping
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: Checking if /home/sonia/.dmrc should be copied to cache /var/cache/gdm/sonia/dmrc
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Trying script /etc/gdm/PostSession/::ffff:127.0.0.1
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script /etc/gdm/PostSession/::ffff:127.0.0.1 not found; skipping
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Trying script /etc/gdm/PostSession/Default
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Destination file is newer
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Running process: /etc/gdm/PostSession/Default
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.415
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Not copying file /home/sonia/.dmrc to cache
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing session for cookie: 29cf1aac9c32865f9da7044b4cf27d81-1337753504.793880-2099813755
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: X_SERVERS=/var/gdm/::ffff:127.0.0.1:0.Xservers
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Copying user face file to cache
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Emitting session-removed: /org/freedesktop/ConsoleKit/Session66
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: XAUTHORITY=/tmp/gdm-auth-cookies-CmaWDe/auth-for-gdm-3maWDe/database
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: LOGNAME=sonia
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: Checking if /home/sonia/.face should be copied to cache /var/cache/gdm/sonia/face
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: PWD=/home/sonia
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: HOME=/home/sonia
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: DISPLAY=::ffff:127.0.0.1:0
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): File does not exist
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: REMOTE_HOST=::ffff:127.0.0.1
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: PATH=/usr/bin
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: SHELL=/usr/bin/bash
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Not copying file /home/sonia/.face to cache
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: RUNNING_UNDER_GDM=true
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: USER=sonia
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: script environment: USERNAME=sonia
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: Checking if /home/sonia/.face.icon should be copied to cache /var/cache/gdm/sonia/face
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Running programs in /etc/ConsoleKit/run-session.d for action session_removed
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): File does not exist
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Running programs in /usr/lib/ConsoleKit/run-session.d for action session_removed
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Not copying file /home/sonia/.face.icon to cache
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Got uid: 0
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): Checking user's ~/.gnome/gdm file
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): File does not exist
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Writing log for event: 1337767195.554 type=SEAT_SESSION_REMOVED : seat-id='XDMCP__ffff_127_0_0_1_0' session-id='Session66' session-type='' display-type='' session-x11-display='' session-x11-display-device='' session-display-device='' session-remote-host-name='' session-is-local=FALSE session-unix-user=0 session-creation-time='2012-05-23T06:11:44.856368Z'
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.crit] GLib-GObject-CRITICAL: file gobject.c: line 2396: assertion `G_IS_OBJECT (object)' failed
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.415', old_service_name=':1.415' new_service_name=''
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplayStore: Unreffing display: 80bf0d8
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: state NONE
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Process exit status: 0
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): slave finished
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSimpleSlave: Stopping simple_slave
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Stopping slave
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Disconnected from display
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionDirect: Closing session
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorkerJob: Stopping job pid:3501
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmCommon: sending signal 15 to process 3501
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: obj_path=/org/freedesktop/DBus/Local interface=org.freedesktop.DBus.Local method=Disconnected
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorkerJob: Waiting on process 3501
May 23 11:59:55 smicro gdm-session-worker[3501]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorker: Got disconnected from the server
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.414
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.414', old_service_name=':1.414' new_service_name=''
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmCommon: process (pid:3501) done (status:1)
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorkerJob: Wait on child process failed
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionWorkerJob: SessionWorkerJob died
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionDirect: Disposing session
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionDirect: Closing session
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSessionDirect: Disconnected from display
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSlave: Stopping slave
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): GdmSignalHandler: Finalizing signal handler
May 23 11:59:55 smicro gdm-simple-slave[3459]: [ID 702911 daemon.warning] DEBUG(+): Slave finished
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.410
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.410', old_service_name=':1.410' new_service_name=''
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmSlaveProxy: slave (pid:3459) done (status:0)
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplay: Slave exited: 0
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplay: Finishing display: /org/gnome/DisplayManager/Display17
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmXdmcpDisplayFactory: xdmcp display status changed: 3
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplay: finish display
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplay: Unmanaging display
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmDisplay: unmanage display
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmSlaveProxy: Killing slave
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmSlaveProxy: Disposing slave proxy
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmSlaveProxy: Killing slave
May 23 11:59:55 smicro gdm-binary[2286]: [ID 702911 daemon.warning] DEBUG(+): GdmXdmcpDisplayFactory: xdmcp display status changed: 0
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.420
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.420', old_service_name=':1.420' new_service_name=''
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: Removing sessions for service name: :1.419
May 23 11:59:55 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: NameOwnerChanged: service_name=':1.419', old_service_name=':1.419' new_service_name=''
May 23 11:59:57 smicro console-kit-daemon[1928]: [ID 702911 daemon.warning] DEBUG: timeout for under request of session /org/freedesktop/ConsoleKit/Session55
</pre>
this last line look suspicious...
----------------------------------------
Bug #1987: dbus taking 100% of cpu
https://www.illumos.org/issues/1987
Author: Jeffrey Baitis
Status: New
Priority: Normal
Assignee: OI Userland
Category:
Target version: oi_151_stable
Difficulty: Medium
Tags: dbus
After my 151a machine had about 39 days of uptime with heavy X11 use, top noticed that dbus-daemon was taking 100% of the cpu time in one of my CPU cores. svcadm disable dbus did not seem to kill the rogue dbus-daemon; I had to kill it by pid manually.
I ran the Proc/dapptrace script from the DTrace toolkit. Here's the output that I got:
<pre>
CALL(args) = return
-> check_babysit_events(0x2CF8, 0x20, 0x1)
<- check_babysit_events = 177
-> _dbus_poll(0x8047490, 0x2, 0xFFFFFFFF)
<- _dbus_poll = 47
-> check_babysit_events(0x2CF8, 0x20, 0x1)
<- check_babysit_events = 177
-> _dbus_poll(0x8047490, 0x2, 0xFFFFFFFF)
<- _dbus_poll = 47
-> check_babysit_events(0x2CF8, 0x20, 0x1)
<- check_babysit_events = 177
-> _dbus_poll(0x8047490, 0x2, 0xFFFFFFFF)
<- _dbus_poll = 47
-> check_babysit_events(0x2CF8, 0x20, 0x1)
<- check_babysit_events = 177
-> _dbus_poll(0x8047490, 0x2, 0xFFFFFFFF)
<- _dbus_poll = 47
-> check_babysit_events(0x2CF8, 0x20, 0x1)
<- check_babysit_events = 177
-> _dbus_poll(0x8047490, 0x2, 0xFFFFFFFF)
<- _dbus_poll = 47
</pre>
... ad nauseam
--
You have received this notification because you have either subscribed to it, or are involved in it.
To change your notification preferences, please click here: http://www.illumos.org/my/account
More information about the Userland-team
mailing list