Re: [9fans] 9vx - os x fix

["andrey mirtchovski" <mirtchovski@gmail.com>]

trying to answer my own question about high cpu load, it looks like
9vx is busy switching all the time. if anyone knows these tracing
facilities better, please step up :)

dappprof (profiles execution, elapsed time is in nanoseconds):

CALL                                                       ELAPSED
libSystem.B.dylib swtch_pri                                67472182
libSystem.B.dylib sched_yield                              75788623
9vx.OSX          unlock                                  297823144
9vx.OSX          lock                                    362717059
9vx.OSX          canlock                                 516405744
libSystem.B.dylib pthread_getspecific                42273900861098
9vx.OSX          getmach                            46118238370761
libSystem.B.dylib pthread_cond_wait                  65330580967450
libSystem.B.dylib _pthread_cond_wait                222897259712785
9vx.OSX          __i686.get_pc_thunk.bx           1256657382372551

dapptrace (traces execution, only a small fragment is listed, without
thread ids):

-> libSystem.B.dylib:sched_yield(0xF30E0, 0xF30E0, 0xB038CE88)
-> libSystem.B.dylib:swtch_pri(0x0, 0x0, 0x0)
-> libSystem.B.dylib:_sysenter_trap(0x93846BC1, 0x0, 0x0)
<- libSystem.B.dylib:swtch_pri = 10
<- libSystem.B.dylib:sched_yield = 21
-> 9vx.OSX:canlock(0xF30E0, 0xF30E0, 0xB038CE88)
-> 9vx.OSX:__i686.get_pc_thunk.bx(0x0, 0x0, 0x0)
<- 9vx.OSX:__i686.get_pc_thunk.bx = 3
-> 9vx.OSX:getmach(0x0, 0x0, 0x0)
-> 9vx.OSX:__i686.get_pc_thunk.bx(0x101, 0x0, 0x0)
<- 9vx.OSX:__i686.get_pc_thunk.bx = 3
-> libSystem.B.dylib:pthread_getspecific(0x101, 0x0, 0x0)
<- libSystem.B.dylib:pthread_getspecific = 12
<- 9vx.OSX:getmach = 31
-> 9vx.OSX:getmach(0x0, 0x0, 0x0)
-> 9vx.OSX:__i686.get_pc_thunk.bx(0x101, 0x0, 0x0)
<- 9vx.OSX:__i686.get_pc_thunk.bx = 3
-> libSystem.B.dylib:pthread_getspecific(0x101, 0x0, 0x0)
<- libSystem.B.dylib:pthread_getspecific = 12
<- 9vx.OSX:getmach = 31
<- 9vx.OSX:canlock = 104
-> libSystem.B.dylib:sched_yield(0xF30E0, 0xF30E0, 0xB038CE88)
-> libSystem.B.dylib:swtch_pri(0x0, 0x0, 0x0)
-> libSystem.B.dylib:_sysenter_trap(0x93846BC1, 0x0, 0x0)
<- libSystem.B.dylib:swtch_pri = 10
<- libSystem.B.dylib:sched_yield = 21

a gdb backtrace:

(gdb) attach 25798
Attaching to process 25798.
Reading symbols for shared libraries . done
Reading symbols for shared libraries ....... done
0x9380a390 in _pthread_cond_wait ()
(gdb) bt
#0  0x9380a390 in _pthread_cond_wait ()
#1  0x93850371 in pthread_cond_wait ()
#2  0x0000abc6 in idlehands () at 9vx/sched.c:47
#3  0x000419cd in _runproc () at 9vx/a/proc.c:542
#4  0x00043696 in sched () at 9vx/a/proc.c:165
#5  0x00009e48 in main (argc=2, argv=0xbffff6ac) at 9vx/main.c:178
(gdb) info thread
Thread 0x10b (local 0xf03) has current state "WAITING"
Thread 0x10b has a suspend count of 0.
(gdb) info threads
  9 process 25798 thread 0x1803  0x937d858a in swtch_pri ()
  8 process 25798 thread 0x1703  0x937d858a in swtch_pri ()
  7 process 25798 thread 0x1603  canlock (l=0xf30e0) at 9vx/stub.c:300
  6 process 25798 thread 0x1503  0x937d858a in swtch_pri ()
  5 process 25798 thread 0x1403  0x937d858a in swtch_pri ()
  4 process 25798 thread 0x1103  0x937d858a in swtch_pri ()
  3 process 25798 thread 0x1003  0x9384e24a in __sigwait ()
  2 process 25798 thread 0xf03  0x9383fbf6 in poll$UNIX2003 ()
* 1 process 25798 thread 0x10b  0x9380a390 in _pthread_cond_wait ()
(gdb)

and an sc_usage run (sc_usage traces system calls, i'm including it
here because it lists what the different threads are doing,
unfortunately you need to see it run interactively to get an idea of
what's happening):

TYPE                            NUMBER        CPU_TIME   WAIT_TIME
------------------------------------------------------------------------------
System         Idle                                      0:00.000
System         Busy                                      0:11.684( 0:00.613)
9vx.OSX        Usermode                       0:16.647

swtch_pri                     72985(5840)     0:00.165   1:25.690( 0:05.028) 4
select_nocancel                  70(1)        0:00.000   0:00.844( 0:00.014)


CURRENT_TYPE              LAST_PATHNAME_WAITED_FOR     CUR_WAIT_TIME THRD# PRI
------------------------------------------------------------------------------
swtch_pri                                                     0:00.011   0   0
swtch_pri                                                     0:00.011   1   0
Pre-empted                                                    0:00.001   2   0
Running U                                                     0:00.001   3  30
swtch_pri                                                     0:00.011   4   0
swtch_pri                                                     0:00.011   5   0