Skip to content

SFTP with Crypt backend does not utilize bandwidth #6763

@sidamos

Description

@sidamos

The associated forum post URL from https://forum.rclone.org

https://forum.rclone.org/t/rclone-transfer-rate-slower-than-rsync/34967/3

What is the problem you are having with rclone?

When I use SFTP plus Crypt, then it does not utilize my upload bandwidth. I have about 35 MBit upload speed, which should result in about 4 MBytes/s transfer.
If I use rsync plus encfs then I get 4 MBytes/s,
If I use rclone SFTP with Crypt, then I get only 2.6 MBytes/s.
If I use rclone SFTP without Crypt, then I get 4 MBytes/s.

CPU usage on my Core i5 is very low, so that is not the issue.

What is your rclone version (output from rclone version)

rclone v1.61.1

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

Which OS you are using and how many bits (e.g. Windows 7, 64 bit)

Linux 64 Bit. Gentoo.

Which cloud storage system are you using? (e.g. Google Drive)

SFTP to Hetzner storage box.

The command you were trying to run (e.g. rclone copy /tmp remote:tmp)

rclone sync localdir hetzner-crypt:/destdir --links --progress --transfers 9 --checkers 9 --check-first --create-empty-src-dirs --log-level ERROR

For testing rsync + encfs vs. rclone SFTP + Crypt, I transferred only one large file with one thread:

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.

Now rclone without Crypt:

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 MBytes/s during transfer and the total transfer time is good, too.

A log from the command with the -vv flag (e.g. output from rclone -vv copy /tmp remote:tmp)

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

How to use GitHub

  • Please use the 👍 reaction to show that you are affected by the same issue.
  • Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
  • Subscribe to receive notifications on status change and new comments.

Metadata

Metadata

Assignees

No one assigned

    Type

    No type
    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions