From mboxrd@z Thu Jan 1 00:00:00 1970 Message-ID: <14ec7b180806270944x33b13f20tc396c841998b0eb8@mail.gmail.com> Date: Fri, 27 Jun 2008 10:44:53 -0600 From: "andrey mirtchovski" To: "Fans of the OS Plan 9 from Bell Labs" <9fans@9fans.net> In-Reply-To: MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <14ec7b180806270816t389b0794i1654ae3b6ed2a46d@mail.gmail.com> <20080627152937.4DA6A1E8C2B@holo.morphisms.net> Subject: Re: [9fans] 9vx - os x fix Topicbox-Message-UUID: c8b9df12-ead3-11e9-9d60-3106f5b1d025 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