OpenZFS zvol performance issues

Explore

OpenZFS zvol performance issues

OpenZFS zvol performance issues

raw zfs send / recv issue

When I first detected this issue the system had been up and stable 54 days running zfs 2.0.3-pve2 and kernel 5.4.101-1-pve. Since boot iostat showed ~75 TiB of reads from the disks and 6.4 TiB of writes. 16 of the 20 disks in the system use are incorporated into zpools.

I wanted to test changing my zpool backup approach from individual encryption keys for storeN and storeN-backup which worked well in practice for local zpools but had the side-effect that syncoid jobs required both pools to have their keys loaded, AND it was not possible to perform incremental raw send and receive because the crypto keys were different. The long term goal is to move the storeN-backup pools off-site, so raw incremental operations were a MUST HAVE. Why?

So the blocks being transmitted would be encrypted with their key during send+recv operations.

AND so I can perform incremental/delta block replication between the src and dst zpools over WAN in the future.

So I did a bit of research and went about performing a zfs send --replicate --raw equivalent with syncoid to seed storeN-backup as identically as possible to storeN, and then tested the raw incremental operations. In initial tests everything looked good...

I did some testing first with a spare disk, and the moved on to perform this for the smallest store6 and then store1. For store1 I ran into some issues as follows:

started a syncoid job to recursively seed store6-backup zpool.

time syncoid --compress=none --sendoptions=Rw --no-sync-snap store6/data store6-backup/data

no issues detected.

started a syncoid job to recursively seed store1-backup zpool.

time syncoid --compress=none --sendoptions=Rw --no-sync-snap store1/data store1-backup/data

🔥🔥🔥 significant performance drop off without recovery after ~3h of transfer, kernel logging:

task txg_sync:3748 blocked for more than 120 seconds

CTRL+C the syncoid process.

double checked the dataset sync=disabled settings were being inherited in the send process, increased mbuffer size and resumed point 2 job, had to be specific to the dataset to resume:

time syncoid --compress=none --mbuffer-size=32M --sendoptions=w --no-sync-snap store1/data/vm/raw store1-backup/data/vm/raw

performance did not recover to expected levels, apt --full-upgrade which included upgrades to kernel and zfs:

kernel 5.4.101-1-pve to 5.4.157-1-pve

zfsutils-linux/stable 2.0.3-pve2 to 2.0.6-pve1~bpo10+1 amd64

After the reboot resumed the job per step 5

time syncoid --compress=none --mbuffer-size=32M --sendoptions=w --no-sync-snap store1/data/vm/raw store1-backup/data/vm/raw

Let the job finish and then followed up with:

time syncoid --sendoptions=w --recursive store1/data store1-backup/data

✅ to check that the recursive send+recv is good.

Note, I checked to see which HBA’s the disks were connected to

# check the disks LUN location:

root@viper:~# udevadm info --query=all --name=/dev/sdh | grep S:.*by-path # store6-bk

S: disk/by-path/pci-0000:02:00.0-sas-phy7-lun-0

root@viper:~# udevadm info --query=all --name=/dev/sdb | grep S:.*by-path # store1-bk

S: disk/by-path/pci-0000:02:00.0-sas-phy1-lun-0

root@viper:~# udevadm info --query=all --name=/dev/sdn | grep S:.*by-path # syncoid-test

S: disk/by-path/pci-0000:03:00.0-sas-phy6-lun-0

root@viper:~# udevadm info --query=all --name=/dev/sdi | grep S:.*by-path # store1

S: disk/by-path/pci-0000:02:00.0-sas-phy18-lun-0

root@viper:~# udevadm info --query=all --name=/dev/sdr | grep S:.*by-path # store6

S: disk/by-path/pci-0000:03:00.0-sas-phy18-lun-0

the store6 to syncoid-test was same-HBA ✅

the store6 to store6-backup was inter-HBA ✅

the store1 to store1-backup was same-HBA 🔥

No strong evidence on HBA issues there at the moment.

⁠

RAM+SWAP for the same time range:

⁠

store1-backup (sdb) notable disk stats.

note how average write I/O time jumped during the issue, and again during the later part of the operation after kernel upgrade.

it looks like the timestamp of the txg_sync logs match the degradation on graph here.

⁠

sample of 1 of 5 kernel log examples for txg_sync:

