See here for a script that post-processes lockstat output and quantifies
the overhead from lock spinning:
http://blogs.sun.com/sistare/entry/measuring_lock_spin_utilization
I just ran it (using a guestimate for your CPU count), and the culprits
clearly are the kstat related locks. Something on your system is gathering
kstats frequently - probably multiple somethings. Find the kstat consumers,
and eliminate them or reduce their frequency. There is a CR open for this
condition, but no fix pending:
6734910 kstat_hold doesn't scale well on large systems
In that particular CR, the kstat consumer was Oracle, who issued a patch
to reduce the kstat usage, in Oracle patch 8531434 "KSTAT CALLS BY MMNL/CJQ0
INCUR HIGH SYSTEM CPU WHEN RUNNING NUMEROUS INSTANCES"
- Steve
On 10/20/09 08:33, Matt V. wrote:
OK, I've tried lockstat; here, the lockstat.out
Adaptive mutex spin: 75935 events in 10.334 seconds (7348 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
2338 3% 3% 0.00 16898 0x1999a78 sfmmu_mlspl_enter+0xa4
2122 3% 6% 0.00 11547 0x3001ac65c88 PowerDispatch+0x84
1794 2% 8% 0.00 118177 vx_worklist_lk vx_worklist_process+0x98
1376 2% 10% 0.00 7743 pr_pidlock pr_p_lock+0xc
1022 1% 11% 0.00 36757396 kstat_chain_lock kstat_hold+0x10
983 1% 13% 0.00 170177 pidlock waitid+0x9c
968 1% 14% 0.00 11196 0x3001a91a888 PowerDispatch+0x84
856 1% 15% 0.00 9624118 kstat_chain_lock kstat_rele+0xc
749 1% 16% 0.00 420823 pidlock pr_lookup_procdir+0xa0
741 1% 17% 0.00 17877 0x46a1ceac060 aio_cleanup+0x30
726 1% 18% 0.00 115534 vx_sched_lk vx_worklist_thread+0x7c
650 1% 19% 0.00 10134 0x30001508000 untimeout+0x20
639 1% 20% 0.00 11096 0x3000152c000 untimeout+0x20
587 1% 20% 0.00 190500 0x3000caaeb00 post_syscall+0x320
584 1% 21% 0.00 18626 vx_worklist_lk
vx_worklist_enqueue_wlp+0x44
569 1% 22% 0.00 16227 0x46a1ceac060 aionotify+0x18
559 1% 23% 0.00 272993 0x3000cad0cc0 post_syscall+0x320
554 1% 23% 0.00 11577 0x3000152f000 untimeout+0x20
553 1% 24% 0.00 178346 0x3000cabfd40 post_syscall+0x320
537 1% 25% 0.00 270443 kpr_mutex hat_page_relocate+0x48
-------------------------------------------------------------------------------
Adaptive mutex block: 1257 events in 10.334 seconds (122 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
167 13% 13% 0.00 30363782 kstat_chain_lock kstat_hold+0x10
92 7% 21% 0.00 31315642 kstat_chain_lock kstat_hold+0x44
81 6% 27% 0.00 64669229 mod_lock mod_hold_stub+0x18
57 5% 32% 0.00 1753528 vx_sched_lk vx_worklist_thread+0x7c
39 3% 35% 0.00 187616949 dtrace_meta_lock
dtrace_helpers_destroy+0x90
39 3% 38% 0.00 136880797 dtrace_meta_lock
dtrace_helper_provider_register+0x10
33 3% 40% 0.00 30083569 kstat_chain_lock kstat_rele+0xc
25 2% 42% 0.00 175304 0x46a1ceac060 cv_timedwait_sig+0x188
22 2% 44% 0.00 19649443 dtrace_lock dtrace_ioctl+0xcb8
20 2% 46% 0.00 69715284 dtrace_lock dtrace_probe_create+0x18
19 2% 47% 0.00 83167194 dtrace_lock dtrace_ioctl_helper+0xa0
17 1% 49% 0.00 41281151 pidlock waitid+0x9c
16 1% 50% 0.00 190365547 dtrace_meta_lock
dtrace_helper_destroygen+0x134
15 1% 51% 0.00 58197881 dtrace_lock dtrace_ioctl_helper+0xf4
14 1% 52% 0.00 213720 0x41b4731c060 cv_timedwait_sig+0x188
13 1% 53% 0.00 91726780 cpu_lock
system_misc_kstat_update+0x48
12 1% 54% 0.00 150031 0x3092bb0fe90 cv_wait_sig+0x13c
12 1% 55% 0.00 401751 0x3000cabd1c0 post_syscall+0x320
12 1% 56% 0.00 1504110 vx_sched_lk vx_worklist_thread+0x70
11 1% 57% 0.00 24758391 pidlock pr_lookup_procdir+0xa0
-------------------------------------------------------------------------------
Spin lock spin: 168195 events in 10.334 seconds (16276 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
7986 5% 5% 0.00 16771 0x300139b2008 fss_inactive+0x24
6889 4% 9% 0.00 16061 0x300139b2008 fss_active+0x24
4575 3% 12% 0.00 68283 0x300133eade0 disp_getbest+0x4
4054 2% 14% 0.00 56921 0x38387f72ab0 disp_getbest+0x4
3908 2% 16% 0.00 64195 0x300133ead50 disp_getbest+0x4
3438 2% 18% 0.00 61207 0x30010ad3f98 disp_getbest+0x4
3341 2% 20% 0.00 62008 0x68c99bf9230 disp_getbest+0x4
3193 2% 22% 0.00 54864 0x68c99c3f778 disp_getbest+0x4
3093 2% 24% 0.00 59941 0x300133eacf0 disp_getbest+0x4
3039 2% 26% 0.00 64692 0x300133eaf60 disp_getbest+0x4
2932 2% 28% 0.00 63589 cpu0_disp disp_getbest+0x4
2920 2% 29% 0.00 61495 0x300133eaf00 disp_getbest+0x4
2898 2% 31% 0.00 55494 0x300133ea990 disp_getbest+0x4
2775 2% 33% 0.00 57689 0x300133eac30 disp_getbest+0x4
2695 2% 34% 0.00 57490 0x300133eac90 disp_getbest+0x4
2506 1% 36% 0.00 58194 0x300133ea5a0 disp_getbest+0x4
2317 1% 37% 0.00 52482 0x300b0766098 disp_getbest+0x4
2277 1% 39% 0.00 65461 0x300133ea240 disp_getbest+0x4
2270 1% 40% 0.00 54691 0x300133ea9f0 disp_getbest+0x4
2269 1% 41% 0.00 49036 0x300133ea930 disp_getbest+0x4
-------------------------------------------------------------------------------
Thread lock spin: 1309 events in 10.334 seconds (127 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
40 3% 3% 0.00 29786 transition_lock fss_tick+0x4
39 3% 6% 0.00 5653 0x300133ead50 pr_wait_stop+0x90
37 3% 9% 0.00 4679 0x30010ad3f98 pr_wait_stop+0x90
31 2% 11% 0.00 4844 0x300133eaf60 pr_wait_stop+0x90
31 2% 14% 0.00 5414 0x300133ea930 pr_wait_stop+0x90
23 2% 15% 0.00 4883 0x300133eade0 pr_wait_stop+0x90
21 2% 17% 0.00 5394 0x300133ea0c0 pr_wait_stop+0x90
20 2% 18% 0.00 5188 0x300133ea2a0 pr_wait_stop+0x90
19 1% 20% 0.00 4336 0x300133ea4e0 pr_wait_stop+0x90
19 1% 21% 0.00 9937 shuttle_lock fss_update_list+0x58
17 1% 23% 0.00 4263 0x38387f72ab0 pr_wait_stop+0x90
17 1% 24% 0.00 5854 0x300133eac90 pr_wait_stop+0x90
16 1% 25% 0.00 4250 0x306fe811bf8 pr_wait_stop+0x90
16 1% 26% 0.00 5440 0x300133ea360 pr_wait_stop+0x90
16 1% 28% 0.00 5775 0x300133ea1e0 pr_wait_stop+0x90
16 1% 29% 0.00 13530 shuttle_lock prchoose+0x8c
14 1% 30% 0.00 4737 0x300b0766098 pr_wait_stop+0x90
14 1% 31% 0.00 2411 shuttle_lock door_return+0x14c
13 1% 32% 0.00 7507 0x300133eac30 pr_wait_stop+0x90
13 1% 33% 0.00 8067 cpu0_disp pr_wait_stop+0x90
-------------------------------------------------------------------------------
R/W writer blocked by writer: 1 events in 10.334 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
1 100% 100% 0.00 136644 0x3001099ff08 dv_find+0x54c
-------------------------------------------------------------------------------
R/W writer blocked by readers: 1 events in 10.334 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
1 100% 100% 0.00 95442 0x3001099ff08 dv_find+0x54c
-------------------------------------------------------------------------------
R/W reader blocked by writer: 2 events in 10.334 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
2 100% 100% 0.00 1878814 0x300af6cc530 ufs_iaccess+0x14
-------------------------------------------------------------------------------
I'll try to understand this output now :-)
Matt
_______________________________________________
perf-discuss mailing list
[email protected]
