我们有一个application运行时的速度离我们的预期有距离。在多线程的高并发应用程序中,我们可能怀疑是由于资源竞争导致过多的“等待”。
-bash-3.00$ prstat -mp 21746
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP
21746 arrowpig 0.0 0.0 0.0 0.0 0.0 76 24 0.0 142 0 151 0 httpd/17
使用-m参数要求prstat显示进程的微状态。注意到LCK=76,表示在进程的运行过程中,有76%的时间用在了等待用户级锁上(The percentage of time the process has spent processing text page faults.)
-bash-3.00$ prstat -p 21746
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
21746 arrowpig 16M 9380K cpu9 59 0 15:30:55 25% httpd/17
注意到,该应用程序的CPU消耗只有25%,也就是说应用程序完全有能力运行得更快。
那下一步就是确定到底是什么操作造成了大量的锁等待!我们使用plockstat 。
-bash-3.00$ sudo plockstat -p 21746 > result.txt
Ctrl+C
0
Mutex hold
Count nsec Lock Caller
——————————————————————————-
254397 3755 libc.so.1`libc_malloc_lock libstdc++.so.6`_Znwm+0×20
38401 4258 libc.so.1`libc_malloc_lock libarrowpig.so`_ZN7Arrowpig14IsGoodManC1Ev+0×90
…
Mutex block
Count nsec Lock Caller
——————————————————————————-
54500 1986382 libc.so.1`libc_malloc_lock libc.so.1`free+0×18
35365 1978442 libc.so.1`libc_malloc_lock libc.so.1`malloc+0×25
154795 152279 libc.so.1`libc_malloc_lock libc.so.1`free+0×18
138134 108478 libc.so.1`libc_malloc_lock libc.so.1`malloc+0×25
310 1594997 libc.so.1`libc_malloc_lock libc.so.1`realloc+0×42
1310 55278 libc.so.1`libc_malloc_lock libc.so.1`realloc+0×42
…
在result.txt中共分成两部分,第一部分是Mutex hold,其实我们并不关心Mutex Hold,他们只是hold了mutex而阻塞别人而已,我们关心的是Mutex Block,这部分给出了所有被阻塞的情况。这里,我们看到很多阻塞发生在malloc和free中,由此我们怀疑到我们链接的libc库是单线程的,在多线程应用程序中我们应该使用多线程的malloc和free。
关于在Solaris下多线程malloc/free的使用,可以参见A Comparison of Memory Allocators in Multiprocessors
最后,当我们使用libumem来运行应用程序,prstat -mp显示,LCK从76降到30。
-bash-3.00$ LD_PRELOAD=libumem.so.1 httpd &
注意,我们启动libumem的时候没有使用UMEM_DEBUG=default UMEM_LOGGING=transaction。因为我们在这里不需要使用mdb debug应用程序。我们需要的只是要求应用程序使用libumem的malloc/free。关于libumem,我写过5篇文章来介绍。