Incredibly slow zfs send/recv to USB disks.

[hadmut]

Hi,
I'm using a HP microserver 10plus, Intel(R) Xeon(R) E-2224 CPU @ 3.40GHz, 16 GB RAM, with 4xWD Red as a raidz2, and doing a zfs send from my old server onto this new machine worked well and fast. Around 7TB of data within a couple of hours. (encrypted)

Now I'm creating a backup from the zpool built from the internal 4 disks onto 4 USB 3.0 connected WD 2.5 Inch hard disks, also configured as a raidz2.

But a zfs send -w -R INTERNALZFS@SNAPSHOT | zfs recv USBBASEZFS

is extremely slow. Even when putting a mbuffer -q -s 128k -m 1G in the pipe, as some people recommend, the transfer from the internal to the USB based ZPOOL is in the range of just some MB/s.

Why is ZFS recv so incredibly slow when using external USB disks? (directly attached, no USB hub)

Originally I used three disks as a raidz, and this was significantly faster, but since I added a fourth disks and a raidz2, it became extremely slow.

[rincebrain]

If you would like suggestions on this, you should probably include:

• the ZFS version in question
• the output of cat /proc/spl/kstat/zfs/vdev_raidz_bench to give us some idea what the parity calcs might bottleneck at
• The precise model(s) of the 2.5in drives
• The output of zdb -l [disk] on the first partition of one of the disks in the 2.5in pool, to tell us what ashift it is
• Actual values for how fast you can recv data over not-USB versus USB
• What OS version, including kernel, you're running
• What, say, perf top and mpstat 1 think you're spending time on while doing the recv to the internal disks versus to the USB disks - is it in iowait most of the time and low CPU usage, all in raidz parity calculations and high usage, or something else entirely?

All that said, USB can be a garbage protocol for storage. Disks often reset or detach randomly, with varying levels and types of errors bubbling up the stack, and for disks that aren't UASP-compatible (USB-attached-SCSI protocol, which was a replacement for the old protocol for mass storage on USB), the overhead can be substantial.

[hadmut]

I'm using Ubuntu 22.04.1 server, zfs 2.1.4 , kernel 5.15.0-47-generic #51-Ubuntu SMP

cat /proc/spl/kstat/zfs/vdev_raidz_bench
19 0 0x01 -1 0 15898883470 270261231408429
implementation gen_p gen_pq gen_pqr rec_p rec_q rec_r rec_pq rec_pr rec_qr rec_pqr
original 495901246 214180419 122409351 1410540672 135595717 19174894 52945582 14594364 14507482 10136841
scalar 1414499341 388363881 208406043 1626149864 427922330 170026146 292339957 230666591 145523944 106068941
sse2 1941136397 976940633 650846380 2494366517 823241749 739511582 494027063 464278886 286182056 127745365
ssse3 1826584616 1199408912 654222307 1799773178 1353167086 471152546 806741959 737659923 547694261 476448215
avx2 3506532242 1784807458 1032699959 3923520408 2630375561 2128125783 1543311670 1277572113 983275330 786268950
fastest avx2 avx2 avx2 avx2 avx2 avx2 avx2 avx2 avx2 avx2

I don't know the precise model, it is an external Western Digital 5TB 2.5 inch usb disk, but no idea what's in the usb housing. Cannot open without breaking, and the USB interface completely hides what physical disk is inside. Three call them

Bus 003 Device 004: ID 1058:2621 Western Digital Technologies, Inc. Elements 2621

