RClone S3 backend copy is 2x slower than aws s3 cp

Help and Support
1

What is the problem you are having with rclone?

I'm experiencing much slower speeds with rclone copy vs aws s3 cp. I'm doing a transfer between an EC2 node and S3 via an s3 endpoint. All within the same region.

Not 100% sure why this could be. I'm wondering if there are any flags I could set that would increase this speed? Or if it's natively an issue with rclone. Ideally I'll be mounting rclone, but I'm using copy to demonstrate the difference in transfer time.

I also notice that when rclone is transferring, it starts at the max bandwidth and then slowly decreases over time.

What is your rclone version (output from rclone version)

rclone v1.56.0

  • os/version: Microsoft Windows Server 2019 Datacenter 1809 (64 bit)
  • os/kernel: 10.0.17763.1757 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.16.5
  • go/linking: dynamic
  • go/tags: cmount

Which cloud storage system are you using?

S3

The command you were trying to run

rclone copy remote:path dest:path --no-traverse --fast-list

The rclone config contents with secrets removed.

[remote]
type = s3
provider = AWS
env_auth = false
access_key_id = **
secret_access_key = **
region = us-east-2
acl = private
storage_class = STANDARD
server_side_encryption = aws:kms

A log

2021/11/04 19:11:16 DEBUG : rclone: Version "v1.56.0" starting with parameters ["C:\\ProgramData\\chocolatey\\lib\\rclone.portable\\tools\\rclone-v1.56.0-windows-amd64\\rclone.exe" "copy" "remote:bucket/file.test" "C:/Desktop" "--progress" "--verbose" "--no-traverse" "--fast-list" "-vv"]
2021/11/04 19:11:16 DEBUG : Creating backend with remote "remote:bucket/file.test"
2021/11/04 19:11:16 DEBUG : Using config file from "C:\\Users\\Administrator\\.config\\rclone\\rclone.conf"
2021/11/04 19:11:16 DEBUG : fs cache: adding new entry for parent of "remote:bucket/file.test", "remote:bucket/"
2021/11/04 19:11:16 DEBUG : Creating backend with remote "C:/Desktop"
2021/11/04 19:11:16 DEBUG : fs cache: renaming cache item "C:/Desktop" to be canonical "//?/C:/Desktop"
2021-11-04 19:11:16 DEBUG : file.test: Need to transfer - File not found at Destination
2021-11-04 19:11:16 INFO  : Writing sparse files: use --local-no-sparse or --multi-thread-streams 0 to disable
2021-11-04 19:11:16 DEBUG : file.test: Starting multi-thread copy with 4 parts of size 308.750Mi
2021-11-04 19:11:16 DEBUG : file.test: multi-thread copy: stream 4/4 (971243520-1294845506) size 308.611Mi starting
2021-11-04 19:11:16 DEBUG : file.test: multi-thread copy: stream 1/4 (0-323747840) size 308.750Mi starting
2021-11-04 19:11:16 DEBUG : file.test: multi-thread copy: stream 2/4 (323747840-647495680) size 308.750Mi starting
2021-11-04 19:11:16 DEBUG : file.test: multi-thread copy: stream 3/4 (647495680-971243520) size 308.750Mi starting
2021-11-04 19:11:20 DEBUG : file.test: multi-thread copy: stream 4/4 (971243520-1294845506) size 308.611Mi finished
2021-11-04 19:11:20 DEBUG : file.test: multi-thread copy: stream 2/4 (323747840-647495680) size 308.750Mi finished
2021-11-04 19:11:20 DEBUG : file.test: multi-thread copy: stream 3/4 (647495680-971243520) size 308.750Mi finished
2021-11-04 19:11:20 DEBUG : file.test: multi-thread copy: stream 1/4 (0-323747840) size 308.750Mi finished
2021-11-04 19:11:20 DEBUG : file.test: Finished multi-thread copy with 4 parts of size 308.750Mi
2021-11-04 19:11:29 INFO  : file.test: Multi-thread Copied (new)
Transferred:        1.206Gi / 1.206 GiByte, 100%, 102.893 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        12.5s
2021/11/04 19:11:29 INFO  :
Transferred:        1.206Gi / 1.206 GiByte, 100%, 102.893 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        12.5s

2021/11/04 19:11:29 DEBUG : 11 go routines active

vs

