Multipart upload stops for few minutes after 4th chunk

What is the problem you are having with rclone?

I'm trying to upload a 3GiB file to S3. I set the chunk size to 500 MiB.

It starts blazing fast, but after 4th chunk is completed it stops for several minutes before uploading the next one. There are also more pauses later.

This is fully reproducible on my side, I run it several times changing some params, and it always behaves the same.

If I change the chunk size to something similar, like 800 MiB, it uploads the first 4 chunks fast and then stops. It does not happen with small chunks (like 5 or 10 MiB), but I also didn't wait for 3 GiB to be uploaded this way, as it takes long.

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

rclone v1.57.0
- os/version: darwin 12.2 (64 bit)
- os/kernel: 21.3.0 (x86_64)
- os/type: darwin
- os/arch: amd64
- go/version: go1.17.2
- go/linking: dynamic
- go/tags: none

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

AWS S3

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

I tried to use rcat first:

tar -vzcf - "/my-dir" | rclone rcat -P -vvv --s3-chunk-size 500Mi "backup:my-bucket/my-dir"

I thought the problem may be because of the rcat, so I created an archive /to-upload/my-dir.tar.gz first and run the upload with copy:

rclone copy -P -vvv --s3-chunk-size 500Mi "/to-upload" "backup:my-bucket/my-dir"

The same behavior with both commands.

The rclone config contents with secrets removed.

[backup]
type = s3
provider = aws
env_auth = true
acl = private
region = eu-west-1

A log from the command with the -vv flag

2022/02/06 22:47:15 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "copy" "-P" "-vvv" "--s3-chunk-size" "500Mi" "--log-file" "/tmp/log" "/to-upload" "backup:my-bucket/my-dir"]
2022/02/06 22:47:15 DEBUG : Creating backend with remote "/to-upload/"
2022/02/06 22:47:15 DEBUG : Using config file from "/Users/mradzikowski/.config/rclone/rclone.conf"
2022/02/06 22:47:15 DEBUG : Creating backend with remote "backup:my-bucket/my-dir"
2022/02/06 22:47:15 DEBUG : backup: detected overridden config - adding "{E03ez}" suffix to name
2022/02/06 22:47:16 DEBUG : fs cache: renaming cache item "backup:my-bucket/my-dir" to be canonical "backup{E03ez}:my-bucket/my-dir"
2022/02/06 22:47:16 DEBUG : S3 bucket my-bucket path my-dir: Waiting for checks to finish
2022/02/06 22:47:16 DEBUG : S3 bucket my-bucket path my-dir: Waiting for transfers to finish
2022/02/06 22:47:21 DEBUG : my-dir.tar.gz: multipart upload starting chunk 1 size 500Mi offset 0/3.130Gi
2022/02/06 22:47:23 DEBUG : my-dir.tar.gz: multipart upload starting chunk 2 size 500Mi offset 500Mi/3.130Gi
2022/02/06 22:47:24 DEBUG : my-dir.tar.gz: multipart upload starting chunk 3 size 500Mi offset 1000Mi/3.130Gi
2022/02/06 22:47:25 DEBUG : my-dir.tar.gz: multipart upload starting chunk 4 size 500Mi offset 1.465Gi/3.130Gi
2022/02/06 22:50:41 DEBUG : my-dir.tar.gz: multipart upload starting chunk 5 size 500Mi offset 1.953Gi/3.130Gi
2022/02/06 22:52:28 DEBUG : my-dir.tar.gz: multipart upload starting chunk 6 size 500Mi offset 2.441Gi/3.130Gi
2022/02/06 22:54:10 DEBUG : my-dir.tar.gz: multipart upload starting chunk 7 size 204.785Mi offset 2.930Gi/3.130Gi
2022/02/06 22:56:11 DEBUG : my-dir.tar.gz: md5 = f37768d920ee7ed98adc1ca458636a34 OK
2022/02/06 22:56:11 INFO  : my-dir.tar.gz: Copied (new)
2022/02/06 22:56:11 INFO  : 
Transferred:   	    3.130 GiB / 3.130 GiB, 100%, 5.617 KiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      8m55.6s

