Monday, May 17, 2010

Poor Man's Profiler using Solaris' pstack

Recently I was working with the output of pstack from a hung MySQL server and wanted to use Poor Man's Profiler in order to combine stack traces. Unfortunately, the awk magic expects the output from gdb's thread apply all bt output.

gdb output:

Thread 10 (Thread 0xa644db90 (LWP 26275)):
#0 0xb7f47410 in __kernel_vsyscall ()
#1 0xb7f33b1a in do_sigwait () from /lib/tls/i686/cmov/libpthread.so.0
#2 0xb7f33bbf in sigwait () from /lib/tls/i686/cmov/libpthread.so.0
#3 0x081cc4fc in signal_hand ()
#4 0xb7f2b4fb in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#5 0xb7d25e5e in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 9 (Thread 0xa641cb90 (LWP 26273)):
#0 0xb7f47410 in __kernel_vsyscall ()
#1 0xb7d1e881 in select () from /lib/tls/i686/cmov/libc.so.6
#2 0x081d1190 in handle_connections_sockets ()
#3 0x081d1ef3 in main ()
...

pstack output:

----------------- lwp# 56 / thread# 56 --------------------
fffffd7ffed7bb7a sigtimedwait (fffffd7ffe3aee10, fffffd7ffe3aee20, 0)
fffffd7ffed6aced sigwait () + d
fffffd7ffed62740 __posix_sigwait () + 40
0000000000712dcd signal_hand () + 12d
fffffd7ffed7704b _thr_setup () + 5b
fffffd7ffed77280 _lwp_start ()
----------------- lwp# 53 / thread# 53 --------------------
fffffd7ffed7c6ca pollsys (fffffd732fe31dd0, 0, fffffd732fe31e60, 0)
fffffd7ffed234c4 pselect () + 154
fffffd7ffed23792 select () + 72
fffffd7ffe866008 os_thread_sleep () + 50
fffffd7ffea6dafb srv_lock_timeout_and_monitor_thread () + 1b3
fffffd7ffed7704b _thr_setup () + 5b
fffffd7ffed77280 _lwp_start ()
...

However, we can see how powerful and flexible PMP is by making a small change to the awk script and poof, we had the same output:


awk '
BEGIN { s = ""; }
/thread#/ { print s; s = ""; }
/^ [0-9a-f]/ { if (s != "" ) { s = s "," $2} else { s = $2 } }
END { print s }' | sort | uniq -c | sort -r -n -k 1,1


Yet another win for PMP.