Massive performance degradation on sustained sequential write

Question

I'm in the process of migrating data into LUKS partitions. Now that the operating system drive is running off LUKS, I tried to start migrating the data drives. Then the server stopped responding.

This LUKS device was opened:

cryptsetup luksOpen /dev/sdc data1

And either of these commands strangled the server:

pv /dev/zero > /dev/mapper/data1
pv /dev/zero > /dev/sdc

Not immediately, but within seconds, the server became unusably slow. Everything blocked on I/O:

root@node51 [~]# ps aux | awk '{if($8~"D"||$8=="STAT"){print $0}}' 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      1197  0.0  0.0      0     0 ?        D    06:39   0:00 [jbd2/dm-1-8]
root      1687  0.1  0.0      0     0 ?        D    11:15   0:12 [kworker/u96:5]
root     13057  2.0  0.0      0     0 ?        D    13:10   0:01 [dmcrypt_write]
root     13644 10.9  0.0   7452   784 pts/1    D+   13:10   0:08 pv /dev/zero
root     14159  0.0  0.0  98256  6836 ?        DNs  13:10   0:00 sshd: root [priv]
root     14772  0.0  0.0  29008    92 ?        D    13:11   0:00 /usr/sbin/CRON -f
root     14773  0.0  0.0  98256  6748 ?        DNs  13:11   0:00 sshd: root [priv]
root     15411  0.0  0.0  98256  6876 ?        DNs  13:11   0:00 sshd: root [priv]
root     16009  0.1  0.0  98256  6840 ?        DNs  13:11   0:00 sshd: root [priv]
root     16632  0.5  0.0  98256  6892 ?        DNs  13:11   0:00 sshd: root [priv]
root     16900  0.0  0.0   5448   356 pts/3    D+   13:11   0:00 awk {if($8~"D"||$8=="STAT"){print $0}}
root     28553  0.6  0.0      0     0 ?        D    12:12   0:21 [txg_sync]

Of note, for about two seconds, pv reported that it was copying data at more than 2GiB/s. This is both the write-back cache and the dirty pages filling up (found by monitoring /proc/meminfo).

Afterwards, pv recorded a normal 200MiB/s write speed, but it was still ahead by between 2GiB and 3GiB in the write-back cache.

The server load average jumped up past 10.00 because of all the I/O blocking going on.

It takes a while to abort the pv write test because the write-back cache needs to be emptied, but right after the test was aborted, server performance returned to normal.

Interestingly, these commands don't cause the server to lag:

# Reads from dm-crypt block device
pv /dev/mapper/data1 > /dev/zero
# Reads from the raw block device
pv /dev/sdc > /dev/zero

# Writes to a control disk of a different model
pv /dev/zero > /dev/sdi
# Reads from a control disk
pv /dev/sdi > /dev/zero

# Writes to a file on a dm-crypt ext4 filesystem on a solid-state drive
pv /dev/zero > /tmp/empty
# Reads from that same solid-state drive
pv /dev/sda > /dev/zero

I have these questions:

Why do sustained sequential writes to this data disk slow down the server so much?
How can I avoid bogging down the other disks when writing to a specific one or few?
Why is this kind of hard drive causing performance issues, but other drives don't?

I have six disks of the same model (/dev/sdc, /dev/sdd, /dev/sde, /dev/sdf, /dev/sdg, and /dev/sdh) to encrypt and they will have sequential write workloads in the future, so I don't want the server to stall from this problem.

Additional Information

Quick Facts

Server: Dell PowerEdge T320

Kernel: Linux node51 4.4.0-22-generic #39-Ubuntu SMP Thu May 5 16:53:32 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

Operating system: Ubuntu Server 16.04 LTS Xenial Xerus 64-bit

Problematic hard drive: Toshiba PH3500U-1I72

I have six of these disks, all known to be healthy, and I tested two of them and experienced a server-wide I/O performance drop with both. They read and write at 200MiB/s near the beginning.

Control (problem-free) hard drive: Samsung SP1614C

This disk has a sustained write speed of 50MiB/s. Could it be that the problematic disk is too fast?

Disk controller: Dell PERC H310

Two solid-state drives and six problematic hard drives are connected to this controller, all of which are passed directly as AHCI. The control disk is connected to a SATA port built into the motherboard.

I/O schedulers

root@node51 [/tmp]# tail -n +1 /sys/block/sd*/queue/scheduler 
==> /sys/block/sda/queue/scheduler <==
noop [deadline] cfq 