2022/02/06 22:56:11 DEBUG : 8 go routines active

As you can see, first 4 chunks were uploaded quickly. The progress showed that transferred was 1.953GiB / 1.953GiB and it just waited for a few minutes before starting the next chunk.

Logs are not showing that anything was done during that time.

Any thoughts on this? At least how I can debug it more? Or maybe use some other config params?

might have something to do with multipart uploads,
--s3-upload-concurrency defaults to four.

can be tested if rclone uploads 9+ chunks, which is 4+4+1

With --s3-upload-concurrency 10 all 7 chunks uploaded fast, it showed transfer was 100% completed, and then there was nothing happening for the next 8 minutes. The object was not visible in S3 for that time.

2022/02/07 09:59:32 DEBUG : S3 bucket my-bucket path my-dir: Waiting for checks to finish
2022/02/07 09:59:32 DEBUG : S3 bucket my-bucket path my-dir: Waiting for transfers to finish
2022/02/07 09:59:38 DEBUG : my-dir.tar.gz: multipart upload starting chunk 1 size 500Mi offset 0/3.130Gi
2022/02/07 09:59:39 DEBUG : my-dir.tar.gz: multipart upload starting chunk 2 size 500Mi offset 500Mi/3.130Gi
2022/02/07 09:59:40 DEBUG : my-dir.tar.gz: multipart upload starting chunk 3 size 500Mi offset 1000Mi/3.130Gi
2022/02/07 09:59:42 DEBUG : my-dir.tar.gz: multipart upload starting chunk 4 size 500Mi offset 1.465Gi/3.130Gi
2022/02/07 09:59:43 DEBUG : my-dir.tar.gz: multipart upload starting chunk 5 size 500Mi offset 1.953Gi/3.130Gi
2022/02/07 09:59:44 DEBUG : my-dir.tar.gz: multipart upload starting chunk 6 size 500Mi offset 2.441Gi/3.130Gi
2022/02/07 09:59:44 DEBUG : my-dir.tar.gz: multipart upload starting chunk 7 size 204.785Mi offset 2.930Gi/3.130Gi
2022/02/07 10:08:27 DEBUG : my-dir.tar.gz: md5 = f37768d920ee7ed98adc1ca458636a34 OK
2022/02/07 10:08:27 INFO  : my-dir.tar.gz: Copied (new)
2022/02/07 10:08:27 INFO  : 
Transferred:   	    3.130 GiB / 3.130 GiB, 100%, 0 B/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      8m56.2s

2022/02/07 10:08:27 DEBUG : 8 go routines active

With --s3-upload-concurrency 2 it paused after 2 chunks, so it's definitely related.

I thought the problem may be with calculating the checksum, but nothing changed with --s3-no-head and --s3-disable-checksum flags.

Seems to be similar to this thread: Large delay in log, not sure why - #2 by ncw but there the checksums were the problem.

But I found the --debug headers flag there and run the command with it (and concurrency 10):

2022/02/07 10:19:56 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "copy" "-P" "-vvv" "--s3-chunk-size" "500Mi" "--log-file" "/Users/mradzikowski/Documents/backup-to-s3/log" "--s3-no-head" "--s3-disable-checksum" "--dump" "headers" "--s3-upload-concurrency" "10" "/Users/mradzikowski/Documents/backup-to-s3/my-dir/" "backup:my-bucket/my-dir"]
2022/02/07 10:19:56 DEBUG : Creating backend with remote "/Users/mradzikowski/Documents/backup-to-s3/my-dir/"
2022/02/07 10:19:56 DEBUG : Using config file from "/Users/mradzikowski/.config/rclone/rclone.conf"
2022/02/07 10:19:56 DEBUG : Creating backend with remote "backup:my-bucket/my-dir"
2022/02/07 10:19:56 DEBUG : backup: detected overridden config - adding "{mEHG8}" suffix to name
2022/02/07 10:19:56 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2022/02/07 10:19:56 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:56 DEBUG : HTTP REQUEST (req 0xc000648e00)
2022/02/07 10:19:56 DEBUG : HEAD /my-bucket/my-dir HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20220207T091956Z
X-Amz-Security-Token: REDACTED