Measure-Command {aws s3 cp s3://file.test C:/Desktop}

Seconds           : 6
Milliseconds      : 524
Ticks             : 65248857
TotalDays         : 7.55195104166667E-05
TotalHours        : 0.00181246825
TotalMinutes      : 0.108748095
TotalSeconds      : 6.5248857
TotalMilliseconds : 6524.8857
2

hello and welcome to the forum,

please post a full debug log by adding --log-level=DEBUG --log-file=rclone.log

3

Thanks for the welcome and the response! I have edited the post and added full log

4

sure,

  • so this is a good test as it is a copy of a single file.

  • post the output of rclone version

  • about that log:
    looks like rclone took four seconds to copy the file, 19:11:16-19:11:20
    not sure what is going on between 19:11:20-19:11:29.

  • what is the results of a speed test, looks like you have 1Gbps download?

  • "any flags I could set"
    it depends on the speed test results.
    if you have 1Gbps down and rclone is maxing that, not sure what else there is to do.
    might experiment with
    https://rclone.org/docs/#multi-thread-cutoff-size
    https://rclone.org/docs/#multi-thread-streams-n

5

Thanks again for the response!

I have edited the post with output from rclone version.

  • "what is the results of a speed test, looks like you have 1Gbps download?"

Indeed, it's actually 1.5Gbps according to speedtest.net.

Not sure what that extra 9 seconds added after the copy come from. Is there anyway to get more info on what is happening?

  • "might experiment with"

Will try this out!

Thanks so much

6

in some quick testing, from wasabi, a s3 clone to local.
if we assume that the time to checksum the dest is constant,
then it seems that the more threads the larger time gap.

about the speed slowing down, i believe that that rclone calculates the final speed based on the total time it takes to execute the rclone command, not the actual download time.

2021-11-04 18:43:16 DEBUG : file.test: Finished multi-thread copy with 16 parts of size 80.938Mi
2021-11-04 18:43:22 DEBUG : file.test: md5 = 98dcf7754eb6049147593c72d1128145 OK
2021-11-04 18:43:22 INFO  : file.test: Multi-thread Copied (new)
Transferred:        1.265Gi / 1.265 GiByte, 100%, 48.869 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        24.9s

2021-11-04 18:53:34 DEBUG : file.test: Finished multi-thread copy with 256 parts of size 5.062Mi
2021-11-04 18:53:42 DEBUG : file.test: md5 = 98dcf7754eb6049147593c72d1128145 OK
2021-11-04 18:53:42 INFO  : file.test: Multi-thread Copied (new)
Transferred:        1.265Gi / 1.265 GiByte, 100%, 58.592 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:        21.6s
7

@ncw,
we are curious about that time gap between when rclone claims to have finished the download and when rclone exits?

8

It will be checking the hash I expect.

Turn that off with --ignore-checksum and it will run quicker but with less data integrity!

9

i thought of that but in the OP debug, rclone is not checking the hash.

what is rclone doing between 19:11:20 and 19:11:29?

on the one hand, rclone is checking the hash and not reporting that.
on the second hand, rclone is not checking the hash as server_side_encryption is used.
on the third hand, something else is going on

10

I think what is happening is that rclone checks the source and dest objects in parallel. However it discovers that the source object does not have a hash as it is a multipart upload, but it still does the destination hash anyway.

That is my guess...

@SeanDevonport can you try your original test with --ignore-checksum

If that is the case then there is an optimization we could do there - if the hash is returned as "" then we could cancel the other hash.

11

Hey @ncw and @asdffdsa

Thanks for the feedback!

Seems that --ignore-checksum did the trick! Downloading the same file at 3.8s!

@ncw I also just wanted to check if you know if this carries over to rclone mount commands? If we use --ignore-checksum, would we achieve faster data transfer (obviously with cost of data-integrity)

12

yes, it does carry over

without --ignore-checksum

DEBUG : file.txt: vfs cache: starting upload
DEBUG : file.txt: md5 = f28f14c6a404f3273f68ccedbe26ed8a OK
INFO  : file.txt: Copied (new)

with --ignore-checksum

DEBUG : file.txt: vfs cache: starting upload
INFO  : file.txt: Copied (new)
13

@SeanDevonport I made the optimization of cancelling the other hash if the first returned an empty string.

This should make your copy without --ignore-checksum almost as fast as with it. Using --ignore-checksum is best if you are after absolute speed, but I'd be very interested in your tests with the code below - thanks!

v1.58.0-beta.5859.1aa015bd2.fix-hasher on branch fix-hasher (uploaded in 15-30 mins)