Dec 10 18:24:46 viper kernel: INFO: task txg_sync:3748 blocked for more than 120 seconds.

Dec 10 18:24:46 viper kernel: Tainted: P O 5.4.101-1-pve #1

Dec 10 18:24:46 viper kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Dec 10 18:24:46 viper kernel: txg_sync D 0 3748 2 0x80004000

Dec 10 18:24:46 viper kernel: Call Trace:

Dec 10 18:24:46 viper kernel: __schedule+0x2e6/0x6f0

Dec 10 18:24:46 viper kernel: schedule+0x33/0xa0

Dec 10 18:24:46 viper kernel: schedule_timeout+0x152/0x330

Dec 10 18:24:46 viper kernel: ? __next_timer_interrupt+0xd0/0xd0

Dec 10 18:24:46 viper kernel: io_schedule_timeout+0x1e/0x50

Dec 10 18:24:46 viper kernel: __cv_timedwait_common+0x138/0x170 [spl]

Dec 10 18:24:46 viper kernel: ? wait_woken+0x80/0x80

Dec 10 18:24:46 viper kernel: __cv_timedwait_io+0x19/0x20 [spl]

Dec 10 18:24:46 viper kernel: zio_wait+0x139/0x280 [zfs]

Dec 10 18:24:46 viper kernel: ? _cond_resched+0x19/0x30

Dec 10 18:24:46 viper kernel: dsl_pool_sync+0xdc/0x510 [zfs]

Dec 10 18:24:46 viper kernel: spa_sync+0x5a4/0xfe0 [zfs]

Dec 10 18:24:46 viper kernel: ? mutex_lock+0x12/0x30

Dec 10 18:24:46 viper kernel: ? spa_txg_history_init_io+0x104/0x110 [zfs]

Dec 10 18:24:46 viper kernel: txg_sync_thread+0x2e1/0x4a0 [zfs]

Dec 10 18:24:46 viper kernel: ? txg_thread_exit.isra.13+0x60/0x60 [zfs]

Dec 10 18:24:46 viper kernel: thread_generic_wrapper+0x74/0x90 [spl]

Dec 10 18:24:46 viper kernel: kthread+0x120/0x140

Dec 10 18:24:46 viper kernel: ? __thread_exit+0x20/0x20 [spl]

Dec 10 18:24:46 viper kernel: ? kthread_park+0x90/0x90

Dec 10 18:24:46 viper kernel: ret_from_fork+0x35/0x40

iostat before the reboot:

kyle@viper:~$ uptime

22:44:53 up 54 days, 7:04, 1 user, load average: 0.61, 3.10, 4.54

kyle@viper:~$ iostat

Linux 5.4.101-1-pve (viper) 12/10/2021 _x86_64_ (24 CPU)

avg-cpu: %user %nice %system %iowait %steal %idle

0.54 0.00 0.91 0.25 0.00 98.31

Device tps kB_read/s kB_wrtn/s kB_read kB_wrtn

loop0 0.00 0.01 0.00 63649 0

sdg 19.26 21.82 228.97 102369166 1074133692

sdj 19.05 21.61 228.97 101351830 1074133692

sda 8.07 2129.45 15.54 9989454888 72889608

sde 0.66 602.21 0.52 2825035260 2450892

sdi (store1) 10.11 2323.14 15.54 10898051016 72905464

sdf 0.26 213.37 0.16 1000933524 770944

sdc 0.66 605.09 1.20 2838522632 5619112

sdd 0.66 593.64 0.48 2784796908 2255996

sdb (store1-bk) 1.18 585.46 271.15 2746468296 1272002744

sdh (store6-bk) 0.61 188.96 217.38 886421900 1019732520

sdr (store6) 4.58 1038.45 93.69 4871453828 439530028

sdl 5.96 1460.52 66.38 6851450978 311392323

sdq 9.31 2140.22 15.49 10039950012 72672928

sdo 5.96 1460.52 66.38 6851451078 311392340

sdm 5.96 1460.52 66.38 6851451298 311392319

sdp 3.02 605.20 15.17 2839068356 71175112

sdn (syncoid-test)0.31 0.02 172.87 86290 810945685

sdk 8.63 2106.64 15.70 9882432536 73669984

sds 0.00 0.00 0.00 3223 0

Upgraded kernel 5.4.101-1-pve to 5.4.157-1-pve.