2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:56 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:56 DEBUG : HTTP RESPONSE (req 0xc000648e00)
2022/02/07 10:19:56 DEBUG : HTTP/1.1 404 Not Found
Connection: close
Content-Type: application/xml
Date: Mon, 07 Feb 2022 09:19:56 GMT
Server: AmazonS3
X-Amz-Id-2: Ql4xqAspn5ebGwVjoSiJRomfU73PjxTLeZmgjwr6GfpaCoshDAcoBSdbVINOBsLEOdGUtgCCKEo=
X-Amz-Request-Id: A1CTA97WD85121HA

2022/02/07 10:19:56 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:56 DEBUG : fs cache: renaming cache item "backup:my-bucket/my-dir" to be canonical "backup{mEHG8}:my-bucket/my-dir"
2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:56 DEBUG : HTTP REQUEST (req 0xc00004fc00)
2022/02/07 10:19:56 DEBUG : GET /my-bucket?delimiter=%2F&max-keys=1000&prefix=my-dir%2F HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20220207T091956Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:56 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:56 DEBUG : HTTP RESPONSE (req 0xc00004fc00)
2022/02/07 10:19:56 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Mon, 07 Feb 2022 09:19:58 GMT
Server: AmazonS3
X-Amz-Bucket-Region: eu-west-1
X-Amz-Id-2: RDdxqLz3xUQCfNOZBGGVpzU3iYSvBZ3fCTP/340qhvbSxmIT73rvsVkfO+Q1/rpz7IkCRi688N4=
X-Amz-Request-Id: 538717Z7VG4JTSCA

2022/02/07 10:19:56 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:56 DEBUG : S3 bucket my-bucket path my-dir: Waiting for checks to finish
2022/02/07 10:19:56 DEBUG : S3 bucket my-bucket path my-dir: Waiting for transfers to finish
2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:56 DEBUG : HTTP REQUEST (req 0xc0004ad200)
2022/02/07 10:19:56 DEBUG : POST /my-bucket/my-dir/test.tar.gz?uploads= HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 0
Authorization: XXXX
Content-Type: application/gzip
X-Amz-Acl: private
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20220207T091956Z
X-Amz-Meta-Mtime: 1644180707.167825637
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:19:56 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:19:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:57 DEBUG : HTTP RESPONSE (req 0xc0004ad200)
2022/02/07 10:19:57 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Mon, 07 Feb 2022 09:19:58 GMT
Server: AmazonS3
X-Amz-Abort-Date: Fri, 11 Feb 2022 00:00:00 GMT
X-Amz-Abort-Rule-Id: AbortIncompleteMultipartUpload
X-Amz-Id-2: 2LtmywhnMBgCcImaQIV7TLYJMV4DPsC+smGJkyLRscQfgjeqyYRFbkccAdYLC6vqYrv4bHVmE08=
X-Amz-Request-Id: 53848GPZBZ0G8N9T

2022/02/07 10:19:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:19:57 DEBUG : test.tar.gz: multipart upload starting chunk 1 size 500Mi offset 0/3.130Gi
2022/02/07 10:19:59 DEBUG : test.tar.gz: multipart upload starting chunk 2 size 500Mi offset 500Mi/3.130Gi
2022/02/07 10:20:01 DEBUG : test.tar.gz: multipart upload starting chunk 3 size 500Mi offset 1000Mi/3.130Gi
2022/02/07 10:20:01 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:01 DEBUG : HTTP REQUEST (req 0xc000648400)
2022/02/07 10:20:01 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=1&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: SiOGuSKwmm0hT8zqibtoSQ==
Expect: 100-Continue
X-Amz-Content-Sha256: 9e350ff3bd80d6883392247e2c9180bbb6efc24b6211bc18928d0d6526babf1f
X-Amz-Date: 20220207T091959Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:01 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:02 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:02 DEBUG : HTTP REQUEST (req 0xc0004ac000)
2022/02/07 10:20:02 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=2&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: F3+OEjgDhNl6cWiIuhRgFQ==
Expect: 100-Continue
X-Amz-Content-Sha256: 98d89afb1f06e3a73a5662d59e1e439e31eee531f09ca05de1c75a270beb9a88
X-Amz-Date: 20220207T092001Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:02 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:02 DEBUG : test.tar.gz: multipart upload starting chunk 4 size 500Mi offset 1.465Gi/3.130Gi
2022/02/07 10:20:04 DEBUG : test.tar.gz: multipart upload starting chunk 5 size 500Mi offset 1.953Gi/3.130Gi
2022/02/07 10:20:04 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:04 DEBUG : HTTP REQUEST (req 0xc00079a100)
2022/02/07 10:20:04 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=3&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: X/DWIj4PExXirl/aC6r5mA==
Expect: 100-Continue
X-Amz-Content-Sha256: 77c8ddd89f83094e9245daff079342b54a6145e68ff27023b637c62679e741c5
X-Amz-Date: 20220207T092003Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:04 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:06 DEBUG : test.tar.gz: multipart upload starting chunk 6 size 500Mi offset 2.441Gi/3.130Gi
2022/02/07 10:20:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:06 DEBUG : HTTP REQUEST (req 0xc000c30100)
2022/02/07 10:20:06 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=4&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: lVGASNwkSV7L9OYjnJDRRA==
Expect: 100-Continue
X-Amz-Content-Sha256: 89481068e7634a7b57c6ca4b938a0e7377940b1dbe1a8fdbeac945d30c01b954
X-Amz-Date: 20220207T092005Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:07 DEBUG : test.tar.gz: multipart upload starting chunk 7 size 204.785Mi offset 2.930Gi/3.130Gi
2022/02/07 10:20:08 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:08 DEBUG : HTTP REQUEST (req 0xc000988200)
2022/02/07 10:20:08 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=5&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: wFD3NwUKiypXLZpr24P22Q==
Expect: 100-Continue
X-Amz-Content-Sha256: 313e5d211dc2cfb4a6688b8ec9f11b51bb2bbd7a8bedc4006c666ed0623aa73b
X-Amz-Date: 20220207T092007Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:08 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:09 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:09 DEBUG : HTTP REQUEST (req 0xc000774300)
2022/02/07 10:20:09 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=7&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 214732800
Authorization: XXXX
Content-Md5: QqNYiH//ncI1YjQdiSI32w==
Expect: 100-Continue
X-Amz-Content-Sha256: ee820a04bc6dfe19f15d278ae65eb9bd1d78c75688cef3df70af4185ae1fafdb
X-Amz-Date: 20220207T092008Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:09 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:09 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:20:09 DEBUG : HTTP REQUEST (req 0xc000394400)
2022/02/07 10:20:09 DEBUG : PUT /my-bucket/my-dir/test.tar.gz?partNumber=6&uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 524288000
Authorization: XXXX
Content-Md5: rO6j3Scd77Js4c47cuItlA==
Expect: 100-Continue
X-Amz-Content-Sha256: 58d65b35563dc468a3f7a7dd288519e8e75440a7476299e4cc10c0af389c7eef
X-Amz-Date: 20220207T092008Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:20:09 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:25:04 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:25:04 DEBUG : HTTP RESPONSE (req 0xc000774300)
2022/02/07 10:25:04 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:10 GMT
Etag: "42a358887fff9dc23562341d892237db"
Server: AmazonS3
X-Amz-Id-2: adg/RHKTPiH4oTCdXnL2n1lmDxkn+yxcqKyUOWk0THPoit0fxNvTZOx9eO3AfyVM+6o5VIW0kME=
X-Amz-Request-Id: HNBACKG6JR2TBXJT

