#256 Excessive CPU when in background

Other
open
nobody
None
5
2003-09-10
2003-09-10
Gavin Sherlock
No

Hi,

I have XFree86 4.3 installed from the xfree86 binaries on
OSX 10.2.6. I use it in rooted mode, in conjunction with
gnome and sawfish. Sometimes, when it is in the
background, and I'm working in a Mac app, I notice that
there is excessive CPU usage (>100% on a dual G4), which
top attributes to XDarwin. This doens;t happen every time,
but it has happened on many occasions. Switching to
XDarwin and back usually cures it. Anyway, as I noticed it
today, I thought I'd sample the process, in case it was any
use to you. The results are below:

SW-90-732-818-2 112 % top -d

398 CPU Monito 0.9% 2:01.87 8 0/0 40/28
0/70 20
576 panel-real 0.9% 0:03.90 0 0/0 0/0
22/0 13

Processes: 67 total, 3 running, 64 sleeping... 151 threads
10:52:18
Load Avg: 1.48, 1.25, 1.06 CPU usage: 16.5% user,
46.6% sys, 36.9% idle
Networks: 29 ipkts/19K 0 opkts /1K
Disks: 0 reads/0K 0 writes/0K
VM: 0 pageins 0 pageouts

PID COMMAND %CPU TIME FAULTS PGINS/COWS
MSENT/MRCVD BSD/MACH CSW
510 XDarwin 103.9% 1:46.76 0 0/0 0/0
77878/51 574
507 iTunes 8.7% 6:57.68 1 0/0 79/50
5/750 272
188 Window Man 5.8% 9:02.23 27 0/0 384/163
0/727 259
442 Adobe Read 1.9% 2:30.80 1 0/1 128/4
8/268 200
399 Terminal 1.9% 0:11.15 3 0/0 23/21
9/49 13
635 top 1.9% 0:00.27 154 0/4 729/726
104/861 128
0 kernel_tas 0.9% 2:30.91 0 0/0 1153/983
0/0 1449
506 Safari 0.0% 14:48.27 0 0/0 3/2
1/10 3
394 Mail 0.0% 4:08.75 0 0/0 0/0 0/
0 0
398 CPU Monito 0.0% 2:01.87 6 0/0 40/28
0/70 17
591 Microsoft 0.0% 1:12.56 2 0/1 12/0
0/470 38
184 ATSServer 0.0% 0:45.78 8 0/0 14/14
16/26 15
391 SystemUISe 0.0% 0:25.39 1 0/0 11/10
1/22 7
392 Finder 0.0% 0:25.65 0 0/0 0/0
0/0 0
390 Dock 0.0% 0:16.84 0 0/0 12/0
0/18 12
113 configd 0.0% 0:12.64 0 0/0 0/0
0/0 0
587 Microsoft 0.0% 0:11.13 1 0/1 8/1
0/44 27
278 lookupd 0.0% 0:07.82 0 0/0 0/0
0/0 0
273 netinfod 0.0% 0:05.11 0 0/0 0/0
0/0 0
400 X-Assist 0.0% 0:04.45 0 0/0 0/0
0/0 0