Upgraded zfsutils-linux/stable 2.0.3-pve2 to 2.0.6-pve1~bpo10+1 amd64

Rebooted

During the final part of the send+recv there was one more example of the txg_sync message in the kernel log:

Dec 11 03:28:03 viper kernel: INFO: task txg_sync:11367 blocked for more than 120 seconds.

Dec 11 03:28:03 viper kernel: Tainted: P O 5.4.157-1-pve #1

Dec 11 03:28:03 viper kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Dec 11 03:28:03 viper kernel: txg_sync D 0 11367 2 0x80004000

Dec 11 03:28:03 viper kernel: Call Trace:

Dec 11 03:28:03 viper kernel: __schedule+0x2e6/0x6f0

Dec 11 03:28:03 viper kernel: schedule+0x33/0xa0

Dec 11 03:28:03 viper kernel: schedule_timeout+0x152/0x330

Dec 11 03:28:03 viper kernel: ? __next_timer_interrupt+0xd0/0xd0

Dec 11 03:28:03 viper kernel: io_schedule_timeout+0x1e/0x50

Dec 11 03:28:03 viper kernel: __cv_timedwait_common+0x138/0x170 [spl]

Dec 11 03:28:03 viper kernel: ? wait_woken+0x80/0x80

Dec 11 03:28:03 viper kernel: __cv_timedwait_io+0x19/0x20 [spl]

Dec 11 03:28:03 viper kernel: zio_wait+0x139/0x280 [zfs]

Dec 11 03:28:03 viper kernel: ? _cond_resched+0x19/0x30

Dec 11 03:28:03 viper kernel: dsl_pool_sync+0xdc/0x510 [zfs]

Dec 11 03:28:03 viper kernel: spa_sync+0x584/0xff0 [zfs]

Dec 11 03:28:03 viper kernel: ? mutex_lock+0x12/0x30

Dec 11 03:28:03 viper kernel: ? spa_txg_history_init_io+0x104/0x110 [zfs]

Dec 11 03:28:03 viper kernel: txg_sync_thread+0x2e1/0x4a0 [zfs]

Dec 11 03:28:03 viper kernel: ? txg_thread_exit.isra.13+0x60/0x60 [zfs]

Dec 11 03:28:03 viper kernel: thread_generic_wrapper+0x74/0x90 [spl]

Dec 11 03:28:03 viper kernel: kthread+0x120/0x140

Dec 11 03:28:03 viper kernel: ? __thread_exit+0x20/0x20 [spl]

Dec 11 03:28:03 viper kernel: ? kthread_park+0x90/0x90

Dec 11 03:28:03 viper kernel: ret_from_fork+0x35/0x40

summary and open points

related github issue:

task txg_sync blocked for more than 120 seconds. · Issue #9130 · openzfs/zfs⁠

. I made post on the issue

here⁠

This initial issue documents a case with rsync but other thread contributors talk about having the issue with send / recv operations.

The kernel upgrade + reboot seemed to help some but its unclear which one, will continue to monitor.

Note that the txg_sync log entries happened before and after the kernel upgrade/reboot.

From the github issue kirscheGIT commented on 12 May:

After upgrade to zfs-2.0.4-pve1 the problem mentioned here
#9130 (comment)⁠
disappeared.

So that is promising as I upgraded from 2.0.3 to 2.0.6.

However... matti commented on 17 Oct:

same here with proxmox 7.0, kernel 5.11. no smart errors, tried multiple disks.

I guess only time will tell as this stage.

Q: could it be that the performance of the operation has a relation to the layout and content of the blocks on the sender? store6 contains a lot of media backups with compressed binary data, and store1 is more of a mixed bag of various backups and file sizes and counts. I assume that because the transfer is --raw that the receiving side cannot perform any optimisation or such on the incoming blocks.

Q: TEST ME: can one create a dataset with the same key and perform a mixture of --raw and non --raw transfers? It sounds like this should be possible but it will break the raw incremental ability.

Note that if you do not use this flag (--raw) for sending encrypted datasets, data will be sent unencrypted and may be re-encrypted with a different encryption key on the receiving system, which will disable the ability to do a raw send to that system for incrementals.

A: 2021-12-13 citing from man zfs-receive:

The added security provided by raw sends adds some restrictions to the send and receive process. ZFS will not allow a mix of raw receives and non-raw receives. Specifically, ⚠ any raw incremental receives that are attempted after a non-raw receive will fail ⚠. Non-raw receives do not have this restriction and, therefore, are always possible. Because of this, it is best practice to always use either raw sends for their security benefits or non-raw sends for their flexibility when working with encrypted datasets, but not a combination.

Overall HBA or disk performance does NOT appear to be an issue, the following screenshot shows the system under heavy load. 1.65 GiB/s read throughput during the active scrub of 13 zpools made of single vdev 2.5” HDD.

✅ TODO: re-patch the zfs scrub script to scrub max n zpools concurrently which was overwritten during the zfsutils upgrade. Why didn’t dpkg prompt to keep this modified file? because it was outside of /etc? make the file immutable? will that fail package updates?

⁠

2021-12-13 update

Happened again after ~3.5h during store2 → store2-backup --raw --replicate send / receive.

Dec 13 11:19:07 viper kernel: INFO: task txg_sync:11792 blocked for more than 120 seconds.

Dec 13 11:19:07 viper kernel: Tainted: P O 5.4.157-1-pve #1

Dec 13 11:19:07 viper kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Dec 13 11:19:07 viper kernel: txg_sync D 0 11792 2 0x80004000

Dec 13 11:19:07 viper kernel: Call Trace:

Dec 13 11:19:07 viper kernel: __schedule+0x2e6/0x6f0

Dec 13 11:19:08 viper kernel: schedule+0x33/0xa0

Dec 13 11:19:08 viper kernel: schedule_timeout+0x152/0x330

Dec 13 11:19:08 viper kernel: ? __next_timer_interrupt+0xd0/0xd0

Dec 13 11:19:08 viper kernel: io_schedule_timeout+0x1e/0x50

Dec 13 11:19:08 viper kernel: __cv_timedwait_common+0x138/0x170 [spl]

Dec 13 11:19:08 viper kernel: ? wait_woken+0x80/0x80

Dec 13 11:19:08 viper kernel: __cv_timedwait_io+0x19/0x20 [spl]

Dec 13 11:19:08 viper kernel: zio_wait+0x139/0x280 [zfs]

Dec 13 11:19:08 viper kernel: ? _cond_resched+0x19/0x30

Dec 13 11:19:08 viper kernel: dsl_pool_sync+0xdc/0x510 [zfs]

Dec 13 11:19:08 viper kernel: spa_sync+0x584/0xff0 [zfs]

Dec 13 11:19:08 viper kernel: ? mutex_lock+0x12/0x30

Dec 13 11:19:08 viper kernel: ? spa_txg_history_init_io+0x104/0x110 [zfs]

Dec 13 11:19:08 viper kernel: txg_sync_thread+0x2e1/0x4a0 [zfs]

Dec 13 11:19:08 viper kernel: ? txg_thread_exit.isra.13+0x60/0x60 [zfs]

Dec 13 11:19:08 viper kernel: thread_generic_wrapper+0x74/0x90 [spl]

Dec 13 11:19:08 viper kernel: kthread+0x120/0x140

Dec 13 11:19:08 viper kernel: ? __thread_exit+0x20/0x20 [spl]

Dec 13 11:19:08 viper kernel: ? kthread_park+0x90/0x90

Dec 13 11:19:08 viper kernel: ret_from_fork+0x35/0x40

⁠

2022-11-26 update - rsync issue

hypervisor graphs

⁠

Nothing remarkable in the ZFS Cache graphs

Nov 26 08:48:18 viper kernel: INFO: task txg_sync:447490 blocked for more than 120 seconds.

Nov 26 08:48:18 viper kernel: Tainted: P O 5.13.19-4-pve #1

Nov 26 08:48:18 viper kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Nov 26 08:48:18 viper kernel: task:txg_sync state:D stack: 0 pid:447490 ppid: 2 flags:0x00004000

Nov 26 08:48:18 viper kernel: Call Trace:

Nov 26 08:48:18 viper kernel: <TASK>

Nov 26 08:48:18 viper kernel: __schedule+0x2fa/0x910

Nov 26 08:48:18 viper kernel: schedule+0x4f/0xc0

Nov 26 08:48:18 viper kernel: schedule_timeout+0x8a/0x140

Nov 26 08:48:18 viper kernel: ? __bpf_trace_tick_stop+0x10/0x10

Nov 26 08:48:18 viper kernel: io_schedule_timeout+0x51/0x80