2022/02/07 10:25:04 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:25:17 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:25:17 DEBUG : HTTP RESPONSE (req 0xc000988200)
2022/02/07 10:25:17 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:09 GMT
Etag: "c050f737050a8b2a572d9a6bdb83f6d9"
Server: AmazonS3
X-Amz-Id-2: 7PB3eDt83qxH3wk2kYGgUSNIeZ8Z/qOzYtFcw/7aO37lE4OK9165RzZY4wQ3PqyNl15n2QvtB9Q=
X-Amz-Request-Id: CYHFWQ0SP3M9PJK8

2022/02/07 10:25:17 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:07 DEBUG : HTTP RESPONSE (req 0xc000648400)
2022/02/07 10:27:07 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:02 GMT
Etag: "4a2386b922b09a6d214fccea89bb6849"
Server: AmazonS3
X-Amz-Id-2: U8kOdXtLeFvutfl38N2a70XVwp8vGW3NHGJpjH/4+rHjfxiX92m112LZtD8Jy9AmnEJBfaT0GZs=
X-Amz-Request-Id: 9E5DR3H9SB11NXK6

2022/02/07 10:27:07 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:21 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:21 DEBUG : HTTP RESPONSE (req 0xc0004ac000)
2022/02/07 10:27:21 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:03 GMT
Etag: "177f8e12380384d97a716888ba146015"
Server: AmazonS3
X-Amz-Id-2: rCDehPKTlZ7fEEOLpHhM493RswT0fbBEEE2X594pA+I9zecz+ofdGzKVHmwEcMx0hb6brdxw8eo=
X-Amz-Request-Id: C52SHH7NC1HJB263

2022/02/07 10:27:21 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:27:54 DEBUG : HTTP RESPONSE (req 0xc000394400)
2022/02/07 10:27:54 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:10 GMT
Etag: "aceea3dd271defb26ce1ce3b72e22d94"
Server: AmazonS3
X-Amz-Id-2: wDKLI7iIucv+wLSzpXcL97KFNL6IC9TJFU4utMR4Ch/k9BYHiZK4rMRKvrDwJXRdAwn+mzZVZVg=
X-Amz-Request-Id: HNB0HVJ5AH554W81

2022/02/07 10:27:54 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:46 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:46 DEBUG : HTTP RESPONSE (req 0xc00079a100)
2022/02/07 10:28:46 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:06 GMT
Etag: "5ff0d6223e0f1315e2ae5fda0baaf998"
Server: AmazonS3
X-Amz-Id-2: cbXgDFiz2PG7YEa3s7NjcwOdw7O6e7IqC6Bpe0IwAGmdi/HZm6mCXIj7OZf43CK1iDv+GaYuYJo=
X-Amz-Request-Id: QHNMTS2952TREA8T

2022/02/07 10:28:46 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:53 DEBUG : HTTP RESPONSE (req 0xc000c30100)
2022/02/07 10:28:53 DEBUG : HTTP/1.1 200 OK
Connection: close
Content-Length: 0
Date: Mon, 07 Feb 2022 09:20:08 GMT
Etag: "95518048dc24495ecbf4e6239c90d144"
Server: AmazonS3
X-Amz-Id-2: Vyw3Dx61Ph87/YJEsg96GDC1nrm43MxEWtUGWhU3TebGtNvvxn0hiItiHuZ2eVbyPHeirhY4cAE=
X-Amz-Request-Id: GTWS2QXKDYM7SQDC

