Rclone transfer rate slower than rsync

sidamos · December 22, 2022, 8:42am

What is the problem you are having with rclone?

I am coming from rsync over encfs over sshfs to backup files to my Hetzner StorageBox.
I have VDSL with 90 MBit download and 35 MBit upload.
To compare rclone with rsync, I have a similar setup:

rsync: mount remote directory with sshfs and encrypt that with encfs
rclone: define remote via SFTP and inside that a crypt remote

rclone is 40% slower than rsync for large files. For small files, rclone wins because of parallel transfers.

Test directory has one large file.

time rsync -Whav --progress --delete-after source dest

building file list ... 
2 files to consider
backup-test/
backup-test/rpi.img.gz_old
          1,60G 100%    3,71MB/s    0:06:51 (xfr#1, to-chk=0/2)

sent 1,60G bytes  received 37 bytes  3,88M bytes/sec
total size is 1,60G  speedup is 1,00

real    6m52,996s
user    0m5,595s
sys     0m2,648s

time ./rclone sync source dest --links --progress --transfers 1 --checkers 1 --check-first --create-empty-src-dirs

Transferred:        1.493 GiB / 1.493 GiB, 100%, 1.852 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      9m45.1s

real    9m45,241s
user    0m16,047s
sys     0m6,916s

If I run rclone with for example 4 or 8 transfers on a real directory with mixed file sizes, I am seeing the same issue. Max total transfer rate I get is 2.6 MByte/s but should be up to 4 MByte/s.

Run the command 'rclone version' and share the full output of the command.

rclone v1.61.0

os/version: gentoo 2.9 (64 bit)
os/kernel: 5.15.75-gentoo-x86_64 (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.19.4
go/linking: static
go/tags: none

Which cloud storage system are you using? (eg Google Drive)

SFTP: Hetzner StorageBox.

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

See above.

The rclone config contents with secrets removed.

[hetzner]
type = sftp
host = xxx.your-storagebox.de
user = xxx
port = 23
pass = xxx
shell_type = unix
md5sum_command = md5 -r
sha1sum_command = sha1 -r

[hetzner-crypt]
type = crypt
remote = hetzner:rclone
password = xxx

A log from the command with the `-vv` flag

2022/12/22 09:30:14 DEBUG : rclone: Version "v1.61.0" starting with parameters ["./rclone" "sync" "/work2/backup-test" "hetzner-crypt:/backup-test" "--links" "--progress" "--transfers" "1" "--checkers" "1" "--check-first" "--create-empty-src-dirs" "-vv" "--log-file" "rclone.log"]
2022/12/22 09:30:14 DEBUG : Creating backend with remote "/work2/backup-test"
2022/12/22 09:30:14 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2022/12/22 09:30:14 DEBUG : local: detected overridden config - adding "{b6816}" suffix to name
2022/12/22 09:30:14 DEBUG : fs cache: renaming cache item "/work2/backup-test" to be canonical "local{b6816}:/work2/backup-test"
2022/12/22 09:30:14 DEBUG : Creating backend with remote "hetzner-crypt:/backup-test"
2022/12/22 09:30:14 DEBUG : Creating backend with remote "hetzner:rclone/t7sn3p3miij4fskh9s5hdk58og"
2022/12/22 09:30:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: New connection 192.168.0.2:36604->168.119.80.176:23 to "SSH-2.0-OpenSSH_8.8 FreeBSD-20211221"
2022/12/22 09:30:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Shell type "unix" from config
2022/12/22 09:30:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Relative path resolved to "/home/rclone/t7sn3p3miij4fskh9s5hdk58og"
2022/12/22 09:30:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Using root directory "/home/rclone/t7sn3p3miij4fskh9s5hdk58og"
2022/12/22 09:30:15 INFO  : Encrypted drive 'hetzner-crypt:/backup-test': Running all checks before starting transfers
2022/12/22 09:30:15 DEBUG : Encrypted drive 'hetzner-crypt:/backup-test': Waiting for checks to finish
2022/12/22 09:30:15 INFO  : Encrypted drive 'hetzner-crypt:/backup-test': Checks finished, now starting transfers
2022/12/22 09:30:15 DEBUG : Encrypted drive 'hetzner-crypt:/backup-test': Waiting for transfers to finish
2022/12/22 09:31:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:32:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:33:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:34:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:35:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:36:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:37:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:38:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:39:15 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Not closing 1 unused connections as 1 sessions active
2022/12/22 09:39:53 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Shell path "/home/rclone/t7sn3p3miij4fskh9s5hdk58og/9nu7j523t3t4uh4elp5ti9l850"
2022/12/22 09:39:53 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Running remote command: md5 -r /home/rclone/t7sn3p3miij4fskh9s5hdk58og/9nu7j523t3t4uh4elp5ti9l850
2022/12/22 09:39:59 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Remote command result: e64a7d5f2c2642b1e7dc83e74613e97f /home/rclone/t7sn3p3miij4fskh9s5hdk58og/9nu7j523t3t4uh4elp5ti9l850
2022/12/22 09:39:59 DEBUG : 9nu7j523t3t4uh4elp5ti9l850: Parsed hash: e64a7d5f2c2642b1e7dc83e74613e97f
2022/12/22 09:39:59 DEBUG : rpi.img.gz_old: md5 = e64a7d5f2c2642b1e7dc83e74613e97f OK
2022/12/22 09:39:59 INFO  : rpi.img.gz_old: Copied (new)
2022/12/22 09:39:59 DEBUG : Waiting for deletions to finish
2022/12/22 09:39:59 INFO  : 
Transferred:        1.493 GiB / 1.493 GiB, 100%, 1.840 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      9m44.5s

2022/12/22 09:39:59 DEBUG : 12 go routines active
2022/12/22 09:39:59 DEBUG : sftp://xxx@xxx.your-storagebox.de:23/rclone/t7sn3p3miij4fskh9s5hdk58og: Closing 1 unused connections

ncw · December 22, 2022, 9:26am

Rclone does a post-copy checksum of the file which takes some time. Try adding --ignore-checksum and see if that speeds rclone up...

Actually I just realised that the crypt backend will ignore this flag and do its post copy checksum regardless.

Looking at your log this is only taking 6 seconds anyway, so ignore that.

You can try tweaking these.

SFTP
SFTP

It would also be interesting to try an unencrypted speed comparison to see whether the crypt backend is the problem or not.

sidamos · December 22, 2022, 2:38pm

Thanks for the quick reply.

Your assumption was right, it is the crypt backend.
Without:

time ./rclone sync source hetzner:/home/test/backup-test --links --progress --transfers 1 --checkers 1 --check-first --create-empty-src-dirs

Transferred:        1.492 GiB / 1.492 GiB, 100%, 3.188 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      6m29.6s

real    6m29,639s
user    0m9,417s
sys     0m4,676s

Although rclone states 3.188 MiB/s as last number, it was near 4 during transfer and the total transfer time is good, too.
I will try the options you mentioned next.

ncw · December 22, 2022, 2:43pm

Interesting. The crypt backend can run at 500 MiB/s on my laptop so I wouldn't have expected it to be the bottleneck.

Slowdowns like this are often caused by rclone checking the checksums. You can turn this off with --ignore-checksum, but I can see from your log it only took 6 seconds.

There may be some interaction between it and the SFTP backend. I can't think what at the moment...

If you are using crypt+sftp does rclone use a lot of CPU?

sidamos · December 22, 2022, 2:52pm

rclone uses 4% CPU when running sync against crypt + sftp.

I also tried --sftp-chunk-size 128. This made it even slower, 1.9 MByte/s.

--sftp-concurrency 128 did not change anything. Same speed.

sidamos · December 23, 2022, 3:45pm

Unfortunately, I cannot change the subject, now that it is a bit more clear where the problem is.

Shall I file a bug report?

ncw · December 23, 2022, 4:38pm

There is definitely a performance problem here

I have a VM at Hetzner and also a storage box account

Here is a 1G file with no encryption

$ rclone copy -P 1G hbox:test/
Transferred:            1 GiB / 1 GiB, 100%, 47.254 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        21.7s

And here is a 1G file with encryption

$ rclone copy -P 1G ':crypt,remote="hbox:secrets",password=XXX:'
Transferred:        1.000 GiB / 1.000 GiB, 100%, 35.907 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        27.7s

A quick test with no_data_encryption shows that the problem is the encryption.

This is using about 50% of one CPU on the VM I'm using which is 5 threads with roughly 10% CPU each.

I suspect this is a scheduling problem as in some work is being done in sequence when it should be done in parallel.

I'd prefer not to make an issue about it until we have some idea that we can fix the problem. Can you do some investigations - try parameters and see if you can improve it? I tried --buffer-size and got a small improvement.

sidamos · December 24, 2022, 10:06am

I do not get improvement from raising the buffer size from 16Mi to 256Mi.

Your performance hit is "only" 27%, where as mine is 40%. Maybe because I have higher latency?
I have 16ms ping time to my storage box.

Regarding CPU: As I said, my old Core i5 uses 4% CPU time for rsync with crypt, so that is not the issue.

Honestly, I see no point in trying out various options to maybe find an improvement, I wouldn't even know which ones make sense to try.
IMHO, someone with knowledge of the source code and the ability to add debug code, should have a look at that.
And of course, the problem can be fixed, since rsync via sshfs plus encfs is way faster.

system · January 23, 2023, 10:06am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.