XFS blocked task in xlog_cil_force_lsn
Hi,
around April 2012 there was a similar thread on this list which I have found via Google, so my mail topic is the same.
I have a RAID6 array with 5 disks (each 2TB, net: 6TB). While copying under heavy load there are always these blocks. At the bottom of this message I have included some line from the syslog.
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
So... first I have thought that my disks are faulty.
But with smartmontools I have started a short and a long test on all of the 5 disks: no errors
Then I have even recreated the whole array, but no improvement.
Details about my server: 3.2.0-57-generic, Ubuntu 12.04.3 LTS Details about the array: soft array with mdadm v3.2.5, no hardware raid controller in the server
The scheduler of the raid disks:
Quoted 6 lines
$ cat /sys/block/sd[cdefg]/queue/scheduler noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq]
Any ideas what I can do?
Thanks,
Kevin
Quoted 82 lines
Dec 18 02:19:19 kernel: [390470.193560] INFO: task kswapd0:51 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.194541] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.195795] kswapd0 D ffffffff81806240 0 51 2 0x00000000 Dec 18 02:19:19 kernel: [390470.195804] ffff8804658099f0 0000000000000046 ffff880465809a74 ffff880465809a78 Dec 18 02:19:19 kernel: [390470.195813] ffff880465809fd8 ffff880465809fd8 ffff880465809fd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.195820] ffff880465dd1700 ffff880465818000 0000000000000000 ffff88046175aa28 Dec 18 02:19:19 kernel: [390470.195827] Call Trace: Dec 18 02:19:19 kernel: [390470.195844] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.195850] [<ffffffff81660437>] __mutex_lock_slowpath+0xd7/0x150 Dec 18 02:19:19 kernel: [390470.195856] [<ffffffff8166004a>] mutex_lock+0x2a/0x50 Dec 18 02:19:19 kernel: [390470.195904] [<ffffffffa029dcf8>] xfs_reclaim_inodes_ag+0x2d8/0x3a0 [xfs] Dec 18 02:19:19 kernel: [390470.195928] [<ffffffffa029d83a>] ? __xfs_inode_set_reclaim_tag+0x4a/0x140 [xfs] Dec 18 02:19:19 kernel: [390470.195951] [<ffffffffa029d96d>] ? xfs_inode_set_reclaim_tag+0x3d/0xa0 [xfs] Dec 18 02:19:19 kernel: [390470.195973] [<ffffffffa029d9b4>] ? xfs_inode_set_reclaim_tag+0x84/0xa0 [xfs] Dec 18 02:19:19 kernel: [390470.195995] [<ffffffffa029c6a5>] ? xfs_fs_destroy_inode+0x65/0x150 [xfs] Dec 18 02:19:19 kernel: [390470.196003] [<ffffffff81194dfc>] ? destroy_inode+0x3c/0x70 Dec 18 02:19:19 kernel: [390470.196008] [<ffffffff81194f5a>] ? evict+0x12a/0x1c0 Dec 18 02:19:19 kernel: [390470.196016] [<ffffffff8166154e>] ? _raw_spin_lock+0xe/0x20 Dec 18 02:19:19 kernel: [390470.196037] [<ffffffffa029df63>] xfs_reclaim_inodes_nr+0x33/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.196059] [<ffffffffa029a715>] xfs_fs_free_cached_objects+0x15/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.196067] [<ffffffff8117d71e>] prune_super+0x10e/0x1a0 Dec 18 02:19:19 kernel: [390470.196073] [<ffffffff8112b924>] shrink_slab+0x154/0x300 Dec 18 02:19:19 kernel: [390470.196079] [<ffffffff8112ec1a>] balance_pgdat+0x50a/0x6d0 Dec 18 02:19:19 kernel: [390470.196085] [<ffffffff8112ef01>] kswapd+0x121/0x220 Dec 18 02:19:19 kernel: [390470.196090] [<ffffffff8112ede0>] ? balance_pgdat+0x6d0/0x6d0 Dec 18 02:19:19 kernel: [390470.196097] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.196105] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.196111] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.196117] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13 Dec 18 02:19:19 kernel: [390470.196121] INFO: task kswapd1:52 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.197086] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.198427] kswapd1 D 0000000000000007 0 52 2 0x00000000 Dec 18 02:19:19 kernel: [390470.198434] ffff88046580b840 0000000000000046 0000000000000001 00000000ffffffff Dec 18 02:19:19 kernel: [390470.198441] ffff88046580bfd8 ffff88046580bfd8 ffff88046580bfd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.198447] ffff880865e8ae00 ffff880465819700 ffff88046580b830 0000000000000004 Dec 18 02:19:19 kernel: [390470.198454] Call Trace: Dec 18 02:19:19 kernel: [390470.198462] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.198498] [<ffffffffa02e4d17>] xlog_cil_force_lsn+0xf7/0x120 [xfs] Dec 18 02:19:19 kernel: [390470.198510] [<ffffffff811643af>] ? unfreeze_partials+0x24f/0x2b0 Dec 18 02:19:19 kernel: [390470.198521] [<ffffffff810608e0>] ? try_to_wake_up+0x200/0x200 Dec 18 02:19:19 kernel: [390470.198554] [<ffffffffa02d1c65>] ? xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198587] [<ffffffffa02e3367>] _xfs_log_force_lsn+0x57/0x2e0 [xfs] Dec 18 02:19:19 kernel: [390470.198617] [<ffffffffa02ba398>] ? xfs_bmbt_get_all+0x18/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.198646] [<ffffffffa02ae972>] ? xfs_bmap_search_multi_extents+0x92/0x110 [xfs] Dec 18 02:19:19 kernel: [390470.198677] [<ffffffffa02d1c65>] ? xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198710] [<ffffffffa02e3608>] xfs_log_force_lsn+0x18/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.198740] [<ffffffffa02cfdd4>] xfs_iunpin_nowait+0x44/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198769] [<ffffffffa02d1c65>] xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198780] [<ffffffff8104ef9b>] ? try_wait_for_completion+0x4b/0x60 Dec 18 02:19:19 kernel: [390470.198806] [<ffffffffa029cf72>] xfs_reclaim_inode+0xb2/0x2a0 [xfs] Dec 18 02:19:19 kernel: [390470.198818] [<ffffffff81314a4c>] ? radix_tree_gang_lookup_tag.part.7+0x6c/0xf0 Dec 18 02:19:19 kernel: [390470.198844] [<ffffffffa029dc5f>] xfs_reclaim_inodes_ag+0x23f/0x3a0 [xfs] Dec 18 02:19:19 kernel: [390470.198871] [<ffffffffa029df63>] xfs_reclaim_inodes_nr+0x33/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.198895] [<ffffffffa029a715>] xfs_fs_free_cached_objects+0x15/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.198905] [<ffffffff8117d71e>] prune_super+0x10e/0x1a0 Dec 18 02:19:19 kernel: [390470.198913] [<ffffffff8112b924>] shrink_slab+0x154/0x300 Dec 18 02:19:19 kernel: [390470.198922] [<ffffffff8112ec1a>] balance_pgdat+0x50a/0x6d0 Dec 18 02:19:19 kernel: [390470.198931] [<ffffffff8112ef01>] kswapd+0x121/0x220 Dec 18 02:19:19 kernel: [390470.198938] [<ffffffff8112ede0>] ? balance_pgdat+0x6d0/0x6d0 Dec 18 02:19:19 kernel: [390470.198947] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.198956] [<ffffffff8105f750>] ? __migrate_task+0x120/0x120 Dec 18 02:19:19 kernel: [390470.198966] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.198974] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.198984] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13 Dec 18 02:19:19 kernel: [390470.199017] INFO: task xfsaild/dm-0:19192 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.199828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.200262] xfsaild/dm-0 D 0000000000000001 0 19192 2 0x00000000 Dec 18 02:19:19 kernel: [390470.200268] ffff88084e847a60 0000000000000046 ffff88046454d500 0000000000000000 Dec 18 02:19:19 kernel: [390470.200274] ffff88084e847fd8 ffff88084e847fd8 ffff88084e847fd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.200281] ffff88045fdd0000 ffff880461b1dc00 ffff88084e847a50 ffff88085f47d080 Dec 18 02:19:19 kernel: [390470.200288] Call Trace: Dec 18 02:19:19 kernel: [390470.200293] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.200323] [<ffffffffa02e25da>] xlog_state_get_iclog_space+0xea/0x2e0 [xfs] Dec 18 02:19:19 kernel: [390470.200330] [<ffffffff810608e0>] ? try_to_wake_up+0x200/0x200 Dec 18 02:19:19 kernel: [390470.200358] [<ffffffffa02e2b99>] xlog_write+0xe9/0x400 [xfs] Dec 18 02:19:19 kernel: [390470.200382] [<ffffffffa02a2877>] ? kmem_zone_alloc+0x67/0xe0 [xfs] Dec 18 02:19:19 kernel: [390470.200410] [<ffffffffa02e440c>] xlog_cil_push+0x20c/0x380 [xfs] Dec 18 02:19:19 kernel: [390470.200438] [<ffffffffa02e4d2e>] xlog_cil_force_lsn+0x10e/0x120 [xfs] Dec 18 02:19:19 kernel: [390470.200446] [<ffffffff810136e5>] ? __switch_to+0xf5/0x360 Dec 18 02:19:19 kernel: [390470.200473] [<ffffffffa02e3098>] _xfs_log_force+0x68/0x2a0 [xfs] Dec 18 02:19:19 kernel: [390470.200481] [<ffffffff81078cb2>] ? try_to_del_timer_sync+0x92/0x130 Dec 18 02:19:19 kernel: [390470.200507] [<ffffffffa02e32e8>] xfs_log_force+0x18/0x40 [xfs]
Quoted 8 lines
Dec 18 02:19:19 kernel: [390470.200535] [<ffffffffa02e7743>] xfsaild_push+0x213/0x680 [xfs] Dec 18 02:19:19 kernel: [390470.200540] [<ffffffff8165fb45>] ? schedule_timeout+0x175/0x320 Dec 18 02:19:19 kernel: [390470.200568] [<ffffffffa02e7c12>] xfsaild+0x62/0xc0 [xfs] Dec 18 02:19:19 kernel: [390470.200593] [<ffffffffa02e7bb0>] ? xfsaild_push+0x680/0x680 [xfs] Dec 18 02:19:19 kernel: [390470.200599] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.200605] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.200611] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.200617] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 31 lines · Kevin Richter
Hi,
around April 2012 there was a similar thread on this list which I have found via Google, so my mail topic is the same.
I have a RAID6 array with 5 disks (each 2TB, net: 6TB). While copying under heavy load there are always these blocks. At the bottom of this message I have included some line from the syslog.
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
So... first I have thought that my disks are faulty.
But with smartmontools I have started a short and a long test on all of the 5 disks: no errorsThen I have even recreated the whole array, but no improvement.
Details about my server: 3.2.0-57-generic, Ubuntu 12.04.3 LTS Details about the array: soft array with mdadm v3.2.5, no hardware raid controller in the server
The scheduler of the raid disks:
Quoted 6 lines
$ cat /sys/block/sd[cdefg]/queue/scheduler noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq]
Quoted 1 line
Any ideas what I can do?
Your workload is seeking the disks to death, which is why you're getting these timeouts. The actuators simply can't keep up.
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
2. Post your chunk size and RAID6 stripe_cache_size value. They may be sub optimal for your workload. For the latter
$ cat /sys/block/mdX/md/stripe_cache_size
3. Post 'xfs_info /dev/mdX'
4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
Quoted 96 lines
Thanks,
KevinQuoted 90 lines
Dec 18 02:19:19 kernel: [390470.193560] INFO: task kswapd0:51 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.194541] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.195795] kswapd0 D ffffffff81806240 0 51 2 0x00000000 Dec 18 02:19:19 kernel: [390470.195804] ffff8804658099f0 0000000000000046 ffff880465809a74 ffff880465809a78 Dec 18 02:19:19 kernel: [390470.195813] ffff880465809fd8 ffff880465809fd8 ffff880465809fd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.195820] ffff880465dd1700 ffff880465818000 0000000000000000 ffff88046175aa28 Dec 18 02:19:19 kernel: [390470.195827] Call Trace: Dec 18 02:19:19 kernel: [390470.195844] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.195850] [<ffffffff81660437>] __mutex_lock_slowpath+0xd7/0x150 Dec 18 02:19:19 kernel: [390470.195856] [<ffffffff8166004a>] mutex_lock+0x2a/0x50 Dec 18 02:19:19 kernel: [390470.195904] [<ffffffffa029dcf8>] xfs_reclaim_inodes_ag+0x2d8/0x3a0 [xfs] Dec 18 02:19:19 kernel: [390470.195928] [<ffffffffa029d83a>] ? __xfs_inode_set_reclaim_tag+0x4a/0x140 [xfs] Dec 18 02:19:19 kernel: [390470.195951] [<ffffffffa029d96d>] ? xfs_inode_set_reclaim_tag+0x3d/0xa0 [xfs] Dec 18 02:19:19 kernel: [390470.195973] [<ffffffffa029d9b4>] ? xfs_inode_set_reclaim_tag+0x84/0xa0 [xfs] Dec 18 02:19:19 kernel: [390470.195995] [<ffffffffa029c6a5>] ? xfs_fs_destroy_inode+0x65/0x150 [xfs] Dec 18 02:19:19 kernel: [390470.196003] [<ffffffff81194dfc>] ? destroy_inode+0x3c/0x70 Dec 18 02:19:19 kernel: [390470.196008] [<ffffffff81194f5a>] ? evict+0x12a/0x1c0 Dec 18 02:19:19 kernel: [390470.196016] [<ffffffff8166154e>] ? _raw_spin_lock+0xe/0x20 Dec 18 02:19:19 kernel: [390470.196037] [<ffffffffa029df63>] xfs_reclaim_inodes_nr+0x33/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.196059] [<ffffffffa029a715>] xfs_fs_free_cached_objects+0x15/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.196067] [<ffffffff8117d71e>] prune_super+0x10e/0x1a0 Dec 18 02:19:19 kernel: [390470.196073] [<ffffffff8112b924>] shrink_slab+0x154/0x300 Dec 18 02:19:19 kernel: [390470.196079] [<ffffffff8112ec1a>] balance_pgdat+0x50a/0x6d0 Dec 18 02:19:19 kernel: [390470.196085] [<ffffffff8112ef01>] kswapd+0x121/0x220 Dec 18 02:19:19 kernel: [390470.196090] [<ffffffff8112ede0>] ? balance_pgdat+0x6d0/0x6d0 Dec 18 02:19:19 kernel: [390470.196097] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.196105] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.196111] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.196117] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13 Dec 18 02:19:19 kernel: [390470.196121] INFO: task kswapd1:52 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.197086] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.198427] kswapd1 D 0000000000000007 0 52 2 0x00000000 Dec 18 02:19:19 kernel: [390470.198434] ffff88046580b840 0000000000000046 0000000000000001 00000000ffffffff Dec 18 02:19:19 kernel: [390470.198441] ffff88046580bfd8 ffff88046580bfd8 ffff88046580bfd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.198447] ffff880865e8ae00 ffff880465819700 ffff88046580b830 0000000000000004 Dec 18 02:19:19 kernel: [390470.198454] Call Trace: Dec 18 02:19:19 kernel: [390470.198462] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.198498] [<ffffffffa02e4d17>] xlog_cil_force_lsn+0xf7/0x120 [xfs] Dec 18 02:19:19 kernel: [390470.198510] [<ffffffff811643af>] ? unfreeze_partials+0x24f/0x2b0 Dec 18 02:19:19 kernel: [390470.198521] [<ffffffff810608e0>] ? try_to_wake_up+0x200/0x200 Dec 18 02:19:19 kernel: [390470.198554] [<ffffffffa02d1c65>] ? xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198587] [<ffffffffa02e3367>] _xfs_log_force_lsn+0x57/0x2e0 [xfs] Dec 18 02:19:19 kernel: [390470.198617] [<ffffffffa02ba398>] ? xfs_bmbt_get_all+0x18/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.198646] [<ffffffffa02ae972>] ? xfs_bmap_search_multi_extents+0x92/0x110 [xfs] Dec 18 02:19:19 kernel: [390470.198677] [<ffffffffa02d1c65>] ? xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198710] [<ffffffffa02e3608>] xfs_log_force_lsn+0x18/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.198740] [<ffffffffa02cfdd4>] xfs_iunpin_nowait+0x44/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198769] [<ffffffffa02d1c65>] xfs_iunpin_wait+0x35/0xb0 [xfs] Dec 18 02:19:19 kernel: [390470.198780] [<ffffffff8104ef9b>] ? try_wait_for_completion+0x4b/0x60 Dec 18 02:19:19 kernel: [390470.198806] [<ffffffffa029cf72>] xfs_reclaim_inode+0xb2/0x2a0 [xfs] Dec 18 02:19:19 kernel: [390470.198818] [<ffffffff81314a4c>] ? radix_tree_gang_lookup_tag.part.7+0x6c/0xf0 Dec 18 02:19:19 kernel: [390470.198844] [<ffffffffa029dc5f>] xfs_reclaim_inodes_ag+0x23f/0x3a0 [xfs] Dec 18 02:19:19 kernel: [390470.198871] [<ffffffffa029df63>] xfs_reclaim_inodes_nr+0x33/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.198895] [<ffffffffa029a715>] xfs_fs_free_cached_objects+0x15/0x20 [xfs] Dec 18 02:19:19 kernel: [390470.198905] [<ffffffff8117d71e>] prune_super+0x10e/0x1a0 Dec 18 02:19:19 kernel: [390470.198913] [<ffffffff8112b924>] shrink_slab+0x154/0x300 Dec 18 02:19:19 kernel: [390470.198922] [<ffffffff8112ec1a>] balance_pgdat+0x50a/0x6d0 Dec 18 02:19:19 kernel: [390470.198931] [<ffffffff8112ef01>] kswapd+0x121/0x220 Dec 18 02:19:19 kernel: [390470.198938] [<ffffffff8112ede0>] ? balance_pgdat+0x6d0/0x6d0 Dec 18 02:19:19 kernel: [390470.198947] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.198956] [<ffffffff8105f750>] ? __migrate_task+0x120/0x120 Dec 18 02:19:19 kernel: [390470.198966] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.198974] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.198984] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13 Dec 18 02:19:19 kernel: [390470.199017] INFO: task xfsaild/dm-0:19192 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.199828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.200262] xfsaild/dm-0 D 0000000000000001 0 19192 2 0x00000000 Dec 18 02:19:19 kernel: [390470.200268] ffff88084e847a60 0000000000000046 ffff88046454d500 0000000000000000 Dec 18 02:19:19 kernel: [390470.200274] ffff88084e847fd8 ffff88084e847fd8 ffff88084e847fd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.200281] ffff88045fdd0000 ffff880461b1dc00 ffff88084e847a50 ffff88085f47d080 Dec 18 02:19:19 kernel: [390470.200288] Call Trace: Dec 18 02:19:19 kernel: [390470.200293] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.200323] [<ffffffffa02e25da>] xlog_state_get_iclog_space+0xea/0x2e0 [xfs] Dec 18 02:19:19 kernel: [390470.200330] [<ffffffff810608e0>] ? try_to_wake_up+0x200/0x200 Dec 18 02:19:19 kernel: [390470.200358] [<ffffffffa02e2b99>] xlog_write+0xe9/0x400 [xfs] Dec 18 02:19:19 kernel: [390470.200382] [<ffffffffa02a2877>] ? kmem_zone_alloc+0x67/0xe0 [xfs] Dec 18 02:19:19 kernel: [390470.200410] [<ffffffffa02e440c>] xlog_cil_push+0x20c/0x380 [xfs] Dec 18 02:19:19 kernel: [390470.200438] [<ffffffffa02e4d2e>] xlog_cil_force_lsn+0x10e/0x120 [xfs] Dec 18 02:19:19 kernel: [390470.200446] [<ffffffff810136e5>] ? __switch_to+0xf5/0x360 Dec 18 02:19:19 kernel: [390470.200473] [<ffffffffa02e3098>] _xfs_log_force+0x68/0x2a0 [xfs] Dec 18 02:19:19 kernel: [390470.200481] [<ffffffff81078cb2>] ? try_to_del_timer_sync+0x92/0x130 Dec 18 02:19:19 kernel: [390470.200507] [<ffffffffa02e32e8>] xfs_log_force+0x18/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.200535] [<ffffffffa02e7743>] xfsaild_push+0x213/0x680 [xfs] Dec 18 02:19:19 kernel: [390470.200540] [<ffffffff8165fb45>] ? schedule_timeout+0x175/0x320 Dec 18 02:19:19 kernel: [390470.200568] [<ffffffffa02e7c12>] xfsaild+0x62/0xc0 [xfs] Dec 18 02:19:19 kernel: [390470.200593] [<ffffffffa02e7bb0>] ? xfsaild_push+0x680/0x680 [xfs] Dec 18 02:19:19 kernel: [390470.200599] [<ffffffff8108b64c>] kthread+0x8c/0xa0 Dec 18 02:19:19 kernel: [390470.200605] [<ffffffff8166bcf4>] kernel_thread_helper+0x4/0x10 Dec 18 02:19:19 kernel: [390470.200611] [<ffffffff8108b5c0>] ? flush_kthread_worker+0xa0/0xa0 Dec 18 02:19:19 kernel: [390470.200617] [<ffffffff8166bcf0>] ? gs_change+0x13/0x13
Signature · 6 lines
Stan _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Thanks for your mails!
Quoted 1 line
This is unusual. How long have you waited?
For the reboot? One night.
After the copy process hangs: several hours. But mostly it recovers after several minutes.
Quoted 2 lines
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
Can I switch it while my copy process (from a separate hd to this raid) is running... without data loss? Otherwise I would wait a bit, because now it is actually running for 8 hours without kernel panics.
Quoted 2 lines
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload.
$ cat /sys/block/md2/md/stripe_cache_size 256 $ mdadm --detail /dev/md2 | grep Chunk Chunk Size : 512K
Quoted 1 line
3. Post '
xfs_info/dev/mdX'
There is a LUKS volume around /dev/md2, named '6tb'.
Quoted 13 lines
$ xfs_info /dev/md2
xfs_info: /dev/md2 is not a mounted XFS filesystem
$ xfs_info /dev/mapper/6tb
meta-data=/dev/mapper/6tb isize=256 agcount=32, agsize=45631360 blks
= sectsz=512 attr=2
data = bsize=4096 blocks=1460203520, imaxpct=5
= sunit=128 swidth=384 blks
naming =version 2 bsize=4096 ascii-ci=0
log =internal bsize=4096 blocks=521728, version=2
= sectsz=512 sunit=8 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0Quoted 7 lines
4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
No no, swap is not on any of the raid disks.
Quoted 3 lines
# cat /proc/swaps Filename Type Size Used Priority /dev/sda3 partition 7812496 0 -1
sda is not in the raid. In the raid there are sd[cdefg].
Quoted 2 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
cd /olddharddisk
cp -av . /raid/
oldhardddisk is a mounted 1tb old harddisk, /raid is the 6tb raid from above.
Heavy workload while this copy process (2 CPUs, each 4 cores):
Quoted 8 lines
top - 11:13:37 up 4 days, 21:32, 2 users, load average: 12.95, 11.33, 10.32
Tasks: 155 total, 2 running, 153 sleeping, 0 stopped, 0 zombie Cpu(s): 0.0%us, 5.7%sy, 0.0%ni, 82.1%id, 11.8%wa, 0.0%hi, 0.3%si, 0.0%st Mem: 32916276k total, 32750240k used, 166036k free, 10076760k buffers Swap: 7812496k total, 0k used, 7812496k free, 21221136k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
699 root 20 0 0 0 0 S 11 0.0 248:17.59md2_raid6
Dont know what consumes all of this 32GB RAM... 'top' sorted by memory consumption does not tell me. All entries are only 0.0% and 0.1%
Thanks,
Kevin
Am 18.12.2013 04:38, schrieb Stan Hoeppner:
Quoted 55 lines · Kevin Richter
Quoted 31 lines
Hi,
around April 2012 there was a similar thread on this list which I have found via Google, so my mail topic is the same.
I have a RAID6 array with 5 disks (each 2TB, net: 6TB). While copying under heavy load there are always these blocks. At the bottom of this message I have included some line from the syslog.
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
So... first I have thought that my disks are faulty.
But with smartmontools I have started a short and a long test on all of the 5 disks: no errorsThen I have even recreated the whole array, but no improvement.
Details about my server: 3.2.0-57-generic, Ubuntu 12.04.3 LTS Details about the array: soft array with mdadm v3.2.5, no hardware raid controller in the server
The scheduler of the raid disks:
Quoted 6 lines
$ cat /sys/block/sd[cdefg]/queue/scheduler noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq]Quoted 1 line
Any ideas what I can do?
Your workload is seeking the disks to death, which is why you're getting these timeouts. The actuators simply can't keep up.
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload. For the latter$ cat /sys/block/mdX/md/stripe_cache_size3. Post '
xfs_info/dev/mdX'4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
Quoted 3 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 8 lines · Kevin Richter
Thanks for your mails!
Quoted 1 line
This is unusual. How long have you waited?
For the reboot? One night.
After the copy process hangs: several hours. But mostly it recovers after several minutes.
Quoted 6 lines
Quoted 2 lines
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
Can I switch it while my copy process (from a separate hd to this raid) is running... without data loss? Otherwise I would wait a bit, because now it is actually running for 8 hours without kernel panics.
Yes, you can safely change the elevator on the fly. Repeat the following once for each disk, replacing X appropriately.
$ echo deadline > /sys/block/sdX/queue/scheduler
This on the fly change is not permanent. Add "elevator=deadline" to your kernel command line in your bootloader config file. Or you can add the commands to a startup script. Or if you build your own kernels simply make it the default, and/or remove all the other elevators from your kernel config, which is what I do.
Quoted 5 lines
Quoted 2 lines
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload.$ cat /sys/block/md2/md/stripe_cache_size 256
256 is the default and it is way too low. This is limiting your write througput. Increase this to a minimum of 1024 which will give you a 20MB stripe cache buffer. This should become active immediately. Add it to a startup script to make it permanent.
$ echo 1024 > /sys/block/md2/md/stripe_cache_size
((4096*stripe-cache_size)*num_drives)= RAM consumed for stripe cache
At some future point when the system is idle, play with FIO write testing and multiple jobs (threads) with stripe_cache_size values up to 2048 to see which value gives the best throughput. Test 1024, 2048, 4096. Going higher probably won't gain anything. And at some point as you go higher your throughput will decrease. When you see that, select the previous value and make it permanent.
Quoted 6 lines
$ mdadm --detail /dev/md2 | grep Chunk Chunk Size : 512KQuoted 1 line
3. Post '
xfs_info/dev/mdX'There is a LUKS volume around
/dev/md2, named '6tb'.
Ok, this adds a huge fly to the ointment. LUKS is single threaded per device. You've encrypted the md device instead of the individual disks.
This limits your encryption throughput to a single CPU core. You've
not provided any data on your LUKS thread. Is it pegging a core during large file IO? I'd bet it is. That would explain all of this.
Quoted 11 lines
Quoted 11 lines
$ xfs_info /dev/md2 xfs_info: /dev/md2 is not a mounted XFS filesystem $ xfs_info /dev/mapper/6tb meta-data=/dev/mapper/6tb isize=256 agcount=32, agsize=45631360 blks = sectsz=512 attr=2 data = bsize=4096 blocks=1460203520, imaxpct=5 = sunit=128 swidth=384 blks naming =version 2 bsize=4096 ascii-ci=0 log =internal bsize=4096 blocks=521728, version=2 = sectsz=512 sunit=8 blks, lazy-count=1 realtime =none extsz=4096 blocks=0, rtextents=0
md2 is 5 spindle RAID6, geometry 512KB * 3 = 1.5MB stripe width. The XFS alignment matches the md device. This may be hurting you with LUKS between XFS and md. I don't know how LUKS handles 1.5MB inbound writes and if it passes an aligned write to md after encrypting. I also don't know how it handles writes barriers passed down the stack by XFS, or if it does at all.
Quoted 8 lines
Quoted 7 lines
4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
Quoted 6 lines
No no, swap is not on any of the raid disks.
Quoted 3 lines
# cat /proc/swaps Filename Type Size Used Priority /dev/sda3 partition 7812496 0 -1sda is not in the raid. In the raid there are sd[cdefg].
I was wrong here. After reading a little about kswapd I now know it doesn't simply move pages to/from disk. It frees memory in other ways as well. In this case it's apparently waiting to free an inode being reclaimed by xfs_reclaim_inode, which is stalled on lower level IO. So kswapd times out as a result. A slow LUKS thread would explain this as well.
Quoted 8 lines
Quoted 2 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
cd /olddharddisk
cp -av . /raid/oldhardddisk is a mounted 1tb old harddisk, /raid is the 6tb raid from above.
So you are simply doing a huge file copy from an apparently slower single disk to an apparently faster striped RAID. But you get horrible throughput and kernel timeout errors, and the RAID disks are apparently fairly idle.
Quoted 1 line
Heavy workload while this copy process (2 CPUs, each 4 cores):
Model # of the CPUs so I can look up the specs?
Quoted 11 lines
Quoted 8 lines
top - 11:13:37 up 4 days, 21:32, 2 users, load average: 12.95, 11.33, 10.32
Tasks: 155 total, 2 running, 153 sleeping, 0 stopped, 0 zombie Cpu(s): 0.0%us, 5.7%sy, 0.0%ni, 82.1%id, 11.8%wa, 0.0%hi, 0.3%si, 0.0%st Mem: 32916276k total, 32750240k used, 166036k free, 10076760k buffers Swap: 7812496k total, 0k used, 7812496k free, 21221136k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
699 root 20 0 0 0 0 S 11 0.0 248:17.59md2_raid6Dont know what consumes all of this 32GB RAM... 'top' sorted by memory consumption does not tell me. All entries are only 0.0% and 0.1%
~30GB of your RAM is being eaten by filesystem metadata buffers (10GB) and page cache (20GB). Linux uses nearly all free memory for cache and buffers to prevent disk accesses, which speeds up access to frequently used data considerably. This is normal. A huge copy like this is going to cause a huge amount caching.
I assume this 1TB file copy has finally completed. Start another large test copy and paste the CPU burn for the LUKS thread so we can confirm whether this is the root cause of your problem.
Signature · 1 line
Stan
Quoted 65 lines
Thanks,
KevinAm 18.12.2013 04:38, schrieb Stan Hoeppner:
Quoted 55 lines · Kevin Richter
Quoted 31 lines
Hi,
around April 2012 there was a similar thread on this list which I have found via Google, so my mail topic is the same.
I have a RAID6 array with 5 disks (each 2TB, net: 6TB). While copying under heavy load there are always these blocks. At the bottom of this message I have included some line from the syslog.
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
So... first I have thought that my disks are faulty.
But with smartmontools I have started a short and a long test on all of the 5 disks: no errorsThen I have even recreated the whole array, but no improvement.
Details about my server: 3.2.0-57-generic, Ubuntu 12.04.3 LTS Details about the array: soft array with mdadm v3.2.5, no hardware raid controller in the server
The scheduler of the raid disks:
Quoted 6 lines
$ cat /sys/block/sd[cdefg]/queue/scheduler noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq] noop deadline [cfq]Quoted 1 line
Any ideas what I can do?
Your workload is seeking the disks to death, which is why you're getting these timeouts. The actuators simply can't keep up.
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload. For the latter$ cat /sys/block/mdX/md/stripe_cache_size3. Post '
xfs_info/dev/mdX'4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
Quoted 9 lines
Quoted 3 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Thanks a lot for your huge replies!
Quoted 2 lines
Oh, that's quite old. I'd suggest upgrading to a much more recent kernel as we've fixed lots of issues in this area since then.
First I have switched to the newer kernel from Ubuntu Saucy:
$ uname -a Linux 3.11.0-14-generic #21~precise1-Ubuntu SMP
Thus, it seems that the default scheduler has been changed to deadline. I did not change anything. After a reboot the schedulers of all disks are now deadline.
Quoted 1 line
Model # of the CPUs so I can look up the specs?
Intel(R) Xeon(R) CPU E5-2609 0 @ 2.40GHz
I have prepared a folder with 60GB for the tests. This is nearly twice of the available memory, so the process should be forced to actually write the stuff to the disk - and not only hold in the memory.
Quoted 18 lines
$ echo 256 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /6tb/foo1/ real 25m38.925s user 0m0.595s sys 1m23.182s$ echo 1024 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo2/ real 7m32.824s user 0m0.438s sys 1m6.759s$ echo 2048 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo3/ real 5m32.847s user 0m0.418s sys 1m5.671s
Quoted 5 lines
$ echo 4096 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo4/ real 5m54.554s user 0m0.437s sys 1m6.268s
The difference is really amazing! So 2048 seems to be the best choice. 60GB in 5,5minutes are 180MB/sek. That sounds a bit high, doesnt it? The RAID only consist of 5 SATA disks with 7200rpm.
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 6 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cached
Quoted 12 lines
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1
And the best thing at all:
While all of these tests there are no warnings/panics in the syslog.
With best regards,
Kevin
Am 19.12.2013 15:11, schrieb Stan Hoeppner:
Quoted 139 lines · Kevin Richter
Quoted 8 lines
Thanks for your mails!
Quoted 1 line
This is unusual. How long have you waited?
For the reboot? One night.
After the copy process hangs: several hours. But mostly it recovers after several minutes.Quoted 6 lines
Quoted 2 lines
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
Can I switch it while my copy process (from a separate hd to this raid) is running... without data loss? Otherwise I would wait a bit, because now it is actually running for 8 hours without kernel panics.
Yes, you can safely change the elevator on the fly. Repeat the following once for each disk, replacing X appropriately.
$ echo deadline > /sys/block/sdX/queue/schedulerThis on the fly change is not permanent. Add "elevator=deadline" to your kernel command line in your bootloader config file. Or you can add the commands to a startup script. Or if you build your own kernels simply make it the default, and/or remove all the other elevators from your kernel config, which is what I do.
Quoted 5 lines
Quoted 2 lines
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload.$ cat /sys/block/md2/md/stripe_cache_size 256256 is the default and it is way too low. This is limiting your write througput. Increase this to a minimum of 1024 which will give you a 20MB stripe cache buffer. This should become active immediately. Add it to a startup script to make it permanent.
$ echo 1024 > /sys/block/md2/md/stripe_cache_size((4096*stripe-cache_size)*num_drives)= RAM consumed for stripe cache
At some future point when the system is idle, play with FIO write testing and multiple jobs (threads) with
stripe_cache_sizevalues up to 2048 to see which value gives the best throughput. Test 1024, 2048, 4096. Going higher probably won't gain anything. And at some point as you go higher your throughput will decrease. When you see that, select the previous value and make it permanent.Quoted 6 lines
$ mdadm --detail /dev/md2 | grep Chunk Chunk Size : 512KQuoted 1 line
3. Post '
xfs_info/dev/mdX'There is a LUKS volume around
/dev/md2, named '6tb'.Ok, this adds a huge fly to the ointment. LUKS is single threaded per device. You've encrypted the md device instead of the individual disks.
This limits your encryption throughput to a single CPU core. You've
not provided any data on your LUKS thread. Is it pegging a core during large file IO? I'd bet it is. That would explain all of this.Quoted 11 lines
Quoted 11 lines
$ xfs_info /dev/md2 xfs_info: /dev/md2 is not a mounted XFS filesystem $ xfs_info /dev/mapper/6tb meta-data=/dev/mapper/6tb isize=256 agcount=32, agsize=45631360 blks = sectsz=512 attr=2 data = bsize=4096 blocks=1460203520, imaxpct=5 = sunit=128 swidth=384 blks naming =version 2 bsize=4096 ascii-ci=0 log =internal bsize=4096 blocks=521728, version=2 = sectsz=512 sunit=8 blks, lazy-count=1 realtime =none extsz=4096 blocks=0, rtextents=0md2 is 5 spindle RAID6, geometry 512KB * 3 = 1.5MB stripe width. The XFS alignment matches the md device. This may be hurting you with LUKS between XFS and md. I don't know how LUKS handles 1.5MB inbound writes and if it passes an aligned write to md after encrypting. I also don't know how it handles writes barriers passed down the stack by XFS, or if it does at all.
Quoted 8 lines
Quoted 7 lines
4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
Quoted 6 lines
No no, swap is not on any of the raid disks.
Quoted 3 lines
# cat /proc/swaps Filename Type Size Used Priority /dev/sda3 partition 7812496 0 -1sda is not in the raid. In the raid there are sd[cdefg].
I was wrong here. After reading a little about kswapd I now know it doesn't simply move pages to/from disk. It frees memory in other ways as well. In this case it's apparently waiting to free an inode being reclaimed by
xfs_reclaim_inode, which is stalled on lower level IO. So kswapd times out as a result. A slow LUKS thread would explain this as well.Quoted 8 lines
Quoted 2 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
cd /olddharddisk
cp -av . /raid/oldhardddisk is a mounted 1tb old harddisk, /raid is the 6tb raid from above.
So you are simply doing a huge file copy from an apparently slower single disk to an apparently faster striped RAID. But you get horrible throughput and kernel timeout errors, and the RAID disks are apparently fairly idle.
Quoted 1 line
Heavy workload while this copy process (2 CPUs, each 4 cores):
Model # of the CPUs so I can look up the specs?
Quoted 11 lines
Quoted 8 lines
top - 11:13:37 up 4 days, 21:32, 2 users, load average: 12.95, 11.33, 10.32
Tasks: 155 total, 2 running, 153 sleeping, 0 stopped, 0 zombie Cpu(s): 0.0%us, 5.7%sy, 0.0%ni, 82.1%id, 11.8%wa, 0.0%hi, 0.3%si, 0.0%st Mem: 32916276k total, 32750240k used, 166036k free, 10076760k buffers Swap: 7812496k total, 0k used, 7812496k free, 21221136k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
699 root 20 0 0 0 0 S 11 0.0 248:17.59md2_raid6Dont know what consumes all of this 32GB RAM... 'top' sorted by memory consumption does not tell me. All entries are only 0.0% and 0.1%
~30GB of your RAM is being eaten by filesystem metadata buffers (10GB) and page cache (20GB). Linux uses nearly all free memory for cache and buffers to prevent disk accesses, which speeds up access to frequently used data considerably. This is normal. A huge copy like this is going to cause a huge amount caching.
Quoted 4 lines
I assume this 1TB file copy has finally completed. Start another large test copy and paste the CPU burn for the LUKS thread so we can confirm whether this is the root cause of your problem.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 1 line · Kevin Richter
Thanks a lot for your huge replies!
You're welcome.
Quoted 10 lines
Quoted 2 lines
Oh, that's quite old. I'd suggest upgrading to a much more recent kernel as we've fixed lots of issues in this area since then.
First I have switched to the newer kernel from Ubuntu Saucy:
$ uname -a Linux 3.11.0-14-generic #21~precise1-Ubuntu SMPThus, it seems that the default scheduler has been changed to deadline. I did not change anything. After a reboot the schedulers of all disks are now deadline.
Good move Ubuntu.
Quoted 2 lines
Quoted 1 line
Model # of the CPUs so I can look up the specs?
Intel(R) Xeon(R) CPU E5-2609 0 @ 2.40GHz
Strong CPUs.
Quoted 28 lines
I have prepared a folder with 60GB for the tests. This is nearly twice of the available memory, so the process should be forced to actually write the stuff to the disk - and not only hold in the memory.
Quoted 18 lines
$ echo 256 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /6tb/foo1/ real 25m38.925s user 0m0.595s sys 1m23.182s$ echo 1024 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo2/ real 7m32.824s user 0m0.438s sys 1m6.759s$ echo 2048 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo3/ real 5m32.847s user 0m0.418s sys 1m5.671sQuoted 5 lines
$ echo 4096 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo4/ real 5m54.554s user 0m0.437s sys 1m6.268s
Quoted 3 lines
The difference is really amazing! So 2048 seems to be the best choice. 60GB in 5,5minutes are 180MB/sek. That sounds a bit high, doesnt it? The RAID only consist of 5 SATA disks with 7200rpm.
A lot of the source data is being cached between runs so these numbers aren't accurate. The throughput of this copy operation will be limited by the speed of the single source disk, not the array. To make the elapsed times of this copy test accurate you need to execute something like these commands after each run:
# sync # echo 3 > /proc/sys/vm/drop_caches
But this copy test will not inform you about the potential peak performance of your array. That's why I suggested you test with FIO, the flexible IO tester.
# aptitude install fio # man fio
Sample job file suitable for your system:
[global]
directory=/your/XFS/test/directoryzero_buffers
numjobs=8group_reporting
blocksize=512k
ioengine=libaio
iodepth=16
direct=1
size=10g
[read]
rw=read
stonewall
[write]
rw=write
stonewall
This should give you a relatively accurate picture of the actual potential throughput of your array and filesystem.
Quoted 19 lines
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1
Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Quoted 5 lines
And the best thing at all:
While all of these tests there are no warnings/panics in the syslog.With best regards,
Kevin
Even though XFS wasn't the cause of the problem I'm glad we were able to help you fix it nonetheless. I'm really curious to see what kind of throughput you can achieve with FIO, and whether crypto is a bottleneck at the 250-350 MB/s your array should be capable of. It would be great if you would play around a bit with FIO and post some numbers.
--
Stan
Quoted 143 lines
Am 19.12.2013 15:11, schrieb Stan Hoeppner:
Quoted 142 lines · Kevin Richter
Quoted 8 lines
Thanks for your mails!
Quoted 1 line
This is unusual. How long have you waited?
For the reboot? One night.
After the copy process hangs: several hours. But mostly it recovers after several minutes.Quoted 6 lines
Quoted 2 lines
1. Switch to deadline. CFQ is not suitable for RAID storage, and not suitable for XFS. This may not be a silver bullet but it will help.
Can I switch it while my copy process (from a separate hd to this raid) is running... without data loss? Otherwise I would wait a bit, because now it is actually running for 8 hours without kernel panics.
Yes, you can safely change the elevator on the fly. Repeat the following once for each disk, replacing X appropriately.
$ echo deadline > /sys/block/sdX/queue/schedulerThis on the fly change is not permanent. Add "elevator=deadline" to your kernel command line in your bootloader config file. Or you can add the commands to a startup script. Or if you build your own kernels simply make it the default, and/or remove all the other elevators from your kernel config, which is what I do.
Quoted 5 lines
Quoted 2 lines
2. Post your chunk size and RAID6
stripe_cache_sizevalue. They may be sub optimal for your workload.$ cat /sys/block/md2/md/stripe_cache_size 256256 is the default and it is way too low. This is limiting your write througput. Increase this to a minimum of 1024 which will give you a 20MB stripe cache buffer. This should become active immediately. Add it to a startup script to make it permanent.
$ echo 1024 > /sys/block/md2/md/stripe_cache_size((4096*stripe-cache_size)*num_drives)= RAM consumed for stripe cache
At some future point when the system is idle, play with FIO write testing and multiple jobs (threads) with
stripe_cache_sizevalues up to 2048 to see which value gives the best throughput. Test 1024, 2048, 4096. Going higher probably won't gain anything. And at some point as you go higher your throughput will decrease. When you see that, select the previous value and make it permanent.Quoted 6 lines
$ mdadm --detail /dev/md2 | grep Chunk Chunk Size : 512KQuoted 1 line
3. Post '
xfs_info/dev/mdX'There is a LUKS volume around
/dev/md2, named '6tb'.Ok, this adds a huge fly to the ointment. LUKS is single threaded per device. You've encrypted the md device instead of the individual disks.
This limits your encryption throughput to a single CPU core. You've
not provided any data on your LUKS thread. Is it pegging a core during large file IO? I'd bet it is. That would explain all of this.Quoted 11 lines
Quoted 11 lines
$ xfs_info /dev/md2 xfs_info: /dev/md2 is not a mounted XFS filesystem $ xfs_info /dev/mapper/6tb meta-data=/dev/mapper/6tb isize=256 agcount=32, agsize=45631360 blks = sectsz=512 attr=2 data = bsize=4096 blocks=1460203520, imaxpct=5 = sunit=128 swidth=384 blks naming =version 2 bsize=4096 ascii-ci=0 log =internal bsize=4096 blocks=521728, version=2 = sectsz=512 sunit=8 blks, lazy-count=1 realtime =none extsz=4096 blocks=0, rtextents=0md2 is 5 spindle RAID6, geometry 512KB * 3 = 1.5MB stripe width. The XFS alignment matches the md device. This may be hurting you with LUKS between XFS and md. I don't know how LUKS handles 1.5MB inbound writes and if it passes an aligned write to md after encrypting. I also don't know how it handles writes barriers passed down the stack by XFS, or if it does at all.
Quoted 8 lines
Quoted 7 lines
4. You're getting a lot of kswapd timeouts because you have swap and the md/RAID6 array on the same disks. Relocate swap to disks that are not part of this RAID6. Small SSDs are cheap and fast. Buy one and put swap on it. Or install more RAM in the machine. Going the SSD route is better as it gives flexibility. For instance, you can also relocate your syslog files to it and anything else that does IO without eating lots of space. This decreases the IOPS load on your rust.
Quoted 6 lines
No no, swap is not on any of the raid disks.
Quoted 3 lines
# cat /proc/swaps Filename Type Size Used Priority /dev/sda3 partition 7812496 0 -1sda is not in the raid. In the raid there are sd[cdefg].
I was wrong here. After reading a little about kswapd I now know it doesn't simply move pages to/from disk. It frees memory in other ways as well. In this case it's apparently waiting to free an inode being reclaimed by
xfs_reclaim_inode, which is stalled on lower level IO. So kswapd times out as a result. A slow LUKS thread would explain this as well.Quoted 8 lines
Quoted 2 lines
5. Describe in some detail the workload(s) causing the heavy IO, and thus these timeouts.
cd /olddharddisk
cp -av . /raid/oldhardddisk is a mounted 1tb old harddisk, /raid is the 6tb raid from above.
So you are simply doing a huge file copy from an apparently slower single disk to an apparently faster striped RAID. But you get horrible throughput and kernel timeout errors, and the RAID disks are apparently fairly idle.
Quoted 1 line
Heavy workload while this copy process (2 CPUs, each 4 cores):
Model # of the CPUs so I can look up the specs?
Quoted 11 lines
Quoted 8 lines
top - 11:13:37 up 4 days, 21:32, 2 users, load average: 12.95, 11.33, 10.32
Tasks: 155 total, 2 running, 153 sleeping, 0 stopped, 0 zombie Cpu(s): 0.0%us, 5.7%sy, 0.0%ni, 82.1%id, 11.8%wa, 0.0%hi, 0.3%si, 0.0%st Mem: 32916276k total, 32750240k used, 166036k free, 10076760k buffers Swap: 7812496k total, 0k used, 7812496k free, 21221136k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
699 root 20 0 0 0 0 S 11 0.0 248:17.59md2_raid6Dont know what consumes all of this 32GB RAM... 'top' sorted by memory consumption does not tell me. All entries are only 0.0% and 0.1%
~30GB of your RAM is being eaten by filesystem metadata buffers (10GB) and page cache (20GB). Linux uses nearly all free memory for cache and buffers to prevent disk accesses, which speeds up access to frequently used data considerably. This is normal. A huge copy like this is going to cause a huge amount caching.
I assume this 1TB file copy has finally completed. Start another large test copy and paste the CPU burn for the LUKS thread so we can confirm whether this is the root cause of your problem.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 21 lines · Stan Hoeppner
Quoted 19 lines · Kevin Richter
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1
Quoted 2 lines
Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Kworkers are an anonymous kernel worker threads that do work that has been pushed to a workqueue. kworker/3:1 is the 2nd worker thread on CPU 3 (3:0 is the first). The kworker is a thread pool that grows and shrinks according to demand.
As the naming suggests, kworker threads are per-CPU, and there can be hundreds of them per CPU is there is enough workqueue work blocks during execution of the work (e.g. on locks, waiting for IO, etc). If there is little blocking occurring, there might on ly be a couple of kworker threads that do all the work, and hence you see them consuming huge amounts of CPU on behalf of other systems...
XFS uses workqueues for lots of things, so it's not unusual to see an IO or metadata heavy workload end up with this huge numbers of kworker threads doing work:
<run parallel fsmark test>
....
$ ps -ef |grep kworker |wc -l 91 $
Cheers,
Dave.
Signature · 7 lines
Dave Chinner [email protected] _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Quoted 37 lines · Dave Chinner
Quoted 21 lines · Stan Hoeppner
Quoted 19 lines · Kevin Richter
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1Quoted 2 lines
Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Kworkers are an anonymous kernel worker threads that do work that has been pushed to a workqueue. kworker/3:1 is the 2nd worker thread on CPU 3 (3:0 is the first). The kworker is a thread pool that grows and shrinks according to demand.
As the naming suggests, kworker threads are per-CPU, and there can be hundreds of them per CPU is there is enough workqueue work blocks during execution of the work (e.g. on locks, waiting for IO, etc). If there is little blocking occurring, there might on ly be a couple of kworker threads that do all the work, and hence you see them consuming huge amounts of CPU on behalf of other systems...
Quoted 8 lines
XFS uses workqueues for lots of things, so it's not unusual to see an IO or metadata heavy workload end up with this huge numbers of kworker threads doing work:
<run parallel fsmark test>
....$ ps -ef |grep kworker |wc -l 91
For the record, again, I've never used dm-crypt. I'm just trying to work through the layers to identify the source of Kevin's problems. So please don't clobber me too hard for going OT, or trying to speak (somewhat) intelligently about something I'm just learning about...
So, how does one identify who is doing work inside a worker thread? In this case we're trying to figure out if dm-crypt might be eating a CPU core thus limiting its throughput. However...
I just read a thread on dm-devel about dm-crypt performance dated late March 2013. It wasn't clear to me if dm-crypt yet uses unbound workqueues, if it dispatches work to multiple queues, or if it still uses the hand built dispatcher, as of kernel 3.11, which Kevin just updated to.
What was clear is that as of March dm-crypt was not preserving IO ordering. If this is still the case, that would imply RMW with md parity arrays, which would tend to explain Kevin's write throughput being ~1/3rd of his read, and less than a single disk.
Mikulas Patocka posted 400-620 MB/s dm-crypt throughput with a RAMdisk.
It was not stated which CPU/clock he was using. Even if it were a 4GHz
core, Kevin's 2.4GHz SandyBridge should be capable of far more than ~80 MB/s of encryption.
So if dm-crypt is contributing to Kevin's low throughput I'd think it would be due to the IO ordering causing RMW, not due to CPU starvation.
Is there an easy way for a mere mortal to peek under the hood and see
if dm-crypt is causing RMW?
Christoph you were involved in that thread WRT IO ordering. Can you shed more light on this, and if it may be a factor here.
Signature · 6 lines
Stan _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Quoted 47 lines · Stan Hoeppner
Quoted 37 lines · Dave Chinner
Quoted 21 lines · Stan Hoeppner
Quoted 19 lines · Kevin Richter
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1Quoted 2 lines
Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Kworkers are an anonymous kernel worker threads that do work that has been pushed to a workqueue. kworker/3:1 is the 2nd worker thread on CPU 3 (3:0 is the first). The kworker is a thread pool that grows and shrinks according to demand.
As the naming suggests, kworker threads are per-CPU, and there can be hundreds of them per CPU is there is enough workqueue work blocks during execution of the work (e.g. on locks, waiting for IO, etc). If there is little blocking occurring, there might on ly be a couple of kworker threads that do all the work, and hence you see them consuming huge amounts of CPU on behalf of other systems...
Quoted 8 lines
XFS uses workqueues for lots of things, so it's not unusual to see an IO or metadata heavy workload end up with this huge numbers of kworker threads doing work:
<run parallel fsmark test>
....$ ps -ef |grep kworker |wc -l 91
Quoted 8 lines
For the record, again, I've never used dm-crypt. I'm just trying to work through the layers to identify the source of Kevin's problems. So please don't clobber me too hard for going OT, or trying to speak (somewhat) intelligently about something I'm just learning about...
So, how does one identify who is doing work inside a worker thread? In this case we're trying to figure out if dm-crypt might be eating a CPU core thus limiting its throughput. However...
perf top is your friend for finding out where the kernel is spending it's CPU time. It will tell you functions (and call chains) that are consuming CPU time rather than what individual threads are doing.
If you really want to know what worker threads are doing, /proc/sysrq-trigger dumps the kworker threads with the name of the workqueue they are doing work on behalf of as well as the stack trace.
Quoted 6 lines
I just read a thread on dm-devel about dm-crypt performance dated late March 2013. It wasn't clear to me if dm-crypt yet uses unbound workqueues, if it dispatches work to multiple queues, or if it still uses the hand built dispatcher, as of kernel 3.11, which Kevin just updated to.
dm-crypt uses workqueues with a concurrency depth of 1, and kcryptd is defined as CPU intensive and so is scheduled like a long running kernel thread rather than a workqueue. Reads decrypting is done on IO completion, so if you've only got one CPU processing IO completions, then read decryption will effectively be single threaded due to the nature of per-cpu work queues and a concurrency depth of 1.
Quoted 4 lines
What was clear is that as of March dm-crypt was not preserving IO ordering. If this is still the case, that would imply RMW with md parity arrays, which would tend to explain Kevin's write throughput being ~1/3rd of his read, and less than a single disk.
encryption adds IO latency, so unless you have lots of concurrency to hide the latency, dm-crypt will almost always be slower than the same IO an equivalent unencrypted disk.
Cheers,
Dave.
Signature · 7 lines
Dave Chinner [email protected] _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Quoted 4 lines · Stan Hoeppner
For the record, again, I've never used dm-crypt. I'm just trying to work through the layers to identify the source of Kevin's problems. So please don't clobber me too hard for going OT, or trying to speak (somewhat) intelligently about something I'm just learning about...
This stuff isn't easy. There are a lot of security-vs-speed tradeoffs, and kernel support varies by processor and architecture. Take this example from x86:
# info from fdisk: /dev/sda5 8404992 10502143 1048576 83 Linux
# cryptsetup status /dev/mapper/wCrypt /dev/mapper/wCrypt is active. type: LUKS1 cipher: aes-xts-essiv:sha256 keysize: 512 bits device: /dev/sda5 offset: 4096 sectors size: 2093056 sectors mode: read/write
What this jibberish means from a speed standpoint is this:
aes: had assembly speedups in the kernel; NIST approved;
xts: almost as fast as cbc while being more secure;
essiv: "plain" is faster, but essiv is more secure;
sha256: it seemed like an ok hash;
512 bits: much slower than 256 or 128 bits, but hopefully more secure, fine for a small partition like this.
A similar "cryptsetup status <cryptname>" from Kevin might help you benchmark things, and Kevin might explain his rationale without blowing his cover ;-) A zcat /proc/config.gz | grep CRYPTO` might help you see what kernel support he has as well.
Dave's recent post about I/O latency with dm-crypt reads/writes might be the answer that you're seeking. I just wanted to put in my two cents.
Good luck!
Michael
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Okay, well, I've run your fio config... but with so many results and abbrevations I currently feel a bit overchallenged :)
So, please dont take badly, if I just paste the whole results. I have tried with a stripe cache size of 1024, 2048 and 4096.
Btw, I also have /dev/md1, this is a 15GB unencrypted array using the same 5 disks like my LUKS-md2 array, so nearly the same just without this LUKS layer. If helpful, I can execute some fio tests on this filesystem, too.
So long :)
Kevin
$ echo 1024 > /sys/block/md2/md/stripe_cache_size
Quoted 36 lines
Jobs: 1 (f=1): [
____________W___] [99.7% done] [0K/99.24M /s] [0 /193 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=12987
read : io=81920MB, bw=189835KB/s, iops=370 , runt=441890msecslat (usec): min=32 , max=4561 , avg=76.28, stdev=28.66 clat (msec): min=5 , max=1115 , avg=334.19, stdev=151.18 lat (msec): min=5 , max=1115 , avg=334.26, stdev=151.18 bw (KB/s) : min= 0, max=261120, per=12.79%, avg=24288.95, stdev=11586.29 cpu : usr=0.05%, sys=0.50%, ctx=157180, majf=0, minf=16982 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.52%, 20=0.71%, 50=3.01%, 100=6.17%, 250=14.59% lat (msec): 500=68.81%, 750=4.87%, 1000=1.08%, 2000=0.25% write: (groupid=1, jobs=8): err= 0: pid=13202 write: io=81920MB, bw=58504KB/s, iops=114 , runt=1433851msec slat (usec): min=45 , max=1729 , avg=212.20, stdev=56.68 clat (msec): min=14 , max=11691 , avg=1101.17, stdev=1116.82 lat (msec): min=14 , max=11691 , avg=1101.39, stdev=1116.82 bw (KB/s) : min= 0, max=106666, per=14.35%, avg=8395.94, stdev=6752.35 cpu : usr=0.28%, sys=0.10%, ctx=117451, majf=0, minf=3410 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.17%, 100=2.03%, 250=17.02%, 500=22.20% lat (msec): 750=12.22%, 1000=8.66%, 2000=20.04%, >=2000=17.64%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189834KB/s, minb=194390KB/s, maxb=194390KB/s, mint=441890msec, maxt=441890msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=58504KB/s, minb=59908KB/s, maxb=59908KB/s, mint=1433851msec, maxt=1433851msec
Quoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327756, merge=0/0, ticks=78591352/353235376, in_queue=431834680, util=100.00%, aggrios=327681/327922, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327922, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=171660/222845, aggrmerge=4561629/9494657, aggrticks=16341417/4008187, aggrin_queue=20351472, aggrutil=85.78% sdc: ios=181512/222455, merge=4583055/9505634, ticks=15650600/5944080, in_queue=21596560, util=85.78% sdd: ios=180545/224362, merge=4526197/9587956, ticks=14356708/5542120, in_queue=19900820, util=85.42% sde: ios=179853/224317, merge=4519718/9540999, ticks=13375156/5676828, in_queue=19053876, util=83.90% sdf: ios=157605/222569, merge=4551205/9459549, ticks=18828608/1234632, in_queue=20065204, util=75.36% sdg: ios=158787/220525, merge=4627970/9379150, ticks=19496016/1643276, in_queue=21140904, util=77.26%
$ echo 2048 > /sys/block/md2/md/stripe_cache_size
Quoted 36 lines
Jobs: 1 (f=1): [
_________W______] [99.6% done] [0K/92182K /s] [0 /175 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=6392
read : io=81920MB, bw=185893KB/s, iops=363 , runt=451259msecslat (usec): min=32 , max=524 , avg=75.08, stdev=26.00 clat (msec): min=8 , max=1849 , avg=335.65, stdev=149.76 lat (msec): min=8 , max=1849 , avg=335.72, stdev=149.76 bw (KB/s) : min= 0, max=105860, per=13.08%, avg=24308.99, stdev=7467.64 cpu : usr=0.05%, sys=0.49%, ctx=157968, majf=0, minf=17171 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.01%, 20=0.06%, 50=2.32%, 100=7.44%, 250=15.36% lat (msec): 500=69.09%, 750=4.50%, 1000=0.87%, 2000=0.35% write: (groupid=1, jobs=8): err= 0: pid=6663 write: io=81920MB, bw=75377KB/s, iops=147 , runt=1112887msec slat (usec): min=46 , max=6453.8K, avg=988.13, stdev=46664.22 clat (msec): min=10 , max=8631 , avg=854.18, stdev=683.37 lat (msec): min=10 , max=8631 , avg=855.17, stdev=684.82 bw (KB/s) : min= 0, max=100352, per=14.04%, avg=10581.97, stdev=6871.80 cpu : usr=0.34%, sys=0.11%, ctx=92502, majf=0, minf=1531 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.09%, 100=1.14%, 250=11.19%, 500=24.64% lat (msec): 750=18.78%, 1000=13.40%, 2000=24.53%, >=2000=6.23%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=185893KB/s, minb=190354KB/s, maxb=190354KB/s, mint=451259msec, maxt=451259msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=75376KB/s, minb=77186KB/s, maxb=77186KB/s, mint=1112887msec, maxt=1112887msec
Quoted 8 lines
Disk stats (read/write):
dm-0: ios=327701/328169, merge=0/0, ticks=79402348/261890568, in_queue=341301888, util=100.00%, aggrios=327701/328481, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327701/328481, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=127112/146994, aggrmerge=3364061/7997232, aggrticks=18091347/5817941, aggrin_queue=23914356, aggrutil=94.20% sdc: ios=135729/149357, merge=3341205/8134447, ticks=18312932/8398716, in_queue=26721324, util=92.77% sdd: ios=135561/151584, merge=3312121/8238249, ticks=16877204/8190968, in_queue=25077332, util=92.44% sde: ios=135741/146023, merge=3345948/7981968, ticks=17659792/8659780, in_queue=26322124, util=94.20% sdf: ios=114396/143768, merge=3413295/7801050, ticks=18551976/1652924, in_queue=20207384, util=72.89% sdg: ios=114134/144241, merge=3407738/7830447, ticks=19054832/2187320, in_queue=21243620, util=74.96%
$ echo 4096 > /sys/block/md2/md/stripe_cache_size
Quoted 36 lines
Jobs: 1 (f=1): [
________W_______] [100.0% done] [0K/95848K /s] [0 /182 iops] [eta 00m:00s]
read: (groupid=0, jobs=8): err= 0: pid=11787
read : io=81920MB, bw=189274KB/s, iops=369 , runt=443200msecslat (usec): min=31 , max=4511 , avg=75.47, stdev=29.74 clat (msec): min=5 , max=1338 , avg=336.39, stdev=155.14 lat (msec): min=5 , max=1338 , avg=336.47, stdev=155.14 bw (KB/s) : min= 0, max=253455, per=12.77%, avg=24162.01, stdev=11368.71 cpu : usr=0.05%, sys=0.49%, ctx=157193, majf=0, minf=17313 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.47%, 20=0.66%, 50=2.95%, 100=6.33%, 250=14.56% lat (msec): 500=68.12%, 750=5.42%, 1000=1.15%, 2000=0.33% write: (groupid=1, jobs=8): err= 0: pid=12060 write: io=81920MB, bw=64993KB/s, iops=126 , runt=1290687msec slat (usec): min=61 , max=16991 , avg=197.22, stdev=110.87 clat (msec): min=14 , max=2820 , avg=980.92, stdev=366.56 lat (msec): min=14 , max=2821 , avg=981.12, stdev=366.56 bw (KB/s) : min= 0, max=103770, per=13.11%, avg=8517.92, stdev=3794.28 cpu : usr=0.28%, sys=0.08%, ctx=84352, majf=0, minf=723 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.03%, 100=0.28%, 250=0.22%, 500=5.37% lat (msec): 750=22.02%, 1000=31.66%, 2000=39.27%, >=2000=1.16%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189273KB/s, minb=193816KB/s, maxb=193816KB/s, mint=443200msec, maxt=443200msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=64993KB/s, minb=66553KB/s, maxb=66553KB/s, mint=1290687msec, maxt=1290687msec
Quoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327629, merge=0/0, ticks=78990724/301988444, in_queue=380991692, util=100.00%, aggrios=327681/327709, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327709, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=120158/119573, aggrmerge=2858405/7663126, aggrticks=17291831/9119008, aggrin_queue=26414023, aggrutil=99.60% sdc: ios=135579/119976, merge=2813832/7324879, ticks=13974928/2192484, in_queue=16167996, util=66.57% sdd: ios=136115/127048, merge=2826584/7736191, ticks=12932248/2477796, in_queue=15410924, util=68.08% sde: ios=136007/130908, merge=2844473/7936354, ticks=12642232/3141268, in_queue=15784336, util=71.86% sdf: ios=78473/94458, merge=2882361/7865984, ticks=29053772/37421808, in_queue=66488856, util=99.60% sdg: ios=114620/125479, merge=2924777/7452224, ticks=17855976/361684, in_queue=18218004, util=54.84%
Am 20.12.2013 13:36, schrieb Stan Hoeppner:
Quoted 121 lines · Kevin Richter
Quoted 1 line
Thanks a lot for your huge replies!
You're welcome.
Quoted 10 lines
Quoted 2 lines
Oh, that's quite old. I'd suggest upgrading to a much more recent kernel as we've fixed lots of issues in this area since then.
First I have switched to the newer kernel from Ubuntu Saucy:
$ uname -a Linux 3.11.0-14-generic #21~precise1-Ubuntu SMPThus, it seems that the default scheduler has been changed to deadline. I did not change anything. After a reboot the schedulers of all disks are now deadline.
Good move Ubuntu.
Quoted 2 lines
Quoted 1 line
Model # of the CPUs so I can look up the specs?
Intel(R) Xeon(R) CPU E5-2609 0 @ 2.40GHz
Strong CPUs.
Quoted 28 lines
I have prepared a folder with 60GB for the tests. This is nearly twice of the available memory, so the process should be forced to actually write the stuff to the disk - and not only hold in the memory.
Quoted 18 lines
$ echo 256 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /6tb/foo1/ real 25m38.925s user 0m0.595s sys 1m23.182s$ echo 1024 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo2/ real 7m32.824s user 0m0.438s sys 1m6.759s$ echo 2048 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo3/ real 5m32.847s user 0m0.418s sys 1m5.671sQuoted 5 lines
$ echo 4096 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo4/ real 5m54.554s user 0m0.437s sys 1m6.268sQuoted 3 lines
The difference is really amazing! So 2048 seems to be the best choice. 60GB in 5,5minutes are 180MB/sek. That sounds a bit high, doesnt it? The RAID only consist of 5 SATA disks with 7200rpm.
A lot of the source data is being cached between runs so these numbers aren't accurate. The throughput of this copy operation will be limited by the speed of the single source disk, not the array. To make the elapsed times of this copy test accurate you need to execute something like these commands after each run:
# sync # echo 3 > /proc/sys/vm/drop_cachesBut this copy test will not inform you about the potential peak performance of your array. That's why I suggested you test with FIO, the flexible IO tester.
# aptitude install fio # man fioSample job file suitable for your system:
[global]
directory=/your/XFS/test/directoryzero_buffers
numjobs=8group_reporting
blocksize=512k
ioengine=libaio
iodepth=16
direct=1
size=10g[read]
rw=read
stonewall[write]
rw=write
stonewallThis should give you a relatively accurate picture of the actual potential throughput of your array and filesystem.
Quoted 19 lines
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Quoted 3 lines
And the best thing at all:
While all of these tests there are no warnings/panics in the syslog.
Quoted 9 lines
Quoted 2 lines
With best regards,
KevinEven though XFS wasn't the cause of the problem I'm glad we were able to help you fix it nonetheless. I'm really curious to see what kind of throughput you can achieve with FIO, and whether crypto is a bottleneck at the 250-350 MB/s your array should be capable of. It would be great if you would play around a bit with FIO and post some numbers.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 1 line · Kevin Richter
Okay, well, I've run your fio config... but with so many results and
I'm glad you changed to size=1G instead of size=10G lest the test would have read/written 80GB instead of 8GB, and taken forever. I often forget the size parameter is per job (thread) not global.
Quoted 3 lines
abbrevations I currently feel a bit overchallenged :) So, please dont take badly, if I just paste the whole results. I have tried with a stripe cache size of 1024, 2048 and 4096.
The full output is good. Going from 1024 to 2048 gained you ~17MB/s throughput with this job file. But you didn't run with the default 256 for comparison, which is very useful to know. That's ok, as you can do so with the next set of test runs. Given the huge latencies I'm thinking this config may be seeking the disks too much. Modify your fio job file as follows:
numjobs=4
blocksize=1536k
iodepth=4
size=1g
as this may yield a little better results. ~190MB/s read and 75MB/s write is very low for three effective 7.2K RPM SATA spindles, especially the write throughput. Compare to a similar FIO job with 2 threads, iodepth 16, directio, run against a single 500GB 7.2K WD SATA drive, NQC disabled, w/deadline elevator:
Run status group 0 (all jobs):
READ: io=2048MB, aggrb=88663KB/s, minb=90791KB/s, maxb=90791KB/s
Run status group 1 (all jobs):
WRITE: io=2048MB, aggrb=108089KB/s, minb=110683KB/s, maxb=110683KB/s
88MB/s read, 108MB/s write. Write is faster apparently due to the small 16MB drive write cache. With your eight 2.4GHz SandyBridge cores and md-RAID6 on much newer larger 7.2K drives w/larger caches, you should have significantly greater write speed than this old single SATA drive.
Currently you're showing 30MB/s slower write throughput, some 40%
slower than this single drive. With aligned writes, thus no RMW, you should be getting at least 2 spindles worth of throughput, or ~200MB/s.
So, run FIO again with the mods above, once with stripe_cache_size 256 and once with 2048. Something seems to be seriously dragging down your throughput. I'm sure you'd like to know what, and how to fix it.
Quoted 4 lines
Btw, I also have
/dev/md1, this is a 15GB unencrypted array using the same 5 disks like my LUKS-md2 array, so nearly the same just without this LUKS layer. If helpful, I can execute some fio tests on this filesystem, too.
This is also a RAID6 array, without dm-crypt? If so this will afford a great comparison, and may be very informative. Run FIO against this filesystem (I assume it's also XFS) as well with stripe_cache_size 512 and 2048. Four FIO tests total including the two on the big array.
It'll be interesting to see where this leads. At this point the candidates I see are a single dm-crypt thread peaking a core, dm-crypt taking aligned writes and misaligning them causing all writes to be RMWs, or AF drives with misaligned partitions causing every write to be an internal RMW. Or maybe something I've not considered.
Quoted 279 lines
So long :)
Kevin$ echo 1024 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
____________W___] [99.7% done] [0K/99.24M /s] [0 /193 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=12987
read : io=81920MB, bw=189835KB/s, iops=370 , runt=441890msecslat (usec): min=32 , max=4561 , avg=76.28, stdev=28.66 clat (msec): min=5 , max=1115 , avg=334.19, stdev=151.18 lat (msec): min=5 , max=1115 , avg=334.26, stdev=151.18 bw (KB/s) : min= 0, max=261120, per=12.79%, avg=24288.95, stdev=11586.29 cpu : usr=0.05%, sys=0.50%, ctx=157180, majf=0, minf=16982 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.52%, 20=0.71%, 50=3.01%, 100=6.17%, 250=14.59% lat (msec): 500=68.81%, 750=4.87%, 1000=1.08%, 2000=0.25% write: (groupid=1, jobs=8): err= 0: pid=13202 write: io=81920MB, bw=58504KB/s, iops=114 , runt=1433851msec slat (usec): min=45 , max=1729 , avg=212.20, stdev=56.68 clat (msec): min=14 , max=11691 , avg=1101.17, stdev=1116.82 lat (msec): min=14 , max=11691 , avg=1101.39, stdev=1116.82 bw (KB/s) : min= 0, max=106666, per=14.35%, avg=8395.94, stdev=6752.35 cpu : usr=0.28%, sys=0.10%, ctx=117451, majf=0, minf=3410 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.17%, 100=2.03%, 250=17.02%, 500=22.20% lat (msec): 750=12.22%, 1000=8.66%, 2000=20.04%, >=2000=17.64%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189834KB/s, minb=194390KB/s, maxb=194390KB/s, mint=441890msec, maxt=441890msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=58504KB/s, minb=59908KB/s, maxb=59908KB/s, mint=1433851msec, maxt=1433851msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327756, merge=0/0, ticks=78591352/353235376, in_queue=431834680, util=100.00%, aggrios=327681/327922, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327922, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=171660/222845, aggrmerge=4561629/9494657, aggrticks=16341417/4008187, aggrin_queue=20351472, aggrutil=85.78% sdc: ios=181512/222455, merge=4583055/9505634, ticks=15650600/5944080, in_queue=21596560, util=85.78% sdd: ios=180545/224362, merge=4526197/9587956, ticks=14356708/5542120, in_queue=19900820, util=85.42% sde: ios=179853/224317, merge=4519718/9540999, ticks=13375156/5676828, in_queue=19053876, util=83.90% sdf: ios=157605/222569, merge=4551205/9459549, ticks=18828608/1234632, in_queue=20065204, util=75.36% sdg: ios=158787/220525, merge=4627970/9379150, ticks=19496016/1643276, in_queue=21140904, util=77.26%$ echo 2048 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
_________W______] [99.6% done] [0K/92182K /s] [0 /175 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=6392
read : io=81920MB, bw=185893KB/s, iops=363 , runt=451259msecslat (usec): min=32 , max=524 , avg=75.08, stdev=26.00 clat (msec): min=8 , max=1849 , avg=335.65, stdev=149.76 lat (msec): min=8 , max=1849 , avg=335.72, stdev=149.76 bw (KB/s) : min= 0, max=105860, per=13.08%, avg=24308.99, stdev=7467.64 cpu : usr=0.05%, sys=0.49%, ctx=157968, majf=0, minf=17171 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.01%, 20=0.06%, 50=2.32%, 100=7.44%, 250=15.36% lat (msec): 500=69.09%, 750=4.50%, 1000=0.87%, 2000=0.35% write: (groupid=1, jobs=8): err= 0: pid=6663 write: io=81920MB, bw=75377KB/s, iops=147 , runt=1112887msec slat (usec): min=46 , max=6453.8K, avg=988.13, stdev=46664.22 clat (msec): min=10 , max=8631 , avg=854.18, stdev=683.37 lat (msec): min=10 , max=8631 , avg=855.17, stdev=684.82 bw (KB/s) : min= 0, max=100352, per=14.04%, avg=10581.97, stdev=6871.80 cpu : usr=0.34%, sys=0.11%, ctx=92502, majf=0, minf=1531 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.09%, 100=1.14%, 250=11.19%, 500=24.64% lat (msec): 750=18.78%, 1000=13.40%, 2000=24.53%, >=2000=6.23%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=185893KB/s, minb=190354KB/s, maxb=190354KB/s, mint=451259msec, maxt=451259msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=75376KB/s, minb=77186KB/s, maxb=77186KB/s, mint=1112887msec, maxt=1112887msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327701/328169, merge=0/0, ticks=79402348/261890568, in_queue=341301888, util=100.00%, aggrios=327701/328481, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327701/328481, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=127112/146994, aggrmerge=3364061/7997232, aggrticks=18091347/5817941, aggrin_queue=23914356, aggrutil=94.20% sdc: ios=135729/149357, merge=3341205/8134447, ticks=18312932/8398716, in_queue=26721324, util=92.77% sdd: ios=135561/151584, merge=3312121/8238249, ticks=16877204/8190968, in_queue=25077332, util=92.44% sde: ios=135741/146023, merge=3345948/7981968, ticks=17659792/8659780, in_queue=26322124, util=94.20% sdf: ios=114396/143768, merge=3413295/7801050, ticks=18551976/1652924, in_queue=20207384, util=72.89% sdg: ios=114134/144241, merge=3407738/7830447, ticks=19054832/2187320, in_queue=21243620, util=74.96%$ echo 4096 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
________W_______] [100.0% done] [0K/95848K /s] [0 /182 iops] [eta 00m:00s]
read: (groupid=0, jobs=8): err= 0: pid=11787
read : io=81920MB, bw=189274KB/s, iops=369 , runt=443200msecslat (usec): min=31 , max=4511 , avg=75.47, stdev=29.74 clat (msec): min=5 , max=1338 , avg=336.39, stdev=155.14 lat (msec): min=5 , max=1338 , avg=336.47, stdev=155.14 bw (KB/s) : min= 0, max=253455, per=12.77%, avg=24162.01, stdev=11368.71 cpu : usr=0.05%, sys=0.49%, ctx=157193, majf=0, minf=17313 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.47%, 20=0.66%, 50=2.95%, 100=6.33%, 250=14.56% lat (msec): 500=68.12%, 750=5.42%, 1000=1.15%, 2000=0.33% write: (groupid=1, jobs=8): err= 0: pid=12060 write: io=81920MB, bw=64993KB/s, iops=126 , runt=1290687msec slat (usec): min=61 , max=16991 , avg=197.22, stdev=110.87 clat (msec): min=14 , max=2820 , avg=980.92, stdev=366.56 lat (msec): min=14 , max=2821 , avg=981.12, stdev=366.56 bw (KB/s) : min= 0, max=103770, per=13.11%, avg=8517.92, stdev=3794.28 cpu : usr=0.28%, sys=0.08%, ctx=84352, majf=0, minf=723 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.03%, 100=0.28%, 250=0.22%, 500=5.37% lat (msec): 750=22.02%, 1000=31.66%, 2000=39.27%, >=2000=1.16%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189273KB/s, minb=193816KB/s, maxb=193816KB/s, mint=443200msec, maxt=443200msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=64993KB/s, minb=66553KB/s, maxb=66553KB/s, mint=1290687msec, maxt=1290687msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327629, merge=0/0, ticks=78990724/301988444, in_queue=380991692, util=100.00%, aggrios=327681/327709, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327709, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=120158/119573, aggrmerge=2858405/7663126, aggrticks=17291831/9119008, aggrin_queue=26414023, aggrutil=99.60% sdc: ios=135579/119976, merge=2813832/7324879, ticks=13974928/2192484, in_queue=16167996, util=66.57% sdd: ios=136115/127048, merge=2826584/7736191, ticks=12932248/2477796, in_queue=15410924, util=68.08% sde: ios=136007/130908, merge=2844473/7936354, ticks=12642232/3141268, in_queue=15784336, util=71.86% sdf: ios=78473/94458, merge=2882361/7865984, ticks=29053772/37421808, in_queue=66488856, util=99.60% sdg: ios=114620/125479, merge=2924777/7452224, ticks=17855976/361684, in_queue=18218004, util=54.84%Am 20.12.2013 13:36, schrieb Stan Hoeppner:
Quoted 121 lines · Kevin Richter
Quoted 1 line
Thanks a lot for your huge replies!
You're welcome.
Quoted 10 lines
Quoted 2 lines
Oh, that's quite old. I'd suggest upgrading to a much more recent kernel as we've fixed lots of issues in this area since then.
First I have switched to the newer kernel from Ubuntu Saucy:
$ uname -a Linux 3.11.0-14-generic #21~precise1-Ubuntu SMPThus, it seems that the default scheduler has been changed to deadline. I did not change anything. After a reboot the schedulers of all disks are now deadline.
Good move Ubuntu.
Quoted 2 lines
Quoted 1 line
Model # of the CPUs so I can look up the specs?
Intel(R) Xeon(R) CPU E5-2609 0 @ 2.40GHz
Strong CPUs.
Quoted 28 lines
I have prepared a folder with 60GB for the tests. This is nearly twice of the available memory, so the process should be forced to actually write the stuff to the disk - and not only hold in the memory.
Quoted 18 lines
$ echo 256 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /6tb/foo1/ real 25m38.925s user 0m0.595s sys 1m23.182s$ echo 1024 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo2/ real 7m32.824s user 0m0.438s sys 1m6.759s$ echo 2048 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo3/ real 5m32.847s user 0m0.418s sys 1m5.671sQuoted 5 lines
$ echo 4096 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo4/ real 5m54.554s user 0m0.437s sys 1m6.268sQuoted 3 lines
The difference is really amazing! So 2048 seems to be the best choice. 60GB in 5,5minutes are 180MB/sek. That sounds a bit high, doesnt it? The RAID only consist of 5 SATA disks with 7200rpm.
A lot of the source data is being cached between runs so these numbers aren't accurate. The throughput of this copy operation will be limited by the speed of the single source disk, not the array. To make the elapsed times of this copy test accurate you need to execute something like these commands after each run:
# sync # echo 3 > /proc/sys/vm/drop_cachesBut this copy test will not inform you about the potential peak performance of your array. That's why I suggested you test with FIO, the flexible IO tester.
# aptitude install fio # man fioSample job file suitable for your system:
[global]
directory=/your/XFS/test/directoryzero_buffers
numjobs=8group_reporting
blocksize=512k
ioengine=libaio
iodepth=16
direct=1
size=10g[read]
rw=read
stonewall[write]
rw=write
stonewallThis should give you a relatively accurate picture of the actual potential throughput of your array and filesystem.
Quoted 19 lines
'top' while copying with stripe size of 2048 (the source disk is ntfs):
Quoted 18 lines
top - 10:48:24 up 1 day, 1:41, 2 users, load average: 5.66, 3.53, 2.17
Tasks: 210 total, 2 running, 208 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 35.8%sy, 0.0%ni, 46.0%id, 17.9%wa, 0.0%hi, 0.2%si, 0.0%st Mem: 32913992k total, 32709208k used, 204784k free, 10770344k buffers Swap: 7812496k total, 0k used, 7812496k free, 20866844k cachedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19524 root 20 0 0 0 0 R 93 0.0 4:00.12 kworker/3:1 23744 root 20 0 0 0 0 S 55 0.0 0:50.84 kworker/0:1 23738 root 20 0 0 0 0 S 29 0.0 0:56.94 kworker/4:0 3893 root 20 0 0 0 0 S 28 0.0 36:47.50 md2_raid6 4551 root 20 0 22060 3328 720 D 25 0.0 20:21.61 mount.ntfs 23273 root 20 0 0 0 0 S 22 0.0 1:54.86 kworker/7:2 23734 root 20 0 21752 1280 1040 D 21 0.0 0:49.84 cp 84 root 20 0 0 0 0 S 7 0.0 8:19.34 kswapd1 83 root 20 0 0 0 0 S 6 0.0 11:55.81 kswapd0 23745 root 20 0 0 0 0 S 2 0.0 0:33.60 kworker/1:2 21598 root 20 0 0 0 0 D 1 0.0 0:11.33 kworker/u17:1Hmm, what's kworker/3:1? That's not a crypto thread eating 93% of a SandyBridge core at only ~180 MB/s throughput is it?
Quoted 3 lines
And the best thing at all:
While all of these tests there are no warnings/panics in the syslog.Quoted 9 lines
Quoted 2 lines
With best regards,
KevinEven though XFS wasn't the cause of the problem I'm glad we were able to help you fix it nonetheless. I'm really curious to see what kind of throughput you can achieve with FIO, and whether crypto is a bottleneck at the 250-350 MB/s your array should be capable of. It would be great if you would play around a bit with FIO and post some numbers.
Quoted 5 lines
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 1 line
I'm glad you changed to size=1G instead of size=10G
No no, I didnt change that. It has been written 160GB on these disks. 80 for the read part, 80 for the write part. Each test took round 30 minutes.
Quoted 1 line
This is also a RAID6 array, without dm-crypt?
Yeah, right. The same 5 disks in RAID6 mode, just in each case another partition on these disks. And yes, of course, XFS.
So, with your new config I have made 7 fio runs:
1) 15GB RAID6 array, stripe 256
2) 15GB RAID6 array, stripe 1024
3) 15GB RAID6 array, stripe 2048
4) 15GB RAID6 array, stripe 4096
5) 3TB LUKS volume (no raid, just one single disk)
6) 6TB RAID6+LUKS array, stripe 256
7) 6TB RAID6+LUKS array, stripe 2048
In the 15GB array a stripe size of 4096 seems to get slightly more throughput than 2048.
See below for the results :-)
Perhaps, I should give you another information about the server hardware, which might (but hopefully do not) explain the low performance:
The server is that one:
http://www.supermicro.com/products/system/2u/6027/ssg-6027r-e1r12l.cfm
with a 12-port SAS expander, which is that one:
http://www.thomas-krenn.com/de/wiki/BPN-SAS-826EL1_SAS_Expander_Backplane
But the backplane should have a thoughput of 3Gb/s
However... I am very curious about your comments :-)
Bye,
Kevin
#################################
1) 15GB RAID6 volume, stripe 256:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=3959
read : io=4092.0MB, bw=217900KB/s, iops=141 , runt= 19230msecslat (usec): min=190 , max=1325 , avg=231.32, stdev=77.13 clat (msec): min=7 , max=326 , avg=111.45, stdev=67.48 lat (msec): min=7 , max=326 , avg=111.69, stdev=67.48 bw (KB/s) : min=29425, max=109280, per=24.98%, avg=54423.27, stdev=15887.11 cpu : usr=0.03%, sys=0.90%, ctx=2614, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.66%, 20=4.84%, 50=16.35%, 100=25.70%, 250=47.91% lat (msec): 500=4.55% write: (groupid=1, jobs=4): err= 0: pid=3964 write: io=4092.0MB, bw=54044KB/s, iops=35 , runt= 77533msec slat (msec): min=9 , max=339 , avg=113.48, stdev=36.86 clat (msec): min=2 , max=744 , avg=339.51, stdev=70.02 lat (msec): min=23 , max=927 , avg=453.00, stdev=82.81 bw (KB/s) : min= 5475, max=20756, per=24.92%, avg=13467.27, stdev=2107.66 cpu : usr=0.58%, sys=6.26%, ctx=343060, majf=0, minf=550 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 4=0.04%, 10=0.04%, 50=0.11%, 100=0.26%, 250=5.94% lat (msec): 500=91.50%, 750=2.13%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=217899KB/s, minb=223129KB/s, maxb=223129KB/s, mint=19230msec, maxt=19230msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=54044KB/s, minb=55341KB/s, maxb=55341KB/s, mint=77533msec, maxt=77533msec
Quoted 7 lines
Disk stats (read/write):
md1: ios=10912/10904, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=22836/29872, aggrmerge=364645/574313, aggrticks=216408/101340, aggrin_queue=317789, aggrutil=69.36%sdc: ios=23542/29233, merge=377270/563331, ticks=217520/152300, in_queue=369860, util=67.99% sdd: ios=23462/28930, merge=378915/557686, ticks=214104/142224, in_queue=356428, util=67.81% sde: ios=22264/29920, merge=355831/576114, ticks=149184/99724, in_queue=248924, util=58.22% sdf: ios=22240/30724, merge=352471/588412, ticks=126740/52916, in_queue=179696, util=55.44% sdg: ios=22676/30557, merge=358741/586025, ticks=374496/59540, in_queue=434040, util=69.36%
#################################
2) 15GB RAID6 array, stripe 1024:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4334
read : io=4092.0MB, bw=237702KB/s, iops=154 , runt= 17628msecslat (usec): min=196 , max=1469 , avg=232.84, stdev=88.56 clat (msec): min=6 , max=391 , avg=101.62, stdev=56.61 lat (msec): min=7 , max=391 , avg=101.85, stdev=56.61 bw (KB/s) : min=26482, max=107305, per=24.94%, avg=59289.94, stdev=14153.87 cpu : usr=0.04%, sys=0.98%, ctx=2581, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.22%, 20=3.08%, 50=16.83%, 100=31.01%, 250=47.10% lat (msec): 500=1.76% write: (groupid=1, jobs=4): err= 0: pid=4340 write: io=4092.0MB, bw=120759KB/s, iops=78 , runt= 34699msec slat (msec): min=1 , max=156 , avg=47.70, stdev=27.94 clat (msec): min=15 , max=520 , avg=152.37, stdev=53.34 lat (msec): min=28 , max=564 , avg=200.07, stdev=57.63 bw (KB/s) : min= 0, max=62270, per=25.04%, avg=30239.54, stdev=5435.51 cpu : usr=1.34%, sys=5.68%, ctx=134184, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.04%, 50=1.10%, 100=12.02%, 250=82.18%, 500=4.62% lat (msec): 750=0.04%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=237701KB/s, minb=243406KB/s, maxb=243406KB/s, mint=17628msec, maxt=17628msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=120758KB/s, minb=123656KB/s, maxb=123656KB/s, mint=34699msec, maxt=34699msec
Quoted 7 lines
Disk stats (read/write):
md1: ios=10912/10901, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=4062/6768, aggrmerge=109645/369712, aggrticks=157952/111924, aggrin_queue=270487, aggrutil=89.91%sdc: ios=4070/6893, merge=109432/378682, ticks=173784/179392, in_queue=353780, util=89.88% sdd: ios=4041/6961, merge=110017/380798, ticks=164960/160236, in_queue=325820, util=89.91% sde: ios=4039/6727, merge=110658/366163, ticks=169804/166052, in_queue=336484, util=88.98% sdf: ios=4080/6591, merge=108922/359343, ticks=39460/24636, in_queue=64820, util=52.33% sdg: ios=4081/6668, merge=109197/363574, ticks=241752/29308, in_queue=271532, util=73.63%
#################################
3) 15GB RAID6 array, stripe 2048:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4102
read : io=4092.0MB, bw=207827KB/s, iops=135 , runt= 20162msecslat (usec): min=122 , max=3904 , avg=230.75, stdev=99.04 clat (msec): min=5 , max=363 , avg=117.03, stdev=70.26 lat (msec): min=5 , max=363 , avg=117.27, stdev=70.25 bw (KB/s) : min=26533, max=104239, per=25.00%, avg=51947.24, stdev=13121.27 cpu : usr=0.05%, sys=0.83%, ctx=2640, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.55%, 20=4.99%, 50=14.96%, 100=21.33%, 250=53.01% lat (msec): 500=5.17% write: (groupid=1, jobs=4): err= 0: pid=4108 write: io=4092.0MB, bw=145833KB/s, iops=94 , runt= 28733msec slat (usec): min=768 , max=94184 , avg=1838.20, stdev=4140.24 clat (msec): min=15 , max=1155 , avg=145.02, stdev=128.70 lat (msec): min=16 , max=1156 , avg=146.86, stdev=128.77 bw (KB/s) : min= 6144, max=104448, per=29.22%, avg=42617.70, stdev=17118.84 cpu : usr=1.63%, sys=2.52%, ctx=4086, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.37%, 50=9.02%, 100=38.42%, 250=39.22%, 500=10.12% lat (msec): 750=2.09%, 1000=0.59%, 2000=0.18%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=207827KB/s, minb=212814KB/s, maxb=212814KB/s, mint=20162msec, maxt=20162msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=145832KB/s, minb=149332KB/s, maxb=149332KB/s, mint=28733msec, maxt=28733msec
Quoted 7 lines
Disk stats (read/write):
md1: ios=10912/10873, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=3018/4990, aggrmerge=79606/371231, aggrticks=152741/83319, aggrin_queue=236284, aggrutil=92.45%sdc: ios=2988/5046, merge=79033/376737, ticks=129600/103552, in_queue=233412, util=84.14% sdd: ios=3010/5140, merge=77101/390954, ticks=119032/103236, in_queue=222536, util=85.87% sde: ios=3039/5009, merge=79935/374563, ticks=196200/159792, in_queue=356236, util=92.45% sdf: ios=3021/4883, merge=80483/356643, ticks=29976/24956, in_queue=55100, util=49.53% sdg: ios=3033/4872, merge=81481/357261, ticks=288900/25060, in_queue=314136, util=76.17%
#################################
4) 15GB RAID6 array, stripe 4096:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4411
read : io=4092.0MB, bw=214938KB/s, iops=139 , runt= 19495msecslat (usec): min=192 , max=1468 , avg=226.97, stdev=87.18 clat (msec): min=4 , max=339 , avg=112.51, stdev=63.05 lat (msec): min=4 , max=339 , avg=112.73, stdev=63.05 bw (KB/s) : min= 0, max=96000, per=24.87%, avg=53457.49, stdev=13728.88 cpu : usr=0.02%, sys=0.89%, ctx=2591, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.15%, 20=4.62%, 50=13.56%, 100=26.43%, 250=52.20% lat (msec): 500=3.04% write: (groupid=1, jobs=4): err= 0: pid=4419 write: io=4092.0MB, bw=146526KB/s, iops=95 , runt= 28597msec slat (usec): min=822 , max=36057 , avg=1585.60, stdev=1174.08 clat (msec): min=14 , max=1132 , avg=142.49, stdev=126.05 lat (msec): min=15 , max=1134 , avg=144.08, stdev=126.08 bw (KB/s) : min= 0, max=83836, per=28.88%, avg=42315.69, stdev=18036.84 cpu : usr=1.42%, sys=2.85%, ctx=2937, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.18%, 50=10.08%, 100=37.61%, 250=40.62%, 500=8.50% lat (msec): 750=2.46%, 1000=0.44%, 2000=0.11%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=214937KB/s, minb=220096KB/s, maxb=220096KB/s, mint=19495msec, maxt=19495msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=146526KB/s, minb=150042KB/s, maxb=150042KB/s, mint=28597msec, maxt=28597msec
Quoted 7 lines
Disk stats (read/write):
md1: ios=10912/10895, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=3013/5053, aggrmerge=78083/371841, aggrticks=151707/88554, aggrin_queue=240554, aggrutil=92.72%sdc: ios=2981/5124, merge=77153/379556, ticks=142800/116248, in_queue=259356, util=87.13% sdd: ios=2990/5182, merge=75443/390196, ticks=128184/107752, in_queue=236264, util=86.87% sde: ios=3034/5057, merge=77882/372755, ticks=185048/159352, in_queue=344636, util=92.72% sdf: ios=3035/4941, merge=79423/356692, ticks=29196/28100, in_queue=57520, util=50.56% sdg: ios=3026/4963, merge=80518/360009, ticks=273308/31320, in_queue=304996, util=76.24%
###################################################
5) 3TB LUKS volume (no raid, just one single disk):
Quoted 28 lines
read: (groupid=0, jobs=4): err= 0: pid=31359
read : io=4092.0MB, bw=125032KB/s, iops=81 , runt= 33513msecslat (usec): min=86 , max=1404 , avg=125.10, stdev=97.21 clat (msec): min=26 , max=323 , avg=195.52, stdev=39.04 lat (msec): min=26 , max=323 , avg=195.65, stdev=39.03 bw (KB/s) : min=21982, max=41890, per=25.12%, avg=31405.62, stdev=3662.77 cpu : usr=0.02%, sys=0.31%, ctx=2738, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 50=0.51%, 100=2.38%, 250=93.07%, 500=4.03% write: (groupid=1, jobs=4): err= 0: pid=31364 write: io=4092.0MB, bw=158193KB/s, iops=102 , runt= 26488msec slat (usec): min=181 , max=673 , avg=442.78, stdev=67.26 clat (msec): min=21 , max=555 , avg=154.33, stdev=45.35 lat (msec): min=21 , max=555 , avg=154.77, stdev=45.35 bw (KB/s) : min=19097, max=45988, per=25.04%, avg=39617.62, stdev=5714.79 cpu : usr=1.00%, sys=0.25%, ctx=2737, majf=0, minf=86 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.44%, 100=1.54%, 250=94.61%, 500=3.15%, 750=0.26%Run status group 0 (all jobs):
Quoted 8 lines
READ: io=4092.0MB, aggrb=125032KB/s, minb=128033KB/s, maxb=128033KB/s, mint=33513msec, maxt=33513msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=158192KB/s, minb=161989KB/s, maxb=161989KB/s, mint=26488msec, maxt=26488msecDisk stats (read/write):
dm-1: ios=8184/8196, merge=0/0, ticks=1521200/1235264, in_queue=2759104, util=99.58%, aggrios=8184/8225, aggrmerge=0/31, aggrticks=1421660/1137984, aggrin_queue=2559612, aggrutil=99.49%sda: ios=8184/8225, merge=0/31, ticks=1421660/1137984, in_queue=2559612, util=99.49%
##############################
6) 6TB LUKS array, stripe 256:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=31121
read : io=4092.0MB, bw=137700KB/s, iops=89 , runt= 30430msecslat (usec): min=123 , max=1353 , avg=157.35, stdev=91.53 clat (msec): min=15 , max=545 , avg=148.80, stdev=61.30 lat (msec): min=15 , max=545 , avg=148.96, stdev=61.29 bw (KB/s) : min= 0, max=129024, per=29.75%, avg=40959.72, stdev=21470.47 cpu : usr=0.01%, sys=0.51%, ctx=2797, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 20=0.29%, 50=9.90%, 100=12.76%, 250=75.07%, 500=1.58% lat (msec): 750=0.40% write: (groupid=1, jobs=4): err= 0: pid=31131 write: io=4092.0MB, bw=41225KB/s, iops=26 , runt=101643msec slat (usec): min=197 , max=1309 , avg=557.69, stdev=124.14 clat (msec): min=42 , max=2648 , avg=586.07, stdev=393.18 lat (msec): min=43 , max=2649 , avg=586.63, stdev=393.19 bw (KB/s) : min= 0, max=35583, per=26.36%, avg=10867.00, stdev=5232.75 cpu : usr=0.33%, sys=0.09%, ctx=2699, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.07%, 100=1.39%, 250=18.55%, 500=31.82%, 750=20.49% lat (msec): 1000=12.57%, 2000=14.66%, >=2000=0.44%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=137699KB/s, minb=141004KB/s, maxb=141004KB/s, mint=30430msec, maxt=30430msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=41224KB/s, minb=42214KB/s, maxb=42214KB/s, mint=101643msec, maxt=101643msec
Quoted 8 lines
Disk stats (read/write):
dm-0: ios=10912/10906, merge=0/0, ticks=1385524/5596828, in_queue=6983364, util=99.89%, aggrios=10912/10940, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=10912/10940, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=20710/27494, aggrmerge=358521/573067, aggrticks=208334/119186, aggrin_queue=327551, aggrutil=61.95% sdc: ios=21005/27276, merge=366645/567533, ticks=224772/179916, in_queue=404728, util=61.95% sdd: ios=21154/26926, merge=369215/564213, ticks=212876/160624, in_queue=373552, util=60.42% sde: ios=20460/27449, merge=354440/571659, ticks=127008/102188, in_queue=229220, util=48.28% sdf: ios=20464/27908, merge=350591/581422, ticks=241608/78180, in_queue=319784, util=55.24% sdg: ios=20470/27915, merge=351718/580509, ticks=235408/75024, in_queue=310472, util=55.91%
###############################
7) 6TB LUKS array, stripe 2048:
Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=30910
read : io=4092.0MB, bw=237500KB/s, iops=154 , runt= 17643msecslat (usec): min=134 , max=1511 , avg=165.25, stdev=96.45 clat (msec): min=16 , max=859 , avg=101.07, stdev=61.40 lat (msec): min=17 , max=859 , avg=101.23, stdev=61.40 bw (KB/s) : min=32807, max=97523, per=25.40%, avg=60325.02, stdev=15396.63 cpu : usr=0.02%, sys=0.76%, ctx=2709, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 20=0.07%, 50=13.38%, 100=48.90%, 250=34.38%, 500=3.08% lat (msec): 750=0.15%, 1000=0.04% write: (groupid=1, jobs=4): err= 0: pid=30915 write: io=4092.0MB, bw=90652KB/s, iops=59 , runt= 46223msec slat (usec): min=173 , max=983 , avg=599.60, stdev=141.06 clat (msec): min=34 , max=1185 , avg=258.48, stdev=135.97 lat (msec): min=34 , max=1185 , avg=259.08, stdev=135.98 bw (KB/s) : min= 0, max=88722, per=25.95%, avg=23524.06, stdev=9036.31 cpu : usr=0.77%, sys=0.22%, ctx=2576, majf=0, minf=86 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.48%, 100=7.00%, 250=49.01%, 500=37.72%, 750=5.10% lat (msec): 1000=0.59%, 2000=0.11%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=237499KB/s, minb=243199KB/s, maxb=243199KB/s, mint=17643msec, maxt=17643msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=90652KB/s, minb=92827KB/s, maxb=92827KB/s, mint=46223msec, maxt=46223msec
Quoted 8 lines
Disk stats (read/write):
dm-0: ios=10912/10875, merge=0/0, ticks=544880/2481824, in_queue=3026996, util=99.57%, aggrios=10912/10930, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=10912/10930, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=5058/6798, aggrmerge=153871/404343, aggrticks=195870/113487, aggrin_queue=309447, aggrutil=92.15% sdc: ios=5024/7100, merge=152571/421782, ticks=332612/204936, in_queue=537660, util=92.15% sdd: ios=4961/7109, merge=150591/422166, ticks=257308/161200, in_queue=418608, util=88.11% sde: ios=5019/6697, merge=154781/395583, ticks=226120/152068, in_queue=378296, util=85.49% sdf: ios=5118/6463, merge=156068/385905, ticks=65716/23932, in_queue=89724, util=55.85% sdg: ios=5172/6624, merge=155347/396280, ticks=97596/25300, in_queue=122948, util=60.00%
Am 22.12.2013 09:12, schrieb Stan Hoeppner:
Quoted 56 lines · Kevin Richter
Quoted 1 line
Okay, well, I've run your fio config... but with so many results and
I'm glad you changed to size=1G instead of size=10G lest the test would have read/written 80GB instead of 8GB, and taken forever. I often forget the size parameter is per job (thread) not global.
Quoted 3 lines
abbrevations I currently feel a bit overchallenged :) So, please dont take badly, if I just paste the whole results. I have tried with a stripe cache size of 1024, 2048 and 4096.
The full output is good. Going from 1024 to 2048 gained you ~17MB/s throughput with this job file. But you didn't run with the default 256 for comparison, which is very useful to know. That's ok, as you can do so with the next set of test runs. Given the huge latencies I'm thinking this config may be seeking the disks too much. Modify your fio job file as follows:
numjobs=4
blocksize=1536k
iodepth=4
size=1gas this may yield a little better results. ~190MB/s read and 75MB/s write is very low for three effective 7.2K RPM SATA spindles, especially the write throughput. Compare to a similar FIO job with 2 threads, iodepth 16, directio, run against a single 500GB 7.2K WD SATA drive, NQC disabled, w/deadline elevator:
Run status group 0 (all jobs):
READ: io=2048MB, aggrb=88663KB/s, minb=90791KB/s, maxb=90791KB/sRun status group 1 (all jobs):
WRITE: io=2048MB, aggrb=108089KB/s, minb=110683KB/s, maxb=110683KB/s88MB/s read, 108MB/s write. Write is faster apparently due to the small 16MB drive write cache. With your eight 2.4GHz SandyBridge cores and md-RAID6 on much newer larger 7.2K drives w/larger caches, you should have significantly greater write speed than this old single SATA drive.
Currently you're showing 30MB/s slower write throughput, some 40%
slower than this single drive. With aligned writes, thus no RMW, you should be getting at least 2 spindles worth of throughput, or ~200MB/s.So, run FIO again with the mods above, once with
stripe_cache_size256 and once with 2048. Something seems to be seriously dragging down your throughput. I'm sure you'd like to know what, and how to fix it.Quoted 4 lines
Btw, I also have
/dev/md1, this is a 15GB unencrypted array using the same 5 disks like my LUKS-md2 array, so nearly the same just without this LUKS layer. If helpful, I can execute some fio tests on this filesystem, too.This is also a RAID6 array, without dm-crypt? If so this will afford a great comparison, and may be very informative. Run FIO against this filesystem (I assume it's also XFS) as well with
stripe_cache_size512 and 2048. Four FIO tests total including the two on the big array.
Quoted 149 lines
It'll be interesting to see where this leads. At this point the candidates I see are a single dm-crypt thread peaking a core, dm-crypt taking aligned writes and misaligning them causing all writes to be RMWs, or AF drives with misaligned partitions causing every write to be an internal RMW. Or maybe something I've not considered.
Quoted 142 lines
So long :)
Kevin$ echo 1024 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
____________W___] [99.7% done] [0K/99.24M /s] [0 /193 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=12987
read : io=81920MB, bw=189835KB/s, iops=370 , runt=441890msecslat (usec): min=32 , max=4561 , avg=76.28, stdev=28.66 clat (msec): min=5 , max=1115 , avg=334.19, stdev=151.18 lat (msec): min=5 , max=1115 , avg=334.26, stdev=151.18 bw (KB/s) : min= 0, max=261120, per=12.79%, avg=24288.95, stdev=11586.29 cpu : usr=0.05%, sys=0.50%, ctx=157180, majf=0, minf=16982 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.52%, 20=0.71%, 50=3.01%, 100=6.17%, 250=14.59% lat (msec): 500=68.81%, 750=4.87%, 1000=1.08%, 2000=0.25% write: (groupid=1, jobs=8): err= 0: pid=13202 write: io=81920MB, bw=58504KB/s, iops=114 , runt=1433851msec slat (usec): min=45 , max=1729 , avg=212.20, stdev=56.68 clat (msec): min=14 , max=11691 , avg=1101.17, stdev=1116.82 lat (msec): min=14 , max=11691 , avg=1101.39, stdev=1116.82 bw (KB/s) : min= 0, max=106666, per=14.35%, avg=8395.94, stdev=6752.35 cpu : usr=0.28%, sys=0.10%, ctx=117451, majf=0, minf=3410 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.17%, 100=2.03%, 250=17.02%, 500=22.20% lat (msec): 750=12.22%, 1000=8.66%, 2000=20.04%, >=2000=17.64%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189834KB/s, minb=194390KB/s, maxb=194390KB/s, mint=441890msec, maxt=441890msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=58504KB/s, minb=59908KB/s, maxb=59908KB/s, mint=1433851msec, maxt=1433851msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327756, merge=0/0, ticks=78591352/353235376, in_queue=431834680, util=100.00%, aggrios=327681/327922, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327922, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=171660/222845, aggrmerge=4561629/9494657, aggrticks=16341417/4008187, aggrin_queue=20351472, aggrutil=85.78% sdc: ios=181512/222455, merge=4583055/9505634, ticks=15650600/5944080, in_queue=21596560, util=85.78% sdd: ios=180545/224362, merge=4526197/9587956, ticks=14356708/5542120, in_queue=19900820, util=85.42% sde: ios=179853/224317, merge=4519718/9540999, ticks=13375156/5676828, in_queue=19053876, util=83.90% sdf: ios=157605/222569, merge=4551205/9459549, ticks=18828608/1234632, in_queue=20065204, util=75.36% sdg: ios=158787/220525, merge=4627970/9379150, ticks=19496016/1643276, in_queue=21140904, util=77.26%$ echo 2048 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
_________W______] [99.6% done] [0K/92182K /s] [0 /175 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=6392
read : io=81920MB, bw=185893KB/s, iops=363 , runt=451259msecslat (usec): min=32 , max=524 , avg=75.08, stdev=26.00 clat (msec): min=8 , max=1849 , avg=335.65, stdev=149.76 lat (msec): min=8 , max=1849 , avg=335.72, stdev=149.76 bw (KB/s) : min= 0, max=105860, per=13.08%, avg=24308.99, stdev=7467.64 cpu : usr=0.05%, sys=0.49%, ctx=157968, majf=0, minf=17171 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.01%, 20=0.06%, 50=2.32%, 100=7.44%, 250=15.36% lat (msec): 500=69.09%, 750=4.50%, 1000=0.87%, 2000=0.35% write: (groupid=1, jobs=8): err= 0: pid=6663 write: io=81920MB, bw=75377KB/s, iops=147 , runt=1112887msec slat (usec): min=46 , max=6453.8K, avg=988.13, stdev=46664.22 clat (msec): min=10 , max=8631 , avg=854.18, stdev=683.37 lat (msec): min=10 , max=8631 , avg=855.17, stdev=684.82 bw (KB/s) : min= 0, max=100352, per=14.04%, avg=10581.97, stdev=6871.80 cpu : usr=0.34%, sys=0.11%, ctx=92502, majf=0, minf=1531 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.09%, 100=1.14%, 250=11.19%, 500=24.64% lat (msec): 750=18.78%, 1000=13.40%, 2000=24.53%, >=2000=6.23%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=185893KB/s, minb=190354KB/s, maxb=190354KB/s, mint=451259msec, maxt=451259msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=75376KB/s, minb=77186KB/s, maxb=77186KB/s, mint=1112887msec, maxt=1112887msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327701/328169, merge=0/0, ticks=79402348/261890568, in_queue=341301888, util=100.00%, aggrios=327701/328481, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327701/328481, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=127112/146994, aggrmerge=3364061/7997232, aggrticks=18091347/5817941, aggrin_queue=23914356, aggrutil=94.20% sdc: ios=135729/149357, merge=3341205/8134447, ticks=18312932/8398716, in_queue=26721324, util=92.77% sdd: ios=135561/151584, merge=3312121/8238249, ticks=16877204/8190968, in_queue=25077332, util=92.44% sde: ios=135741/146023, merge=3345948/7981968, ticks=17659792/8659780, in_queue=26322124, util=94.20% sdf: ios=114396/143768, merge=3413295/7801050, ticks=18551976/1652924, in_queue=20207384, util=72.89% sdg: ios=114134/144241, merge=3407738/7830447, ticks=19054832/2187320, in_queue=21243620, util=74.96%$ echo 4096 > /sys/block/md2/md/stripe_cache_sizeQuoted 44 lines
Jobs: 1 (f=1): [
________W_______] [100.0% done] [0K/95848K /s] [0 /182 iops] [eta 00m:00s]
read: (groupid=0, jobs=8): err= 0: pid=11787
read : io=81920MB, bw=189274KB/s, iops=369 , runt=443200msecslat (usec): min=31 , max=4511 , avg=75.47, stdev=29.74 clat (msec): min=5 , max=1338 , avg=336.39, stdev=155.14 lat (msec): min=5 , max=1338 , avg=336.47, stdev=155.14 bw (KB/s) : min= 0, max=253455, per=12.77%, avg=24162.01, stdev=11368.71 cpu : usr=0.05%, sys=0.49%, ctx=157193, majf=0, minf=17313 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.47%, 20=0.66%, 50=2.95%, 100=6.33%, 250=14.56% lat (msec): 500=68.12%, 750=5.42%, 1000=1.15%, 2000=0.33% write: (groupid=1, jobs=8): err= 0: pid=12060 write: io=81920MB, bw=64993KB/s, iops=126 , runt=1290687msec slat (usec): min=61 , max=16991 , avg=197.22, stdev=110.87 clat (msec): min=14 , max=2820 , avg=980.92, stdev=366.56 lat (msec): min=14 , max=2821 , avg=981.12, stdev=366.56 bw (KB/s) : min= 0, max=103770, per=13.11%, avg=8517.92, stdev=3794.28 cpu : usr=0.28%, sys=0.08%, ctx=84352, majf=0, minf=723 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.03%, 100=0.28%, 250=0.22%, 500=5.37% lat (msec): 750=22.02%, 1000=31.66%, 2000=39.27%, >=2000=1.16%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189273KB/s, minb=193816KB/s, maxb=193816KB/s, mint=443200msec, maxt=443200msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=64993KB/s, minb=66553KB/s, maxb=66553KB/s, mint=1290687msec, maxt=1290687msecDisk stats (read/write):
dm-0: ios=327681/327629, merge=0/0, ticks=78990724/301988444, in_queue=380991692, util=100.00%, aggrios=327681/327709, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327709, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=120158/119573, aggrmerge=2858405/7663126, aggrticks=17291831/9119008, aggrin_queue=26414023, aggrutil=99.60% sdc: ios=135579/119976, merge=2813832/7324879, ticks=13974928/2192484, in_queue=16167996, util=66.57% sdd: ios=136115/127048, merge=2826584/7736191, ticks=12932248/2477796, in_queue=15410924, util=68.08% sde: ios=136007/130908, merge=2844473/7936354, ticks=12642232/3141268, in_queue=15784336, util=71.86% sdf: ios=78473/94458, merge=2882361/7865984, ticks=29053772/37421808, in_queue=66488856, util=99.60% sdg: ios=114620/125479, merge=2924777/7452224, ticks=17855976/361684, in_queue=18218004, util=54.84%
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 3 lines · Kevin Richter
Quoted 1 line
I'm glad you changed to size=1G instead of size=10G
No no, I didnt change that. It has been written 160GB on these disks. 80 for the read part, 80 for the write part. Each test took round 30 minutes.
I read this "read : io=81920MB" without the zero hence my incorrect assumption. Again, my apologies for the length test runs. Use "1g" from now on as that should be plenty to get good data, and run quickly.
Quoted 18 lines
Quoted 1 line
This is also a RAID6 array, without dm-crypt?
Yeah, right. The same 5 disks in RAID6 mode, just in each case another partition on these disks. And yes, of course, XFS.
So, with your new config I have made 7 fio runs:
1) 15GB RAID6 array, stripe 256
2) 15GB RAID6 array, stripe 1024
3) 15GB RAID6 array, stripe 2048
4) 15GB RAID6 array, stripe 4096
5) 3TB LUKS volume (no raid, just one single disk)
6) 6TB RAID6+LUKS array, stripe 256
7) 6TB RAID6+LUKS array, stripe 2048In the 15GB array a stripe size of 4096 seems to get slightly more throughput than 2048.
See below for the results :-)
Quoted 7 lines
Perhaps, I should give you another information about the server hardware, which might (but hopefully do not) explain the low performance:
The server is that one:
http://www.supermicro.com/products/system/2u/6027/ssg-6027r-e1r12l.cfm
with a 12-port SAS expander, which is that one:
http://www.thomas-krenn.com/de/wiki/BPN-SAS-826EL1_SAS_Expander_Backplane
But the backplane should have a thoughput of 3Gb/s
The hardware is fine. You have 1.2GB/s <-> the backplane.
Quoted 1 line
However... I am very curious about your comments :-)
3) 15GB RAID6 array, stripe 2048:
READ: io=4092.0MB, aggrb=207827KB/s, minb=212814KB/s, maxb=212814KB/s
WRITE: io=4092.0MB, aggrb=145832KB/s, minb=149332KB/s, maxb=149332KB/s
~50MB/s per drive * 5 drives = ~250 MB/s
This may simply be the md-RAID6 max write you'll get from these drives.
But 145MB/s aggregate write throughput is still decidedly better than
90MB/s, some 62% faster than the encrypted array.
5) 3TB LUKS volume (no raid, just one single disk):
READ: io=4092.0MB, aggrb=125032KB/s, minb=128033KB/s, maxb=128033KB/s
WRITE: io=4092.0MB, aggrb=158192KB/s, minb=161989KB/s, maxb=161989KB/s
~160MB/s per drive, ~160MB/s dm-crypt throughput
7) 6TB LUKS array, stripe 2048:
READ: io=4092.0MB, aggrb=237499KB/s, minb=243199KB/s, maxb=243199KB/s
WRITE: io=4092.0MB, aggrb=90652KB/s, minb=92827KB/s, maxb=92827KB/s
~30MB/s per drive * 5 drives = ~150MB/s dm-crypt throughput.
Write throughput is ~100MB/s lower on your RAID6 w/dm-crypt than without. Read throughput however is ~30MB/s higher, though these differences may not be as great with multiple runs and normalized data.
Even so, since the read throughput is roughly the same at 71-81MB/s per
drive, both with/out encryption, I don't believe the difference in write speed is due to platter placement of the filesystems and test files.
So at this point I'd guess we need to look at dm-crypt, which may be peaking a core or unaligning your IOs causing RMW cycles. And look at your partitions under the encrypted RAID6 to see if they're aligned.
We can identify the latter easily if you post 'fdisk -l' output for each of the 5 drives. Whether partitions are misaligned or dm-crypt is the problem, the fix in either case is very destructive and time consuming, requiring a full backup/restore after redoing the stack.
--
Stan
Quoted 526 lines
Bye,
Kevin#################################
1) 15GB RAID6 volume, stripe 256:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=3959
read : io=4092.0MB, bw=217900KB/s, iops=141 , runt= 19230msecslat (usec): min=190 , max=1325 , avg=231.32, stdev=77.13 clat (msec): min=7 , max=326 , avg=111.45, stdev=67.48 lat (msec): min=7 , max=326 , avg=111.69, stdev=67.48 bw (KB/s) : min=29425, max=109280, per=24.98%, avg=54423.27, stdev=15887.11 cpu : usr=0.03%, sys=0.90%, ctx=2614, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.66%, 20=4.84%, 50=16.35%, 100=25.70%, 250=47.91% lat (msec): 500=4.55% write: (groupid=1, jobs=4): err= 0: pid=3964 write: io=4092.0MB, bw=54044KB/s, iops=35 , runt= 77533msec slat (msec): min=9 , max=339 , avg=113.48, stdev=36.86 clat (msec): min=2 , max=744 , avg=339.51, stdev=70.02 lat (msec): min=23 , max=927 , avg=453.00, stdev=82.81 bw (KB/s) : min= 5475, max=20756, per=24.92%, avg=13467.27, stdev=2107.66 cpu : usr=0.58%, sys=6.26%, ctx=343060, majf=0, minf=550 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 4=0.04%, 10=0.04%, 50=0.11%, 100=0.26%, 250=5.94% lat (msec): 500=91.50%, 750=2.13%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=217899KB/s, minb=223129KB/s, maxb=223129KB/s, mint=19230msec, maxt=19230msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=54044KB/s, minb=55341KB/s, maxb=55341KB/s, mint=77533msec, maxt=77533msecQuoted 7 lines
Disk stats (read/write):
md1: ios=10912/10904, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=22836/29872, aggrmerge=364645/574313, aggrticks=216408/101340, aggrin_queue=317789, aggrutil=69.36%sdc: ios=23542/29233, merge=377270/563331, ticks=217520/152300, in_queue=369860, util=67.99% sdd: ios=23462/28930, merge=378915/557686, ticks=214104/142224, in_queue=356428, util=67.81% sde: ios=22264/29920, merge=355831/576114, ticks=149184/99724, in_queue=248924, util=58.22% sdf: ios=22240/30724, merge=352471/588412, ticks=126740/52916, in_queue=179696, util=55.44% sdg: ios=22676/30557, merge=358741/586025, ticks=374496/59540, in_queue=434040, util=69.36%#################################
2) 15GB RAID6 array, stripe 1024:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4334
read : io=4092.0MB, bw=237702KB/s, iops=154 , runt= 17628msecslat (usec): min=196 , max=1469 , avg=232.84, stdev=88.56 clat (msec): min=6 , max=391 , avg=101.62, stdev=56.61 lat (msec): min=7 , max=391 , avg=101.85, stdev=56.61 bw (KB/s) : min=26482, max=107305, per=24.94%, avg=59289.94, stdev=14153.87 cpu : usr=0.04%, sys=0.98%, ctx=2581, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.22%, 20=3.08%, 50=16.83%, 100=31.01%, 250=47.10% lat (msec): 500=1.76% write: (groupid=1, jobs=4): err= 0: pid=4340 write: io=4092.0MB, bw=120759KB/s, iops=78 , runt= 34699msec slat (msec): min=1 , max=156 , avg=47.70, stdev=27.94 clat (msec): min=15 , max=520 , avg=152.37, stdev=53.34 lat (msec): min=28 , max=564 , avg=200.07, stdev=57.63 bw (KB/s) : min= 0, max=62270, per=25.04%, avg=30239.54, stdev=5435.51 cpu : usr=1.34%, sys=5.68%, ctx=134184, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.04%, 50=1.10%, 100=12.02%, 250=82.18%, 500=4.62% lat (msec): 750=0.04%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=237701KB/s, minb=243406KB/s, maxb=243406KB/s, mint=17628msec, maxt=17628msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=120758KB/s, minb=123656KB/s, maxb=123656KB/s, mint=34699msec, maxt=34699msecQuoted 7 lines
Disk stats (read/write):
md1: ios=10912/10901, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=4062/6768, aggrmerge=109645/369712, aggrticks=157952/111924, aggrin_queue=270487, aggrutil=89.91%sdc: ios=4070/6893, merge=109432/378682, ticks=173784/179392, in_queue=353780, util=89.88% sdd: ios=4041/6961, merge=110017/380798, ticks=164960/160236, in_queue=325820, util=89.91% sde: ios=4039/6727, merge=110658/366163, ticks=169804/166052, in_queue=336484, util=88.98% sdf: ios=4080/6591, merge=108922/359343, ticks=39460/24636, in_queue=64820, util=52.33% sdg: ios=4081/6668, merge=109197/363574, ticks=241752/29308, in_queue=271532, util=73.63%#################################
3) 15GB RAID6 array, stripe 2048:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4102
read : io=4092.0MB, bw=207827KB/s, iops=135 , runt= 20162msecslat (usec): min=122 , max=3904 , avg=230.75, stdev=99.04 clat (msec): min=5 , max=363 , avg=117.03, stdev=70.26 lat (msec): min=5 , max=363 , avg=117.27, stdev=70.25 bw (KB/s) : min=26533, max=104239, per=25.00%, avg=51947.24, stdev=13121.27 cpu : usr=0.05%, sys=0.83%, ctx=2640, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.55%, 20=4.99%, 50=14.96%, 100=21.33%, 250=53.01% lat (msec): 500=5.17% write: (groupid=1, jobs=4): err= 0: pid=4108 write: io=4092.0MB, bw=145833KB/s, iops=94 , runt= 28733msec slat (usec): min=768 , max=94184 , avg=1838.20, stdev=4140.24 clat (msec): min=15 , max=1155 , avg=145.02, stdev=128.70 lat (msec): min=16 , max=1156 , avg=146.86, stdev=128.77 bw (KB/s) : min= 6144, max=104448, per=29.22%, avg=42617.70, stdev=17118.84 cpu : usr=1.63%, sys=2.52%, ctx=4086, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.37%, 50=9.02%, 100=38.42%, 250=39.22%, 500=10.12% lat (msec): 750=2.09%, 1000=0.59%, 2000=0.18%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=207827KB/s, minb=212814KB/s, maxb=212814KB/s, mint=20162msec, maxt=20162msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=145832KB/s, minb=149332KB/s, maxb=149332KB/s, mint=28733msec, maxt=28733msecQuoted 7 lines
Disk stats (read/write):
md1: ios=10912/10873, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=3018/4990, aggrmerge=79606/371231, aggrticks=152741/83319, aggrin_queue=236284, aggrutil=92.45%sdc: ios=2988/5046, merge=79033/376737, ticks=129600/103552, in_queue=233412, util=84.14% sdd: ios=3010/5140, merge=77101/390954, ticks=119032/103236, in_queue=222536, util=85.87% sde: ios=3039/5009, merge=79935/374563, ticks=196200/159792, in_queue=356236, util=92.45% sdf: ios=3021/4883, merge=80483/356643, ticks=29976/24956, in_queue=55100, util=49.53% sdg: ios=3033/4872, merge=81481/357261, ticks=288900/25060, in_queue=314136, util=76.17%#################################
4) 15GB RAID6 array, stripe 4096:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=4411
read : io=4092.0MB, bw=214938KB/s, iops=139 , runt= 19495msecslat (usec): min=192 , max=1468 , avg=226.97, stdev=87.18 clat (msec): min=4 , max=339 , avg=112.51, stdev=63.05 lat (msec): min=4 , max=339 , avg=112.73, stdev=63.05 bw (KB/s) : min= 0, max=96000, per=24.87%, avg=53457.49, stdev=13728.88 cpu : usr=0.02%, sys=0.89%, ctx=2591, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 10=0.15%, 20=4.62%, 50=13.56%, 100=26.43%, 250=52.20% lat (msec): 500=3.04% write: (groupid=1, jobs=4): err= 0: pid=4419 write: io=4092.0MB, bw=146526KB/s, iops=95 , runt= 28597msec slat (usec): min=822 , max=36057 , avg=1585.60, stdev=1174.08 clat (msec): min=14 , max=1132 , avg=142.49, stdev=126.05 lat (msec): min=15 , max=1134 , avg=144.08, stdev=126.08 bw (KB/s) : min= 0, max=83836, per=28.88%, avg=42315.69, stdev=18036.84 cpu : usr=1.42%, sys=2.85%, ctx=2937, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 20=0.18%, 50=10.08%, 100=37.61%, 250=40.62%, 500=8.50% lat (msec): 750=2.46%, 1000=0.44%, 2000=0.11%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=214937KB/s, minb=220096KB/s, maxb=220096KB/s, mint=19495msec, maxt=19495msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=146526KB/s, minb=150042KB/s, maxb=150042KB/s, mint=28597msec, maxt=28597msecQuoted 7 lines
Disk stats (read/write):
md1: ios=10912/10895, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=3013/5053, aggrmerge=78083/371841, aggrticks=151707/88554, aggrin_queue=240554, aggrutil=92.72%sdc: ios=2981/5124, merge=77153/379556, ticks=142800/116248, in_queue=259356, util=87.13% sdd: ios=2990/5182, merge=75443/390196, ticks=128184/107752, in_queue=236264, util=86.87% sde: ios=3034/5057, merge=77882/372755, ticks=185048/159352, in_queue=344636, util=92.72% sdf: ios=3035/4941, merge=79423/356692, ticks=29196/28100, in_queue=57520, util=50.56% sdg: ios=3026/4963, merge=80518/360009, ticks=273308/31320, in_queue=304996, util=76.24%###################################################
5) 3TB LUKS volume (no raid, just one single disk):Quoted 28 lines
read: (groupid=0, jobs=4): err= 0: pid=31359
read : io=4092.0MB, bw=125032KB/s, iops=81 , runt= 33513msecslat (usec): min=86 , max=1404 , avg=125.10, stdev=97.21 clat (msec): min=26 , max=323 , avg=195.52, stdev=39.04 lat (msec): min=26 , max=323 , avg=195.65, stdev=39.03 bw (KB/s) : min=21982, max=41890, per=25.12%, avg=31405.62, stdev=3662.77 cpu : usr=0.02%, sys=0.31%, ctx=2738, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 50=0.51%, 100=2.38%, 250=93.07%, 500=4.03% write: (groupid=1, jobs=4): err= 0: pid=31364 write: io=4092.0MB, bw=158193KB/s, iops=102 , runt= 26488msec slat (usec): min=181 , max=673 , avg=442.78, stdev=67.26 clat (msec): min=21 , max=555 , avg=154.33, stdev=45.35 lat (msec): min=21 , max=555 , avg=154.77, stdev=45.35 bw (KB/s) : min=19097, max=45988, per=25.04%, avg=39617.62, stdev=5714.79 cpu : usr=1.00%, sys=0.25%, ctx=2737, majf=0, minf=86 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.44%, 100=1.54%, 250=94.61%, 500=3.15%, 750=0.26%Run status group 0 (all jobs):
Quoted 8 lines
READ: io=4092.0MB, aggrb=125032KB/s, minb=128033KB/s, maxb=128033KB/s, mint=33513msec, maxt=33513msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=158192KB/s, minb=161989KB/s, maxb=161989KB/s, mint=26488msec, maxt=26488msecDisk stats (read/write):
dm-1: ios=8184/8196, merge=0/0, ticks=1521200/1235264, in_queue=2759104, util=99.58%, aggrios=8184/8225, aggrmerge=0/31, aggrticks=1421660/1137984, aggrin_queue=2559612, aggrutil=99.49%sda: ios=8184/8225, merge=0/31, ticks=1421660/1137984, in_queue=2559612, util=99.49%##############################
6) 6TB LUKS array, stripe 256:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=31121
read : io=4092.0MB, bw=137700KB/s, iops=89 , runt= 30430msecslat (usec): min=123 , max=1353 , avg=157.35, stdev=91.53 clat (msec): min=15 , max=545 , avg=148.80, stdev=61.30 lat (msec): min=15 , max=545 , avg=148.96, stdev=61.29 bw (KB/s) : min= 0, max=129024, per=29.75%, avg=40959.72, stdev=21470.47 cpu : usr=0.01%, sys=0.51%, ctx=2797, majf=0, minf=6241 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 20=0.29%, 50=9.90%, 100=12.76%, 250=75.07%, 500=1.58% lat (msec): 750=0.40% write: (groupid=1, jobs=4): err= 0: pid=31131 write: io=4092.0MB, bw=41225KB/s, iops=26 , runt=101643msec slat (usec): min=197 , max=1309 , avg=557.69, stdev=124.14 clat (msec): min=42 , max=2648 , avg=586.07, stdev=393.18 lat (msec): min=43 , max=2649 , avg=586.63, stdev=393.19 bw (KB/s) : min= 0, max=35583, per=26.36%, avg=10867.00, stdev=5232.75 cpu : usr=0.33%, sys=0.09%, ctx=2699, majf=0, minf=94 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.07%, 100=1.39%, 250=18.55%, 500=31.82%, 750=20.49% lat (msec): 1000=12.57%, 2000=14.66%, >=2000=0.44%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=137699KB/s, minb=141004KB/s, maxb=141004KB/s, mint=30430msec, maxt=30430msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=41224KB/s, minb=42214KB/s, maxb=42214KB/s, mint=101643msec, maxt=101643msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=10912/10906, merge=0/0, ticks=1385524/5596828, in_queue=6983364, util=99.89%, aggrios=10912/10940, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=10912/10940, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=20710/27494, aggrmerge=358521/573067, aggrticks=208334/119186, aggrin_queue=327551, aggrutil=61.95% sdc: ios=21005/27276, merge=366645/567533, ticks=224772/179916, in_queue=404728, util=61.95% sdd: ios=21154/26926, merge=369215/564213, ticks=212876/160624, in_queue=373552, util=60.42% sde: ios=20460/27449, merge=354440/571659, ticks=127008/102188, in_queue=229220, util=48.28% sdf: ios=20464/27908, merge=350591/581422, ticks=241608/78180, in_queue=319784, util=55.24% sdg: ios=20470/27915, merge=351718/580509, ticks=235408/75024, in_queue=310472, util=55.91%###############################
7) 6TB LUKS array, stripe 2048:Quoted 35 lines
read: (groupid=0, jobs=4): err= 0: pid=30910
read : io=4092.0MB, bw=237500KB/s, iops=154 , runt= 17643msecslat (usec): min=134 , max=1511 , avg=165.25, stdev=96.45 clat (msec): min=16 , max=859 , avg=101.07, stdev=61.40 lat (msec): min=17 , max=859 , avg=101.23, stdev=61.40 bw (KB/s) : min=32807, max=97523, per=25.40%, avg=60325.02, stdev=15396.63 cpu : usr=0.02%, sys=0.76%, ctx=2709, majf=0, minf=6233 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=2728/0/0, short=0/0/0 lat (msec): 20=0.07%, 50=13.38%, 100=48.90%, 250=34.38%, 500=3.08% lat (msec): 750=0.15%, 1000=0.04% write: (groupid=1, jobs=4): err= 0: pid=30915 write: io=4092.0MB, bw=90652KB/s, iops=59 , runt= 46223msec slat (usec): min=173 , max=983 , avg=599.60, stdev=141.06 clat (msec): min=34 , max=1185 , avg=258.48, stdev=135.97 lat (msec): min=34 , max=1185 , avg=259.08, stdev=135.98 bw (KB/s) : min= 0, max=88722, per=25.95%, avg=23524.06, stdev=9036.31 cpu : usr=0.77%, sys=0.22%, ctx=2576, majf=0, minf=86 IO depths : 1=0.1%, 2=0.3%, 4=99.6%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/2728/0, short=0/0/0 lat (msec): 50=0.48%, 100=7.00%, 250=49.01%, 500=37.72%, 750=5.10% lat (msec): 1000=0.59%, 2000=0.11%Run status group 0 (all jobs):
READ: io=4092.0MB, aggrb=237499KB/s, minb=243199KB/s, maxb=243199KB/s, mint=17643msec, maxt=17643msecRun status group 1 (all jobs):
WRITE: io=4092.0MB, aggrb=90652KB/s, minb=92827KB/s, maxb=92827KB/s, mint=46223msec, maxt=46223msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=10912/10875, merge=0/0, ticks=544880/2481824, in_queue=3026996, util=99.57%, aggrios=10912/10930, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=10912/10930, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=5058/6798, aggrmerge=153871/404343, aggrticks=195870/113487, aggrin_queue=309447, aggrutil=92.15% sdc: ios=5024/7100, merge=152571/421782, ticks=332612/204936, in_queue=537660, util=92.15% sdd: ios=4961/7109, merge=150591/422166, ticks=257308/161200, in_queue=418608, util=88.11% sde: ios=5019/6697, merge=154781/395583, ticks=226120/152068, in_queue=378296, util=85.49% sdf: ios=5118/6463, merge=156068/385905, ticks=65716/23932, in_queue=89724, util=55.85% sdg: ios=5172/6624, merge=155347/396280, ticks=97596/25300, in_queue=122948, util=60.00%Am 22.12.2013 09:12, schrieb Stan Hoeppner:
Quoted 56 lines · Kevin Richter
Quoted 1 line
Okay, well, I've run your fio config... but with so many results and
I'm glad you changed to size=1G instead of size=10G lest the test would have read/written 80GB instead of 8GB, and taken forever. I often forget the size parameter is per job (thread) not global.
Quoted 3 lines
abbrevations I currently feel a bit overchallenged :) So, please dont take badly, if I just paste the whole results. I have tried with a stripe cache size of 1024, 2048 and 4096.
The full output is good. Going from 1024 to 2048 gained you ~17MB/s throughput with this job file. But you didn't run with the default 256 for comparison, which is very useful to know. That's ok, as you can do so with the next set of test runs. Given the huge latencies I'm thinking this config may be seeking the disks too much. Modify your fio job file as follows:
numjobs=4
blocksize=1536k
iodepth=4
size=1gas this may yield a little better results. ~190MB/s read and 75MB/s write is very low for three effective 7.2K RPM SATA spindles, especially the write throughput. Compare to a similar FIO job with 2 threads, iodepth 16, directio, run against a single 500GB 7.2K WD SATA drive, NQC disabled, w/deadline elevator:
Run status group 0 (all jobs):
READ: io=2048MB, aggrb=88663KB/s, minb=90791KB/s, maxb=90791KB/sRun status group 1 (all jobs):
WRITE: io=2048MB, aggrb=108089KB/s, minb=110683KB/s, maxb=110683KB/s88MB/s read, 108MB/s write. Write is faster apparently due to the small 16MB drive write cache. With your eight 2.4GHz SandyBridge cores and md-RAID6 on much newer larger 7.2K drives w/larger caches, you should have significantly greater write speed than this old single SATA drive.
Currently you're showing 30MB/s slower write throughput, some 40%
slower than this single drive. With aligned writes, thus no RMW, you should be getting at least 2 spindles worth of throughput, or ~200MB/s.So, run FIO again with the mods above, once with
stripe_cache_size256 and once with 2048. Something seems to be seriously dragging down your throughput. I'm sure you'd like to know what, and how to fix it.Quoted 4 lines
Btw, I also have
/dev/md1, this is a 15GB unencrypted array using the same 5 disks like my LUKS-md2 array, so nearly the same just without this LUKS layer. If helpful, I can execute some fio tests on this filesystem, too.This is also a RAID6 array, without dm-crypt? If so this will afford a great comparison, and may be very informative. Run FIO against this filesystem (I assume it's also XFS) as well with
stripe_cache_size512 and 2048. Four FIO tests total including the two on the big array.Quoted 149 lines
It'll be interesting to see where this leads. At this point the candidates I see are a single dm-crypt thread peaking a core, dm-crypt taking aligned writes and misaligning them causing all writes to be RMWs, or AF drives with misaligned partitions causing every write to be an internal RMW. Or maybe something I've not considered.
Quoted 142 lines
So long :)
Kevin$ echo 1024 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
____________W___] [99.7% done] [0K/99.24M /s] [0 /193 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=12987
read : io=81920MB, bw=189835KB/s, iops=370 , runt=441890msecslat (usec): min=32 , max=4561 , avg=76.28, stdev=28.66 clat (msec): min=5 , max=1115 , avg=334.19, stdev=151.18 lat (msec): min=5 , max=1115 , avg=334.26, stdev=151.18 bw (KB/s) : min= 0, max=261120, per=12.79%, avg=24288.95, stdev=11586.29 cpu : usr=0.05%, sys=0.50%, ctx=157180, majf=0, minf=16982 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.52%, 20=0.71%, 50=3.01%, 100=6.17%, 250=14.59% lat (msec): 500=68.81%, 750=4.87%, 1000=1.08%, 2000=0.25% write: (groupid=1, jobs=8): err= 0: pid=13202 write: io=81920MB, bw=58504KB/s, iops=114 , runt=1433851msec slat (usec): min=45 , max=1729 , avg=212.20, stdev=56.68 clat (msec): min=14 , max=11691 , avg=1101.17, stdev=1116.82 lat (msec): min=14 , max=11691 , avg=1101.39, stdev=1116.82 bw (KB/s) : min= 0, max=106666, per=14.35%, avg=8395.94, stdev=6752.35 cpu : usr=0.28%, sys=0.10%, ctx=117451, majf=0, minf=3410 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.17%, 100=2.03%, 250=17.02%, 500=22.20% lat (msec): 750=12.22%, 1000=8.66%, 2000=20.04%, >=2000=17.64%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189834KB/s, minb=194390KB/s, maxb=194390KB/s, mint=441890msec, maxt=441890msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=58504KB/s, minb=59908KB/s, maxb=59908KB/s, mint=1433851msec, maxt=1433851msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327681/327756, merge=0/0, ticks=78591352/353235376, in_queue=431834680, util=100.00%, aggrios=327681/327922, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327922, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=171660/222845, aggrmerge=4561629/9494657, aggrticks=16341417/4008187, aggrin_queue=20351472, aggrutil=85.78% sdc: ios=181512/222455, merge=4583055/9505634, ticks=15650600/5944080, in_queue=21596560, util=85.78% sdd: ios=180545/224362, merge=4526197/9587956, ticks=14356708/5542120, in_queue=19900820, util=85.42% sde: ios=179853/224317, merge=4519718/9540999, ticks=13375156/5676828, in_queue=19053876, util=83.90% sdf: ios=157605/222569, merge=4551205/9459549, ticks=18828608/1234632, in_queue=20065204, util=75.36% sdg: ios=158787/220525, merge=4627970/9379150, ticks=19496016/1643276, in_queue=21140904, util=77.26%$ echo 2048 > /sys/block/md2/md/stripe_cache_sizeQuoted 36 lines
Jobs: 1 (f=1): [
_________W______] [99.6% done] [0K/92182K /s] [0 /175 iops] [eta 00m:06s]
read: (groupid=0, jobs=8): err= 0: pid=6392
read : io=81920MB, bw=185893KB/s, iops=363 , runt=451259msecslat (usec): min=32 , max=524 , avg=75.08, stdev=26.00 clat (msec): min=8 , max=1849 , avg=335.65, stdev=149.76 lat (msec): min=8 , max=1849 , avg=335.72, stdev=149.76 bw (KB/s) : min= 0, max=105860, per=13.08%, avg=24308.99, stdev=7467.64 cpu : usr=0.05%, sys=0.49%, ctx=157968, majf=0, minf=17171 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.01%, 20=0.06%, 50=2.32%, 100=7.44%, 250=15.36% lat (msec): 500=69.09%, 750=4.50%, 1000=0.87%, 2000=0.35% write: (groupid=1, jobs=8): err= 0: pid=6663 write: io=81920MB, bw=75377KB/s, iops=147 , runt=1112887msec slat (usec): min=46 , max=6453.8K, avg=988.13, stdev=46664.22 clat (msec): min=10 , max=8631 , avg=854.18, stdev=683.37 lat (msec): min=10 , max=8631 , avg=855.17, stdev=684.82 bw (KB/s) : min= 0, max=100352, per=14.04%, avg=10581.97, stdev=6871.80 cpu : usr=0.34%, sys=0.11%, ctx=92502, majf=0, minf=1531 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.09%, 100=1.14%, 250=11.19%, 500=24.64% lat (msec): 750=18.78%, 1000=13.40%, 2000=24.53%, >=2000=6.23%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=185893KB/s, minb=190354KB/s, maxb=190354KB/s, mint=451259msec, maxt=451259msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=75376KB/s, minb=77186KB/s, maxb=77186KB/s, mint=1112887msec, maxt=1112887msecQuoted 8 lines
Disk stats (read/write):
dm-0: ios=327701/328169, merge=0/0, ticks=79402348/261890568, in_queue=341301888, util=100.00%, aggrios=327701/328481, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327701/328481, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=127112/146994, aggrmerge=3364061/7997232, aggrticks=18091347/5817941, aggrin_queue=23914356, aggrutil=94.20% sdc: ios=135729/149357, merge=3341205/8134447, ticks=18312932/8398716, in_queue=26721324, util=92.77% sdd: ios=135561/151584, merge=3312121/8238249, ticks=16877204/8190968, in_queue=25077332, util=92.44% sde: ios=135741/146023, merge=3345948/7981968, ticks=17659792/8659780, in_queue=26322124, util=94.20% sdf: ios=114396/143768, merge=3413295/7801050, ticks=18551976/1652924, in_queue=20207384, util=72.89% sdg: ios=114134/144241, merge=3407738/7830447, ticks=19054832/2187320, in_queue=21243620, util=74.96%$ echo 4096 > /sys/block/md2/md/stripe_cache_sizeQuoted 44 lines
Jobs: 1 (f=1): [
________W_______] [100.0% done] [0K/95848K /s] [0 /182 iops] [eta 00m:00s]
read: (groupid=0, jobs=8): err= 0: pid=11787
read : io=81920MB, bw=189274KB/s, iops=369 , runt=443200msecslat (usec): min=31 , max=4511 , avg=75.47, stdev=29.74 clat (msec): min=5 , max=1338 , avg=336.39, stdev=155.14 lat (msec): min=5 , max=1338 , avg=336.47, stdev=155.14 bw (KB/s) : min= 0, max=253455, per=12.77%, avg=24162.01, stdev=11368.71 cpu : usr=0.05%, sys=0.49%, ctx=157193, majf=0, minf=17313 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=163840/0/0, short=0/0/0 lat (msec): 10=0.47%, 20=0.66%, 50=2.95%, 100=6.33%, 250=14.56% lat (msec): 500=68.12%, 750=5.42%, 1000=1.15%, 2000=0.33% write: (groupid=1, jobs=8): err= 0: pid=12060 write: io=81920MB, bw=64993KB/s, iops=126 , runt=1290687msec slat (usec): min=61 , max=16991 , avg=197.22, stdev=110.87 clat (msec): min=14 , max=2820 , avg=980.92, stdev=366.56 lat (msec): min=14 , max=2821 , avg=981.12, stdev=366.56 bw (KB/s) : min= 0, max=103770, per=13.11%, avg=8517.92, stdev=3794.28 cpu : usr=0.28%, sys=0.08%, ctx=84352, majf=0, minf=723 IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=99.9%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=0/163840/0, short=0/0/0 lat (msec): 20=0.01%, 50=0.03%, 100=0.28%, 250=0.22%, 500=5.37% lat (msec): 750=22.02%, 1000=31.66%, 2000=39.27%, >=2000=1.16%Run status group 0 (all jobs):
READ: io=81920MB, aggrb=189273KB/s, minb=193816KB/s, maxb=193816KB/s, mint=443200msec, maxt=443200msecRun status group 1 (all jobs):
WRITE: io=81920MB, aggrb=64993KB/s, minb=66553KB/s, maxb=66553KB/s, mint=1290687msec, maxt=1290687msecDisk stats (read/write):
dm-0: ios=327681/327629, merge=0/0, ticks=78990724/301988444, in_queue=380991692, util=100.00%, aggrios=327681/327709, aggrmerge=0/0, aggrticks=0/0, aggrin_queue=0, aggrutil=0.00%md2: ios=327681/327709, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=120158/119573, aggrmerge=2858405/7663126, aggrticks=17291831/9119008, aggrin_queue=26414023, aggrutil=99.60% sdc: ios=135579/119976, merge=2813832/7324879, ticks=13974928/2192484, in_queue=16167996, util=66.57% sdd: ios=136115/127048, merge=2826584/7736191, ticks=12932248/2477796, in_queue=15410924, util=68.08% sde: ios=136007/130908, merge=2844473/7936354, ticks=12642232/3141268, in_queue=15784336, util=71.86% sdf: ios=78473/94458, merge=2882361/7865984, ticks=29053772/37421808, in_queue=66488856, util=99.60% sdg: ios=114620/125479, merge=2924777/7452224, ticks=17855976/361684, in_queue=18218004, util=54.84%
Quoted 5 lines
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 32 lines · Kevin Richter
Quoted 26 lines
Quoted 2 lines
$ cat /sys/block/md2/md/stripe_cache_size 256256 is the default and it is way too low. This is limiting your write througput. Increase this to a minimum of 1024 which will give you a 20MB stripe cache buffer. This should become active immediately. Add it to a startup script to make it permanent.
$ echo 256 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /6tb/foo1/ real 25m38.925s user 0m0.595s sys 1m23.182s$ echo 1024 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo2/ real 7m32.824s user 0m0.438s sys 1m6.759s$ echo 2048 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo3/ real 5m32.847s user 0m0.418s sys 1m5.671sQuoted 5 lines
$ echo 4096 > /sys/block/md2/md/stripe_cache_size $ time cp -a /olddisk/testfolder /raid/foo4/ real 5m54.554s user 0m0.437s sys 1m6.268s
Quoted 3 lines
The difference is really amazing! So 2048 seems to be the best choice. 60GB in 5,5minutes are 180MB/sek. That sounds a bit high, doesnt it? The RAID only consist of 5 SATA disks with 7200rpm.
I wonder why kernel is giving defaults that everyone repeatly recommends to change/increase? Has anyone tried to bugreport that for stripe_cache_size case?
Signature · 6 lines
Arkadiusz Miśkiewicz, arekm / maven.pl _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
I renamed the subject as your question doesn't really apply to XFS, or the OP, but to md-RAID.
Quoted 3 lines · Arkadiusz Miśkiewicz
I wonder why kernel is giving defaults that everyone repeatly recommends to change/increase? Has anyone tried to bugreport that for
stripe_cache_sizecase?
The answer is balancing default md-RAID5/6 write performance against kernel RAM consumption, with more weight given to the latter. The formula:
((4096*stripe_cache_size)*num_drives)= RAM consumed for stripe cache
High stripe_cache_size values will cause the kernel to eat non trivial amounts of RAM for the stripe cache buffer. This table demonstrates the effect today for typical RAID5/6 disk counts.
stripe_cache_size drives RAM consumed
256 4 4 MB
8 8 MB 16 16 MB 512 4 8 MB 8 16 MB 16 32 MB 1024 4 16 MB 8 32 MB 16 64 MB 2048 4 32 MB 8 64 MB 16 128 MB 4096 4 64 MB 8 128 MB 16 256 MB
The powers that be, Linus in particular, are not fond of default settings that create a lot of kernel memory structures. The default md-RAID5/6 stripe_cache-size yields 1MB consumed per member device.
With SSDs becoming mainstream, and becoming ever faster, at some point the md-RAID5/6 architecture will have to be redesigned because of the memory footprint required for performance. Currently the required size of the stripe cache appears directly proportional to the aggregate write throughput of the RAID devices. Thus the optimal value will vary greatly from one system to another depending on the throughput of the drives.
For example, I assisted a user with 5x Intel SSDs back in January and his system required 4096, or 80MB of RAM for stripe cache, to reach maximum write throughput of the devices. This yielded 600MB/s or 60% greater throughput than 2048, or 40MB RAM for cache. In his case 60MB more RAM than the default was well worth the increase as the machine was an iSCSI target server with 8GB RAM.
In the previous case with 5x rust RAID6 the 2048 value seemed optimal (though not yet verified), requiring 40MB less RAM than the 5x Intel SSDs. For a 3 modern rust RAID5 the default of 256, or 3MB, is close to optimal but maybe a little low. Consider that 256 has been the default for a very long time, and was selected back when average drive throughput was much much lower, as in 50MB/s or less, SSDs hadn't yet been invented, and system memories were much smaller.
Due to the massive difference in throughput between rust and SSD, any meaningful change in the default really requires new code to sniff out what type of devices constitute the array, if that's possible, and it probably isn't, and set a lowish default accordingly. Again, SSDs didn't exist when md-RAID was coded, nor when this default was set, and this throws a big monkey wrench into these spokes.
Signature · 6 lines
Stan -- To unsubscribe from this list: send the line "unsubscribe linux-raid" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
Quoted 62 lines · Stan Hoeppner
I renamed the subject as your question doesn't really apply to XFS, or the OP, but to md-RAID.
Quoted 3 lines · Arkadiusz Miśkiewicz
I wonder why kernel is giving defaults that everyone repeatly recommends to change/increase? Has anyone tried to bugreport that for
stripe_cache_sizecase?The answer is balancing default md-RAID5/6 write performance against kernel RAM consumption, with more weight given to the latter. The formula:
((4096*stripe_cache_size)*num_drives)= RAM consumed for stripe cache
High
stripe_cache_sizevalues will cause the kernel to eat non trivial amounts of RAM for the stripe cache buffer. This table demonstrates the effect today for typical RAID5/6 disk counts.
stripe_cache_sizedrives RAM consumed
256 4 4 MB8 8 MB 16 16 MB 512 4 8 MB 8 16 MB 16 32 MB 1024 4 16 MB 8 32 MB 16 64 MB 2048 4 32 MB 8 64 MB 16 128 MB 4096 4 64 MB 8 128 MB 16 256 MBThe powers that be, Linus in particular, are not fond of default settings that create a lot of kernel memory structures. The default md-RAID5/6 stripe_cache-size yields 1MB consumed per member device.
With SSDs becoming mainstream, and becoming ever faster, at some point the md-RAID5/6 architecture will have to be redesigned because of the memory footprint required for performance. Currently the required size of the stripe cache appears directly proportional to the aggregate write throughput of the RAID devices. Thus the optimal value will vary greatly from one system to another depending on the throughput of the drives.
For example, I assisted a user with 5x Intel SSDs back in January and his system required 4096, or 80MB of RAM for stripe cache, to reach maximum write throughput of the devices. This yielded 600MB/s or 60% greater throughput than 2048, or 40MB RAM for cache. In his case 60MB more RAM than the default was well worth the increase as the machine was an iSCSI target server with 8GB RAM.
In the previous case with 5x rust RAID6 the 2048 value seemed optimal (though not yet verified), requiring 40MB less RAM than the 5x Intel SSDs. For a 3 modern rust RAID5 the default of 256, or 3MB, is close to optimal but maybe a little low. Consider that 256 has been the default for a very long time, and was selected back when average drive throughput was much much lower, as in 50MB/s or less, SSDs hadn't yet been invented, and system memories were much smaller.
Quoted 6 lines
Due to the massive difference in throughput between rust and SSD, any meaningful change in the default really requires new code to sniff out what type of devices constitute the array, if that's possible, and it probably isn't, and set a lowish default accordingly. Again, SSDs didn't exist when md-RAID was coded, nor when this default was set, and this throws a big monkey wrench into these spokes.
Hi Stan,
nice analytical report, as usual...
My dumb suggestion would be to simply use udev to setup the drives.
Everything, stripe_cache, read_ahead, stcerr, etc. can be configured, I suppose, by udev rules.
bye,
Signature · 5 lines
piergiorgio -- To unsubscribe from this list: send the line "unsubscribe linux-raid" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
In reply to Stan HoeppnerOn 12/21/2013 5:18 AM, Stan Hoeppner wrote:
...
Quoted 6 lines
For example, I assisted a user with 5x Intel SSDs back in January and his system required 4096, or 80MB of RAM for stripe cache, to reach maximum write throughput of the devices. This yielded 600MB/s or 60% greater throughput than 2048, or 40MB RAM for cache. In his case 60MB more RAM than the default was well worth the increase as the machine was an iSCSI target server with 8GB RAM.
Correction here. I said above that 80MB was 60MB greater than the default for his 5 drives. This should have said 75MB greater than the default which is 1MB per member device, or 5MB for 5 drives.
Signature · 6 lines
Stan _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Re: md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
In reply to Stan HoeppnerQuoted 3 lines · Stan Hoeppner
The powers that be, Linus in particular, are not fond of default settings that create a lot of kernel memory structures. The default md-RAID5/6 stripe_cache-size yields 1MB consumed per member device.
The default sizing is stupid as it basically makes RAID unusable out of the box, I always have to fix that up, as well as a somewhat reasonable chunk size for parity RAID to make it usable. I'm also pretty sure I complained about it at least once a while ago, but never got a reply.
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Re: md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
Quoted 10 lines · Christoph Hellwig
Quoted 3 lines · Stan Hoeppner
The powers that be, Linus in particular, are not fond of default settings that create a lot of kernel memory structures. The default md-RAID5/6 stripe_cache-size yields 1MB consumed per member device.
The default sizing is stupid as it basically makes RAID unusable out of the box, I always have to fix that up, as well as a somewhat reasonable chunk size for parity RAID to make it usable. I'm also pretty sure I complained about it at least once a while ago, but never got a reply.
IIRC you Dave C. and myself all voiced criticism after the default chunk size was changed from 64KB to 512KB. I guess we didn't make a strong enough case to have it reduced, or maybe didn't use the right approach.
Maybe Neil is waiting for patches to be submitted for changing these defaults, and to argue the merits in that context instead of pure discussion? Dunno. Just guessing. Maybe he'll read this and jump in.
Signature · 7 lines
Stan _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs
Re: md-RAID5/6 stripe_cache_size default value vs performance vs memory footprint
Quoted 12 lines · On Thu, 26 Dec 2013 03:24:00 -0600 Stan Hoeppner <[email protected]> wrote:
Quoted 10 lines · Christoph Hellwig
Quoted 3 lines · Stan Hoeppner
The powers that be, Linus in particular, are not fond of default settings that create a lot of kernel memory structures. The default md-RAID5/6 stripe_cache-size yields 1MB consumed per member device.
The default sizing is stupid as it basically makes RAID unusable out of the box, I always have to fix that up, as well as a somewhat reasonable chunk size for parity RAID to make it usable. I'm also pretty sure I complained about it at least once a while ago, but never got a reply.
Quoted 8 lines
IIRC you Dave C. and myself all voiced criticism after the default chunk size was changed from 64KB to 512KB. I guess we didn't make a strong enough case to have it reduced, or maybe didn't use the right approach.
Maybe Neil is waiting for patches to be submitted for changing these defaults, and to argue the merits in that context instead of pure discussion? Dunno. Just guessing. Maybe he'll read this and jump in.
Good guess.
NeilBrown
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 2 lines
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
This is unusual. How long have you waited?
_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
Quoted 11 lines · Kevin Richter
Hi,
around April 2012 there was a similar thread on this list which I have found via Google, so my mail topic is the same.
I have a RAID6 array with 5 disks (each 2TB, net: 6TB). While copying under heavy load there are always these blocks. At the bottom of this message I have included some line from the syslog.
Even a reboot is now not possible anymore, because the whole system hangs while executing the "sync" command in one of the shutdown scripts.
Of course it will hang - it's waiting for the filesystem to make progress, and clearly it isn't....
Quoted 8 lines
So... first I have thought that my disks are faulty.
But with smartmontools I have started a short and a long test on all of the 5 disks: no errorsThen I have even recreated the whole array, but no improvement.
Details about my server: 3.2.0-57-generic, Ubuntu 12.04.3 LTS
Oh, that's quite old. I'd suggest upgrading to a much more recent kernel as we've fixed lots of issues in this area since then.
Quoted 9 lines
Quoted 9 lines
kswapd0 D
ffffffff818062400 51 20x00000000
ffff8804658099f00000000000000046ffff880465809a74ffff880465809a78ffff880465809fd8ffff880465809fd8ffff880465809fd800000000000137c0ffff880465dd1700ffff8804658180000000000000000000ffff88046175aa28Call Trace: [<ffffffff8165f62f>] schedule+0x3f/0x60 [<ffffffff81660437>] __mutex_lock_slowpath+0xd7/0x150 [<ffffffff8166004a>] mutex_lock+0x2a/0x50 [<ffffffffa029dcf8>] xfs_reclaim_inodes_ag+0x2d8/0x3a0 [xfs]
So, reclaim is stalled, meaning there there's other threads blocked reclaiming inodes....
Quoted 6 lines
Quoted 6 lines
INFO: task kswapd1:52 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. kswapd1 D 0000000000000007 0 52 2 0x00000000 ffff88046580b840 0000000000000046 0000000000000001 00000000ffffffff ffff88046580bfd8 ffff88046580bfd8 ffff88046580bfd8 00000000000137c0 ffff880865e8ae00 ffff880465819700 ffff88046580b830 0000000000000004
Quoted 8 lines
Quoted 8 lines
Call Trace: [<ffffffff8165f62f>] schedule+0x3f/0x60 [<ffffffffa02e4d17>] xlog_cil_force_lsn+0xf7/0x120 [xfs] [<ffffffffa02e3367>] _xfs_log_force_lsn+0x57/0x2e0 [xfs] [<ffffffffa02e3608>] xfs_log_force_lsn+0x18/0x40 [xfs] [<ffffffffa02cfdd4>] xfs_iunpin_nowait+0x44/0xb0 [xfs] [<ffffffffa02d1c65>] xfs_iunpin_wait+0x35/0xb0 [xfs] [<ffffffffa029cf72>] xfs_reclaim_inode+0xb2/0x2a0 [xfs]
Yup, there's the stalled reclaim, waiting on a log force in progress to complete.
Quoted 13 lines
Quoted 13 lines
Dec 18 02:19:19 kernel: [390470.199017] INFO: task xfsaild/dm-0:19192 blocked for more than 120 seconds. Dec 18 02:19:19 kernel: [390470.199828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Dec 18 02:19:19 kernel: [390470.200262] xfsaild/dm-0 D 0000000000000001 0 19192 2 0x00000000 Dec 18 02:19:19 kernel: [390470.200268] ffff88084e847a60 0000000000000046 ffff88046454d500 0000000000000000 Dec 18 02:19:19 kernel: [390470.200274] ffff88084e847fd8 ffff88084e847fd8 ffff88084e847fd8 00000000000137c0 Dec 18 02:19:19 kernel: [390470.200281] ffff88045fdd0000 ffff880461b1dc00 ffff88084e847a50 ffff88085f47d080 Dec 18 02:19:19 kernel: [390470.200288] Call Trace: Dec 18 02:19:19 kernel: [390470.200293] [<ffffffff8165f62f>] schedule+0x3f/0x60 Dec 18 02:19:19 kernel: [390470.200323] [<ffffffffa02e25da>] xlog_state_get_iclog_space+0xea/0x2e0 [xfs] Dec 18 02:19:19 kernel: [390470.200330] [<ffffffff810608e0>] ? try_to_wake_up+0x200/0x200 Dec 18 02:19:19 kernel: [390470.200358] [<ffffffffa02e2b99>] xlog_write+0xe9/0x400 [xfs] Dec 18 02:19:19 kernel: [390470.200382] [<ffffffffa02a2877>] ? kmem_zone_alloc+0x67/0xe0 [xfs] Dec 18 02:19:19 kernel: [390470.200410] [<ffffffffa02e440c>] xlog_cil_push+0x20c/0x380 [xfs]
Quoted 8 lines
Quoted 8 lines
Dec 18 02:19:19 kernel: [390470.200438] [<ffffffffa02e4d2e>] xlog_cil_force_lsn+0x10e/0x120 [xfs] Dec 18 02:19:19 kernel: [390470.200446] [<ffffffff810136e5>] ? __switch_to+0xf5/0x360 Dec 18 02:19:19 kernel: [390470.200473] [<ffffffffa02e3098>] _xfs_log_force+0x68/0x2a0 [xfs] Dec 18 02:19:19 kernel: [390470.200481] [<ffffffff81078cb2>] ? try_to_del_timer_sync+0x92/0x130 Dec 18 02:19:19 kernel: [390470.200507] [<ffffffffa02e32e8>] xfs_log_force+0x18/0x40 [xfs] Dec 18 02:19:19 kernel: [390470.200535] [<ffffffffa02e7743>] xfsaild_push+0x213/0x680 [xfs] Dec 18 02:19:19 kernel: [390470.200540] [<ffffffff8165fb45>] ? schedule_timeout+0x175/0x320 Dec 18 02:19:19 kernel: [390470.200568] [<ffffffffa02e7c12>] xfsaild+0x62/0xc0 [xfs]
And there's the log force that is in progress, and that is waiting on log buffer space to become available to finish the log force. That's waiting on IO completion to occur.
IOWs, There's nothing that points directly at an XFS issue here. There might be a problem, but it's just as likely a hardware or IO path bug that is preventing an IO completion from occurring and that is what XFS is getting hung up on....
Cheers,
Dave.
Signature · 7 lines
Dave Chinner [email protected] _______________________________________________ xfs mailing list [email protected] http://oss.sgi.com/mailman/listinfo/xfs