==> /sys/block/sdb/queue/scheduler <==
noop [deadline] cfq 

==> /sys/block/sdc/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sdd/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sde/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sdf/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sdg/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sdh/queue/scheduler <==
[noop] deadline cfq 

==> /sys/block/sdi/queue/scheduler <==
noop [deadline] cfq

Changing the scheduler of /dev/sdc from noop to deadline makes no perceptible difference. Changing the scheduler to cfq seemed to reduce the delay somewhat, but I/O operations on the other disks still suffered.

`vm.dirty*` kernel parameters

root@node51 [~]# sysctl -a | grep 'vm.dirty'
vm.dirty_background_bytes = 0
vm.dirty_background_ratio = 10
vm.dirty_bytes = 0
vm.dirty_expire_centisecs = 3000
vm.dirty_ratio = 20
vm.dirty_writeback_centisecs = 500
vm.dirtytime_expire_seconds = 43200

Examples of slowness detected and logged to `/var/log/syslog`

ZFS transaction group sync:

May 11 19:28:44 node51 kernel: [ 4080.179688] INFO: task txg_sync:3179 blocked for more than 120 seconds.
May 11 19:28:44 node51 kernel: [ 4080.179905]       Tainted: P           O    4.4.0-22-generic #39-Ubuntu
May 11 19:28:44 node51 kernel: [ 4080.180110] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 11 19:28:44 node51 kernel: [ 4080.180357] txg_sync        D ffff88060b68baa8     0  3179      2 0x00000000
May 11 19:28:44 node51 kernel: [ 4080.180362]  ffff88060b68baa8 ffff880616a96d00 ffff8806133ea940 ffff880603dc2940
May 11 19:28:44 node51 kernel: [ 4080.180366]  ffff88060b68c000 ffff880616ad6d00 7fffffffffffffff ffff88056cb8c508
May 11 19:28:44 node51 kernel: [ 4080.180368]  0000000000000001 ffff88060b68bac0 ffffffff818211f5 0000000000000000
May 11 19:28:44 node51 kernel: [ 4080.180372] Call Trace:
May 11 19:28:44 node51 kernel: [ 4080.180381]  [<ffffffff818211f5>] schedule+0x35/0x80
May 11 19:28:44 node51 kernel: [ 4080.180385]  [<ffffffff81824315>] schedule_timeout+0x1b5/0x270
May 11 19:28:44 node51 kernel: [ 4080.180390]  [<ffffffff810abe52>] ? default_wake_function+0x12/0x20
May 11 19:28:44 node51 kernel: [ 4080.180395]  [<ffffffff810c33b2>] ? __wake_up_common+0x52/0x90
May 11 19:28:44 node51 kernel: [ 4080.180398]  [<ffffffff81820744>] io_schedule_timeout+0xa4/0x110
May 11 19:28:44 node51 kernel: [ 4080.180412]  [<ffffffffc05afbec>] cv_wait_common+0xbc/0x140 [spl]
May 11 19:28:44 node51 kernel: [ 4080.180416]  [<ffffffff810c3a70>] ? wake_atomic_t_function+0x60/0x60
May 11 19:28:44 node51 kernel: [ 4080.180423]  [<ffffffffc05afcc8>] __cv_wait_io+0x18/0x20 [spl]
May 11 19:28:44 node51 kernel: [ 4080.180487]  [<ffffffffc071320e>] zio_wait+0x10e/0x1f0 [zfs]
May 11 19:28:44 node51 kernel: [ 4080.180528]  [<ffffffffc069ce66>] dsl_pool_sync+0x2c6/0x430 [zfs]
May 11 19:28:44 node51 kernel: [ 4080.180573]  [<ffffffffc06b85b6>] spa_sync+0x366/0xb30 [zfs]
May 11 19:28:44 node51 kernel: [ 4080.180576]  [<ffffffff810abe52>] ? default_wake_function+0x12/0x20
May 11 19:28:44 node51 kernel: [ 4080.180623]  [<ffffffffc06c9a4a>] txg_sync_thread+0x3ba/0x630 [zfs]
May 11 19:28:44 node51 kernel: [ 4080.180669]  [<ffffffffc06c9690>] ? txg_delay+0x180/0x180 [zfs]
May 11 19:28:44 node51 kernel: [ 4080.180676]  [<ffffffffc05aae31>] thread_generic_wrapper+0x71/0x80 [spl]
May 11 19:28:44 node51 kernel: [ 4080.180682]  [<ffffffffc05aadc0>] ? __thread_exit+0x20/0x20 [spl]
May 11 19:28:44 node51 kernel: [ 4080.180686]  [<ffffffff810a0588>] kthread+0xd8/0xf0
May 11 19:28:44 node51 kernel: [ 4080.180688]  [<ffffffff810a04b0>] ? kthread_create_on_node+0x1e0/0x1e0
May 11 19:28:44 node51 kernel: [ 4080.180692]  [<ffffffff8182568f>] ret_from_fork+0x3f/0x70
May 11 19:28:44 node51 kernel: [ 4080.180694]  [<ffffffff810a04b0>] ? kthread_create_on_node+0x1e0/0x1e0