2022/02/07 10:28:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:53 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:28:53 DEBUG : HTTP REQUEST (req 0xc000c30200)
2022/02/07 10:28:53 DEBUG : POST /my-bucket/my-dir/test.tar.gz?uploadId=.Og7a9AUns2lj6VA2Wx3gvYWKPXtTsTbCSGtVYSAb4HoaPJbb1rQXERGaBLm1NhgxR03uEkcL2rhFtyJTQZtWgu_fnkBkTSxl6Rn.QwEWkMleMf79iV3W8uhXI3ekhqjtRXpbZJFc4y7cXOpRfoz_w-- HTTP/1.1
Host: s3.eu-west-1.amazonaws.com
User-Agent: rclone/v1.57.0
Content-Length: 757
Authorization: XXXX
X-Amz-Content-Sha256: d07c96b5e7d4582329736e31516fd8c859a2387cd97c8da7dce38cf831fec41e
X-Amz-Date: 20220207T092853Z
X-Amz-Security-Token: REDACTED
Accept-Encoding: gzip

2022/02/07 10:28:53 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2022/02/07 10:28:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:53 DEBUG : HTTP RESPONSE (req 0xc000c30200)
2022/02/07 10:28:53 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Mon, 07 Feb 2022 09:28:54 GMT
Server: AmazonS3
X-Amz-Id-2: T9YEIZPpDMJP+as6mVMgUWLBZuJhpLvrx/5Cgjjqmtey3zCLeZUPzwHZI0f1WxJmdF62TbfoKvs=
X-Amz-Request-Id: E7XTS7PGKT23KRKP
X-Amz-Version-Id: ToOLvGdV9ZV6enA9yoOoX4DqDERqmVtu

2022/02/07 10:28:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2022/02/07 10:28:53 INFO  : test.tar.gz: Copied (new)
2022/02/07 10:28:53 INFO  :
Transferred:   	    3.130 GiB / 3.130 GiB, 100%, 0 B/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      8m56.9s

2022/02/07 10:28:53 DEBUG : 8 go routines active

So it seems that the responses from S3 come after few minutes, despite rclone showing file chunk as uploaded long ago.

Is it normal? The wonderful upload speed does not matter much if at the end you wait few minutes.

I think this might just be an artifact of how the chunks get uploaded being confusing in the log. The chunks get buffered into memory first so as far as the rclone progress indicator is concerned they've been sent at that moment. This works better on some backends where the chunks get read byte by byte, but in the s3 backend it reads the whole chunk first to calculate its SHA256 for uploading.

The important question is, is it filling your upload pipe?

It seemed to take 9 minutes to transfer 3.1 GiB which is 5.9 MiB/s or 49 Mbit/s. Is that about the speed you are expecting?

This is odd though, it seems to say that the transfer speed was 0? Was that the last speed log rclone printed?

Yes, this is at the end. Initially, it shows a speed like 200 MiB/s and decreases overtime to 0.

Yes, you are right. This matches the speed I achieve when using aws cp and my internet upload from the speed tests - around 50 Mbit/s.

Okay, so this seems to be a problem with untruthful info shown with -P progress flag. Do you want me to open a bug issue on github with this?

Thank you for the support!

I don't think I can fix this because the AWS SDK reads the whole buffer before sending it so as far as rclone's instrumentation is concerned it has been sent at that point.

As you've noticed, reducing chunk size helps. I'm not sure setting chunk size so high is really helping, AWS recommend small chunks but more concurrency if you want more speed --s3-upload-concurrency. I think you'll find rclone will hit your bandwidth limits just on the default settings without changing chunk size or concurrency though.

It might be worth a note in the docs for chunk_size that increasing the chunk size decreases the accuracy of rclones statistics, in particular those seen by -P - what do you think?

I increased the chunk size because I saw higher numbers, which did not mean anything really, as it turns out :smiley: Will do.

I can make a small PR with that info in docs.

That would be great.

The chunk_size docs are here: https://github.com/rclone/rclone/blob/06ffd4882d2e7467415221302e0a8a429ddbfe92/backend/s3/s3.go#L1254

All the other docs are auto generated from that source.

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