Hi,
as a sidenote to the recent discussion on
[developer] [zfs] zpool should not accept devices with a
larger (incompatible) ashift
we just had the case that adding a SSD (Sun F20) to an traditional
ashift=9 pool (40 disks, 8 x raidz1 (5 disks) vdevs stripe) results
in a 4k blocked ashift=12 SSD (oi_151a7) used as log and cache
(both 2 disks stripe). Machine is a Sun X4540 (48 2TB SATA disks on
6 LSI SAS1068E JBOD controllers), mpt driver. About 800 processes on 96
machines fetch and write data (in smaller 10k chunks) over a 10 Gbe
(ixgbe) network, plus a few local processes usually reading 10k files
with ~12 MB/s. This config worked with more than 100 MB/s sustained
inflow on opensolaris 2009.06 with an ashift=9 log/cache (the same F20,
two disks mirrored, disk is marked as battery-nvcache enabled in sd.conf).
The question is: Does this new configuration harm pool performance ?
What we saw the last two days was a heavy impact on write performance
that took especially zfs_dirent_unlock to a grinding halt, regardless
of delivering it over nfsv4 or locally (see below). We also saw long
times in txg_hold_open (incomplete txgs ?). Users could not write in
time, even simple remove of an empty directory took minutes. Nevertheless,
the zpool-* workers where reading and writing heavily, driving disks
to over 200 IOPs (cheaper desktop variants,not that powerfull..) constantly,
but mean read/write was only ~12-15MB/s. So a major drawback compared
to the good old OSOL 2009.06. Nothing peculiar otherwise, disks were
in even use, 8-45ms, no outliers, FMA entries, just unbelievably slow,
even the zpool iostats where hard to watch, one line per two secs
instead of 50 lines per sec....
Today, we removed log and cache, exported the pool, rebooted the
machine, reimported the pool, but left out log/cache. And, surprise
surprise, performance is back in the 100ths MB/s read/write, and
longest lockstat entries are down by a factor of ten from seconds to
tenths of seconds (see picked list below) !
So questions outstanding are:
1. Is the 4k blocksize on the SSD mismatching the pool blocksize
the real culprit, does that influence already the way the pool is
imported, and does that cause other blocksizes to be used with
the main pool? Or does the sd/mpt drivers know what to do in
these cases ?
2. If SSDs need 4k as the best native blocksize, and if that really
causes these problems with 512B pools, shouldn't that be warned
about (that's the topic of the before-mentioned post) ? And shouldn't
the log disk attach process ignore the 4k in these cases and format
the disks equally blocked to the pool blocksize ?
3. Or is this just another bug in zfs/dmu/arc/vfs that got triggered
by this peculiar configuration ?
Here are parts of some detailed lockstats during heavy use:
lockstat -A (30 secs, longest entries from various locks 0.1-2.5 secs !
picked out):
...
%cum nanosec
3 0% 97% 0.00 2500824397 0xffffff115f1e4bb0 zfs_zget+0x48
3 0% 97% 0.00 2046893316 0xffffff115f1e4b68 zfs_zget+0x48
1 0% 100% 0.00 1959351121 0xffffff7eb915cba0 dmu_prefetch+0x197
3 0% 97% 0.00 1732292346 0xffffff115f1e4b98 zfs_zget+0x48
1 0% 100% 0.00 1427156921 0xffffff80bcfa5cc8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 1423321061 0xffffff11a3afaee0 zfs_zget+0x157
1 0% 100% 0.00 1413892546 0xffffff115fc1d8d8 zfs_zget+0x157
1 0% 100% 0.00 1386546932 0xffffff28b5250500 zfs_dirent_unlock+0x35
1 0% 99% 0.00 1044400256 0xffffff8482928340 zfs_dirent_unlock+0x35
1 0% 100% 0.00 437142205 0xffffff11d9d7e140 zfs_dirent_unlock+0x35
1 0% 100% 0.00 312273414 0xffffff1418d02ad8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 272967802 0xffffff830bcfff60 zap_unlockdir+0x1a
1 0% 99% 0.00 239907347 0xffffff79a3ee7ee0 zfs_dirent_unlock+0x35
1 0% 100% 0.00 196972200 0xffffff22843c09d8 zfs_dirent_unlock+0x35
11 0% 98% 0.00 189097073 0xffffff236f2db418 zfs_dirent_unlock+0x35
2 0% 99% 0.00 182566775 0xffffff6a00bd19d8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 178867980 0xffffff77ac0fb418 zfs_dirent_unlock+0x35
1 0% 100% 0.00 173185962 0xffffff748856a228 zfs_dirent_unlock+0x35
1 0% 100% 0.00 160723401 0xffffff159a85a048 zfs_dirent_unlock+0x35
16072 4% 43% 0.00 156922110 exported_lock rfs4_compound+0x23f
1 0% 100% 0.00 142336348 0xffffff115f1e4ab0 zfs_zget+0x157
2 0% 99% 0.00 124622828 0xffffff3f63faeba0 dmu_buf_hold+0x9a
1 0% 100% 0.00 119559366 0xffffff1c572c0130 zfs_dirent_unlock+0x35
6 0% 96% 0.00 117816314 0xffffff11a3fa4ac0 txg_hold_open+0x46
2 0% 99% 0.00 109297456 0xffffff11d53459f0 zfs_dirent_unlock+0x35
...
After removing 4k log/cache and reimporting pool (longest entry 0.28 sec):
1 0% 100% 0.00 279930279 0xffffff116ca22460 dmu_prefetch+0x197
1 0% 100% 0.00 149055805 0xffffff133892a630 zfs_dirent_unlock+0x35
2 0% 100% 0.00 58032142 0xffffff1a8a27cde8 zfs_dirent_unlock+0x35
16 0% 99% 0.00 40849373 0xffffff160ab8f968 copen+0x58c
1 0% 100% 0.00 37047525 0xffffff134e9cbee0 zfs_dirent_unlock+0x35
2 0% 100% 0.00 34612487 0xffffff1da1cac908 zfs_dirent_unlock+0x35
1 0% 100% 0.00 31402679 0xffffff1ac1585dd0 zfs_dirent_unlock+0x35
1 0% 100% 0.00 31268710 0xffffff17c9b18078 zap_unlockdir+0x1a
1 0% 100% 0.00 26367731 0xffffff19d217da08 zfs_dirent_unlock+0x35
5 0% 100% 0.00 24357841 0xffffff134ffdc8f8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 23544324 0xffffff2682465eb8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 20290046 0xffffff181a779bd0 zfs_dirent_unlock+0x35
1 0% 100% 0.00 18867886 0xffffff1465c78028 zfs_dirent_unlock+0x35
1 0% 100% 0.00 18141927 0xffffff133878cee8 zfs_dirent_unlock+0x35
100642 6% 72% 0.00 16768113 exported_lock rfs4_compound+0x23f
1 0% 100% 0.00 16623080 0xffffff196cb85508 zfs_dirent_unlock+0x35
1 0% 100% 0.00 13929682 0xffffff116ca0fac0 metaslab_sync_done+0x35b
1 0% 100% 0.00 12627094 0xffffff2c5125a338 zfs_dirent_unlock+0x35
8 0% 99% 0.00 10955155 0xffffff2050ea1000
dmu_buf_hold_array_by_dnode+0x215
1 0% 99% 0.00 10731919 0xffffff116ceab000 metaslab_group_alloc+0x235
1 0% 99% 0.00 9494578 0xffffff116cc35ee0 vdev_queue_io+0x7b
2 0% 100% 0.00 8652322 0xffffff18508f4c18 zap_unlockdir+0x1a
5 0% 100% 0.00 8170190 0xffffff134ef3c458
dmu_buf_hold_array_by_dnode+0x215
1 0% 100% 0.00 7016315 0xffffff23140b53d8 dmu_zfetch_find+0x43e
3 0% 100% 0.00 6952120 0xffffff11f742ede8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 6215148 0xffffff1aa926aad8 zfs_dirent_unlock+0x35
1 0% 100% 0.00 4846856 0xffffff1aa4df89d8 zfs_dirent_unlock+0x35
10 0% 99% 0.00 4476185 0xffffff2704115880 zap_cursor_retrieve+0x197
15 0% 99% 0.00 4136754 0xffffff335e2f1968 zap_cursor_retrieve+0x197
1 0% 100% 0.00 4063059 0xffffff184b9cddc0 zfs_dirent_unlock+0x35
2 0% 100% 0.00 3806224 0xffffff11ca37b540 space_map_sync+0x26d
4 0% 100% 0.00 3717428 0xffffff11ca4baac0 space_map_sync+0x26d
10 0% 99% 0.00 3715663 0xffffff22467758b8
dmu_buf_hold_array_by_dnode+0x215
11 0% 99% 0.00 3689175 0xffffff20dd8a4458
dmu_buf_hold_array_by_dnode+0x215
1 0% 100% 0.00 3399155 0xffffff12c5530740 dbuf_read+0x1c5
1 0% 100% 0.00 3366235 0xffffff12c5587cc0 arc_read+0x88
...
-------------------------------------------------------------------------------
Individual entries (4k block log/cache):
Adaptive mutex spin:
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
44113 33% 33% 0.00 23477 0xffffff118c375a48 cv_wait+0x69
41412 31% 64% 0.00 28288 0xffffff118c375a48 taskq_thread+0x2a8
40750 31% 95% 0.00 26225 0xffffff118c375a48 taskq_dispatch_ent+0x4a
530 0% 96% 0.00 15718 0xffffff115ab806b8 svc_poll+0xbb
398 0% 96% 0.00 30602 0xffffff118c375188 taskq_dispatch_ent+0x4a
310 0% 96% 0.00 15957 0xffffff115ab806b8 svc_queuereq+0x47
218 0% 96% 0.00 2004 vph_mutex+0x4000 page_hashin+0xc6
218 0% 96% 0.00 28304 0xffffff118c375188 taskq_thread+0x2a8
205 0% 97% 0.00 6264 0xffffff115bb88aa0 mpt_doneq_empty+0x90
167 0% 97% 0.00 8342 0xffffff115bb88aa0 mpt_intr+0x24
163 0% 97% 0.00 7843 0xffffff115eae1aa0 mpt_intr+0x24
148 0% 97% 0.00 20202 0xffffff118c375188 cv_wait+0x69
147 0% 97% 0.00 6879 0xffffff115eae1aa0 mpt_doneq_empty+0x90
145 0% 97% 0.00 14285 0xffffff115ab806b8 svc_poll+0x126
143 0% 97% 0.00 2732 0xffffff115f1e49d0 rrw_enter_read+0x22
132 0% 97% 0.00 2780 0xffffff11a2cadb80 zio_notify_parent+0x54
110 0% 97% 0.00 6876 0xffffff115a9abb20 mpt_doneq_empty+0x90
106 0% 98% 0.00 2458 vph_mutex+0x4000 page_hashout+0xf3
105 0% 98% 0.00 3489 0xffffff11a2cadb80 zio_remove_child+0x44
104 0% 98% 0.00 3675 0xffffff115fc1d790 rrw_enter_read+0x22
104 0% 98% 0.00 6895 0xffffff115eae2520 mpt_intr+0x24
103 0% 98% 0.00 772860 ARC_mru+0x58 remove_reference+0x5d
94 0% 98% 0.00 2371 mod_lock mod_hold_stub+0x25
93 0% 98% 0.00 6825 0xffffff114ff860a0 mpt_doneq_empty+0x90
89 0% 98% 0.00 75975 0xffffff115ab806b8
cv_timedwait_sig_hires+0x217
80 0% 98% 0.00 6899 0xffffff115eae2520 mpt_doneq_empty+0x90
71 0% 98% 0.00 9361 0xffffff115ab806b8 svc_poll+0x2b4
70 0% 98% 0.00 8918 0xffffff11afe00100 rfs4_find_dr+0x1bc
...
-------------------------------------------------------------------------------
Adaptive mutex block: 3916 events in 30.432 seconds (129 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
2594 66% 66% 0.00 324362 0xffffff118c375a48 taskq_dispatch_ent+0x4a
685 17% 84% 0.00 332125 0xffffff118c375a48 taskq_thread+0x2a8
330 8% 92% 0.00 471074 0xffffff118c375a48 cv_wait+0x69
45 1% 93% 0.00 23194082 ARC_mru+0x58 remove_reference+0x5d
24 1% 94% 0.00 105190 0xffffff118c375188 taskq_dispatch_ent+0x4a
16 0% 94% 0.00 157748 0xffffff115ab806b8 svc_queuereq+0x47
13 0% 95% 0.00 527208 0xffffff115ab806b8 svc_poll+0xbb
12 0% 95% 0.00 47396018 ARC_mru+0x58 arc_evict+0x93
8 0% 95% 0.00 74443 0xffffff115ab806b8
cv_timedwait_sig_hires+0x217
8 0% 95% 0.00 101856 0xffffff113d82dcc0 kmem_cache_free+0xc5
6 0% 96% 0.00 117816314 0xffffff11a3fa4ac0 txg_hold_open+0x46
6 0% 96% 0.00 34952856 0xffffff11a358f798 cv_wait+0x69
6 0% 96% 0.00 73930 0xffffff113d82ddc0 kmem_cache_free+0xc5
5 0% 96% 0.00 540348 0xffffff11d3ae3868 mir_wput+0xb5
5 0% 96% 0.00 635254 0xffffff118c095ca0 vdev_queue_io_done+0x37
5 0% 96% 0.00 424927 0xffffff114ca7b488 taskq_thread+0x2a8
5 0% 96% 0.00 440484 0xffffff114ca7b488 cv_wait+0x69
4 0% 96% 0.00 67106 0xffffff115a9abb20 mpt_intr+0x24
4 0% 97% 0.00 151519 0xffffff114ff860a0 mpt_doneq_empty+0x90
4 0% 97% 0.00 70906 0xffffff113d82de00 kmem_cache_free+0xc5
3 0% 97% 0.00 31808028 ARC_mru_ghost+0x58 arc_change_state+0x8d
3 0% 97% 0.00 54605 0xffffff11afe00100 rfs4_find_dr+0x6c
3 0% 97% 0.00 183392 0xffffff118c375188 taskq_thread+0x2a8
3 0% 97% 0.00 2500824397 0xffffff115f1e4bb0 zfs_zget+0x48
3 0% 97% 0.00 1732292346 0xffffff115f1e4b98 zfs_zget+0x48
3 0% 97% 0.00 2046893316 0xffffff115f1e4b68 zfs_zget+0x48
3 0% 97% 0.00 73901 0xffffff115eae1aa0 mpt_intr+0x24
2 0% 97% 0.00 42486264 ARC_mru_ghost+0x58 add_reference+0x79
...
-------------------------------------------------------------------------------
Spin lock spin: 3103 events in 30.432 seconds (102 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
1331 43% 43% 0.00 59812 turnstile_table+0xbf8 disp_lock_enter+0x2e
231 7% 50% 0.00 4671 0xffffff115936e708 disp_lock_enter+0x2e
196 6% 57% 0.00 4601 0xffffff1158a49248 disp_lock_enter+0x2e
165 5% 62% 0.00 13930 cpu0_disp disp_lock_enter+0x2e
148 5% 67% 0.00 5731 0xffffff1158cc5db0 disp_lock_enter+0x2e
146 5% 71% 0.00 5885 0xffffff11590924c8 disp_lock_enter+0x2e
133 4% 76% 0.00 4340 0xffffff1159374d58 disp_lock_enter+0x2e
101 3% 79% 0.00 6331 0xffffff11598d6048 disp_lock_enter+0x2e
77 2% 81% 0.00 8568 0xffffff11598d65f8 disp_lock_enter+0x2e
69 2% 84% 0.00 5668 0xffffff11598ba398 disp_lock_enter+0x2e
59 2% 86% 0.00 5463 0xffffff11598ba9b8 disp_lock_enter+0x2e
51 2% 87% 0.00 9290 sleepq_head+0x6a08 disp_lock_enter+0x2e
49 2% 89% 0.00 5453 0xffffff11598d6d30 disp_lock_enter+0x2e
49 2% 90% 0.00 4884 0xffffff115936e1c8 disp_lock_enter+0x2e
23 1% 91% 0.00 33451 turnstile_table+0xe68 disp_lock_enter+0x2e
22 1% 92% 0.00 5681 0xffffff1158a49248 disp_lock_enter_high+0x15
21 1% 93% 0.00 43204 turnstile_table+0xd58 disp_lock_enter+0x2e
18 1% 93% 0.00 5789 sleepq_head+0x6a08 disp_lock_enter_high+0x15
18 1% 94% 0.00 9277 0xffffff11598d6d30 disp_lock_enter_high+0x15
17 1% 94% 0.00 10618 0xffffff115936e708 disp_lock_enter_high+0x15
16 1% 95% 0.00 7046 0xffffff11598d6048 disp_lock_enter_high+0x15
14 0% 95% 0.00 17047 turnstile_table+0x8a8 disp_lock_enter+0x2e
14 0% 96% 0.00 9930 0xffffff11598d65f8 disp_lock_enter_high+0x15
13 0% 96% 0.00 46390 turnstile_table+0xb18 disp_lock_enter+0x2e
10 0% 96% 0.00 8755 0xffffff115936e1c8 disp_lock_enter_high+0x15
10 0% 97% 0.00 5422 0xffffff1158cc5db0 disp_lock_enter_high+0x15
...
-------------------------------------------------------------------------------
Thread lock spin: 274 events in 30.432 seconds (9 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
218 80% 80% 0.00 7709 sleepq_head+0x6a08 sysdc_update+0x123
25 9% 89% 0.00 4725 sleepq_head+0x6a08 sysdc_tick+0x1c
3 1% 90% 0.00 1531 sleepq_head+0x6a08 turnstile_pi_waive+0x23
3 1% 91% 0.00 5171 sleepq_head+0x4508 sysdc_update+0x123
3 1% 92% 0.00 15987 turnstile_table+0xbf8 sysdc_update+0x123
3 1% 93% 0.00 14332 cpu[2]+0xe8 cv_wait+0x37
2 1% 94% 0.00 814 sleepq_head+0x6918 setrun+0x16
2 1% 95% 0.00 5499 transition_lock sysdc_tick+0x1c
2 1% 95% 0.00 17213 cpu[1]+0xe8 cv_wait+0x37
2 1% 96% 0.00 1777 cpu[1]+0xe8 sysdc_tick+0x1c
2 1% 97% 0.00 4430 0xffffff1158cc5db0 sysdc_update+0x123
1 0% 97% 0.00 5148 turnstile_table+0x8f8 sysdc_update+0x123
1 0% 97% 0.00 219 cpu[0]+0xe8 turnstile_pi_waive+0x23
1 0% 98% 0.00 585 cpu0_disp sysdc_update+0x123
1 0% 98% 0.00 9548 transition_lock sysdc_update+0x123
1 0% 99% 0.00 6491 cpu[2]+0xe8 turnstile_block+0xbc
1 0% 99% 0.00 9971 0xffffff11598d65f8 sysdc_tick+0x1c
1 0% 99% 0.00 682 cpu[7]+0xe8 sysdc_tick+0x1c
1 0% 100% 0.00 7239 cpu[5]+0xe8 fx_tick+0x1d
1 0% 100% 0.00 42380 cpu[3]+0xe8 cv_wait+0x37
-------------------------------------------------------------------------------
R/W reader blocked by writer: 13 events in 30.432 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
9 69% 69% 0.00 88466 0xffffff11a317f2b0 dmu_zfetch_find+0x4b
2 15% 85% 0.00 1679685 0xffffff11a318cfb8 dmu_zfetch_find+0x4b
1 8% 92% 0.00 202630 0xffffff35d3015ba8 dbuf_read+0x5f
1 8% 100% 0.00 171278 0xffffff1e8960c2e8 dbuf_read+0x5f
-------------------------------------------------------------------------------
Adaptive mutex hold: 9112227 events in 30.432 seconds (299427 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
164279 2% 2% 0.00 23699 0xffffff118c375a48 taskq_dispatch_ent+0x145
149004 2% 3% 0.00 4787 0xffffff118c375a48 taskq_thread+0x228
144654 2% 5% 0.00 18659 0xffffff118c375a48 cv_wait+0x5c
76720 1% 6% 0.00 2529 0xffffff11a2cadb80 zio_notify_parent+0xb0
49041 1% 6% 0.00 1994 0xffffff114cc15480 kmem_cache_alloc+0x8b
48824 1% 7% 0.00 2537 0xffffff1158f06348 spa_config_exit+0x73
48743 1% 7% 0.00 2860 0xffffff113d82dd80 kmem_cache_free+0x152
48590 1% 8% 0.00 2051 0xffffff114cc13f00 kmem_cache_alloc+0x8b
41761 0% 8% 0.00 1651 0xffffff114cc15400 kmem_cache_alloc+0x8b
39732 0% 9% 0.00 2082 0xffffff114cc154c0 kmem_cache_free+0x152
39581 0% 9% 0.00 1939 0xffffff114cc15400 kmem_cache_free+0x152
38870 0% 10% 0.00 2518 0xffffff115f60ac18
ixgbe_tx_recycle_head_wb+0x73
38753 0% 10% 0.00 3105 0xffffff11a2cadb80 zio_remove_child+0x78
38753 0% 11% 0.00 2210 0xffffff114cc15440 kmem_cache_free+0x152
37983 0% 11% 0.00 1704 0xffffff114cc13e80 kmem_cache_alloc+0x8b
37897 0% 11% 0.00 2336 0xffffff114cc15500 kmem_cache_free+0x152
37885 0% 12% 0.00 2545 0xffffff115f60aa18
ixgbe_tx_recycle_head_wb+0x73
37620 0% 12% 0.00 2325 0xffffff114cc15380 kmem_cache_free+0x152
37210 0% 13% 0.00 2476 mod_lock mod_hold_stub+0xae
37209 0% 13% 0.00 2297 mod_lock mod_release_stub+0x61
36581 0% 13% 0.00 2017 0xffffff114cc13e80 kmem_cache_free+0x152
36351 0% 14% 0.00 2528 0xffffff115fc1d790 rrw_enter_read+0x3c
36209 0% 14% 0.00 2485 0xffffff115fc1d790 rrw_exit+0x47
35726 0% 15% 0.00 2225 0xffffff114cc15280 kmem_cache_free+0x152
35597 0% 15% 0.00 1963 0xffffff114cc154c0 kmem_cache_alloc+0x8b
34872 0% 15% 0.00 2176 0xffffff114cc13f40 kmem_cache_free+0x152
34566 0% 16% 0.00 2306 0xffffff114cc13ec0 kmem_cache_free+0x152
34462 0% 16% 0.00 2670 0xffffff115f60a818
ixgbe_tx_recycle_head_wb+0x73
34324 0% 17% 0.00 2436 0xffffff114cc15340 kmem_cache_free+0x152
34299 0% 17% 0.00 2274 zone0+0x20 zone_cred_hold+0x2f
33979 0% 17% 0.00 2436 0xffffff114cc13f80 kmem_cache_free+0x152
33434 0% 18% 0.00 2391 0xffffff114cc13e00 kmem_cache_free+0x152
33359 0% 18% 0.00 3144 0xffffff113d82dcc0 kmem_cache_free+0x152
32922 0% 18% 0.00 2876 0xffffff113d82dd40 kmem_cache_free+0x152
32714 0% 19% 0.00 2138 zone0+0x20 zone_cred_rele+0x8e
32640 0% 19% 0.00 2796 0xffffff113d82ddc0 kmem_cache_free+0x152
32562 0% 20% 0.00 2260 0xffffff114cc13d00 kmem_cache_free+0x152
32311 0% 20% 0.00 3919 0xffffff11a20dbcc0 kmem_cache_free+0x152
31983 0% 20% 0.00 2258 0xffffff1158f06348 spa_config_enter+0xf6
31888 0% 21% 0.00 2020 0xffffff114cc13f40 kmem_cache_alloc+0x8b
31836 0% 21% 0.00 2494 0xffffff114cc13dc0 kmem_cache_free+0x152
31693 0% 21% 0.00 3898 0xffffff11a20dcd40 kmem_cache_free+0x152
31452 0% 22% 0.00 2459 0xffffff114cc153c0 kmem_cache_free+0x152
31401 0% 22% 0.00 1865 0xffffff114cc15380 kmem_cache_alloc+0x8b
31372 0% 22% 0.00 3555 0xffffff11a20dc880 kmem_cache_free+0x152
30851 0% 23% 0.00 3679 0xffffff115eae1aa0 mpt_intr+0x157
30761 0% 23% 0.00 2742 0xffffff115a9abb20 mpt_intr+0x157
30759 0% 23% 0.00 9073 0xffffff115eae1aa0 mpt_doneq_empty+0x5d
30752 0% 24% 0.00 9228 0xffffff115a9abb20 mpt_doneq_empty+0x5d
30585 0% 24% 0.00 3244 0xffffff115bb88aa0 mpt_intr+0x157
30528 0% 24% 0.00 10191 0xffffff115bb88aa0 mpt_doneq_empty+0x5d
30386 0% 25% 0.00 3512 0xffffff11a20dc300 kmem_cache_free+0x152
29661 0% 25% 0.00 2755 0xffffff115eae2520 mpt_intr+0x157
29653 0% 25% 0.00 8727 0xffffff115eae2520 mpt_doneq_empty+0x5d
29461 0% 26% 0.00 2763 0xffffff114cc15300 kmem_cache_free+0x152
28877 0% 26% 0.00 2605 0xffffff114cc152c0 kmem_cache_free+0x152
28480 0% 26% 0.00 2498 0xffffff114cc13e40 kmem_cache_free+0x152
28463 0% 27% 0.00 2765 0xffffff113d82de00 kmem_cache_free+0x152
28364 0% 27% 0.00 1822 0xffffff114cc13e00 kmem_cache_alloc+0x8b
28285 0% 27% 0.00 2730 0xffffff114cc13d80 kmem_cache_free+0x152
28065 0% 27% 0.00 2650 0xffffff114cc13d40 kmem_cache_free+0x152
27608 0% 28% 0.00 2290 0xffffff114cc13f00 kmem_cache_free+0x152
27254 0% 28% 0.00 2572 0xffffff115bb88ae8
mpt_accept_txwq_and_pkt+0x3d
...
-------------------------------------------------------------------------------
Spin lock hold: 1321879 events in 30.432 seconds (43437 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
169726 13% 13% 0.00 15972 sleepq_head+0x6a08 disp_lock_exit+0x55
148431 11% 24% 0.00 8336 sleepq_head+0x6a08
disp_lock_exit_nopreempt+0x43
43089 3% 27% 0.00 5065 0xffffff1158a49248 disp_lock_exit_high+0x33
41642 3% 30% 0.00 4525 0xffffff1159374d58 disp_lock_exit_high+0x33
40968 3% 34% 0.00 4844 0xffffff115936e708 disp_lock_exit_high+0x33
40691 3% 37% 0.00 4496 0xffffff1158cc5db0 disp_lock_exit_high+0x33
40279 3% 40% 0.00 4296 cpu0_disp disp_lock_exit_high+0x33
40211 3% 43% 0.00 4791 0xffffff11590924c8 disp_lock_exit_high+0x33
36076 3% 45% 0.00 6216 0xffffff11598d65f8 disp_lock_exit_high+0x33
34965 3% 48% 0.00 6106 0xffffff11598d6d30 disp_lock_exit_high+0x33
34752 3% 51% 0.00 6256 0xffffff115936e1c8 disp_lock_exit_high+0x33
34368 3% 53% 0.00 6141 0xffffff11598ba398 disp_lock_exit_high+0x33
32895 2% 56% 0.00 6042 0xffffff11598ba9b8 disp_lock_exit_high+0x33
29903 2% 58% 0.00 6076 0xffffff11598d6048 disp_lock_exit_high+0x33
22361 2% 60% 0.00 5086 cpu[1]+0xe8 disp_lock_exit_high+0x33
21599 2% 61% 0.00 5181 cpu[3]+0xe8 disp_lock_exit_high+0x33
21190 2% 63% 0.00 5339 cpu[5]+0xe8 disp_lock_exit_high+0x33
21153 2% 65% 0.00 5253 cpu[4]+0xe8 disp_lock_exit_high+0x33
21026 2% 66% 0.00 5170 cpu[2]+0xe8 disp_lock_exit_high+0x33
20343 2% 68% 0.00 5007 cpu[0]+0xe8 disp_lock_exit_high+0x33
19893 2% 69% 0.00 5863 cpu[8]+0xe8 disp_lock_exit_high+0x33
19521 1% 71% 0.00 5811 cpu[11]+0xe8 disp_lock_exit_high+0x33
19404 1% 72% 0.00 2626 0xffffff1158a49248 disp_lock_exit+0x55
19144 1% 74% 0.00 5742 cpu[7]+0xe8 disp_lock_exit_high+0x33
...
-------------------------------------------------------------------------------
R/W writer hold: 48294 events in 30.432 seconds (1587 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
12534 26% 26% 0.00 5707 0xffffff11a317f2b0 dmu_zfetch_colinear+0x1b1
12315 26% 51% 0.00 3798 0xffffff11a317f2b0
dmu_zfetch_stream_reclaim+0xa2
6312 13% 65% 0.00 3911 0xffffff11a26a3878 dmu_zfetch_colinear+0x1b1
6176 13% 77% 0.00 2837 0xffffff11a26a3878
dmu_zfetch_stream_reclaim+0xa2
1979 4% 81% 0.00 14783 0xffffff8969caf9b8 zap_unlockdir+0x1a
1979 4% 86% 0.00 14733 0xffffff7efb141578 zap_unlockdir+0x1a
764 2% 87% 0.00 33973 0xffffff1188172218 as_map_locked+0x339
763 2% 89% 0.00 4164 0xffffffb6222d7ec0 segvn_extend_prev+0x175
667 1% 90% 0.00 4597 0xffffff11a25f0708 dmu_zfetch_colinear+0x1b1
664 1% 91% 0.00 3875 0xffffff11a25f0708
dmu_zfetch_stream_reclaim+0xa2
557 1% 93% 0.00 2908 0xffffff11a318cfb8 dmu_zfetch_colinear+0x1b1
546 1% 94% 0.00 1968 0xffffff11a318cfb8
dmu_zfetch_stream_reclaim+0xa2
171 0% 94% 0.00 14397 0xffffff11ecc07ba0 tmp_inactive+0x20a
147 0% 94% 0.00 14524 0xffffff12099947b0 tmp_inactive+0x20a
145 0% 95% 0.00 14466 0xffffff6488000db8 tmp_inactive+0x20a
144 0% 95% 0.00 14539 0xffffff2e8fbfa180 tmp_inactive+0x20a
128 0% 95% 0.00 14322 0xffffffb625f2e468 tmp_inactive+0x20a
119 0% 95% 0.00 14347 0xffffff6487f70440 tmp_inactive+0x20a
112 0% 96% 0.00 14922 0xffffff13a9fc4ce8 tmp_inactive+0x20a
110 0% 96% 0.00 14521 0xffffff40d1badef8 tmp_inactive+0x20a
108 0% 96% 0.00 14426 0xffffff11f0d79968 tmp_inactive+0x20a
75 0% 96% 0.00 14271 0xffffff3ff7bac270 tmp_inactive+0x20a
53 0% 96% 0.00 14512 0xffffff13a6d426a0 tmp_inactive+0x20a
48 0% 97% 0.00 14533 0xffffff3ff7b4f718 tmp_inactive+0x20a
41 0% 97% 0.00 14099 0xffffff3ff7bbd7d8 tmp_inactive+0x20a
40 0% 97% 0.00 14325 0xffffff40d1bc66b0 tmp_inactive+0x20a
36 0% 97% 0.00 14883 0xffffff13b66b12c0 tmp_inactive+0x20a
29 0% 97% 0.00 15214 0xffffff64851fb488 tmp_inactive+0x20a
27 0% 97% 0.00 14337 0xffffff3ff7b6b418 tmp_inactive+0x20a
20 0% 97% 0.00 14590 0xffffff3e0a7bd3e0 tmp_inactive+0x20a
20 0% 97% 0.00 14900 0xffffff2e8fc41150 tmp_inactive+0x20a
18 0% 97% 0.00 15053 0xffffff11bb7bf550 tmp_inactive+0x20a
17 0% 97% 0.00 14554 0xffffff11f5ced918 tmp_inactive+0x20a
16 0% 97% 0.00 16233 0xffffff3ff7b6ce90 tmp_inactive+0x20a
16 0% 97% 0.00 14673 0xffffff3e01b8aaa8 tmp_inactive+0x20a
15 0% 97% 0.00 15501 0xffffff3ff7bc9878 tmp_inactive+0x20a
13 0% 97% 0.00 14999 0xffffff6487eca7d0 tmp_inactive+0x20a
13 0% 97% 0.00 14494 0xffffff3749242a28 tmp_inactive+0x20a
13 0% 97% 0.00 14376 0xffffff3582c2e7e0 tmp_inactive+0x20a
13 0% 97% 0.00 14694 0xffffff122a929a08 tmp_inactive+0x20a
12 0% 97% 0.00 14443 0xffffffb6256ddec0 tmp_inactive+0x20a
12 0% 97% 0.00 14690 0xffffff6487f7ee50 tmp_inactive+0x20a
12 0% 97% 0.00 14936 0xffffff3ff7be8da0 tmp_inactive+0x20a
12 0% 97% 0.00 14484 0xffffff3bf3f6b260 tmp_inactive+0x20a
12 0% 97% 0.00 14338 0xffffff13a6d29e98 tmp_inactive+0x20a
12 0% 97% 0.00 14299 0xffffff120a73d3d0 tmp_inactive+0x20a
12 0% 97% 0.00 15366 0xffffff11f0d81db8 tmp_inactive+0x20a
12 0% 97% 0.00 14637 0xffffff11bb7647d8 tmp_inactive+0x20a
12 0% 97% 0.00 3314 0xffffff11a36f6418
dmu_zfetch_stream_reclaim+0xa2
12 0% 97% 0.00 4612 0xffffff11a36f6418 dmu_zfetch_colinear+0x1b1
11 0% 98% 0.00 14772 0xffffff3ff7bd1290 tmp_inactive+0x20a
...
-------------------
R/W reader hold: 385142 events in 30.432 seconds (12656 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
148050 38% 38% 0.00 260982 0xffffff118c375a50 taskq_thread+0x2a0
16072 4% 43% 0.00 156922110 exported_lock rfs4_compound+0x23f
13984 4% 46% 0.00 17078 0xffffff11a317f008 dnode_hold_impl+0xd5
13983 4% 50% 0.00 5783 0xffffff11a317f2b0 dmu_zfetch_find+0x469
13370 3% 53% 0.00 14679 0xffffff115ab806f0 svc_poll+0x1e3
13175 3% 57% 0.00 34155 0xffffff11a317f008 dbuf_read+0x27e
12731 3% 60% 0.00 13634 0xffffff1158a4e4c0
ire_ftable_lookup_simple_v4+0x1ac
12717 3% 63% 0.00 5154 0xffffff115f6b0cf8
ire_ftable_lookup_simple_v4+0xf8
8825 2% 66% 0.00 10544 0xffffff116b8c7980 nfsauth_cache_get+0x289 8654 2% 68% 0.00 12179 0xffffff115ab806f0 svc_poll+0x2ac 8390 2% 70% 0.00 5391 0xffffff11a26a3878 dmu_zfetch_find+0x469 8388 2% 72% 0.00 28856 0xffffff11a26a35d0 dnode_hold_impl+0xd5 8230 2% 74% 0.00 25451 0xffffff11a26a35d0 dbuf_read+0x27e 6049 2% 76% 0.00 151358 0xffffff11a318cfb8 dmu_zfetch_find+0x469 6048 2% 78% 0.00 74204 0xffffff11a318cd10 dnode_hold_impl+0xd5 6026 2% 79% 0.00 168425 0xffffff11a318cd10 dbuf_read+0x27e 5937 2% 81% 0.00 3085 0xffffff11a25efe90 dbuf_read+0x27e 5935 2% 82% 0.00 3064 0xffffff11a25f0178 dbuf_read+0x27e 5689 1% 84% 0.00 2710 0xffffff11ca55abb0 rfs4_servinst_in_grace+0x36 3958 1% 85% 0.00 5017 0xffffff11a25efe90 dmu_buf_hold+0x9a 3956 1% 86% 0.00 4971 0xffffff11a25f0178 dmu_buf_hold+0x9a 3823 1% 87% 0.00 7629 0xffffff11dd163200 nfsauth_cache_get+0x289 3221 1% 88% 0.00 81462 0xffffff1188172218 as_fault+0x6c1 3201 1% 88% 0.00 72452 0xffffffb6222d7ec0 segvn_fault+0xe82 3201 1% 89% 0.00 76733 0xffffff11ceddcc68 segvn_fault+0xe8a 2854 1% 90% 0.00 5196 0xffffff116b713980 nfsauth_cache_get+0x289 2638 1% 91% 0.00 642688 0xffffff118c375190 taskq_thread+0x2a0 1979 1% 91% 0.00 5165 0xffffff7efb141578 zap_unlockdir+0x1a 1978 1% 92% 0.00 5106 0xffffff8969caf9b8 zap_unlockdir+0x1a 1475 0% 92% 0.00 5245 0xffffff7e7654a528 zap_unlockdir+0x1a 1341 0% 92% 0.00 3871 0xffffff11a36f5ba0 dbuf_read+0x27e 1185 0% 93% 0.00 20579 0xffffff114ca7b490 taskq_thread+0x2a0 1059 0% 93% 0.00 8312 0xffffff114cc2fbd8 cyclic_reprogram+0xac 1021 0% 93% 0.00 6695 0xffffff11a25f0708 dmu_zfetch_find+0x469 1021 0% 94% 0.00 13650 0xffffff11a25f0460 dnode_hold_impl+0xd5 1018 0% 94% 0.00 7361 0xffffff114cc2fe60 cyclic_reprogram+0xac ... -- Dr.Udo Grabowski Inst.f.Meteorology a.Climate Research IMK-ASF-SAT www.imk-asf.kit.edu/english/sat.php KIT - Karlsruhe Institute of Technology http://www.kit.edu Postfach 3640,76021 Karlsruhe,Germany T:(+49)721 608-26026 F:-926026 ------------------------------------------- illumos-discuss Archives: https://www.listbox.com/member/archive/182180/=now RSS Feed: https://www.listbox.com/member/archive/rss/182180/21175430-2e6923be Modify Your Subscription: https://www.listbox.com/member/?member_id=21175430&id_secret=21175430-6a77cda4 Powered by Listbox: http://www.listbox.com
smime.p7s
Description: S/MIME Cryptographic Signature