ext4 journal:

May 11 20:46:46 node51 kernel: [ 6000.186474] INFO: task jbd2/dm-2-8:1148 blocked for more than 120 seconds.
May 11 20:46:46 node51 kernel: [ 6000.193164]       Tainted: P           O    4.4.0-22-generic #39-Ubuntu
May 11 20:46:46 node51 kernel: [ 6000.199950] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 11 20:46:46 node51 kernel: [ 6000.208323] jbd2/dm-2-8     D ffff88060a6e7c98     0  1148      2 0x00000000
May 11 20:46:46 node51 kernel: [ 6000.208330]  ffff88060a6e7c98 0000000000000246 ffff8806133eb700 ffff88060b561b80
May 11 20:46:46 node51 kernel: [ 6000.208333]  ffff88060a6e8000 ffff88060aeb68b8 ffff88060a6e7d88 ffff88060a6e7d70
May 11 20:46:46 node51 kernel: [ 6000.208336]  ffff88060b561b80 ffff88060a6e7cb0 ffffffff818211f5 ffff8805fd6af900
May 11 20:46:46 node51 kernel: [ 6000.208339] Call Trace:
May 11 20:46:46 node51 kernel: [ 6000.208355]  [<ffffffff818211f5>] schedule+0x35/0x80
May 11 20:46:46 node51 kernel: [ 6000.208361]  [<ffffffff812ea0e0>] jbd2_journal_commit_transaction+0x240/0x1870
May 11 20:46:46 node51 kernel: [ 6000.208365]  [<ffffffff810b6be1>] ? dequeue_entity+0x431/0xa80
May 11 20:46:46 node51 kernel: [ 6000.208368]  [<ffffffff810b774a>] ? dequeue_task_fair+0x51a/0x8a0
May 11 20:46:46 node51 kernel: [ 6000.208372]  [<ffffffff810c3a70>] ? wake_atomic_t_function+0x60/0x60
May 11 20:46:46 node51 kernel: [ 6000.208378]  [<ffffffff810ec5fe>] ? try_to_del_timer_sync+0x5e/0x90
May 11 20:46:46 node51 kernel: [ 6000.208381]  [<ffffffff812ef32a>] kjournald2+0xca/0x250
May 11 20:46:46 node51 kernel: [ 6000.208384]  [<ffffffff810c3a70>] ? wake_atomic_t_function+0x60/0x60
May 11 20:46:46 node51 kernel: [ 6000.208387]  [<ffffffff812ef260>] ? commit_timeout+0x10/0x10
May 11 20:46:46 node51 kernel: [ 6000.208391]  [<ffffffff810a0588>] kthread+0xd8/0xf0
May 11 20:46:46 node51 kernel: [ 6000.208394]  [<ffffffff810a04b0>] ? kthread_create_on_node+0x1e0/0x1e0
May 11 20:46:46 node51 kernel: [ 6000.208397]  [<ffffffff8182568f>] ret_from_fork+0x3f/0x70
May 11 20:46:46 node51 kernel: [ 6000.208399]  [<ffffffff810a04b0>] ? kthread_create_on_node+0x1e0/0x1e0
May 11 20:46:46 node51 kernel: [ 6292.776357] perf interrupt took too long (2539 > 2500), lowering kernel.perf_event_max_sample_rate to 50000

May I ask what type of performance you'd expect from this setup? — ewwhite, May 13, 2016 at 0:28
@ewwhite: If I type in uptime and press [Enter], I should expect to see the load averages in less than 0m0.010s, not after 6m49.891s. (Yes, that is an actual result from time.) — Deltik, May 13, 2016 at 0:40
Considering you are using a decent PERC, perhaps try disabling OS write cache — Patrick, May 13, 2016 at 0:49
This discusses an issue where the os write cache is so large, when the system flushes it, the system grinds to a halt. Where as, if you make it smaller, it is only the application that will grind. linux-kernel.2935.n7.nabble.com/… — Patrick, May 13, 2016 at 0:58
@Patrick: Disabling the write cache (sysctl vm.dirty_background_ratio=0 and sysctl vm.dirty_ratio=0) eliminated the OS freezing as a side effect of reducing I/O throughput by a factor of 165. I tried playing with the ratios, but the whole server I/O still crumples at the hard drive's 200MiB/s sustained write. — Deltik, May 13, 2016 at 1:28