one (although bought later
Bus 003 Device 005: ID 1058:2620 Western Digital Technologies, Inc. Elements 2620

zdb -l /dev/sde1

---

LABEL 0

version: 5000
name: 'vierling1'
state: 0
txg: 4
pool_guid: 8421093415928506860
errata: 0
hostid: 1990279830
hostname: 'server10'
top_guid: 10429690649981175986
guid: 3162575250293464638
vdev_children: 1
vdev_tree:
    type: 'raidz'
    id: 0
    guid: 10429690649981175986
    nparity: 2
    metaslab_array: 256
    metaslab_shift: 34
    ashift: 12
    asize: 20003761946624
    is_log: 0
    create_txg: 4
    children[0]:
        type: 'disk'
        id: 0
        guid: 12897537212710507392
        path: '/dev/disk/by-id/usb-WD_Elements_2620_57583732444231333654564A-0:0-part1'
        whole_disk: 0
        create_txg: 4
    children[1]:
        type: 'disk'
        id: 1
        guid: 3162575250293464638
        path: '/dev/disk/by-id/usb-WD_Elements_2621_57583732443931464C313830-0:0-part1'
        whole_disk: 0
        create_txg: 4
    children[2]:
        type: 'disk'
        id: 2
        guid: 9622545819740732635
        path: '/dev/disk/by-id/usb-WD_Elements_2621_575837324439315043585531-0:0-part1'
        whole_disk: 0
        create_txg: 4
    children[3]:
        type: 'disk'
        id: 3
        guid: 2731712483771730189
        path: '/dev/disk/by-id/usb-WD_Elements_2621_575838324439314A374C3756-0:0-part1'
        whole_disk: 0
        create_txg: 4
features_for_read:
    com.delphix:hole_birth
    com.delphix:embedded_data
labels = 0 1 2 3 

Samples: 20K of event 'cycles', 4000 Hz, Event count (approx.): 1127014059 lost: 0/0 drop: 0/0
Overhead Shared Object Symbol
3,32% [kernel] [k] crypto_stats_skcipher_encrypt
2,00% [kernel] [k] menu_select
1,97% [kernel] [k] psi_group_change
1,96% [kernel] [k] fletcher_4_avx2_native
1,81% [kernel] [k] crypto_stats_get
1,70% [kernel] [k] _aesni_enc4
1,32% [kernel] [k] _raw_spin_lock
1,30% [kernel] [k] raidz_copy_abd_cb
1,22% [kernel] [k] xhci_ring_ep_doorbell
1,20% [kernel] [k] _raw_spin_lock_irqsave
1,02% perf [.] rb_next
0,95% [kernel] [k] cpuidle_enter_state
0,95% [kernel] [k] aesni_xts_encrypt
0,91% [kernel] [k] raidz_gen_pq_add
0,88% perf [.] kallsyms__parse
0,86% [kernel] [k] memset_erms
0,84% [kernel] [k] __schedule
0,74% perf [.] dso__find_symbol
0,73% [kernel] [k] kallsyms_expand_symbol.constprop.0
0,68% [kernel] [k] native_sched_clock
0,66% [kernel] [k] native_queued_spin_lock_slowpath.part.0
0,66% [kernel] [k] vsnprintf
0,64% [kernel] [k] xhci_update_erst_dequeue

mpstat 1

Linux 5.15.0-47-generic (server10) 10.09.2022 x86_64 (4 CPU)

22:32:38 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
22:32:39 all 0,00 0,00 0,50 74,62 0,00 0,00 0,00 0,00 0,00 24,87
22:32:40 all 0,00 0,00 1,00 72,50 0,00 0,25 0,00 0,00 0,00 26,25
22:32:41 all 0,00 0,00 0,00 82,87 0,00 0,25 0,00 0,00 0,00 16,88
22:32:42 all 0,00 0,00 1,00 68,66 0,00 0,50 0,00 0,00 0,00 29,85

top also showing now process consuming more than 1% of CPU time.

lsusb -t

/: Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/6p, 10000M
|__ Port 3: Dev 2, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
|__ Port 4: Dev 3, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
|__ Port 5: Dev 4, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
|__ Port 6: Dev 5, If 0, Class=Mass Storage, Driver=usb-storage, 5000M

But actually, USB cannot be the only reason. Doing an rsync on the same kind of disk with an ext4 file system (even when encrypted with luks) is much, much faster, although, theoretically, almost twice as much data needs to be transferred per disk compared to a 4-disk raidz2.

The machine is now up for 3 days and it still has
NAME SIZE ALLOC FREE CKPOINT EXPANDSZ FRAG CAP DEDUP HEALTH ALTROOT
vierling1 18.2T 3.97T 14.2T - - 0% 21% 1.00x ONLINE -

although send|recv is from a local 4xWD RED SATA-attached quite fast raidz2 array.

Both filesystems (and subfilesystems) are encrypted, but I am doing zfs send -w -R

I found hints on the internet that disabling the sync attribute makes things faster, and set this for the receiving pool, with zfs recv -v -x sync, but that didn't make any notable difference.

Using mbuffer -q -s 128k -m 1G in between as recommended by many, also didn't speed things up.

regards

[rincebrain]

-x sync just ignores the property from the source, it doesn't change it if it would inherit the default value from a parent, you would want -o sync=disabled to override it, and I don't know how much it'd help here anyway.

I believe your problem is that these are going to be SMR WD drives, since no 2.5in drives are going to be that dense without being SMR currently, and A) ZFS on SMR is generally going to be slow for many kinds of operations, because it's not architected to engineer around the kinds of tradeoffs you currently need for SMR, and B) WD's SMR implementation in particular is known to somehow interact so badly with ZFS that ZFS eventually boots drives out of arrays for timing out, there's a whole bunch of noise about it to be found online, AFAIK the situation has never improved.

[hadmut]

That's the very first good theory and explanation for the observed problem. It would also explain why the CPU load is just around 1%.