Hi Dave, hmmm, I was kind of expecting this answer. Thanks for your analysis.
senthil On 7/1/08, [EMAIL PROTECTED] <[EMAIL PROTECTED]> wrote: > Ok, this pretty much verifies what I thought. In the short, by running > truss you have > slowed things down enough in the application to significantly remove the > lock contention > on the program's mutex. This is one of those performance items that > appears to be contradictory > on the surface. > > A bit more on this now: > > Your program has a very tight loop, you acquire the lock, increment a > variable and drop the > lock. There is a whole slew of atomic_* operations that essentially does > the same thing, just > more efficient (if they can be used depends on the case). > By being a tight loop as it is, during the operation of the program without > truss it ends up having > the threads queuing up on each other in attempt to acquire the lock. When > we miss on a lock because > it is owned by another thread we end up going into a totally different set > of lock routines which is > expensive. By running truss what you have done is slowed things down > enough to reduce the > lock contention being seen on the mutex in your program and the likeliness > of entering the "slow" lock > path. If you were to add work before or after the mutex operation you will > see the same effect, and probably > even to a greater degree. > Hope this helps. > > > Dave Valin > > senthil ramanujam wrote: > > > Hi Dave, > > > > Here is the plockstat data for both the cases. Let me know if you like > > to see more details. > > > > Looking forward to hear your comments. > > > > thanks. > > > > senthil > > > > > > $ plockstat -A mutex_ops -w4 -r10 > > number of threads:4, run-time (in seconds)=10 > > Thread 2: total ops: 456161, ops/second: 45616 > > Thread 0: total ops: 452104, ops/second: 45210 > > Thread 1: total ops: 167338, ops/second: 16733 > > Thread 3: total ops: 174826, ops/second: 17482 > > plockstat: pid 13497 has exited > > > > Mutex hold > > > > Count nsec Lock Caller > > > ------------------------------------------------------------------------------- > > 1248577 1639 mutex_ops`worker_mutex mutex_ops`do_run+0x1b2 > > 1851 1960 mutex_ops`worker_mutex mutex_ops`do_run+0x1b2 > > 3 104789 mutex_ops`_iob+0xa8 mutex_ops`do_run+0x25a > > 1 82008 libc.so.1`_uberdata+0xfc0 0x400e16 > > 1 42599 libc.so.1`_first_link_lock libc.so.1`_exithandle+0x3b > > 1 39967 libc.so.1`_uberdata+0x60 LM1`ld.so.1`rt_thr_init+0x29 > > 4 9374 libc.so.1`_uberdata+0x1040 libc.so.1`_lwp_start > > 4 8402 libc.so.1`_uberdata+0x40 libc.so.1`pthread_create+0x135 > > 1 32844 mutex_ops`_iob+0x28 libc.so.1`_exithandle+0x3b > > 3 9736 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > 4 6343 libc.so.1`_uberdata mutex_ops`main+0x2e7 > > 1 25319 mutex_ops`_iob+0xa8 mutex_ops`do_run+0x25a > > 4 6162 libc.so.1`_uberdata mutex_ops`main+0x22e > > 4 4369 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > 2 6982 mutex_ops`worker_mutex mutex_ops`do_run+0xea > > 6 1524 libc.so.1`_uberdata+0xd40 libc.so.1`exit+0x11 > > 1 8422 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > 4 1934 libc.so.1`_uberdata+0x1040 libc.so.1`_thrp_unwind+0x5e > > 1 7646 0xfffffd7fff220100 libc.so.1`_thr_exit_common+0x9c > > 2 3517 mutex_ops`worker_mutex mutex_ops`do_run+0xea > > 1 6603 libc.so.1`_uberdata+0xd40 libc.so.1`libc_init+0x2c6 > > 4 1516 libc.so.1`_uberdata+0x1000 libc.so.1`_thrp_unwind+0x5e > > 1 6029 0xfffffd7fff220080 libc.so.1`pthread_create+0x135 > > 1 5789 0xfffffd7fff220080 libc.so.1`_thr_exit_common+0x9c > > 1 4387 0xfffffd7fff2200c0 libc.so.1`pthread_create+0x135 > > 3 1447 libc.so.1`_uberdata+0xe80 libc.so.1`find_stack+0x18a > > 3 1396 libc.so.1`_uberdata libc.so.1`_thrp_create+0x531 > > 1 4078 0xfffffd7fff220100 libc.so.1`pthread_create+0x135 > > 3 1309 libc.so.1`_uberdata libc.so.1`pthread_create+0xfe > > 1 3900 0xfffffd7fff220140 libc.so.1`pthread_create+0x135 > > 1 3811 0xfffffd7fff2200c0 libc.so.1`_thr_exit_common+0x9c > > 1 3436 0xfffffd7fff220140 libc.so.1`_thr_exit_common+0x9c > > 1 2827 0xfffffd7fff220080 libc.so.1`pthread_create+0xfe > > 2 1367 libc.so.1`_uberdata+0xe40 libc.so.1`_thrp_unwind+0x5e > > 1 2369 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > 1 2341 mutex_ops`worker_mutex mutex_ops`do_run+0x1b2 > > 1 2311 libc.so.1`_uberdata+0x1040 LM1`ld.so.1`rt_thr_init+0x29 > > 1 2056 0xfffffd7fff220100 mutex_ops`main+0x2e7 > > 1 1951 0xfffffd7fff2200c0 mutex_ops`main+0x2e7 > > 1 1863 0xfffffd7fff220140 mutex_ops`main+0x2e7 > > 1 1803 0xfffffd7fff220140 libc.so.1`pthread_create+0xfe > > 1 1794 libc.so.1`_uberdata mutex_ops`main+0x22e > > 1 1782 0xfffffd7fff220100 libc.so.1`pthread_create+0xfe > > 1 1671 0xfffffd7fff2200c0 libc.so.1`pthread_create+0xfe > > 1 1622 mutex_ops`_iob+0xa8 libc.so.1`_exithandle+0x3b > > 1 1510 0xfffffd7fff220080 mutex_ops`main+0x2e7 > > 1 1508 libc.so.1`_uberdata+0xe80 libc.so.1`_thrp_create+0x531 > > 1 1506 libc.so.1`_uberdata+0xd40 0x400dbb > > 1 1495 libc.so.1`_uberdata+0xfc0 0x400dbb > > 1 1446 libc.so.1`_uberdata+0xfc0 libc.so.1`pthread_create+0xfe > > 1 1398 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > 1 1389 libc.so.1`_uberdata libc.so.1`pthread_create+0xfe > > 1 1370 libc.so.1`_uberdata+0xfc0 libc.so.1`pthread_create+0xfe > > 1 1347 libc.so.1`_uberdata+0xd40 0x400dc7 > > 1 1310 libc.so.1`_uberdata+0xfc0 0x400dc7 > > 1 1194 libc.so.1`_uberdata+0xfc0 libc.so.1`pthread_create+0xfe > > 1 1177 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > > > Mutex block > > > > Count nsec Lock Caller > > > ------------------------------------------------------------------------------- > > 866 21921703 mutex_ops`worker_mutex mutex_ops`do_run+0x150 > > 692495 8328 mutex_ops`worker_mutex mutex_ops`do_run+0x150 > > 2 11086954 mutex_ops`worker_mutex mutex_ops`do_run+0x94 > > 3 219879 mutex_ops`_iob+0xa8 libc.so.1`_flockget+0x1a > > 1 12013 libc.so.1`_uberdata mutex_ops`main+0x2e7 > > 1 2094 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > > > > > << trusss + mutex >> > > $ plockstat -A truss -fc mutex_ops -w4 -r10 > > number of threads:4, run-time (in seconds)=10 > > Thread 2: total ops: 17918909, ops/second: 1791890 > > Thread 0: total ops: 18518051, ops/second: 1851805 > > Thread 1: total ops: 18280090, ops/second: 1828009 > > Thread 3: total ops: 18889775, ops/second: 1888977 > > > > syscall seconds calls errors > > _exit .000 1 > > write .000 5 > > open .000 3 1 > > close .000 2 > > stat .000 10 7 > > getpid .000 1 > > fstat .000 1 > > ioctl .000 1 > > execve .000 1 > > lwp_park .634 94191 > > lwp_unpark .501 94191 > > sigaction .000 1 > > getcontext .000 1 > > setustack .000 5 > > mmap .000 16 > > munmap .000 2 > > getrlimit .000 1 > > memcntl .000 1 > > sysconfig .000 2 > > yield .082 12845 > > lwp_create .000 4 > > lwp_exit .000 4 > > lwp_continue .000 4 > > lwp_sigmask .000 4 > > lwp_private .000 1 > > lwp_wait .000 4 > > lwp_mutex_wakeup .000 10 > > nanosleep .000 1 > > schedctl .000 5 > > resolvepath .000 4 > > lwp_mutex_timedlock .000 68 > > getcwd .000 1 > > -------- ------ ---- > > sys totals: 1.219 201391 8 > > usr time: 17.809 > > elapsed: 10.030 > > plockstat: pid 13499 has exited > > > > Mutex hold > > > > Count nsec Lock Caller > > > ------------------------------------------------------------------------------- > > 257123 8166 truss`truss_lock truss`worker_thread+0x3a7 > > 145651 11250 truss`truss_lock truss`worker_thread+0x3a7 > > 201384 1893 truss`count_lock truss`sysexit+0x82d > > 1 2468522 libc.so.1`_uberdata+0x60 libproc.so.1`Pxcreate+0x63 > > 1 2447046 libnsl.so.1`_ti_userlock > > libnsl.so.1`_libnsl_parent_atfork+0x10 > > 1 2380540 libc.so.1`_uberdata+0xfc0 libc.so.1`fork+0x130 > > 1 2364179 libc.so.1`_first_link_lock libc.so.1`fork+0x130 > > 1 2356270 libc.so.1`libc_malloc_lock libc.so.1`fork+0x130 > > 1 2337553 libc.so.1`_uberdata+0x40 libproc.so.1`Pxcreate+0x63 > > 4 52074 0x455478 libproc.so.1`Lgrab+0x234 > > 1 144394 libc.so.1`_uberdata+0xfc0 truss`main_thread+0x1e8 > > 4 32702 truss`truss_lock truss`worker_thread+0x5d6 > > 5 23212 0x455478 libproc.so.1`Lfree+0x3a > > 1 66469 0xfef9e1b0 0xfef06df3 > > 1 64668 0xfefa12c0 0xfef67a91 > > 32 1858 truss`_iob+0xa8 truss`report+0x223 > > 1 58652 0x455478 libproc.so.1`Lgrab+0x234 > > 5 11034 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > 32 1583 truss`_iob+0xa8 truss`prtim+0x51 > > 32 1547 truss`_iob+0xa8 truss`report+0x25e > > 2 23108 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 32 1412 truss`_iob+0xa8 truss`prtim+0x64 > > 1 40708 0xfefa12a0 0xfef021df > > 1 40112 libc.so.1`_uberdata+0x60 LM1`ld.so.1`rt_thr_init+0x29 > > 1 34837 libc.so.1`_first_link_lock libc.so.1`_exithandle+0x3b > > 5 6891 truss`truss_lock truss`main_thread+0x116 > > 1 34270 0xfef9e5d0 0xfef14052 > > 4 8244 libc.so.1`_uberdata+0x40 truss`worker_thread+0xe52 > > 1 31319 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 5 6235 libc.so.1`_uberdata truss`main_thread+0x125 > > 4 7557 libc.so.1`libc_malloc_lock libproc.so.1`Lgrab+0xd3 > > 5 6010 libc.so.1`_uberdata+0x1040 libc.so.1`_lwp_start > > 1 29687 libc.so.1`libc_malloc_lock truss`main+0x4ac > > 1 28272 libc.so.1`mktemp_lock.0 truss`main+0xdb4 > > 1 26436 truss`truss_lock truss`worker_thread+0x5d6 > > 1 25322 truss`_iob+0xa8 libc.so.1`_exithandle+0x3b > > 1 25197 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 4 6142 libc.so.1`_uberdata truss`worker_thread+0xe34 > > 1 21847 libc.so.1`libc_malloc_lock truss`my_calloc+0x18 > > 1 19740 libproc.so.1`minfd_lock.0 libproc.so.1`set_minfd+0x46 > > 1 17725 0xfffffd7fff060140 libc.so.1`_thr_exit_common+0x9c > > 1 14834 libc.so.1`libc_malloc_lock truss`free_private+0x44 > > 5 2865 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 12900 0xfffffd7fff200080 truss`Xcritical+0x46 > > 5 2470 libc.so.1`_uberdata > libc.so.1`_thr_exit_common+0x9c > > 1 12239 libc.so.1`__sbrk_lock > libc.so.1`_malloc_unlocked+0x10d > > 1 12155 0xfef9e1f0 0xfef0703b > > 1 12062 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 6 2004 truss`count_lock truss`worker_thread+0x108a > > 1 11918 libc.so.1`_uberdata+0x40 truss`main_thread+0x1ed > > 5 2347 truss`count_lock truss`worker_thread+0xb09 > > 1 11608 0xfef9f708 0xfef26ac9 > > 5 2215 libc.so.1`libc_malloc_lock > libproc.so.1`Lfree_internal+0x67 > > 1 10685 libc.so.1`update_lock libctf.so.1`_libctf_init+0x10 > > 1 10092 libc.so.1`_uberdata libproc.so.1`Pxcreate+0x63 > > 5 2016 libc.so.1`_uberdata+0x1040 libc.so.1`_thrp_unwind+0x5e > > 1 9656 0x455478 libproc.so.1`Pfree+0x117 > > 2 4810 libc.so.1`__sbrk_lock libc.so.1`realloc+0x235 > > 5 1871 0xfffffd7fff200080 truss`Xcritical+0x46 > > 6 1543 libc.so.1`_uberdata+0xd40 libc.so.1`exit+0x11 > > 5 1744 libc.so.1`libc_malloc_lock truss`free_private+0x55 > > 5 1738 libc.so.1`_uberdata+0x1000 libc.so.1`_thrp_unwind+0x5e > > 5 1688 libc.so.1`libc_malloc_lock truss`free_private+0x66 > > 1 8407 truss`count_lock truss`setup_basetime+0x60 > > 1 8252 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 2 4044 libc.so.1`__sbrk_lock libc.so.1`malloc+0x2d > > 1 8072 libc.so.1`libc_malloc_lock libproc.so.1`Lgrab+0x72 > > 5 1612 libc.so.1`_uberdata+0x1000 libc.so.1`_thrp_unwind+0x5e > > 1 8046 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 5 1543 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 2 3818 libc.so.1`__sbrk_lock libc.so.1`realloc+0x235 > > 4 1897 libc.so.1`_uberdata libc.so.1`thr_create+0x3f > > 1 7516 0xfef9e5d0 0xfef14052 > > 5 1497 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 7375 0xfffffd7fff060080 truss`main_thread+0x1ed > > 1 7372 libc.so.1`_uberdata truss`create_thread+0x58 > > 1 6977 libc.so.1`_uberdata+0xd40 libc.so.1`libc_init+0x2c6 > > 1 6664 0xfefa1f80 0xfef63d56 > > 4 1663 libc.so.1`_uberdata+0xe80 libc.so.1`find_stack+0x18a > > 1 6569 0xfffffd7fff060180 libc.so.1`_thr_exit_common+0x9c > > 2 3186 libc.so.1`__sbrk_lock libc.so.1`malloc+0x2d > > 1 6260 libc.so.1`_uberdata+0x1000 truss`main+0xf8 > > 1 5847 libc.so.1`libc_malloc_lock libproc.so.1`Lgrab+0xd3 > > 1 5799 libc.so.1`_uberdata+0x60 > libnsl.so.1`_libnsl_lock_init+0x86 > > 1 5664 0xfffffd7fff060140 truss`worker_thread+0xe52 > > 1 5502 0xfefa2240 0xfef734b2 > > 4 1338 libc.so.1`_uberdata libc.so.1`_thrp_create+0x531 > > 1 5248 0xfffffd7fff0600c0 truss`worker_thread+0xe52 > > 1 5204 libc.so.1`__sbrk_lock > libc.so.1`_malloc_unlocked+0x10d > > 1 5141 truss`count_lock truss`per_proc_init+0xe1 > > 1 5105 0xfefa10e0 0xfef62237 > > 1 4904 0xfefa10e0 0xfef62237 > > 3 1613 libc.so.1`libc_malloc_lock truss`free_private+0x44 > > 1 4403 libc.so.1`_uberdata+0x140 truss`main+0xbeb > > 1 4245 0xfffffd7fff060100 truss`worker_thread+0xe52 > > 1 3702 0xfffffd7fff0600c0 libc.so.1`_thr_exit_common+0x9c > > 1 3469 truss`_iob+0xa8 truss`report+0x418 > > 2 1702 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 3396 0xfffffd7fff060100 libc.so.1`_thr_exit_common+0x9c > > 2 1641 libc.so.1`_uberdata+0xe40 libc.so.1`_thrp_unwind+0x5e > > 2 1514 truss`_iob+0xa8 truss`report+0x366 > > 2 1477 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 2 1369 libc.so.1`libc_malloc_lock truss`sysentry+0x4e7 > > 1 2653 0xfffffd7fff060080 libc.so.1`thr_create+0x3f > > 1 2646 libc.so.1`_uberdata+0x140 truss`main+0xbff > > 1 2528 truss`truss_lock truss`main_thread+0x116 > > 1 2470 libc.so.1`_uberdata+0x580 truss`main+0x554 > > 1 2452 0xfffffd7fff200080 truss`Xcritical+0x46 > > 1 2391 0xfffffd7fff060080 libc.so.1`_thr_exit_common+0x9c > > 1 2223 libc.so.1`_uberdata+0x440 truss`main+0x545 > > 1 2219 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 2203 libc.so.1`_uberdata+0x4c0 truss`main+0x518 > > 1 2187 libc.so.1`_uberdata+0x500 truss`main+0x527 > > 1 2185 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > 1 2182 0xfefa2280 0xfef73271 > > 1 2127 0xfffffd7fff060080 truss`main_thread+0x125 > > 1 2113 0xfffffd7fff060180 truss`worker_thread+0xe52 > > 1 2090 libc.so.1`_uberdata+0x1040 LM1`ld.so.1`rt_thr_init+0x29 > > 1 2082 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 2072 libc.so.1`_uberdata+0x540 truss`main+0x536 > > 1 2057 libc.so.1`_uberdata+0x180 truss`main+0xc0e > > 1 2041 libc.so.1`_uberdata+0x1c0 truss`main+0xc31 > > 1 2035 0xfffffd7fff060140 truss`main_thread+0x125 > > 1 2013 0xfffffd7fff060140 libc.so.1`thr_create+0x3f > > 1 1968 libc.so.1`libc_malloc_lock truss`main+0xdf1 > > 1 1961 0xfefa2000 0xfef63d56 > > 1 1954 libc.so.1`_uberdata libproc.so.1`Pxcreate+0x63 > > 1 1927 0xfffffd7fff0600c0 truss`main_thread+0x125 > > 1 1923 libc.so.1`_uberdata+0x180 truss`main+0xc22 > > 1 1918 0xfffffd7fff060100 libc.so.1`thr_create+0x3f > > 1 1917 truss`_iob+0xa8 truss`prtim+0x20 > > 1 1891 0xfffffd7fff060180 truss`main_thread+0x125 > > 1 1890 libc.so.1`_uberdata+0x1c0 truss`main+0x507 > > 1 1884 libc.so.1`seed_lk truss`main+0xdb4 > > 1 1877 libc.so.1`libc_malloc_lock libproc.so.1`Pfree+0x10f > > 1 1875 libc.so.1`libc_malloc_lock libproc.so.1`Pxcreate+0x52 > > 1 1867 libc.so.1`libc_malloc_lock truss`main+0xdb4 > > 1 1832 0xfffffd7fff0600c0 libc.so.1`thr_create+0x3f > > 1 1830 0xfffffd7fff060100 truss`main_thread+0x125 > > 1 1770 libc.so.1`_uberdata+0xfc0 libc.so.1`thr_create+0x3f > > 1 1765 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 1754 truss`_iob+0x28 libc.so.1`_exithandle+0x3b > > 1 1732 libc.so.1`_uberdata+0xd40 truss`main+0xf8 > > 1 1723 libc.so.1`_uberdata+0xd40 truss`_start+0x1b > > 1 1695 truss`_iob+0xa8 truss`report+0x4af > > 1 1681 libc.so.1`_uberdata+0xd40 > libnsl.so.1`_libnsl_lock_init+0x86 > > 1 1674 libc.so.1`_uberdata+0xe80 libc.so.1`_thrp_create+0x531 > > 1 1649 0xfefa1f80 0xfef63d56 > > 1 1648 truss`_iob+0xa8 truss`report+0x492 > > 1 1647 0xfef9e5d0 0xfef14052 > > 1 1642 0xfffffd7fff200080 truss`Xcritical+0x46 > > 1 1640 truss`_iob+0xa8 truss`report+0x486 > > 1 1637 truss`_iob+0xa8 truss`prtim+0x20 > > 1 1624 0xfffffd7fff060180 libc.so.1`thr_create+0x3f > > 1 1616 0xfefa2200 0xfef01d17 > > 1 1608 libc.so.1`_uberdata truss`create_thread+0x58 > > 1 1608 truss`_iob+0xa8 truss`prtim+0x51 > > 1 1547 truss`_iob+0xa8 truss`report+0x53e > > 1 1547 truss`_iob+0xa8 truss`prtim+0x51 > > 1 1533 0xfefa2040 0xfef63d56 > > 1 1518 0xfefa1f80 0xfef63d56 > > 1 1505 libc.so.1`libc_malloc_lock libproc.so.1`Pfree+0x1cf > > 1 1488 0xfefa1f80 0xfef63d56 > > 1 1466 truss`_iob+0xa8 truss`prtim+0x51 > > 1 1445 libc.so.1`libc_malloc_lock truss`free_private+0x88 > > 1 1443 libc.so.1`libc_malloc_lock truss`my_realloc+0x18 > > 1 1426 truss`_iob+0xa8 truss`report+0x4cb > > 1 1424 truss`_iob+0xa8 truss`prtim+0x20 > > 1 1415 0xfef9e5d0 0xfef14052 > > 1 1404 libc.so.1`_uberdata+0xfc0 libc.so.1`thr_create+0x3f > > 1 1397 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > 1 1378 libc.so.1`_uberdata+0xd40 libc.so.1`_thrp_create+0x370 > > 1 1372 libc.so.1`_uberdata libc.so.1`thr_create+0x3f > > 1 1363 libc.so.1`libc_malloc_lock truss`free_private+0x90 > > 1 1345 libc.so.1`_uberdata+0xd40 truss`_start+0x27 > > 1 1343 0xfefa1f80 0xfef63d56 > > 1 1341 libc.so.1`_uberdata+0xfc0 truss`_start+0x1b > > 1 1340 0xfefa2200 0xfef01d17 > > 1 1324 0xfefa1f80 0xfef63d56 > > 1 1284 libc.so.1`_uberdata+0xfc0 libc.so.1`thr_create+0x3f > > 1 1142 libc.so.1`_uberdata+0xfc0 truss`_start+0x27 > > > > Mutex block > > > > Count nsec Lock Caller > > > ------------------------------------------------------------------------------- > > 124379 34360 truss`truss_lock truss`worker_thread+0x27d > > 88153 2193 truss`truss_lock truss`worker_thread+0x27d > > 3 55924 truss`truss_lock truss`worker_thread+0x5c4 > > 1 12080 libc.so.1`libc_malloc_lock libc.so.1`free+0x18 > > 1 2286 truss`truss_lock truss`main_thread+0xed > > $ > > > > On 7/1/08, [EMAIL PROTECTED] <[EMAIL PROTECTED]> wrote: > > > > > > > Could you please provide lockstat information from plockstat for each of > > > these > > > cases. I think I know what you are seeing, but I want data to back up > the > > > theory. > > > > > > Thanks > > > > > > Dave Valin > > > > > > > > > senthil ramanujam wrote: > > > > > > > > > > > > > Hi, > > > > > > > > I am seeing a strange performance behavior with pthread mutex > > > > operations on my Solaris (4-core) system running S10U5. > > > > > > > > The issue is that if the program is run with truss enabled, I am > > > > getting about 3 times more the performance of the run without truss > > > > enabled. Strange...right? > > > > > > > > The C program does the following: > > > > - accept 2 parameters [number of concurrent threads(N), and run-time] > > > > - create and run N threads simultaneously for <run-time> seconds > > > > - each thread does the following: > > > > - acquires the pthread mutex > > > > - increases the value of it's _own_ long variable by 1 > > > > - releases the pthread mutex > > > > - after run-time expires, each thread reports the value of it's long > > > > > > > > > > > variable > > > > > > > > > > Note that I did not use any special flags to compile it. Reply back to > > > > this email if you like to take a look at the program source code. > > > > > > > > Let's look at the program without truss enabled. > > > > > > > > $ mutex_ops -w4 -r10 > > > > number of threads:4, run-time (in seconds)=10 > > > > Thread 1: total ops: 4580775, ops/second: 458077 > > > > Thread 3: total ops: 3798001, ops/second: 379800 > > > > Thread 0: total ops: 4867850, ops/second: 486785 > > > > Thread 2: total ops: 4925299, ops/second: 492529 > > > > $ > > > > <<vmstat 1>> > > > > kthr memory page disk faults > cpu > > > > r b w swap free re mf pi po fr de sr s0 s1 -- -- in sy cs > us > > > > > > > > > > > sy id > > > > > > > > > > 0 0 0 17121968 14961748 22 205 0 0 0 0 0 0 0 0 0 7960 16218 > 16155 28 > > > > > > > > > > > 2 71 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 19914 41572 > 41568 > > > > > > > > > > > 81 3 16 > > > > > > > > > > 1 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 18711 39086 > 38937 > > > > > > > > > > > 80 3 17 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 19006 39373 > 39382 > > > > > > > > > > > 80 3 17 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 18719 39151 > 39007 > > > > > > > > > > > 80 3 16 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 19560 41243 > 40963 > > > > > > > > > > > 81 4 16 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 20498 43671 > 43203 > > > > > > > > > > > 81 4 16 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 20857 44636 > 44014 > > > > > > > > > > > 80 4 15 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 19149 41239 > 40583 > > > > > > > > > > > 80 4 16 > > > > > > > > > > 0 0 0 17121968 14961748 0 0 0 0 0 0 0 0 0 0 0 21019 44189 > 43995 > > > > > > > > > > > 81 4 15 > > > > > > > > > > 0 0 0 17122372 14962176 7 29 0 0 0 0 0 0 0 0 0 13062 27003 > 26973 > > > > > > > > > > > 46 2 52 > > > > > > > > > > 0 0 0 17122372 14962176 0 0 0 0 0 0 0 0 0 0 0 461 160 274 > 0 > > > > > > > > > > > 0 100 > > > > > > > > > > As you can see above that I am executing the program with 4 concurrent > > > > threads for 10 seconds. The output shows that each thread has acquired > > > > the mutex lock about 400,000 times a second. The vmstat shows that the > > > > program used about 80% of usertime, 4%system and ~15% idle. So far so > > > > good. > > > > > > > > Now, let's look into program with truss case. > > > > > > > > $ truss -fc mutex_ops -w4 -r10 > > > > number of threads:4, run-time (in seconds)=10 > > > > Thread 0: total ops: 13419838, ops/second: 1341983 > > > > Thread 2: total ops: 13959115, ops/second: 1395911 > > > > Thread 1: total ops: 13414291, ops/second: 1341429 > > > > Thread 3: total ops: 13535670, ops/second: 1353567 > > > > > > > > syscall seconds calls errors > > > > _exit .000 1 > > > > write .000 5 > > > > open .000 3 1 > > > > close .000 2 > > > > stat .000 10 7 > > > > getpid .000 1 > > > > fstat .000 1 > > > > ioctl .000 1 > > > > execve .000 1 > > > > lwp_park .905 106423 > > > > lwp_unpark .757 106423 > > > > sigaction .000 1 > > > > getcontext .000 1 > > > > setustack .000 5 > > > > mmap .000 16 > > > > munmap .000 2 > > > > getrlimit .000 1 > > > > memcntl .000 1 > > > > sysconfig .000 2 > > > > yield .182 26004 > > > > lwp_create .000 4 > > > > lwp_exit .000 4 > > > > lwp_continue .000 4 > > > > lwp_sigmask .000 4 > > > > lwp_private .000 1 > > > > lwp_wait .000 4 > > > > lwp_mutex_wakeup .000 9 > > > > nanosleep .000 1 > > > > schedctl .000 5 > > > > resolvepath .000 4 > > > > lwp_mutex_timedlock .000 32 > > > > getcwd .000 1 > > > > -------- ------ ---- > > > > sys totals: 1.846 238977 8 > > > > usr time: 21.363 > > > > elapsed: 10.060 > > > > $ > > > > > > > > <<vmstat 1>> > > > > kthr memory page disk faults > cpu > > > > r b w swap free re mf pi po fr de sr s0 s1 -- -- in sy cs > us > > > > > > > > > > > sy id > > > > > > > > > > 0 0 0 17122372 14962176 0 0 0 0 0 0 0 0 0 0 0 529 262 335 > 0 > > > > > > > > > > > 0 100 > > > > > > > > > > 0 0 0 17121240 14960660 153 632 0 0 0 0 0 0 0 0 0 25259 91754 > > > > 87992 37 15 48 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 62751 178228 > > > > 179102 57 33 10 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 56922 169565 > > > > 168507 59 30 11 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 60935 178967 > > > > 178535 58 32 10 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 61581 180239 > > > > 179751 58 32 10 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 61486 181664 > > > > 180513 58 33 10 > > > > 1 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 67941 186205 > > > > 190703 55 35 10 > > > > 0 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 59981 175708 > > > > 175758 58 32 10 > > > > 1 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 60485 174557 > > > > 175091 58 32 11 > > > > 1 0 0 17121104 14960524 0 0 0 0 0 0 0 0 0 0 0 62799 178328 > > > > 179880 57 32 10 > > > > 0 0 0 17122236 14962040 8 17 0 0 0 0 0 0 0 0 0 19483 58122 > > > > 58317 19 10 71 > > > > 0 0 0 17122236 14962040 0 0 0 0 0 0 0 0 0 0 0 449 160 279 > 0 > > > > > > > > > > > 0 100 > > > > > > > > > > Can you spot the issue? I used the same parameters(4 concurrent > > > > threads, 10 seconds run-time), but this time *with truss enabled*. The > > > > output shows that each thread has acquired the mutex lock about > > > > 1,300,000 times a second. vmstat shows that the program is using a lot > > > > more system time than before. However, I don't know how truss can > > > > cause the system time to go up, which ultimately increases the > > > > performance. Am I missing something? > > > > > > > > BTW, I confirmed the mutex locks generated by the program using > > > > dtrace. The values are indeed correct for both the cases. > > > > > > > > Any inputs/comments are appreciated. > > > > > > > > thanks. > > > > > > > > senthil > > > > _______________________________________________ > > > > perf-discuss mailing list > > > > perf-discuss@opensolaris.org > > > > > > > > > > > > > > > > > > > > > > > > > > _______________________________________________ perf-discuss mailing list perf-discuss@opensolaris.org
