Increasing SFTP transfer speed

Help and Support
1

What is the problem you are having with rclone?

Transfer speeds over SFTP with rclone (whether crypt or plain) never seem to reach maximum potential of my Gigabit upload speed, despite available network capacity, hardware support, and previous network transfers with other services and applications reaching at or near gigabit speeds.

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

rclone v1.56.2

  • os/version: debian 10.11 (64 bit)
  • os/kernel: 5.10.0-0.bpo.8-amd64 (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.16.8
  • go/linking: static
  • go/tags: none

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

SFTP

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

rclone --dump filters -v --log-file=/dev/shm/copy.log --config $HOME/.config/rclone/rclone.conf --progress --sftp-set-modtime=true --create-empty-src-dirs --transfers={8,16,20,24,32} copy /mnt/puredrive1/clients/mediaINPROGRESS/ largestor:clients/mediaINPROGRESS

rclone --dump filters -v --log-file=/dev/shm/copy.log --config $HOME/.config/rclone/rclone.conf --progress --sftp-set-modtime=true --create-empty-src-dirs --transfers={8,16,20,24,32} copy /mnt/puredrive1/clients/mediaCOMPLETE/ crypt-largestor:clients/mediaCOMPLETE

--transfers was set to use one of the listed numbers. Sometimes 32, sometimes 16. Anything below 16 seems to lower speeds.

The rclone config contents with secrets removed.

[largestor]
type = sftp
host = xxx.xxx.xxx.xxx
user = datauser
port = 12345
key_file = $HOME/.ssh/ssh-key
md5sum_command = md5sum
sha1sum_command = sha1sum
idle_timeout = 1m30s

[crypt-largestor]
type = crypt
remote = largestor:
password = *redacted*
password2 = *redacted*

A log from the command with the -vv flag

2022/03/27 22:50:10 DEBUG : rclone: Version "v1.56.2" starting with parameters ["rclone" "-vv" "--log-file=/dev/shm/copy.log" "--config" "/home/datauser/.config/rclone/rclone.conf" "--progress" "--sftp-set-modtime=true" "--create-empty-src-dirs" "--transfers=32" "copy" "." "largestor:clients/mediaINPROGRESS/"]
2022/03/27 22:50:10 DEBUG : Creating backend with remote "."
2022/03/27 22:50:10 DEBUG : Using config file from "/home/datauser/.config/rclone/rclone.conf"
2022/03/27 22:50:10 DEBUG : fs cache: renaming cache item "." to be canonical "/mnt/puredrive1/clients/mediaINPROGRESS/"
2022/03/27 22:50:10 DEBUG : Creating backend with remote "largestor:clients/mediaINPROGRESS/"
2022/03/27 22:50:10 DEBUG : largestor: detected overridden config - adding "{XWmL2}" suffix to name
2022/03/27 22:50:11 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: New connection 192.168.1.2:55998->xxx.xxx.xxx.xxx:12345 to "SSH-2.0-OpenSSH_8.9"
2022/03/27 22:50:12 DEBUG : fs cache: renaming cache item "largestor:clients/mediaINPROGRESS/" to be canonical "largestor{XWmL2}:clients/mediaINPROGRESS/"
2022/03/27 22:50:12 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Waiting for checks to finish
2022/03/27 22:50:12 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Waiting for transfers to finish
2022/03/27 22:50:13 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: New connection 192.168.1.2:56000->xxx.xxx.xxx.xxx:12345 to "SSH-2.0-OpenSSH_8.9"
2022/03/27 22:50:15 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: New connection 192.168.1.2:56002->xxx.xxx.xxx.xxx:12345 to "SSH-2.0-OpenSSH_8.9"
2022/03/27 22:50:19 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: New connection 192.168.1.2:56004->xxx.xxx.xxx.xxx:12345 to "SSH-2.0-OpenSSH_8.9"
2022/03/27 22:50:22 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: New connection 192.168.1.2:56008->xxx.xxx.xxx.xxx:12345 to "SSH-2.0-OpenSSH_8.9"
2022/03/27 22:52:06 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Not closing 5 unused connections as 32 transfers in progress
2022/03/27 22:53:36 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Not closing 5 unused connections as 32 transfers in progress
2022/03/27 22:54:29 DEBUG : sftp cmd = clients/mediaINPROGRESS/10.mov
2022/03/27 22:54:29 DEBUG : sftp output = "55375082146d001f25b6588ef7359a12  clients/mediaINPROGRESS/10.mov\n"
2022/03/27 22:54:29 DEBUG : sftp hash = "55375082146d001f25b6588ef7359a12"
2022/03/27 22:54:29 DEBUG : 10.mov: md5 = 55375082146d001f25b6588ef7359a12 OK
2022/03/27 22:54:29 INFO  : 10.mov: Copied (new)
2022/03/27 22:54:40 DEBUG : sftp cmd = clients/mediaINPROGRESS/14.mov
2022/03/27 22:54:40 DEBUG : sftp output = "809e1dc2fdb0c90e55c6451e0cbd92a7  clients/mediaINPROGRESS/14.mov\n"
2022/03/27 22:54:40 DEBUG : sftp hash = "809e1dc2fdb0c90e55c6451e0cbd92a7"
2022/03/27 22:54:40 DEBUG : 14.mov: md5 = 809e1dc2fdb0c90e55c6451e0cbd92a7 OK
2022/03/27 22:54:40 INFO  : 14.mov: Copied (new)
2022/03/27 22:56:13 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Not closing 5 unused connections as 32 transfers in progress
2022/03/27 22:57:43 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Not closing 5 unused connections as 32 transfers in progress
2022/03/27 22:59:04 DEBUG : sftp cmd = clients/mediaINPROGRESS/25.mov
2022/03/27 22:59:04 DEBUG : sftp output = "4b4be2350ed9e45f7b9116b2579e5079  clients/mediaINPROGRESS/25.mov\n"
2022/03/27 22:59:04 DEBUG : sftp hash = "4b4be2350ed9e45f7b9116b2579e5079"
2022/03/27 22:59:04 DEBUG : 25.mov: md5 = 4b4be2350ed9e45f7b9116b2579e5079 OK
2022/03/27 22:59:04 INFO  : 25.mov: Copied (new)
2022/03/27 22:59:26 DEBUG : sftp cmd = clients/mediaINPROGRESS/37.mov
2022/03/27 22:59:26 DEBUG : sftp output = "025f9dcd5284423e9ddb7a064a0e91f6  clients/mediaINPROGRESS/37.mov\n"
2022/03/27 22:59:26 DEBUG : sftp hash = "025f9dcd5284423e9ddb7a064a0e91f6"
2022/03/27 22:59:26 DEBUG : 37.mov: md5 = 025f9dcd5284423e9ddb7a064a0e91f6 OK
2022/03/27 22:59:26 INFO  : 37.mov: Copied (new)
2022/03/27 22:59:30 DEBUG : sftp cmd = clients/mediaINPROGRESS/36.mov
2022/03/27 22:59:30 DEBUG : sftp output = "fe74b6d76730b83ac83daa72431f3526  clients/mediaINPROGRESS/36.mov\n"
2022/03/27 22:59:30 DEBUG : sftp hash = "fe74b6d76730b83ac83daa72431f3526"
2022/03/27 22:59:30 DEBUG : 36.mov: md5 = fe74b6d76730b83ac83daa72431f3526 OK
2022/03/27 22:59:30 INFO  : 36.mov: Copied (new)
2022/03/27 23:00:15 DEBUG : sftp cmd = clients/mediaINPROGRESS/13.mov
2022/03/27 23:00:15 DEBUG : sftp output = "6dc8f37997230286fea3237457aeef62  clients/mediaINPROGRESS/13.mov\n"
2022/03/27 23:00:15 DEBUG : sftp hash = "6dc8f37997230286fea3237457aeef62"
2022/03/27 23:00:15 DEBUG : 13.mov: md5 = 6dc8f37997230286fea3237457aeef62 OK
2022/03/27 23:00:15 INFO  : 13.mov: Copied (new)
2022/03/27 23:00:34 DEBUG : sftp cmd = clients/mediaINPROGRESS/30.mov
2022/03/27 23:00:34 DEBUG : sftp output = "6c1349dcf1a0c90003c9368b9115f85e  clients/mediaINPROGRESS/30.mov\n"
2022/03/27 23:00:34 DEBUG : sftp hash = "6c1349dcf1a0c90003c9368b9115f85e"
2022/03/27 23:00:34 DEBUG : 30.mov: md5 = 6c1349dcf1a0c90003c9368b9115f85e OK
2022/03/27 23:00:34 INFO  : 30.mov: Copied (new)
2022/03/27 23:01:37 DEBUG : sftp cmd = clients/mediaINPROGRESS/41.mov
2022/03/27 23:01:37 DEBUG : sftp output = "3709e8ddf4ebbd674900fd91c8535b81  clients/mediaINPROGRESS/41.mov\n"
2022/03/27 23:01:37 DEBUG : sftp hash = "3709e8ddf4ebbd674900fd91c8535b81"
2022/03/27 23:01:37 DEBUG : 41.mov: md5 = 3709e8ddf4ebbd674900fd91c8535b81 OK
2022/03/27 23:01:37 INFO  : 41.mov: Copied (new)
2022/03/27 23:03:00 DEBUG : sftp cmd = clients/mediaINPROGRESS/34.mov
2022/03/27 23:03:00 DEBUG : sftp output = "2ae015400b328b7fdf3d697de9b92864  clients/mediaINPROGRESS/34.mov\n"
2022/03/27 23:03:00 DEBUG : sftp hash = "2ae015400b328b7fdf3d697de9b92864"
2022/03/27 23:03:00 DEBUG : 34.mov: md5 = 2ae015400b328b7fdf3d697de9b92864 OK
2022/03/27 23:03:00 INFO  : 34.mov: Copied (new)
2022/03/27 23:03:41 DEBUG : sftp cmd = clients/mediaINPROGRESS/21.mov
2022/03/27 23:03:41 DEBUG : sftp output = "6c19b3ed04599039ed6db38368d3d1a8  clients/mediaINPROGRESS/21.mov\n"
2022/03/27 23:03:41 DEBUG : sftp hash = "6c19b3ed04599039ed6db38368d3d1a8"
2022/03/27 23:03:41 DEBUG : 21.mov: md5 = 6c19b3ed04599039ed6db38368d3d1a8 OK
2022/03/27 23:03:41 INFO  : 21.mov: Copied (new)
2022/03/27 23:03:44 DEBUG : sftp cmd = clients/mediaINPROGRESS/46.mov
2022/03/27 23:03:44 DEBUG : sftp output = "a5fb9293e9db5eb1adbc53a113beec87  clients/mediaINPROGRESS/46.mov\n"
2022/03/27 23:03:44 DEBUG : sftp hash = "a5fb9293e9db5eb1adbc53a113beec87"
2022/03/27 23:03:44 DEBUG : 46.mov: md5 = a5fb9293e9db5eb1adbc53a113beec87 OK
2022/03/27 23:03:44 INFO  : 46.mov: Copied (new)
2022/03/27 23:03:48 DEBUG : sftp cmd = clients/mediaINPROGRESS/3.mov
2022/03/27 23:03:48 DEBUG : sftp output = "71b03a0c0db0d6ef4b3fa5b9285344c5  clients/mediaINPROGRESS/3.mov\n"
2022/03/27 23:03:48 DEBUG : sftp hash = "71b03a0c0db0d6ef4b3fa5b9285344c5"
2022/03/27 23:03:48 DEBUG : 3.mov: md5 = 71b03a0c0db0d6ef4b3fa5b9285344c5 OK
2022/03/27 23:03:48 INFO  : 3.mov: Copied (new)
2022/03/27 23:04:06 DEBUG : sftp cmd = clients/mediaINPROGRESS/27.mov
2022/03/27 23:04:06 DEBUG : sftp output = "4aedc386beec70e8c8fd30e32ca54ab3  clients/mediaINPROGRESS/27.mov\n"
2022/03/27 23:04:06 DEBUG : sftp hash = "4aedc386beec70e8c8fd30e32ca54ab3"
2022/03/27 23:04:06 DEBUG : 27.mov: md5 = 4aedc386beec70e8c8fd30e32ca54ab3 OK
2022/03/27 23:04:06 INFO  : 27.mov: Copied (new)
2022/03/27 23:04:10 DEBUG : sftp cmd = clients/mediaINPROGRESS/33.mov
2022/03/27 23:04:10 DEBUG : sftp output = "cded9aa9ce208fd50d6062632a37f497  clients/mediaINPROGRESS/33.mov\n"
2022/03/27 23:04:10 DEBUG : sftp hash = "cded9aa9ce208fd50d6062632a37f497"
2022/03/27 23:04:10 DEBUG : 33.mov: md5 = cded9aa9ce208fd50d6062632a37f497 OK
2022/03/27 23:04:10 INFO  : 33.mov: Copied (new)
2022/03/27 23:04:15 DEBUG : sftp cmd = clients/mediaINPROGRESS/23.mov
2022/03/27 23:04:15 DEBUG : sftp output = "7b9965840268808c43f48e44d5a33370  clients/mediaINPROGRESS/23.mov\n"
2022/03/27 23:04:15 DEBUG : sftp hash = "7b9965840268808c43f48e44d5a33370"
2022/03/27 23:04:15 DEBUG : 23.mov: md5 = 7b9965840268808c43f48e44d5a33370 OK
2022/03/27 23:04:15 INFO  : 23.mov: Copied (new)
2022/03/27 23:04:29 DEBUG : sftp cmd = clients/mediaINPROGRESS/31.mov
2022/03/27 23:04:29 DEBUG : sftp output = "709447bb966d88fea2463df39d13f6a2  clients/mediaINPROGRESS/31.mov\n"
2022/03/27 23:04:29 DEBUG : sftp hash = "709447bb966d88fea2463df39d13f6a2"
2022/03/27 23:04:29 DEBUG : 31.mov: md5 = 709447bb966d88fea2463df39d13f6a2 OK
2022/03/27 23:04:29 INFO  : 31.mov: Copied (new)
2022/03/27 23:04:34 DEBUG : sftp cmd = clients/mediaINPROGRESS/20.mov
2022/03/27 23:04:34 DEBUG : sftp output = "7143dcb318fbccf593060e01e6a7df6e  clients/mediaINPROGRESS/20.mov\n"
2022/03/27 23:04:34 DEBUG : sftp hash = "7143dcb318fbccf593060e01e6a7df6e"
2022/03/27 23:04:34 DEBUG : 20.mov: md5 = 7143dcb318fbccf593060e01e6a7df6e OK
2022/03/27 23:04:34 INFO  : 20.mov: Copied (new)
2022/03/27 23:05:20 DEBUG : sftp cmd = clients/mediaINPROGRESS/11.mov
2022/03/27 23:05:20 DEBUG : sftp output = "291843457bf802eefcb268bb3fba6b83  clients/mediaINPROGRESS/11.mov\n"
2022/03/27 23:05:20 DEBUG : sftp hash = "291843457bf802eefcb268bb3fba6b83"
2022/03/27 23:05:20 DEBUG : 11.mov: md5 = 291843457bf802eefcb268bb3fba6b83 OK
2022/03/27 23:05:20 INFO  : 11.mov: Copied (new)
2022/03/27 23:05:43 DEBUG : sftp cmd = clients/mediaINPROGRESS/2.mov
2022/03/27 23:05:43 DEBUG : sftp output = "34ff3c87e67e3d529332e924e648d248  clients/mediaINPROGRESS/2.mov\n"
2022/03/27 23:05:43 DEBUG : sftp hash = "34ff3c87e67e3d529332e924e648d248"
2022/03/27 23:05:43 DEBUG : 2.mov: md5 = 34ff3c87e67e3d529332e924e648d248 OK
2022/03/27 23:05:43 INFO  : 2.mov: Copied (new)
2022/03/27 23:06:00 DEBUG : sftp cmd = clients/mediaINPROGRESS/7.mov
2022/03/27 23:06:00 DEBUG : sftp output = "477f2042dfd74fe1f58bc135bc5914bc  clients/mediaINPROGRESS/7.mov\n"
2022/03/27 23:06:00 DEBUG : sftp hash = "477f2042dfd74fe1f58bc135bc5914bc"
2022/03/27 23:06:00 DEBUG : 7.mov: md5 = 477f2042dfd74fe1f58bc135bc5914bc OK
2022/03/27 23:06:00 INFO  : 7.mov: Copied (new)
2022/03/27 23:06:03 DEBUG : sftp cmd = clients/mediaINPROGRESS/17.mov
2022/03/27 23:06:03 DEBUG : sftp output = "6f5f3fc2e29a44c376638a38eab18f94  clients/mediaINPROGRESS/17.mov\n"
2022/03/27 23:06:03 DEBUG : sftp hash = "6f5f3fc2e29a44c376638a38eab18f94"
2022/03/27 23:06:03 DEBUG : 17.mov: md5 = 6f5f3fc2e29a44c376638a38eab18f94 OK
2022/03/27 23:06:03 INFO  : 17.mov: Copied (new)
2022/03/27 23:06:10 DEBUG : sftp cmd = clients/mediaINPROGRESS/29.mov
2022/03/27 23:06:10 DEBUG : sftp output = "dca4f82fcd3b1d8368f14c0961792f48  clients/mediaINPROGRESS/29.mov\n"
2022/03/27 23:06:10 DEBUG : sftp hash = "dca4f82fcd3b1d8368f14c0961792f48"
2022/03/27 23:06:10 DEBUG : 29.mov: md5 = dca4f82fcd3b1d8368f14c0961792f48 OK
2022/03/27 23:06:10 INFO  : 29.mov: Copied (new)
2022/03/27 23:06:11 DEBUG : sftp cmd = clients/mediaINPROGRESS/19.mov
2022/03/27 23:06:11 DEBUG : sftp output = "98d33aefc3b244d39e5c03ed49379ad8  clients/mediaINPROGRESS/19.mov\n"
2022/03/27 23:06:11 DEBUG : sftp hash = "98d33aefc3b244d39e5c03ed49379ad8"
2022/03/27 23:06:11 DEBUG : 19.mov: md5 = 98d33aefc3b244d39e5c03ed49379ad8 OK
2022/03/27 23:06:11 INFO  : 19.mov: Copied (new)
2022/03/27 23:06:22 DEBUG : sftp cmd = clients/mediaINPROGRESS/15.mov
2022/03/27 23:06:22 DEBUG : sftp output = "cc07d0b1ec1c544caae90fb0ba12d782  clients/mediaINPROGRESS/15.mov\n"
2022/03/27 23:06:22 DEBUG : sftp hash = "cc07d0b1ec1c544caae90fb0ba12d782"
2022/03/27 23:06:22 DEBUG : 15.mov: md5 = cc07d0b1ec1c544caae90fb0ba12d782 OK
2022/03/27 23:06:22 INFO  : 15.mov: Copied (new)
2022/03/27 23:06:23 DEBUG : sftp cmd = clients/mediaINPROGRESS/12.mov
2022/03/27 23:06:23 DEBUG : sftp output = "0f80d3455d7e726a3a63ea431f04ff9f  clients/mediaINPROGRESS/12.mov\n"
2022/03/27 23:06:23 DEBUG : sftp hash = "0f80d3455d7e726a3a63ea431f04ff9f"
2022/03/27 23:06:23 DEBUG : 12.mov: md5 = 0f80d3455d7e726a3a63ea431f04ff9f OK
2022/03/27 23:06:23 INFO  : 12.mov: Copied (new)
2022/03/27 23:06:32 DEBUG : sftp cmd = clients/mediaINPROGRESS/35.mov
2022/03/27 23:06:32 DEBUG : sftp output = "feb315f9d7b6122c93925523a73ed048  clients/mediaINPROGRESS/35.mov\n"
2022/03/27 23:06:32 DEBUG : sftp hash = "feb315f9d7b6122c93925523a73ed048"
2022/03/27 23:06:32 DEBUG : 35.mov: md5 = feb315f9d7b6122c93925523a73ed048 OK
2022/03/27 23:06:32 INFO  : 35.mov: Copied (new)
2022/03/27 23:06:35 DEBUG : sftp cmd = clients/mediaINPROGRESS/28.mov
2022/03/27 23:06:35 DEBUG : sftp output = "aff8814dd113e55d8144cf48d3c2b444  clients/mediaINPROGRESS/28.mov\n"
2022/03/27 23:06:35 DEBUG : sftp hash = "aff8814dd113e55d8144cf48d3c2b444"
2022/03/27 23:06:35 DEBUG : 28.mov: md5 = aff8814dd113e55d8144cf48d3c2b444 OK
2022/03/27 23:06:35 INFO  : 28.mov: Copied (new)
2022/03/27 23:06:40 DEBUG : sftp cmd = clients/mediaINPROGRESS/26.mov
2022/03/27 23:06:40 DEBUG : sftp output = "bdbea44002d5a960a72416b835527ebf  clients/mediaINPROGRESS/26.mov\n"
2022/03/27 23:06:40 DEBUG : sftp hash = "bdbea44002d5a960a72416b835527ebf"
2022/03/27 23:06:40 DEBUG : 26.mov: md5 = bdbea44002d5a960a72416b835527ebf OK
2022/03/27 23:06:40 INFO  : 26.mov: Copied (new)
2022/03/27 23:06:58 DEBUG : sftp cmd = clients/mediaINPROGRESS/1.mov
2022/03/27 23:06:58 DEBUG : sftp output = "253b3dc1038ae40db00cd052f80cbcc7  clients/mediaINPROGRESS/1.mov\n"
2022/03/27 23:06:58 DEBUG : sftp hash = "253b3dc1038ae40db00cd052f80cbcc7"
2022/03/27 23:06:58 DEBUG : 1.mov: md5 = 253b3dc1038ae40db00cd052f80cbcc7 OK
2022/03/27 23:06:58 INFO  : 1.mov: Copied (new)
2022/03/27 23:06:59 DEBUG : sftp cmd = clients/mediaINPROGRESS/6.mov
2022/03/27 23:06:59 DEBUG : sftp output = "c83ea7a3c47a45a4e616fdf15178c259  clients/mediaINPROGRESS/6.mov\n"
2022/03/27 23:06:59 DEBUG : sftp hash = "c83ea7a3c47a45a4e616fdf15178c259"
2022/03/27 23:06:59 DEBUG : 6.mov: md5 = c83ea7a3c47a45a4e616fdf15178c259 OK
2022/03/27 23:06:59 INFO  : 6.mov: Copied (new)
2022/03/27 23:07:14 DEBUG : sftp cmd = clients/mediaINPROGRESS/9.mov
2022/03/27 23:07:14 DEBUG : sftp output = "d26b60e319441813facd8dadaecd8540  clients/mediaINPROGRESS/9.mov\n"
2022/03/27 23:07:14 DEBUG : sftp hash = "d26b60e319441813facd8dadaecd8540"
2022/03/27 23:07:14 DEBUG : 9.mov: md5 = d26b60e319441813facd8dadaecd8540 OK
2022/03/27 23:07:14 INFO  : 9.mov: Copied (new)
2022/03/27 23:07:49 DEBUG : sftp cmd = clients/mediaINPROGRESS/22.mov
2022/03/27 23:07:49 DEBUG : sftp output = "3394b14a0acbab132bfe934ab0d33cd6  clients/mediaINPROGRESS/22.mov\n"
2022/03/27 23:07:49 DEBUG : sftp hash = "3394b14a0acbab132bfe934ab0d33cd6"
2022/03/27 23:07:49 DEBUG : 22.mov: md5 = 3394b14a0acbab132bfe934ab0d33cd6 OK
2022/03/27 23:07:49 INFO  : 22.mov: Copied (new)
2022/03/27 23:07:49 DEBUG : sftp cmd = clients/mediaINPROGRESS/18.mov
2022/03/27 23:07:49 DEBUG : sftp output = "5f68576b9f230375a33cf77588ae29dd  clients/mediaINPROGRESS/18.mov\n"
2022/03/27 23:07:49 DEBUG : sftp hash = "5f68576b9f230375a33cf77588ae29dd"
2022/03/27 23:07:49 DEBUG : 18.mov: md5 = 5f68576b9f230375a33cf77588ae29dd OK
2022/03/27 23:07:49 INFO  : 18.mov: Copied (new)
2022/03/27 23:07:55 DEBUG : sftp cmd = clients/mediaINPROGRESS/16.mov
2022/03/27 23:07:55 DEBUG : sftp output = "75b0fe496e6047ca32caecf68c5d3b8f  clients/mediaINPROGRESS/16.mov\n"
2022/03/27 23:07:55 DEBUG : sftp hash = "75b0fe496e6047ca32caecf68c5d3b8f"
2022/03/27 23:07:55 DEBUG : 16.mov: md5 = 75b0fe496e6047ca32caecf68c5d3b8f OK
2022/03/27 23:07:55 INFO  : 16.mov: Copied (new)
2022/03/27 23:08:32 DEBUG : sftp cmd = clients/mediaINPROGRESS/24.mov
2022/03/27 23:08:32 DEBUG : sftp output = "7324263c62e0c424f04827dfe37f8be7  clients/mediaINPROGRESS/24.mov\n"
2022/03/27 23:08:32 DEBUG : sftp hash = "7324263c62e0c424f04827dfe37f8be7"
2022/03/27 23:08:32 DEBUG : 24.mov: md5 = 7324263c62e0c424f04827dfe37f8be7 OK
2022/03/27 23:08:32 INFO  : 24.mov: Copied (new)
2022/03/27 23:08:48 DEBUG : sftp cmd = clients/mediaINPROGRESS/38.mov
2022/03/27 23:08:48 DEBUG : sftp output = "ece8834f29320cc3a1422b159e93476a  clients/mediaINPROGRESS/38.mov\n"
2022/03/27 23:08:48 DEBUG : sftp hash = "ece8834f29320cc3a1422b159e93476a"
2022/03/27 23:08:48 DEBUG : 38.mov: md5 = ece8834f29320cc3a1422b159e93476a OK
2022/03/27 23:08:48 INFO  : 38.mov: Copied (new)
2022/03/27 23:09:27 DEBUG : sftp cmd = clients/mediaINPROGRESS/32.mov
2022/03/27 23:09:27 DEBUG : sftp output = "7798657a15c8a8e2a2cb63ff291b4eb0  clients/mediaINPROGRESS/32.mov\n"
2022/03/27 23:09:27 DEBUG : sftp hash = "7798657a15c8a8e2a2cb63ff291b4eb0"
2022/03/27 23:09:27 DEBUG : 32.mov: md5 = 7798657a15c8a8e2a2cb63ff291b4eb0 OK
2022/03/27 23:09:27 INFO  : 32.mov: Copied (new)
2022/03/27 23:10:12 DEBUG : sftp cmd = clients/mediaINPROGRESS/39.mov
2022/03/27 23:10:12 DEBUG : sftp output = "5390b59a15d43fadded208dffba9af34  clients/mediaINPROGRESS/39.mov\n"
2022/03/27 23:10:12 DEBUG : sftp hash = "5390b59a15d43fadded208dffba9af34"
2022/03/27 23:10:12 DEBUG : 39.mov: md5 = 5390b59a15d43fadded208dffba9af34 OK
2022/03/27 23:10:12 INFO  : 39.mov: Copied (new)
2022/03/27 23:11:25 DEBUG : sftp cmd = clients/mediaINPROGRESS/4.mov
2022/03/27 23:11:25 DEBUG : sftp output = "88837afe11eb7bdb264627f979556e89  clients/mediaINPROGRESS/4.mov\n"
2022/03/27 23:11:25 DEBUG : sftp hash = "88837afe11eb7bdb264627f979556e89"
2022/03/27 23:11:25 DEBUG : 4.mov: md5 = 88837afe11eb7bdb264627f979556e89 OK
2022/03/27 23:11:25 INFO  : 4.mov: Copied (new)
2022/03/27 23:12:52 DEBUG : sftp://datauser@xxx.xxx.xxx.xxx:12345/clients/mediaINPROGRESS/: Not closing 5 unused connections as 7 transfers in progress
2022/03/27 23:13:32 DEBUG : sftp cmd = clients/mediaINPROGRESS/43.mov
2022/03/27 23:13:32 DEBUG : sftp output = "176497599b2b050a235ac1e6ff063c19  clients/mediaINPROGRESS/43.mov\n"
2022/03/27 23:13:32 DEBUG : sftp hash = "176497599b2b050a235ac1e6ff063c19"
2022/03/27 23:13:32 DEBUG : 43.mov: md5 = 176497599b2b050a235ac1e6ff063c19 OK
2022/03/27 23:13:32 INFO  : 43.mov: Copied (new)
2022/03/27 23:13:39 DEBUG : sftp cmd = clients/mediaINPROGRESS/44.mov
2022/03/27 23:13:39 DEBUG : sftp output = "ab01652fa2cd520c7b3ae3116161dd39  clients/mediaINPROGRESS/44.mov\n"
2022/03/27 23:13:39 DEBUG : sftp hash = "ab01652fa2cd520c7b3ae3116161dd39"
2022/03/27 23:13:39 DEBUG : 44.mov: md5 = ab01652fa2cd520c7b3ae3116161dd39 OK
2022/03/27 23:13:39 INFO  : 44.mov: Copied (new)
2022/03/27 23:13:41 DEBUG : sftp cmd = clients/mediaINPROGRESS/42.mov
2022/03/27 23:13:41 DEBUG : sftp output = "21a9e15aa2b7259859a2a37fcaa62e6e  clients/mediaINPROGRESS/42.mov\n"
2022/03/27 23:13:41 DEBUG : sftp hash = "21a9e15aa2b7259859a2a37fcaa62e6e"
2022/03/27 23:13:41 DEBUG : 42.mov: md5 = 21a9e15aa2b7259859a2a37fcaa62e6e OK
2022/03/27 23:13:41 INFO  : 42.mov: Copied (new)
2022/03/27 23:14:04 DEBUG : sftp cmd = clients/mediaINPROGRESS/45.mov
2022/03/27 23:14:04 DEBUG : sftp output = "b83ece9235721e92d060ccdb480cc0ad  clients/mediaINPROGRESS/45.mov\n"
2022/03/27 23:14:04 DEBUG : sftp hash = "b83ece9235721e92d060ccdb480cc0ad"
2022/03/27 23:14:04 DEBUG : 45.mov: md5 = b83ece9235721e92d060ccdb480cc0ad OK
2022/03/27 23:14:04 INFO  : 45.mov: Copied (new)
2022/03/27 23:14:24 DEBUG : sftp cmd = clients/mediaINPROGRESS/40.mov
2022/03/27 23:14:24 DEBUG : sftp output = "5dc83724bb582b839a6f3eadceef83bd  clients/mediaINPROGRESS/40.mov\n"
2022/03/27 23:14:24 DEBUG : sftp hash = "5dc83724bb582b839a6f3eadceef83bd"
2022/03/27 23:14:24 DEBUG : 40.mov: md5 = 5dc83724bb582b839a6f3eadceef83bd OK
2022/03/27 23:14:24 INFO  : 40.mov: Copied (new)
2022/03/27 23:14:41 DEBUG : sftp cmd = clients/mediaINPROGRESS/8.mov
2022/03/27 23:14:41 DEBUG : sftp output = "d68d0f8f02cce9fbf4c2af05992050e7  clients/mediaINPROGRESS/8.mov\n"
2022/03/27 23:14:41 DEBUG : sftp hash = "d68d0f8f02cce9fbf4c2af05992050e7"
2022/03/27 23:14:41 DEBUG : 8.mov: md5 = d68d0f8f02cce9fbf4c2af05992050e7 OK
2022/03/27 23:14:41 INFO  : 8.mov: Copied (new)
2022/03/27 23:14:42 DEBUG : sftp cmd = clients/mediaINPROGRESS/5.mov
2022/03/27 23:14:42 DEBUG : sftp output = "a6bf6aeefa34e3d2baa440fc6b3e740e  clients/mediaINPROGRESS/5.mov\n"
2022/03/27 23:14:42 DEBUG : sftp hash = "a6bf6aeefa34e3d2baa440fc6b3e740e"
2022/03/27 23:14:42 DEBUG : 5.mov: md5 = a6bf6aeefa34e3d2baa440fc6b3e740e OK
2022/03/27 23:14:42 INFO  : 5.mov: Copied (new)
2022/03/27 23:14:42 INFO  : 
Transferred:   	   59.125Gi / 59.125 GiByte, 100%, 14.409 MiByte/s, ETA 0s
Transferred:           46 / 46, 100%
Elapsed time:     24m31.3s

2022/03/27 23:14:42 DEBUG : 48 go routines active

In general, I am finding that I only get 75% of my total upload bandwidth (940Mbit) when transferring to a remote storage server, using SFTP.

The files transferred are all large media files. All at least 1GB, and larger.

I've confirmed that I can reach 90-100MB/s transfer speeds in either direction, using other applications and sources (such as aria2c, wget, curl; doing apt or pacman updates over https repos) so I don't believe it to be some router hardware issue.

I've tried transferring with different --transfers and --buffer-size options, to no avail or general benefit. The most ever reaching speed wise is 75-80MB/s (for example running two copy processes with two different drives and identical settings). I also tried copying from a more powerful computer and SSD backed storage, with no overall difference.

Hardware:

  • CPU: Ryzen 3600
  • RAM: 16GB DDR4 3200Mhz
  • Disk(s): 18TB Seagate and WD models, all 7200rpm, 256MB cache
  • Networking: ASUS Gigabit Router to ISP provided router; Double NATing unfortunately

Remote server:
CPU: Ryzen 3700x
RAM: 128GB DDR4 ECC
Disk(s): 10x18TB in single ZFS pool, speed tests report 2GB/s on sequential writes

Latency from home to server: 110ms
Both ends have true gigabit hardware, and available bandwidth

Really just wondering what, if anything, I can do here? An extra 10-20MB/s, and especially being able to maintain constant 70MB/s (as it flip flops from 50-70MB/s) would shave days, perhaps week(s)
off our transfers.

Thank you!

2

Look up the long fat network problem for background, but the basic problem is that 110ms delay at 1 Gbit/s represents a window size of 13 MiB which is quite a lot of data to have outstanding. TCP can cope with that, but SFTP has a request response architecture with quite small packet size.

Recent iterations of pkg/sftp will use up to 64 concurrent requests, and each one of these is at most 32KiB which is a total of only 2MiB of window so much less than the 13 MiB of window to fill up your pipe, so I think you are unlikely to get more than about 18MiB/s per file with 110mS latency.

They way to fill your pipe up will be to do lots of these at once so increasing --transfers is a great idea.

However those parameters are tweakable in the library and rclone doesn't currently have a way of doing that

Try

v1.59.0-beta.6046.b487e2cef.fix-sftp-chunk-size on branch fix-sftp-chunk-size (uploaded in 15-30 mins)
Which implements that.

You are most likely using OpenSSH which according to my research can use a 256k packet size. This contains some overhead, so I'd recommend the value --sftp-chunk-size 252k - give that a go and see if you can see an improvement.

I've also implemented a way to control the number of chunks in flight. This is normally 64 but you can now control this with --sftp-concurrency 256. I think this number can be as big as you like but I'm not sure. Setting it bigger will make rclone use more memory.

Can you do some scientific tests with a single large file (5 or 10GiB say) and vary the --sftp-chunk-size and --sftp-concurrency parameters and see what difference that makes to throughput?

In order to fill your pipe you need -sftp-chunk-size * --sftp-concurrency * latency to be bigger than the number of bytes your pipe can transfer in one latency unit (110mS) which is 0.11 * 1E9 / 8 = 13 MiB

So for example these might fill up your pipe with a single upload

  • --sftp-chunk-size 252k * --sftp-concurrency 64 = 15.75 MiB
  • --sftp-chunk-size 32k * --sftp-concurrency 512 = 16 MiB

Depending on your tests I might increase the default for --sftp-concurrency since I don't think there is a downside - the extra RAM usage is miminal and the extra requests will only be used if the latency needs it.

2 Likes
3

Hi @ncw and thank you very much for this very thoughtful work and reply. Definitely interesting information to have, I hadn't considered the "actual" backend (ie sftp source) as having extra flags to change.

Indeed, speed wise, I have seen from 12-15MiB/s for single file transfers between our remote system, using tools such as rsync or scp; just an example.
And so far yes, --transfers works well, but we are still hitting that sort of "limit", as mentioned.

Here's a bunch of testing I've done, let me know if anything's missing.

START
Test file is 5.2 GB (5,209,574,759 bytes)

Local: openssh-server/oldstable,now 1:7.9p1-10+deb10u2
Local (alt SSD system): openssh 8.9p1-1
Remote: openssh 8.9p1-1

Command

~/rclone159BetaSFTP/rclone -vv --progress --sftp-set-modtime=true --create-empty-src-dirs copy BIG_TEST.mp4 crypt-largestor:test/

Test 1

--sftp-chunk-size=252k --sftp-concurrency=64
Transferred:        4.853 GiB / 4.853 GiB, 100%, 2.246 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:     19m10.9s
Actual average transfer speed was 4-5MiB/s, inline with iotop

$ dstat -n 5
Says average of 18-19M/s with Send speed

$ sudo iotop
Reports 4-5M/s

Test 2

--sftp-chunk-size=32k  --sftp-concurrency=512
Transferred:        4.853 GiB / 4.853 GiB, 100%, 5.985 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      7m19.8s
Actual average transfer speed was 11-12MiB/s, inline with iotop

$ dstat -n 5
Says average of 18-19M/s with Send speed

$ sudo iotop
Reports 11-12M/s

So it looks like chunk size of 32k is a good choice.
Testing increased --sftp-concurrency with --sftp-chunk-size=32k, same single file and other flags, worked as such:

--sftp-concurrency=1536 , 11.8MiB/s average
--sftp-concurrency=2048 , 11.5MiB/s average
--sftp-concurrency=2560 , 11.8MiB/s average

Next, testing with multiple transfers... produces disappointing speeds. All of the files have sizes above 5GiB.

--sftp-chunk-size=32k --sftp-concurrency=512 --transfers=8
36-40 MiB/s transfer speed; dstat says 60-70M/s send speed
--sftp-chunk-size=32k --sftp-concurrency=1536 --transfers=8
36-40 MiB/s transfer speed; dstat says 60-70M/s send speed
--sftp-chunk-size=252k --sftp-concurrency=128 --transfers=8
15-16MiB/s transfer speed; dstat says 65-70M/s send speed
--sftp-chunk-size=252k --sftp-concurrency=1024 --transfers=8
16-17 MiB/s transfer speed; dstat says 55-60M/s send speed

For all of those, iotop reports speeds mimicing rclone Transfer speed
Increasing multiple file transfers doesn't improve transfer speed, except dstat continues to climb at or near 1Gbit/s speeds.

Also, oddly,

with beta build, --sftp-concurrency=64 --transfers=16; did not use --sftp-chunk-size
36-40 MiB/s transfer speed; dstat says 65-70M/s send

And again moving back to my non-beta rclone, speeds are 65-70MiB/s, with 12-24 transfers. dstat reports accurate send speeds too.

END

So this is definitely some odd results... any further suggestions? I'm curious why dstat would report higher numbers than what's actually being sent as well.

Also hopefully the single test file I used was acceptable size wise.

4

Perhaps the transfers are occasionally waiting for data, what happens if you increase --buffer-size or --use-mmap or both?

5

That is great - thank you.

I don't understand where rclone is getting the 2.2 MiB/s from as I make 4.853 GiB / 19m10.9s as 4.3 MiB/s...

I did a test with some local transfers and dstat and it agreed quite closely with what rclone was saying, so there is something odd going on here.

I wonder if your server really doesn't like the larger packet size and is causing retries at the sftp protocol level or something like that.

I make this 11.2 MiB/s also.

It looks like something is maxing out. 11.8 MiB/s is 99.0 Mbit/s so I wonder if there is a 100 Mbit pipe or limiter somewhere between you and the remote site.

:frowning:

That dstat climbing is very odd. If you look at the interface statistics do you see errors?

$ ifconfig ethXXX
lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 1963810  bytes 10638186315 (10.6 GB)
        RX errors 0  dropped 0  overruns 0  frame 0                 <----- errors here?
        TX packets 1963810  bytes 10638186315 (10.6 GB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0 <----- or here?

And if you do netstat -s do you see TCP retransmits?

$ netstat -s
[snip]
Tcp:
    479 active connection openings
    123 passive connection openings
    24 failed connection attempts
    28 connection resets received
    18 connections established
    1984355 segments received
    1986973 segments sent out
    203 segments retransmitted  <- lots of these?
    0 bad segments received
    63 resets sent
[snip]

This is a puzzle!

I suspect the post-copy checksum is throwing the results out slightly. Try adding --ignore-checksum to the test command lines - this will stop rclone doing an md5sum on the file after the transfer which I suspect is slowing things down. This should get the speeds rclone reports to line up with the iotop ones.

Why are the dstat ones so much higher though?

Do you see the same effect using the beta with no extra flags?

I suspect that rclone or sftp or TCP is doing lots of retries which is causing packet loss somewhere and causing retransmissions since I think you have a 1 Gbit/s link, the remote has a 1 Gbit/s link but something is limiting individual transfers to about 100 Mbit/s. It isn't unheard of for ISPs to do this kind of thing BTW.

Can you try measuring the bandwidth in use at the interface in a different way? I've not used dstat before so I don't know exactly what it is measuring. I usually use itpraf with General interface statistics for this kind of thing then Detailed interface statistics on the specific interface. Note that iptraf measures interface speed in bits/second not bytes/second like rclone!

Can you try transferring a file with scp to the remote end and see how fast that is? This runs through the ssh daemon at the remote end so should give us a baseline on how fast we can expect to transfer files.

Perfect! You could use a smaller one if you want - I just wanted it to take a few minutes to transfer to get rid of the ramp up effects at the start of the sftp transfer.

6

Following a emergency hardware failure and backup, I found some time to do more testing.
Overall I'm just confused and somewhat baffled at the results.

Here's some statistics from my main network interface

$ ifconfig eth0
 eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet xxx.xxx.xxx.xxx  netmask 255.255.255.0  broadcast xxx.xxx.xxx.xxx
        ether xx:xx:xx:xx:xx:xx txqueuelen 1000  (Ethernet)
        RX packets x  bytes x (x)
        RX errors 0  dropped 5906537  overruns 0  frame 0 <<<<<<<<<<<<<<<<<<<<
        TX packets x  bytes x (x)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0 <<<<<<<<<<<<<<<<<<<<

$ netstat -s | grep -i retrans 
    154074353 segments retransmitted <<<<<<<<<<<<<<<<<<<<
    5097 times recovered from packet loss due to fast retransmit
    Detected reordering 44 times using reno fast retransmit
    TCPLostRetransmit: 74840600
    176 timeouts after reno fast retransmit
    39947191 fast retransmits
    3180870 retransmits in slow start
    TCPSynRetrans: 104226565

However... I have an active VPN connection to a different isolated server, so the dropped values could be caused by that. They didn't go up though once the VPN was turned off, and normal transfers (with stable rclone) were run.

I tested generally with iptraf-ng, and noticed similar results as dstat: averages of 50-60Mi/s, with jumps to 70-80Mi/s for a few seconds, before falling back to the average

Here's some values pulled from tail end transfers using stable rclone.

Transferring:
82% /10.723Gi, 8.847Mi/s
62% /14.032Gi, 8.846Mi/s
89% /11.356Gi, 11.996Mi/s < just over 105Mbit

Transferring:
35% /71.423Gi, 11.938Mi/s
94% /22.464Gi, 12.241Mi/s
66% /17.755Gi, 12.295Mi/s < well past 100Mbit

So higher speeds past 100mbit are possibly, but almost barely.

However, check this test:
Doing a straight scp transfer

$ scp kde.iso largestor:test/
kde.iso 100% 3122MB  17.4MB/s   02:59

Speeds peaked at 18MB/s, with average of 17.9MB/s after about 30s. Very impressive and promising if rclone can somehow hit that.

I reran the same tests as previously done, but this time focused on any retransmit errors.

~/rclone159BetaSFTP/rclone -vv --progress --sftp-set-modtime=true --create-empty-src-dirs copy BIG_TEST.mp4 crypt-largestor:test/

Test 1

--sftp-chunk-size=252k --sftp-concurrency=64
Same speeds, 4-5MiB/s.

iptraf showed 150000kbps average. 
No change to netstat TCP retransmission stats

Test 2

--sftp-chunk-size=32k --sftp-concurrency=512
Same speeds, 11-12MiB/s. 

iptraf showed identical speeds. 
No increment on netstat TCP segment retransmitted

Next, multi-transfers

--sftp-chunk-size=32k --sftp-concurrency=512 --transfers=8
same 36-40 MiB/s transfer speed. iptraf says 380000 - 600000 kbps. no change in TCP re-transmit segments

--sftp-chunk-size=32k --sftp-concurrency=1536 --transfers=8
same 36-40 MiB/s transfer speed. iptraf says 380000 - 600000 kbps. no change in TCP re-transmit segments

--sftp-chunk-size=252k --sftp-concurrency=128 --transfers=8
same 15-16MiB/s transfer speed. iptraf says 500000 - 550000 kbps. no change in TCP re-transmit segments

--sftp-chunk-size=252k --sftp-concurrency=1024 --transfers=8
same 15-16MiB/s transfer speed. iptraf says 390000 - 650000 kbps. no change in TCP re-transmit segments

--sftp-concurrency=64 --transfers=16
same 36-40 MiB/s transfer speed. iptraf says 560000 - 600000 kbps. no change in TCP re-transmit segments

Now, to new tests, using stable rclone, as the beta seems to be giving disappointing weird results :frowning:
Each test is run for about 3 minutes before cancelling and starting the next test.

Command

rclone -vv --progress --sftp-set-modtime=true --create-empty-src-dirs --transfers=16 copy . crypt-largestor:test_2_/

buffer size

--buffer-size=64M
Speeds average 58-60MiB/s but would jump to 67-68MiB/s
iptraf says 550000 - 680000 kbps average
No change in TCP retransmit segments.

--buffer-size=32M
Speeds average 60MiB/s with peaks of 75-77MiB/s for about 10 seconds every 30-60 seconds
iptraf goes from 500000 - 600000 kbps, dipping to 450000 kbps sometimes. speeds seem very inconsistent
Nothing changed with TCP retransmit

--buffer-size=16M
Speeds average 59-60MiB/s, jumps to 75-77MiB/s for 3-5 seconds every 60 seconds or so.
iptraf goes from 500000 - 600000 kbps, dipping to 450000 kbps sometimes. speeds seem very inconsistent
Nothing changed with TCP retransmit

--buffer-size=8M
Speeds average 64-66MiB/s , jumps to 68-70MiB/s
iptraf says 560000 kbps - 590000 kbps
No change in TCP retransmit

adding use-mmap to buffer size

--buffer-size=64M --use-mmap
--buffer-size=32M --use-mmap
--buffer-size=16M --use-mmap
--buffer-size=8M --use-mmap
No noticeable changes to speeds or reporting, same as above.

Testing with just --use-mmap didn't change anything noticeable...

One other thing I tested was trying to get individual file speeds up as high as they can go, while doing multi-transfers.
On --transfers=4, each file would peak around 12-13Mi/s, but overall that was only 50Mi/s. Pushing more transfers always gives a better overall speed, but as you climb up in increments of 2, each file slowly loses about 1Mi/s of total bandwidth it pushes (so eventually each file is only using 1Mi-2Mi/s, or a single file uses 5-10 while the rest are slower).

Yes. The only extra flag is --transfers=12 to boost things, and for some reason speeds are not reflected properly from rclone beta.

In rclone beta, I get about 45MiB/s where I'd normally get 60-65MiB/s.
Dstat reports DOUBLE that speed, where it was reporting accurately a moment ago with stable rclone
iptraf is reporting 500000-600000 kbps range, which might be more than what's actually being moved, while rclone reports 40-45MiB/s (and dstat still saying doubles)

Hopefully this is some kind of insightful data, let me know if a test was missed. Thanks to @ncw and @ole for help and suggestions so far!

7

I don’t think I can contribute much more, but I am sure it would help the continued troubleshooting if your rclone commands are as simple as possible and directly comparable to the tests you do with scp, rsync, etc.

As an example, this command copies an entire folder (tree) and creates (any) empty folders and furthermore needs to encrypt files/folder names and file content and print a detailed debug log:

Whereas this command does a plain copy of a single file:

The corresponding rclone command would be:

rclone --progress copy kde.iso largestor:test/

What is the speed of this simplified command?

Edit: This still isn't fully comparable, rclone still has to calculate the hashsum before completing. This is the command to compare against:

rclone --progress --sftp-disable-hashcheck=true copy kde.iso largestor:test/

What is the speed of this simplified barebone copy command?

1 Like
8

Thanks for pointing this out. Here's a plain test about as equivalent to scp as we can get:

$ rclone --progress --sftp-disable-hashcheck=true copy kde.iso largestor:testplain/
Transferred:        3.049Gi / 3.049 GiByte, 100%, 17.458 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       3m0.0s

I also ran a test against the crypt backend

$ rclone --progress --sftp-disable-hashcheck=true copy kde.iso crypt-largestor:
Transferred:        3.050Gi / 3.050 GiByte, 100%, 12.016 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      4m26.5s

So that's an almost 6MiB/s speed loss to crypt. I was watching htop while this ran and didn't notice an overload on the CPU or RAM, both had ample available performance or "space".
Seems then the general overhead would be crypt, which unfortunately is needed for a large portion of our files.

That said, it still is a bit confusing as to why doing more --transfers would cause each file to have a lower speed, when disk read speeds are more than sufficient. When running multiple files in parallel, without using crypt, each one still doesn't hit anywhere near 12 or even 17MiB/s, which is generally disappointing.

If the sftp-checksum is another bottleneck, the question I have is: is it advisable in some form to not use sftp checksumming? I personally prefer to do that, as I don't mind waiting on lingering uploads at the tail end.

Thanks again!

9

Great, now we know that scp and rclone has identical speeds on comparable single file transfers :sweat_smile:

Now, I would like to keep it simple by analyzing/optimizing/explaining one parameter/issue at the time and suggest we start by --transfers to optimize the usage of concurrency on client, network and server. I haven't forgotten encryption, hashsums etc I will return to them - we may also want to visit --checkers when we get to the characteristics of your actual data.

First let's make some well-defined test data:

mkdir testfolder
mkdir testfolder/folderA
cp kde.iso testfolder/folderA/file1
cp kde.iso testfolder/folderA/file2
cp kde.iso testfolder/folderA/file3
cp kde.iso testfolder/folderA/file4
cp -r testfolder/folderA  testfolder/folderB
cp -r testfolder/folderA  testfolder/folderC
cp -r testfolder/folderA  testfolder/folderD

Next, let's collect some raw performance data:

rclone copy ./testfolder/folderA/ largestor:testplain/testfolder/folderA --transfers=1 --sftp-disable-hashcheck=true --ignore-times --progress 
rclone copy ./testfolder/folderA/ largestor:testplain/testfolder/folderA --transfers=2 --sftp-disable-hashcheck=true --ignore-times --progress 
rclone copy ./testfolder/ largestor:testplain/testfolder/ --transfers=4 --sftp-disable-hashcheck=true --ignore-times --progress 
rclone copy ./testfolder/ largestor:testplain/testfolder/ --transfers=8 --sftp-disable-hashcheck=true --ignore-times --progress 
rclone copy ./testfolder/ largestor:testplain/testfolder/ --transfers=16 --sftp-disable-hashcheck=true --ignore-times --progress

What are the results? (please post command and stats like above)

10

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