Raspberry Pi very slow access to external USB drive

I have NCP 1.32.1 with NC20 installed on my RaspberryPi4 (4GB). The data directory is on an external SSD (1TB) with BTRFS connected over a powered USB-Hub on USB3.
The database and OS are on the SD-Card of the Raspberry. Everything works fine in terms of the Nextcloud.
But when I try to do Backups to a second Drive I see some strange behaviour. The second Drive is connected via the USB Hub as well. As a second Backup Drive I tested with a 500GB HDD and a 32GB Flash Drive, both with the same behaviour.

I copy the datadir with the following command to the backup Drive after setting the NC into maintenance mode:
sudo rsync -avrt --delete --progress /media/stefNCP/nextcloudDatadir/ /media/backupNCP/rSyncTest/
The copy process of most of the files goes smooth with a reasonable speed. But every now and then, files occur which take 1min or 30sec to copy. As it takes exactly the same amount of time for these files i suspect some other task to block the file access.
Any ideas what could cause this strange behaviour?
See part of the rtsync log in the following picture:

Have you tried using nc-snapshot-sync
or btrfs-sync, not to sure, but I read somewhere rsync in archive mode can give odd behaviour when used on btrfs.
Check https://ownyourbits.com/2018/03/09/easy-sync-of-btrfs-snapshots-with-btrfs-sync/

Sorry for the big delay. I was not at home.
I setup everything completely new. Now on the arm64 architecture.
But I get the same behaviour.
Also when I try the btrfs-sync I can see in the rate that it stays on 0.0B/s almost all the time and only every 30 seconds the speed goes up for a short period of time.

I found some more details describing the problem. With “dmesg” I found that the drive aborts and resets itself and probably this process takes around 30 seconds…

With that knowledge I found some related topic here in the forum Raspberry Pi4 USB HDD Issues
There it sounds like it must be a power-issue with the drives.

They are now connected together with a powered USB Hub with a Supply of 5V/3A. The Output of “dmesg” is below. They are detected correctly, but after starting RSync ‘sda’ seems to have some failures. SDA is the SSD which anyway should need less power. So thes makes me doubt that the problem is a power-related issue.

[ 3867.315888] usb 2-1: new SuperSpeed Gen 1 USB device number 8 using xhci_hcd
[ 3867.346549] usb 2-1: New USB device found, idVendor=0bda, idProduct=0411, bcdDevice= 1.04
[ 3867.346566] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 3867.346578] usb 2-1: Product: 4-Port USB 3.0 Hub
[ 3867.346590] usb 2-1: Manufacturer: Generic
[ 3867.360093] hub 2-1:1.0: USB hub found
[ 3867.361161] hub 2-1:1.0: 4 ports detected
[ 3867.419484] usb 1-1.1: new high-speed USB device number 5 using xhci_hcd
[ 3867.529973] usb 1-1.1: New USB device found, idVendor=0bda, idProduct=5411, bcdDevice= 1.04
[ 3867.529986] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 3867.529996] usb 1-1.1: Product: 4-Port USB 2.0 Hub
[ 3867.530005] usb 1-1.1: Manufacturer: Generic
[ 3867.531944] hub 1-1.1:1.0: USB hub found
[ 3867.532582] hub 1-1.1:1.0: 4 ports detected
[ 3867.651804] usb 2-1.1: new SuperSpeed Gen 1 USB device number 9 using xhci_hcd
[ 3867.672869] usb 2-1.1: New USB device found, idVendor=1058, idProduct=0741, bcdDevice=10.25
[ 3867.672886] usb 2-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[ 3867.672898] usb 2-1.1: Product: My Passport 0741
[ 3867.672909] usb 2-1.1: Manufacturer: Western Digital
[ 3867.672921] usb 2-1.1: SerialNumber: 575839314141334A32333438
[ 3867.677789] usb-storage 2-1.1:1.0: USB Mass Storage device detected
[ 3867.678563] scsi host0: usb-storage 2-1.1:1.0
[ 3867.759827] usb 2-1.4: new SuperSpeed Gen 1 USB device number 10 using xhci_hcd
[ 3867.781095] usb 2-1.4: New USB device found, idVendor=152d, idProduct=0562, bcdDevice= 2.14
[ 3867.781103] usb 2-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 3867.781108] usb 2-1.4: Product: External
[ 3867.781113] usb 2-1.4: Manufacturer: JMicron
[ 3867.781117] usb 2-1.4: SerialNumber: DD56419883891
[ 3867.790587] scsi host1: uas
[ 3867.791980] scsi 1:0:0:0: Direct-Access JMicron Tech 0214 PQ: 0 ANSI: 6
[ 3867.793339] sd 1:0:0:0: Attached scsi generic sg0 type 0
[ 3868.329526] sd 1:0:0:0: [sda] 1953525168 512-byte logical blocks: (1.00 TB/932 GiB)
[ 3868.329535] sd 1:0:0:0: [sda] 4096-byte physical blocks
[ 3868.329737] sd 1:0:0:0: [sda] Write Protect is off
[ 3868.329743] sd 1:0:0:0: [sda] Mode Sense: 53 00 00 08
[ 3868.330115] sd 1:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn’t support DPO or FUA
[ 3868.330694] sd 1:0:0:0: [sda] Optimal transfer size 33553920 bytes not a multiple of physical block size (4096 bytes)
[ 3868.347533] sda: sda1
[ 3868.349974] sd 1:0:0:0: [sda] Attached SCSI disk
[ 3868.489160] BTRFS info (device sda1): disk space caching is enabled
[ 3868.489170] BTRFS info (device sda1): has skinny extents
[ 3868.497017] BTRFS info (device sda1): bdev /dev/sda1 errs: wr 223, rd 4, flush 0, corrupt 0, gen 0
[ 3868.679937] scsi 0:0:0:0: Direct-Access WD My Passport 0741 1025 PQ: 0 ANSI: 6
[ 3868.680270] scsi 0:0:0:0: Attached scsi generic sg1 type 0
[ 3868.683435] scsi 0:0:0:1: Enclosure WD SES Device 1025 PQ: 0 ANSI: 6
[ 3868.687418] scsi 0:0:0:1: Attached scsi generic sg2 type 13
[ 3868.694259] sd 0:0:0:0: [sdb] Spinning up disk…
[ 3869.703485] …ready
[ 3871.752037] sd 0:0:0:0: [sdb] 1953458176 512-byte logical blocks: (1.00 TB/931 GiB)
[ 3871.752645] sd 0:0:0:0: [sdb] Write Protect is off
[ 3871.752652] sd 0:0:0:0: [sdb] Mode Sense: 47 00 10 08
[ 3871.753261] sd 0:0:0:0: [sdb] No Caching mode page found
[ 3871.753267] sd 0:0:0:0: [sdb] Assuming drive cache: write through
[ 3871.825340] sdb: sdb1
[ 3871.827409] sd 0:0:0:0: [sdb] Attached SCSI disk
[ 3872.163070] BTRFS info (device sdb1): disk space caching is enabled
[ 3872.163080] BTRFS info (device sdb1): has skinny extents
======================= HERE I START RSYNC =============================
[ 3988.533990] sd 1:0:0:0: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 10 inflight: CMD IN
[ 3988.534008] sd 1:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 01 6c ad 70 00 01 d0 00
[ 3988.534383] sd 1:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD IN
[ 3988.534394] sd 1:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 01 6c a9 70 00 04 00 00
[ 3988.535049] sd 1:0:0:0: [sda] tag#19 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD IN
[ 3988.535059] sd 1:0:0:0: [sda] tag#19 CDB: opcode=0x28 28 00 01 6c a5 70 00 04 00 00
[ 3988.535814] sd 1:0:0:0: [sda] tag#18 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD IN
[ 3988.535823] sd 1:0:0:0: [sda] tag#18 CDB: opcode=0x28 28 00 01 6c a1 70 00 04 00 00
[ 3988.536373] sd 1:0:0:0: [sda] tag#17 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD IN
[ 3988.536382] sd 1:0:0:0: [sda] tag#17 CDB: opcode=0x28 28 00 01 6c 9f 40 00 02 30 00
[ 3988.536969] sd 1:0:0:0: [sda] tag#16 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD IN
[ 3988.536978] sd 1:0:0:0: [sda] tag#16 CDB: opcode=0x28 28 00 01 6c 9b 40 00 04 00 00
[ 3988.537479] sd 1:0:0:0: [sda] tag#15 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD IN
[ 3988.537487] sd 1:0:0:0: [sda] tag#15 CDB: opcode=0x28 28 00 01 6c 97 40 00 04 00 00
[ 3988.537849] sd 1:0:0:0: [sda] tag#14 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD IN
[ 3988.537858] sd 1:0:0:0: [sda] tag#14 CDB: opcode=0x28 28 00 01 6c 93 40 00 04 00 00
[ 3988.538349] sd 1:0:0:0: [sda] tag#13 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
[ 3988.538361] sd 1:0:0:0: [sda] tag#13 CDB: opcode=0x28 28 00 01 6c 8b 40 00 04 00 00
[ 3988.538917] sd 1:0:0:0: [sda] tag#12 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD IN
[ 3988.538926] sd 1:0:0:0: [sda] tag#12 CDB: opcode=0x28 28 00 01 6c 8f 40 00 04 00 00
[ 4019.254633] sd 1:0:0:0: [sda] tag#23 uas_eh_abort_handler 0 uas-tag 12 inflight: CMD OUT
[ 4019.254652] sd 1:0:0:0: [sda] tag#23 CDB: opcode=0x2a 2a 00 01 78 fa 58 00 02 00 00
[ 4019.255086] sd 1:0:0:0: [sda] tag#22 uas_eh_abort_handler 0 uas-tag 11 inflight: CMD OUT
[ 4019.255098] sd 1:0:0:0: [sda] tag#22 CDB: opcode=0x2a 2a 00 01 78 f6 58 00 02 00 00
[ 4019.274638] scsi host1: uas_eh_device_reset_handler start
[ 4019.359498] usb 2-1.4: reset SuperSpeed Gen 1 USB device number 10 using xhci_hcd
[ 4019.384874] scsi host1: uas_eh_device_reset_handler success

Any more suggestions?

Solved it myself.
Just posting here for anyone else seeing strange behaviour with external Drives.

The problem lies in the USB-to-SATA enclosure i used. As I found out, not all of these are compatible with the RaspberryPi… I changed to a different model, and now it works!

See the following links for more information:


1 Like

:+1:
Good to know you got it sorted.
Thank you