Patrick · Accepted Answer · 2016-05-13 02:42:14Z

1

The control disk is connected to a SATA port built into the motherboard.

As stated, the disks experiencing the journal flush time out issues are connected to the PERC, the same controller that the 'problematic' Toshiba's are connected to.

The PERC 310 is only a basic hardware raid card. It's CPU is probably easily overwhelmed, either that or there is a firmware bug. Direct AHCI is not a very common usage.

I would suggest the IO is locking up on the PERC, and not the OS

answered May 13, 2016 at 2:42

Patrick

2501 silver badge11 bronze badges

To anyone looking for how to fix the poor I/O performance, the solution is to cross-flash the firmware of the Dell PERC H310 from IR ("Integrated RAID") mode to IT ("Initiator Target") mode, effectively converting the HBA (host bus adapter) to an LSI SAS 9211-8i. The linked tutorial has easy-to-follow instructions on how to flash the IT firmware.
– Deltik
Apr 27 at 4:18

Add a comment |

ewwhite · Accepted Answer · 2016-05-13 00:50:13Z

0

This is a lot to digest.

You're using ZFS, so there's a good chance that this is an issue with the 5TB disks in your pool and potentially your pool setup.

These may be 4k-sector disks, so some accommodations should be made in your ZFS setup to account for that.

Can you provide your df -h, fdisk -l, zpool list, zpool status -v and zfs list output?

answered May 13, 2016 at 0:50

ewwhite

198k92 gold badges444 silver badges811 bronze badges

Since the txg_sync message, I exported the only zpool (which wasn't even actively used at the time) in hopes that would help with the performance problem. The effect of taking down the zpool was negligible. Would you like me to reimport the zpool and provide you the outputs you requested anyway?
– Deltik
May 13, 2016 at 0:59
No, you shouldn't need to. What filesystem are you using?
– ewwhite
May 13, 2016 at 1:04
ext4 for /. There's ext2 for /boot and vfat for /boot/efi, but those probably don't matter. The sequential write benchmark that's killing the server isn't even on a filesystem―it's on the raw block device.
– Deltik
May 13, 2016 at 1:06

Add a comment |

Mikko Rantalainen · Accepted Answer · 2017-05-17 06:35:09Z

0

I think your write cache is too big compared to your block device speeds. I would suggest following:

vm.dirty_background_bytes = 50000000
vm.dirty_bytes = 200000000
vm.dirty_expire_centisecs = 500
vm.dirty_writeback_centisecs = 20

Never ever set both *_bytes and *_ratio because the last one that is set will win. In addition, some Linux kernel versions may have a bug where setting *_ratio does not work as intended. I would suggest using *_bytes every time.

Unfortunately, the write cache settings are global as far as I know. As a result, throughput to your faster devices will suffer a bit when you need to reduce the global write cache size due to some slow device.

answered May 17, 2017 at 6:35

Mikko Rantalainen

1,10014 silver badges30 bronze badges

I've already tried messing with the dirty memory settings and found that disabling the cache entirely works around the issue at a cost of 165× I/O performance degradation. We know the Dell PERC H310 is part of the problem because moving a hard drive directly to SATA makes the issue go away for that hard drive. Perhaps the disk controller can't handle fast hard drives.
– Deltik
May 17, 2017 at 12:53

Add a comment |

Stack Exchange Network

Massive performance degradation on sustained sequential write

Additional Information

Quick Facts

I/O schedulers

`vm.dirty*` kernel parameters

Examples of slowness detected and logged to `/var/log/syslog`

3 Answers 3

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged
linux
performance
hard-drive
io
.

Hot Network Questions

Massive performance degradation on sustained sequential write

Additional Information

Quick Facts

I/O schedulers

vm.dirty* kernel parameters

Examples of slowness detected and logged to /var/log/syslog

3 Answers 3

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged linuxperformancehard-driveio.

Related

Hot Network Questions

`vm.dirty*` kernel parameters

Examples of slowness detected and logged to `/var/log/syslog`

Not the answer you're looking for? Browse other questions tagged
linux
performance
hard-drive
io
.