From: Bob (wick@airmail.net)
Date: Thu Feb 08 2007 - 11:39:23 EST
I have a server that occasionally shows an extraordinary amount of mutex spins.
mpstat shows the following during one of its episodes:
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 254 0 189 311 202 357 29 52 17402 0 1465 1 39 0 59
1 184 0 66 55 9 379 43 67 22769 0 1360 1 51 0 48
2 300 0 165 40 5 422 36 88 20983 0 1266 1 46 0 52
3 384 0 374 80 38 407 42 78 20168 0 1775 2 41 0 57
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 60 0 239 321 203 195 76 40 41660 0 1068 1 99 0 0
1 66 0 115 81 9 413 63 70 33658 0 776 1 84 0 15
2 2 0 33 98 8 393 80 59 40319 0 671 1 91 0 9
3 150 0 377 120 36 392 79 72 40218 0 854 2 85 0 13
CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
0 70 0 187 312 203 393 26 62 13326 0 1560 1 33 0 66
1 260 0 139 49 10 525 36 109 14185 0 1982 2 35 0 63
2 303 0 277 46 13 462 33 103 16067 0 1672 1 42 1 56
3 387 0 377 118 89 506 28 110 6790 0 1904 1 23 0 76
And during that timeframe I ran a lockstat and here's what it shows:
# lockstat sleep 5
Adaptive mutex spin: 664202 events in 5.006 seconds (132688 events/sec)
Count indv cuml rcnt spin Lock Caller
-------------------------------------------------------------------------------
659774 99% 99% 1.00 8 pidlock pr_readdir_procdir+0xd8
3677 1% 100% 1.00 8 pidlock pr_lookup_procdir+0xa0
103 0% 100% 1.00 9 pidlock is_running+0x4c
92 0% 100% 1.00 8 pidlock waitid+0x94
55 0% 100% 1.00 4 vx_sched_lk vx_worklist_thread+0x78
54 0% 100% 1.00 8 pidlock is_descendant+0xbc
40 0% 100% 1.00 2 0x30000e410d0 untimeout+0x18
33 0% 100% 1.00 2 0x30000e3e0a8 untimeout+0x18
32 0% 100% 1.00 2 pr_pidlock pr_p_lock+0x10
30 0% 100% 1.00 9 pidlock sigqkill+0x8c
29 0% 100% 1.00 2 0x30000e410d0 callout_execute+0x98
24 0% 100% 1.00 2 0x30000e3e0a8 callout_execute+0x98
18 0% 100% 1.00 1 0x30000e38058 callout_execute+0x98
16 0% 100% 1.00 2 0x30000e38058 untimeout+0x18
16 0% 100% 1.00 3 vx_worklist_lk vx_worklist_process+0x5c
14 0% 100% 1.00 5 vx_sched_lk vx_worklist_thread+0x6c
14 0% 100% 1.00 1 0x30000e3e0a8 timeout_common+0x4
13 0% 100% 1.00 1 0x30000e410d0 timeout_common+0x4
13 0% 100% 1.00 2 pr_pidlock prinactive+0x30
13 0% 100% 1.00 8 pidlock is_eac_descendant+0x28
10 0% 100% 1.00 9 pidlock thread_exit+0x58
9 0% 100% 1.00 1 0x30000e38058 timeout_common+0x4
7 0% 100% 1.00 4 SEOS_head_lock cv_timedwait+0xb4
7 0% 100% 1.00 6 pidlock getproc+0xdc
7 0% 100% 1.00 6 pidlock cfork+0x76c
6 0% 100% 1.00 4 SEOS_head_lock SEOS_free_reqhead+0x1c
6 0% 100% 1.00 7 pidlock pset_bind+0x178
6 0% 100% 1.00 8 pidlock proc_exit+0x414
6 0% 100% 1.00 5 pidlock proc_exit+0x318
6 0% 100% 1.00 11 pidlock setpgrp+0x438
6 0% 100% 1.00 2 0x30000e38058 callout_execute+0x4
6 0% 100% 1.00 6 pidlock cfork+0x28c
4 0% 100% 1.00 1 SEOS_head_lock SEOS_find_request+0x38
4 0% 100% 1.00 3 vn_vfslocks_buckets+0x840 vn_vfslocks_getlock+0x1c
4 0% 100% 1.00 3 vn_vfslocks_buckets+0x840 vn_vfslocks_rele+0x20
4 0% 100% 1.00 11 pidlock getparents+0x58
4 0% 100% 1.00 7 pidlock thread_create+0x34c
3 0% 100% 1.00 2 0x30001020060 timeout_common+0x4
3 0% 100% 1.00 21 pidlock vfwait+0x18
2 0% 100% 1.00 6 0x300e0616ee0 fifo_write+0x4c
2 0% 100% 1.00 3 0x30006fb6d98 PowerTopIodonePirp+0x60
2 0% 100% 1.00 3 pse_mutex+0xf0 page_unlock+0x1c
2 0% 100% 1.00 10 pidlock cv_wait_sig_swap+0x1b0
2 0% 100% 1.00 2 0x30006c6f918 prroot+0xc
2 0% 100% 1.00 12 pidlock vfwait+0xb8
1 0% 100% 1.00 3 0x300010260b0 timeout_common+0x4
1 0% 100% 1.00 3 0x30001023088 callout_execute+0x98
1 0% 100% 1.00 4 0x3000536cc80 pr_p_lock+0x3c
1 0% 100% 1.00 1 0x30006c6f918 pr_lookup_procdir+0x240
1 0% 100% 1.00 5 0x3000536a940 pr_p_lock+0x3c
1 0% 100% 1.00 2 0x3001b62e068 aio_cleanup+0x24
1 0% 100% 1.00 3 0x3000634dd88 lookuppnat+0xa8
1 0% 100% 1.00 2 0x300010260b0 untimeout+0x18
1 0% 100% 1.00 6 0x3000536a5c0 pr_p_lock+0x3c
1 0% 100% 1.00 5 0x3000536a040 issig_forreal+0x1c
1 0% 100% 1.00 2 0x30006fb6d98 PowerBottomIodoneNew+0x3ec
1 0% 100% 1.00 7 0x30006f0c028 MpcDispatch+0xfc
1 0% 100% 1.00 2 0x300026a5038 segmap_release+0x74
1 0% 100% 1.00 3 0x300062e85c0 fjgi_recv+0x64c
1 0% 100% 1.00 2 0x300026a5038 segmap_unlock+0xb4
1 0% 100% 1.00 9 pidlock sigcld_repost+0x34
1 0% 100% 1.00 3 0x30006c6f918 prlookup+0xfc
1 0% 100% 1.00 1 ctr_mutex+0x50 page_ctr_add+0x78
1 0% 100% 1.00 2 ph_mutex+0xa00 page_find+0x5c
1 0% 100% 1.00 2 pidlock thread_free+0x224
1 0% 100% 1.00 3 vn_vfslocks_buckets+0x840 vn_vfslocks_getlock+0xac
1 0% 100% 1.00 1 0x30007684310 dnlc_lookup+0x14c
-------------------------------------------------------------------------------
Adaptive mutex block: 405 events in 5.006 seconds (81 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
372 92% 92% 1.00 613002 pidlock pr_readdir_procdir+0xd8
15 4% 96% 1.00 8966 SEOS_head_lock cv_timedwait+0xb4
8 2% 98% 1.00 53375 pidlock waitid+0x94
5 1% 99% 1.00 9108500 pidlock pr_lookup_procdir+0xa0
2 0% 99% 1.00 167250 pidlock is_descendant+0xbc
1 0% 100% 1.00 87100 pidlock sigqkill+0x8c
1 0% 100% 1.00 264000 pidlock sigcld_repost+0x34
1 0% 100% 1.00 47300 pidlock cv_wait_sig_swap+0x1b0
-------------------------------------------------------------------------------
Spin lock spin: 702 events in 5.006 seconds (140 events/sec)
Count indv cuml rcnt spin Lock Caller
-------------------------------------------------------------------------------
214 30% 30% 1.00 6 turnstile_table+0xca8 turnstile_lookup+0x4c
133 19% 49% 1.00 2 cpu[1]+0x90 disp+0x90
102 15% 64% 1.00 2 cpu[2]+0x90 disp+0x90
61 9% 73% 1.00 3 cpu[3]+0x90 disp+0x90
45 6% 79% 1.00 4 cp_default disp_getbest+0x4
31 4% 83% 1.00 3 cpu[3]+0x90 setbackdq+0x29c
20 3% 86% 1.00 4 cpu[3]+0x90 disp_getbest+0x4
18 3% 89% 1.00 4 cpu[2]+0x90 disp_getbest+0x4
16 2% 91% 1.00 4 cpu[2]+0x90 setbackdq+0x29c
14 2% 93% 1.00 4 cpu[1]+0x90 setbackdq+0x29c
14 2% 95% 1.00 3 cpu[1]+0x90 disp_getbest+0x4
14 2% 97% 1.00 2 cpu[0]+0x90 disp+0x90
7 1% 98% 1.00 4 cpu[0]+0x90 setbackdq+0x29c
4 1% 99% 1.00 3 cpu[0]+0x90 disp_getbest+0x4
3 0% 99% 1.00 2 cpu[3]+0x90 setfrontdq+0x108
2 0% 99% 1.00 3 cpu[1]+0x90 setfrontdq+0x108
2 0% 100% 1.00 2 cpu[2]+0x90 setfrontdq+0x108
2 0% 100% 1.00 4 cpu[0]+0x90 setfrontdq+0x108
-------------------------------------------------------------------------------
Thread lock spin: 117 events in 5.006 seconds (23 events/sec)
Count indv cuml rcnt spin Lock Caller
-------------------------------------------------------------------------------
88 75% 75% 1.00 741 turnstile_table+0xca8 ts_tick+0x8
6 5% 80% 1.00 68 cpu[3]+0xd0 ts_tick+0x8
6 5% 85% 1.00 71 cpu[2]+0xd0 ts_tick+0x8
6 5% 91% 1.00 237 cpu[0]+0xd0 ts_tick+0x8
4 3% 94% 1.00 217 cpu[1]+0xd0 ts_tick+0x8
3 3% 97% 1.00 60 cpu[2]+0xd0 turnstile_block+0x70
1 1% 97% 1.00 38 cpu[0]+0xd0 turnstile_block+0x1e0
1 1% 98% 1.00 514 cpu[3]+0xd0 turnstile_block+0x70
1 1% 99% 1.00 665 turnstile_table+0xca8 ts_update_list+0x6c
1 1% 100% 1.00 91 lwpsleepq+0x1e08 prchoose+0x88
-------------------------------------------------------------------------------
#
What is this "pr_readdir_procdir" call and what would cause it to spin like
that? This server is dedicated to Oracle databases.
_______________________________________________
sunmanagers mailing list
sunmanagers@sunmanagers.org
http://www.sunmanagers.org/mailman/listinfo/sunmanagers
This archive was generated by hypermail 2.1.7 : Wed Apr 09 2008 - 23:41:36 EDT