SW-90-732-818-2 113 % sample XDarwin 5
Sampling process 510 each 10 msecs 500 times
2003-09-10 10:52:27.015 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.078 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.099 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.142 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.205 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.267 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.288 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:27.714 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:28.160 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:29.155 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:29.176 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:29.197 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:29.218 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.171 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.234 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.255 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.276 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.297 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.318 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.360 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.381 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.666 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.687 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.709 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.730 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
2003-09-10 10:52:30.751 sample[636] thread_read_stack:
stack appears to be in inconsistent state to trace.
Truncating stack.
Sample analysis of process 510 written to file /tmp/
XDarwin_510.sample.txt
SW-90-732-818-2 114 % more /tmp/
XDarwin_510.sample.txt
Analysis of sampling pid 510 every 10 milliseconds
Call graph:
500 Thread_1c03
474 start
474 _start
474 main
474 DarwinHandleGUI
474 NSApplicationMain
474 -[NSApplication run]
474 -[NSApplication
nextEventMatchingMask:untilDate:inMode:dequeue:]
474 _DPSNextEvent
474 BlockUntilNextEventMatchingListInMode
474 ReceiveNextEventCommon
474 RunCurrentEventLoopInMode
474 CFRunLoopRunSpecific
474 __CFRunLoopRun
474 mach_msg
473 mach_msg_trap
473 mach_msg_trap [STACK TOP]
1 mach_msg [STACK TOP]
26 AVLInsertInSubtree
24 _sigtramp
24 _sigtramp [STACK TOP]
2 mach_msg
2 _sigtramp
1 SmartScheduleTimer
1 __error
1 __error [STACK TOP]
1 _sigtramp [STACK TOP]
500 Thread_1d03
500 _pthread_body
500 forkThreadForFunction
500 -[XServer run]
500 main
500 Dispatch
500 WaitForSomething
416 select
416 select [STACK TOP]
45 BlockHandler
35 QuartzBlockHandler
16 NSPopAutoreleasePool
6 NSPopAutoreleasePool [STACK TOP]
3 _NSCurrentThread
2 __udivmoddi4
2 __udivmoddi4 [STACK TOP]
1 _NSCurrentThread [STACK TOP]
2 _NSRemoveHandler2
2 _NSRemoveHandler2 [STACK TOP]
2 _setjmp
2 _setjmp [STACK TOP]
1 _NSAddHandler2
1 _NSCurrentThread
1 pthread_getspecific
1 pthread_getspecific [STACK TOP]
1 __kCFAllocatorSystemDefault
1 _NSRemoveHandler2
1 _NSRemoveHandler2 [STACK TOP]
1 __udivmoddi4
1 __udivmoddi4 [STACK TOP]
8 -[NSAutoreleasePool initWithCapacity:]
4 _NSCurrentThread
4 pthread_getspecific
4 pthread_getspecific [STACK TOP]
3 NSPushAutoreleasePool
2 _NSCurrentThread
2 pthread_getspecific
2 pthread_getspecific [STACK TOP]
1 NSPushAutoreleasePool [STACK TOP]
1 -[NSAutoreleasePool initWithCapacity:]
[STACK TOP]
5 +[NSAutoreleasePool allocWithZone:]
3 _NSCurrentThread
3 pthread_getspecific
2 pthread_getspecific [STACK TOP]
1 __gcc_bcmp
1 __gcc_bcmp [STACK TOP]
2 +[NSAutoreleasePool allocWithZone:]
[STACK TOP]
2 objc_msgSend
2 objc_msgSend [STACK TOP]
1 NSPushAutoreleasePool
1 NSPushAutoreleasePool [STACK TOP]
1 XprintOptions
1 XprintOptions [STACK TOP]
1 _NSCurrentThread
1 _NSCurrentThread [STACK TOP]
1 _NSRemoveHandler2
1 _NSRemoveHandler2 [STACK TOP]
5 NSPopAutoreleasePool
4 NSPopAutoreleasePool [STACK TOP]
1 restFP
1 restFP [STACK TOP]
2 AnimCurScreenBlockHandler
2 AnimCurScreenBlockHandler [STACK TOP]
1 BlockHandler [STACK TOP]
1 miSpriteBlockHandler
1 miSpriteBlockHandler [STACK TOP]
1 shadowRedisplay
1 shadowRedisplay [STACK TOP]
26 GetTimeInMillis
25 gettimeofday
22 __ppc_gettimeofday
22 __ppc_gettimeofday [STACK TOP]
2 gettimeofday [STACK TOP]
1 __gcc_bcmp
1 __gcc_bcmp [STACK TOP]
1 0x1
1 gettimeofday
1 gettimeofday [STACK TOP]
7 WaitForSomething [STACK TOP]
2 WakeupHandler
2 WakeupHandler [STACK TOP]
2 bzero
2 bzero [STACK TOP]
1 SmartScheduleStartTimer
1 setitimer
1 setitimer [STACK TOP]
1 __error
1 __error [STACK TOP]

Total number in stack (recursive counted multiple, when
>=5):
6 _NSCurrentThread

Sort by top of stack, same collapsed (when >= 5):
mach_msg_trap [STACK TOP] 473
select [STACK TOP] 416
_sigtramp [STACK TOP] 25
__ppc_gettimeofday [STACK TOP] 22
NSPopAutoreleasePool [STACK TOP] 10
pthread_getspecific [STACK TOP] 9
WaitForSomething [STACK TOP] 7

Cheers, and keep up the great work!!!

Gavin

Discussion

  • Gavin Sherlock
    Gavin Sherlock
    2003-09-10

    Logged In: YES
    user_id=382329

    I uploaded the sample file, as the web page doesn't preserve its
    indentation

     
  • Gavin Sherlock
    Gavin Sherlock
    2003-09-10

    sample of XDarwin process

     
  • Logged In: YES
    user_id=133579

    Did you sample the process while you were getting anonmalously
    high CPU usage from XDarwin? Looking at your call stack, XDarwin
    is just sitting there waiting for an event. One thread is blocked in
    mach_msg_trap and the other in select. It shouldn't be using CPU
    time at all. Switching to XDarwin will cause it to wake up and
    process a few events. Perhaps, the statistics from top have a
    problem? Were there any symptoms of some process hogging the
    CPU at the time?

     
  • Gavin Sherlock
    Gavin Sherlock
    2003-11-14

    Logged In: YES
    user_id=382329

    Yeah - I definitely sampled while the excessive CPU was seen.
    The CPU monitor alerted me to the excessive CPU, and top
    confirmed it. While it's possible that it was erroneously reporting
    XDarwin as the culprit, I do think it was correct. Switching to
    XDarwin and back cured the excess CPU usage. I'd say I've seen
    this dozens of times, and always swicthing into XDarwin and back
    cures it. I've now upgraded to Panther, meaning I had to switch to
    Apple's X11, so until XDarwin based on xfree4.4 won't be able to
    test again,

    Cheers,
    Gavin

     
  • Logged In: YES
    user_id=133579

    Any updates on this problem with XFree86 4.4.0?