On Sat, 4 Jul 2009, Jonathan Edwards wrote:
this is only going to help if you've got problems in zfetch .. you'd probably
see this better by looking for high lock contention in zfetch with lockstat
This is what lockstat says when performance is poor:
Adaptive mutex spin: 477 events in 30.019 seconds (16 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
47 10% 10% 0.00 5813 0xffffffff80256000 untimeout+0x24
46 10% 19% 0.00 2223 0xffffffffb0a2f200 taskq_thread+0xe3
38 8% 27% 0.00 2252 0xffffffffb0a2f200 cv_wait+0x70
29 6% 34% 0.00 1115 0xffffffff80256000 callout_execute+0xeb
26 5% 39% 0.00 3006 0xffffffffb0a2f200 taskq_dispatch+0x1b8
22 5% 44% 0.00 1200 0xffffffffa06158c0 post_syscall+0x206
18 4% 47% 0.00 3858 arc_eviction_mtx arc_do_user_evicts+0x76
16 3% 51% 0.00 1352 arc_eviction_mtx arc_buf_add_ref+0x2d
15 3% 54% 0.00 5376 0xffffffffb1adac28 taskq_thread+0xe3
11 2% 56% 0.00 2520 0xffffffffb1adac28 taskq_dispatch+0x1b8
9 2% 58% 0.00 2158 0xffffffffbb909e20 pollwakeup+0x116
9 2% 60% 0.00 2431 0xffffffffb1adac28 cv_wait+0x70
8 2% 62% 0.00 3912 0xffffffff80259000 untimeout+0x24
7 1% 63% 0.00 3679 0xffffffffb10dfbc0 polllock+0x3f
7 1% 65% 0.00 2171 0xffffffffb0a2f2d8 cv_wait+0x70
6 1% 66% 0.00 771 0xffffffffb3f23708 pcache_delete_fd+0xac
6 1% 67% 0.00 4679 0xffffffffb0a2f2d8 taskq_dispatch+0x1b8
5 1% 68% 0.00 500 0xffffffffbe555040 fifo_read+0xf8
5 1% 69% 0.00 15838 0xffffffff8025c000 untimeout+0x24
4 1% 70% 0.00 1213 0xffffffffac44b558 sd_initpkt_for_buf+0x110
4 1% 71% 0.00 638 0xffffffffa28722a0 polllock+0x3f
4 1% 72% 0.00 610 0xffffffff80259000 timeout_common+0x39
4 1% 73% 0.00 10691 0xffffffff80256000 timeout_common+0x39
3 1% 73% 0.00 1559 htable_mutex+0x78 htable_release+0x8a
3 1% 74% 0.00 3610 0xffffffffbb909e20 cv_timedwait_sig+0x1c1
3 1% 74% 0.00 1636 0xffffffffa240d410
ohci_allocate_periodic_in_resource+0x71
2 0% 75% 0.00 5959 0xffffffffbe555040 fifo_read+0x5c
2 0% 75% 0.00 3744 0xffffffffbe555040 polllock+0x3f
2 0% 76% 0.00 635 0xffffffffb3f23708 pollwakeup+0x116
2 0% 76% 0.00 709 0xffffffffb3f23708 cv_timedwait_sig+0x1c1
2 0% 77% 0.00 831 0xffffffffb3dd2070 pcache_insert+0x13d
2 0% 77% 0.00 5976 0xffffffffb3dd2070 pollwakeup+0x116
2 0% 77% 0.00 1339 0xffffffffb1eb9b80 metaslab_group_alloc+0x136
2 0% 78% 0.00 1514 0xffffffffb0a2f2d8 taskq_thread+0xe3
2 0% 78% 0.00 4042 0xffffffffb0a22988 vdev_queue_io_done+0xc3
2 0% 79% 0.00 3428 0xffffffffb0a21f08 vdev_queue_io_done+0xc3
2 0% 79% 0.00 1002 0xffffffffac44b558 sd_core_iostart+0x37
2 0% 79% 0.00 1387 0xffffffffa8c56d80 xbuf_iostart+0x7d
2 0% 80% 0.00 698 0xffffffffa58a3318 sd_return_command+0x11b
2 0% 80% 0.00 385 0xffffffffa58a3318 sd_start_cmds+0x115
2 0% 81% 0.00 562 0xffffffffa5647800 ssfcp_scsi_start+0x30
2 0% 81% 0.00 1620 0xffffffffa4162d58 ssfcp_scsi_init_pkt+0x1be
2 0% 82% 0.00 897 0xffffffffa4162d58 ssfcp_scsi_start+0x42
2 0% 82% 0.00 475 0xffffffffa4162b78 ssfcp_scsi_start+0x42
2 0% 82% 0.00 697 0xffffffffa40fb158 sd_start_cmds+0x115
2 0% 83% 0.00 10901 0xffffffffa28722a0 fifo_write+0x5b
2 0% 83% 0.00 4379 0xffffffffa28722a0 fifo_read+0xf8
2 0% 84% 0.00 1534 0xffffffffa2638390 emlxs_tx_get+0x38
2 0% 84% 0.00 1601 0xffffffffa2638350 emlxs_issue_iocb_cmd+0xc1
2 0% 84% 0.00 6697 0xffffffffa2503f08 vdev_queue_io_done+0x7b
2 0% 85% 0.00 4113 0xffffffffa24040b0
gcpu_ntv_mca_poll_wrapper+0x64
2 0% 85% 0.00 928 0xfffffe85dc140658 pollwakeup+0x116
1 0% 86% 0.00 404 iommulib_lock lookup_cache+0x2c
1 0% 86% 0.00 4867 pidlock thread_exit+0x6f
1 0% 86% 0.00 1245 plocks+0x3c0 pollhead_delete+0x23
1 0% 86% 0.00 2452 plocks+0x3c0 pollhead_insert+0x35
1 0% 86% 0.00 882 htable_mutex+0x3c0 htable_lookup+0x83
1 0% 87% 0.00 28547 htable_mutex+0x3c0 htable_create+0xe3
1 0% 87% 0.00 21173 htable_mutex+0x3c0 htable_release+0x8a
1 0% 87% 0.00 1235 htable_mutex+0x370 htable_lookup+0x83
1 0% 87% 0.00 3212 htable_mutex+0x370 htable_release+0x8a
1 0% 87% 0.00 793 htable_mutex+0x78 htable_lookup+0x83
1 0% 88% 0.00 981 buf_hash_table+0x1210 arc_buf_add_ref+0x7c
1 0% 88% 0.00 1222 buf_hash_table+0x1c50 arc_buf_add_ref+0x7c
1 0% 88% 0.00 1585 buf_hash_table+0x2490 arc_buf_remove_ref+0x6d
1 0% 88% 0.00 1545158 ARC_mru+0x58 remove_reference+0x56
1 0% 88% 0.00 564 0xffffffffbcad4a00 strrput+0x19a
1 0% 89% 0.00 1033 0xffffffffbcad4a00 polllock+0x3f
1 0% 89% 0.00 587 0xffffffffbd328098 putnext+0x6c
1 0% 89% 0.00 11576 0xffffffffbd328098 strrput+0x19a
1 0% 89% 0.00 847 0xffffffffb3f23708 pcache_insert+0x13d
1 0% 90% 0.00 703 0xffffffffbb909e20 poll_common+0x258
1 0% 90% 0.00 1286 0xffffffffbcad4870 kstrgetmsg+0x79
1 0% 90% 0.00 1528 0xffffffffb1012e00 cv_wait+0x70
1 0% 90% 0.00 404 0xffffffffb1011de0 zio_notify_parent+0x37
1 0% 90% 0.00 764 0xffffffffb1011de0 zio_create+0x29f
1 0% 91% 0.00 5887 0xffffffffb0a2f3b0 cv_wait+0x70
1 0% 91% 0.00 883 0xffffffffb1ad3de0 metaslab_group_alloc+0x7e
1 0% 91% 0.00 555 0xffffffffb10dfbc0 fifo_write+0x5b
1 0% 91% 0.00 692 0xffffffffb3dd2070 pollrelock+0x36
1 0% 91% 0.00 4390 0xffffffffb0a22988 vdev_queue_io+0x6e
1 0% 92% 0.00 1449 0xffffffffb0a21f60 vdev_cache_write+0x64
1 0% 92% 0.00 859 0xffffffffb0a21a20 vdev_cache_write+0x64
1 0% 92% 0.00 446 0xffffffffb0a20ec8 vdev_queue_io+0x6e
1 0% 92% 0.00 1987 0xffffffffb0a21f08 vdev_queue_io+0x6e
1 0% 92% 0.00 5968 0xffffffffb0a21f08 vdev_queue_io_done+0x3a
1 0% 93% 0.00 280 0xffffffffac44b558 sd_start_cmds+0x115
1 0% 93% 0.00 527 0xffffffffac44b118 sd_core_iostart+0x37
1 0% 93% 0.00 380 0xffffffffac51aed8 sd_initpkt_for_buf+0x110
1 0% 93% 0.00 742 0xffffffffac51aed8 sdstrategy+0x53
1 0% 94% 0.00 696 0xffffffffac51aed8 sd_start_cmds+0x115
1 0% 94% 0.00 5398 0xffffffffb0a1c988 vdev_queue_io_done+0x3a
1 0% 94% 0.00 6102 0xffffffffb0a1c988 vdev_queue_io_done+0x7b
1 0% 94% 0.00 988 0xffffffffa40fbcd8 sd_return_command+0x11b
1 0% 94% 0.00 298 0xffffffffa4101460 ssfcp_scsi_init_pkt+0x3b4
1 0% 95% 0.00 302 0xffffffffa40fbcd8 sdstrategy+0x53
1 0% 95% 0.00 1436 0xffffffffa40fb158 sdintr+0x3a
1 0% 95% 0.00 764 0xffffffffa40fbcd8 sd_initpkt_for_buf+0x110
1 0% 95% 0.00 846 0xffffffffa40fbcd8 sd_start_cmds+0x115
1 0% 95% 0.00 1172 0xffffffffa5644f60 vdev_cache_write+0x64
1 0% 96% 0.00 8401 0xffffffffa5644f08 vdev_queue_io_done+0xc3
1 0% 96% 0.00 417 0xffffffffa5644f08 vdev_queue_io+0x6e
1 0% 96% 0.00 3419 0xffffffffa5644f08 vdev_queue_io_done+0x7b
1 0% 96% 0.00 1341 0xffffffffa58a3318 sd_core_iostart+0x37
1 0% 96% 0.00 431 0xffffffffa22cc840 fc_ulp_init_packet+0x31
1 0% 97% 0.00 569 0xffffffff807a4000 callout_execute+0xeb
1 0% 97% 0.00 695 0xffffffff8025c000 callout_execute+0xeb
1 0% 97% 0.00 500 0xffffffff80244000 callout_execute+0xeb
1 0% 97% 0.00 855 0xfffffe85dc140658 pcache_insert+0x13d
1 0% 97% 0.00 13339 0xfffffe85d67ddc48 cv_wait+0x70
1 0% 98% 0.00 5377 0xffffffff80253000 untimeout+0x24
1 0% 98% 0.00 5104 0xffffffff80253000 timeout_common+0x39
1 0% 98% 0.00 508 0xffffffff80253000 callout_execute+0xeb
1 0% 98% 0.00 260 0xffffffffa2638420 emlxs_register_pkt+0x30
1 0% 99% 0.00 1059 0xffffffffa2638390 emlxs_tx_put+0x79
1 0% 99% 0.00 411 0xffffffffa3e3a298 sdstrategy+0x53
1 0% 99% 0.00 336 0xffffffffa3d6e380 fc_ulp_init_packet+0x31
1 0% 99% 0.00 926 0xffffffffa3cdfc58 sd_start_cmds+0x115
1 0% 99% 0.00 894 0xffffffffa3e3a298 sd_core_iostart+0x37
1 0% 100% 0.00 766 0xffffffffa3e3a298 sd_buf_iodone+0x23
1 0% 100% 0.00 340 0xffffffffa3e58420 emlxs_register_pkt+0x30
1 0% 100% 0.00 1516 0xffffffffa3e58420 emlxs_unregister_pkt+0x53
-------------------------------------------------------------------------------
Adaptive mutex block: 7 events in 30.019 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
1 14% 14% 0.00 39004 0xffffffffbe555040 fifo_read+0x5c
1 14% 29% 0.00 78624 0xffffffffb3dd2070 pollwakeup+0x116
1 14% 43% 0.00 6668 0xffffffffb0a2f200 taskq_dispatch+0x1b8
1 14% 57% 0.00 35694 0xffffffffb0a2f3b0 cv_wait+0x70
1 14% 71% 0.00 22697 0xffffffffb0a21f08 vdev_queue_io_done+0xc3
1 14% 86% 0.00 20174 0xffffffffb0a1c988 vdev_queue_io_done+0x3a
1 14% 100% 0.00 7365 0xfffffe85d67ddc48 cv_wait+0x70
-------------------------------------------------------------------------------
Spin lock spin: 478 events in 30.019 seconds (16 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
131 27% 27% 0.00 1383 0xffffffffa21a89f8 disp_lock_enter+0x1e
93 19% 47% 0.00 962 0xffffffffa250e9c0 disp_lock_enter+0x1e
84 18% 64% 0.00 3085 0xffffffffa21a8a28 disp_lock_enter+0x1e
73 15% 80% 0.00 2105 cpu0_disp disp_lock_enter+0x1e
33 7% 87% 0.00 3548 0xffffffffa21a8a28 disp_lock_enter_high+0x9
22 5% 91% 0.00 6011 cpu0_disp disp_lock_enter_high+0x9
21 4% 96% 0.00 2222 hres_lock hr_clock_lock+0x1d
9 2% 97% 0.00 3869 0xffffffffa21a89f8 disp_lock_enter_high+0x9
8 2% 99% 0.00 1649 0xffffffffa250e9c0 disp_lock_enter_high+0x9
4 1% 100% 0.00 624 cp_default disp_lock_enter+0x1e
-------------------------------------------------------------------------------
Thread lock spin: 6 events in 30.019 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
2 33% 33% 0.00 698 transition_lock ts_update_list+0x5c
2 33% 67% 0.00 779 cpu[3]+0xf8 cv_wait+0x3e
1 17% 83% 0.00 452 cpu[3]+0xf8 cv_timedwait_sig+0xe1
1 17% 100% 0.00 324 cpu[2]+0xf8 cv_timedwait_sig+0xe1
-------------------------------------------------------------------------------
--
Bob Friesenhahn
bfrie...@simple.dallas.tx.us, http://www.simplesystems.org/users/bfriesen/
GraphicsMagick Maintainer, http://www.GraphicsMagick.org/
_______________________________________________
zfs-discuss mailing list
zfs-discuss@opensolaris.org
http://mail.opensolaris.org/mailman/listinfo/zfs-discuss