Nov 26 08:48:18 viper kernel: __cv_timedwait_common+0x131/0x170 [spl]

Nov 26 08:48:18 viper kernel: ? wait_woken+0x80/0x80

Nov 26 08:48:18 viper kernel: __cv_timedwait_io+0x19/0x20 [spl]

Nov 26 08:48:18 viper kernel: zio_wait+0x133/0x2c0 [zfs]

Nov 26 08:48:18 viper kernel: dsl_pool_sync+0xcc/0x4f0 [zfs]

Nov 26 08:48:18 viper kernel: spa_sync+0x55a/0xff0 [zfs]

Nov 26 08:48:18 viper kernel: ? spa_txg_history_init_io+0x106/0x110 [zfs]

Nov 26 08:48:18 viper kernel: txg_sync_thread+0x2d3/0x460 [zfs]

Nov 26 08:48:18 viper kernel: ? txg_init+0x260/0x260 [zfs]

Nov 26 08:48:18 viper kernel: thread_generic_wrapper+0x79/0x90 [spl]

Nov 26 08:48:18 viper kernel: ? __thread_exit+0x20/0x20 [spl]

Nov 26 08:48:18 viper kernel: kthread+0x12b/0x150

Nov 26 08:48:18 viper kernel: ? set_kthread_struct+0x50/0x50

Nov 26 08:48:18 viper kernel: ret_from_fork+0x22/0x30

Nov 26 08:48:18 viper kernel: </TASK>

Nov 26 08:58:22 viper kernel: INFO: task txg_sync:447490 blocked for more than 120 seconds.

Nov 26 08:58:22 viper kernel: Tainted: P O 5.13.19-4-pve #1

Nov 26 08:58:22 viper kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Nov 26 08:58:22 viper kernel: task:txg_sync state:D stack: 0 pid:447490 ppid: 2 flags:0x00004000

Nov 26 08:58:22 viper kernel: Call Trace:

Nov 26 08:58:22 viper kernel: <TASK>

Nov 26 08:58:22 viper kernel: __schedule+0x2fa/0x910

Nov 26 08:58:22 viper kernel: schedule+0x4f/0xc0

Nov 26 08:58:22 viper kernel: schedule_timeout+0x8a/0x140

Nov 26 08:58:22 viper kernel: ? __bpf_trace_tick_stop+0x10/0x10

Nov 26 08:58:22 viper kernel: io_schedule_timeout+0x51/0x80

Nov 26 08:58:22 viper kernel: __cv_timedwait_common+0x131/0x170 [spl]

Nov 26 08:58:22 viper kernel: ? wait_woken+0x80/0x80

Nov 26 08:58:22 viper kernel: __cv_timedwait_io+0x19/0x20 [spl]

Nov 26 08:58:22 viper kernel: zio_wait+0x133/0x2c0 [zfs]

Nov 26 08:58:22 viper kernel: dsl_pool_sync+0xcc/0x4f0 [zfs]

Nov 26 08:58:22 viper kernel: spa_sync+0x55a/0xff0 [zfs]

Nov 26 08:58:22 viper kernel: ? spa_txg_history_init_io+0x106/0x110 [zfs]

Nov 26 08:58:22 viper kernel: txg_sync_thread+0x2d3/0x460 [zfs]

Nov 26 08:58:22 viper kernel: ? txg_init+0x260/0x260 [zfs]

Nov 26 08:58:22 viper kernel: thread_generic_wrapper+0x79/0x90 [spl]

Nov 26 08:58:22 viper kernel: ? __thread_exit+0x20/0x20 [spl]

Nov 26 08:58:22 viper kernel: kthread+0x12b/0x150

Nov 26 08:58:22 viper kernel: ? set_kthread_struct+0x50/0x50

Nov 26 08:58:22 viper kernel: ret_from_fork+0x22/0x30

Nov 26 08:58:22 viper kernel: </TASK>

Nov 26 09:10:27 viper kernel: INFO: task txg_sync:447490 blocked for more than 120 seconds.

Nov 26 09:10:27 viper kernel: Tainted: P O 5.13.19-4-pve #1

summary and open points

2021-12-13 update

2022-11-26 update - rsync issue

Gallery

Want to print your doc?
This is not the way.

Try clicking the ⋯ next to your doc name or using a keyboard shortcut (

CtrlP

) instead.