Rclone multipart upload behavior question

Help and Support
1

What is the problem you are having with rclone?

During multipart upload, I see log messages for all the parts starting, then there is a long delay 5-10 minutes before the upload is complete. For example:
...
2021/02/07 20:05:15 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
...
2021/02/07 20:09:42 INFO : datasets_joc-07.tgz: Copied (new)

The system has lots of memory and a fast storage system. I'm wondering if this means that pretty much the whole transfer is being buffered and the delay is waiting on the network or the backend system.

The goal is to achieve an aggregate of 2-3GB/s over 100G ethernet and I'm trying to identify any obvious bottlenecks.

What is your rclone version (output from rclone version)

rclone v1.54.0

  • os/arch: linux/amd64
  • go version: go1.15.7

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

VERSION="18.04.2 LTS (Bionic Beaver)"
4.15.0-88-generic
x86_64 GNU/Linux

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

Openstack Swift

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

PARMS="-P --use-mmap --ignore-checksum --transfers=40 --checkers=40 --max-backlog=999999"
time rclone copy ${PARMS} --log-level=DEBUG --log-file="s3-test-log-01.txt" /gpfs/fs1/s3-test-1 pbss:circe_gpfs &

The rclone config contents with secrets removed.

[pbss]
type = s3
provider = Other
env_auth = false
endpoint = https://pbss.host.com
chunk_size = 256M
copy_cutoff = 512M
disable_checksum = true
upload_concurrency = 40
upload_cutoff = 512M
memory_pool_use_mmap = true

A log from the command with the -vv flag

2021/02/07 20:00:39 DEBUG : rclone: Version "v1.54.0" starting with parameters ["rclone" "copy" "-P" "--use-mmap" "--ignore-checksum" "--transfers=40" "--checkers=40" "--max-backlog=999999" "--log-level=DEBUG" "--log-file=s3-test-log-01.txt" "/gpfs/fs1/s3-test-1" "pbss:circe_gpfs"]
2021/02/07 20:00:39 DEBUG : Creating backend with remote "/gpfs/fs1/s3-test-1"
2021/02/07 20:00:39 DEBUG : Using config file from "/home/glowell/.config/rclone/rclone.conf"
2021/02/07 20:00:39 DEBUG : Creating backend with remote "pbss:circe_gpfs"
2021/02/07 20:00:39 DEBUG : S3 bucket circe_gpfs: Waiting for checks to finish
2021/02/07 20:00:39 DEBUG : S3 bucket circe_gpfs: Waiting for transfers to finish
2021/02/07 20:00:39 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:39 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 2 size 256M offset 256M/16.397G
2021/02/07 20:00:40 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 2 size 256M offset 256M/16.397G
2021/02/07 20:00:40 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 2 size 256M offset 256M/16.397G
2021/02/07 20:00:40 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 1 size 256M offset 0/16.397G
2021/02/07 20:00:40 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 2 size 256M offset 256M/16.397G
2021/02/07 20:00:40 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 2 size 256M offset 256M/16.397G
<< deleted because exceeds max upload >>
2021/02/07 20:03:30 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:30 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:31 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 52 size 256M offset 12.750G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 53 size 256M offset 13G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 54 size 256M offset 13.250G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 54 size 256M offset 13.250G/16.397G
2021/02/07 20:03:32 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:33 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:35 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 55 size 256M offset 13.500G/16.397G
2021/02/07 20:03:35 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:35 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 55 size 256M offset 13.500G/16.397G
2021/02/07 20:03:36 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:38 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:38 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:39 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:39 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 55 size 256M offset 13.500G/16.397G
2021/02/07 20:03:40 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:41 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:41 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:42 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:43 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:44 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:44 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:44 DEBUG : pacer: low level retry 1/10 (error RequestError: send request failed
caused by: Put "https://pbss.s8k.io/circe_gpfs/datasets_joc-08.tgz?partNumber=19&uploadId=MmFhMWJjYzQtZDk3ZC00YzE0LWI4NjEtYTUwYzU1NWRjMTEy": write tcp 10.0.1.77:45974->24.51.7.209:443: write: connection reset by peer)
2021/02/07 20:03:44 DEBUG : pacer: Rate limited, increasing sleep to 10ms
2021/02/07 20:03:45 DEBUG : pacer: Reducing sleep to 0s
2021/02/07 20:03:45 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:45 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:46 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:46 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:47 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:03:48 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 55 size 256M offset 13.500G/16.397G
2021/02/07 20:03:48 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:48 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:49 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:03:49 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 56 size 256M offset 13.750G/16.397G
2021/02/07 20:03:49 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:50 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:50 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:51 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:51 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:51 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:03:52 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 57 size 256M offset 14G/16.397G
2021/02/07 20:03:52 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:03:52 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:53 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:53 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:03:53 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:03:55 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:03:56 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:58 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:03:58 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:03:58 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:03:59 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:03:59 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:00 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:04:01 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:04:03 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 58 size 256M offset 14.250G/16.397G
2021/02/07 20:04:04 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:04 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:04:04 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:06 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 59 size 256M offset 14.500G/16.397G
2021/02/07 20:04:06 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:04:07 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:11 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:12 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:13 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:04:16 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:16 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:17 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 60 size 256M offset 14.750G/16.397G
2021/02/07 20:04:17 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:17 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:18 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:25 DEBUG : datasets_joc-01.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:27 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:30 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:32 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:04:34 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:35 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:04:36 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:38 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:04:39 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:40 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:04:41 DEBUG : datasets_joc-04.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:42 DEBUG : datasets_joc-08.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:46 DEBUG : datasets_joc-03.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:46 DEBUG : datasets_joc-02.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:47 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:50 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:51 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:04:53 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:54 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:04:55 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:04:55 DEBUG : datasets_joc-00.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:56 DEBUG : datasets_joc-05.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:04:59 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:05:00 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 61 size 256M offset 15G/16.397G
2021/02/07 20:05:01 DEBUG : datasets_joc-06.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:05:04 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:05:06 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 62 size 256M offset 15.250G/16.397G
2021/02/07 20:05:06 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:05:10 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 63 size 256M offset 15.500G/16.397G
2021/02/07 20:05:11 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 64 size 256M offset 15.750G/16.397G
2021/02/07 20:05:12 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 65 size 256M offset 16G/16.397G
2021/02/07 20:05:13 DEBUG : datasets_joc-09.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:05:15 DEBUG : datasets_joc-07.tgz: multipart upload starting chunk 66 size 150.963M offset 16.250G/16.397G
2021/02/07 20:09:36 INFO  : datasets_joc-05.tgz: Copied (new)
2021/02/07 20:09:38 INFO  : datasets_joc-00.tgz: Copied (new)
2021/02/07 20:09:39 INFO  : datasets_joc-08.tgz: Copied (new)
2021/02/07 20:09:39 INFO  : datasets_joc-02.tgz: Copied (new)
2021/02/07 20:09:41 INFO  : datasets_joc-01.tgz: Copied (new)
2021/02/07 20:09:41 INFO  : datasets_joc-06.tgz: Copied (new)
2021/02/07 20:09:41 INFO  : datasets_joc-03.tgz: Copied (new)
2021/02/07 20:09:42 INFO  : datasets_joc-09.tgz: Copied (new)
2021/02/07 20:09:42 INFO  : datasets_joc-04.tgz: Copied (new)
2021/02/07 20:09:42 INFO  : datasets_joc-07.tgz: Copied (new)
2021/02/07 20:09:42 INFO  :
Transferred:   	  163.974G / 163.974 GBytes, 100%, 309.066 MBytes/s, ETA 0s
Transferred:           10 / 10, 100%
Elapsed time:       9m3.3s

2021/02/07 20:09:42 DEBUG : 164 go routines active
2

More is not always better.

What's the source disk?

You have 40 transfers / 40 checkers so I'd guess you are pegging that?

I tend to start with defaults and adjust from there as you can see what the baseline and if you aren't hitting a choke point, you can raise things depending on the choke point.

3

Some of the parameters are guesswork based on reading the forums. I picked 40 transfers since we have 40 cores. I did start-out with defaults and added more stuff and this is where it sort of peaked. The source is GPFS over IB. It's good for 8-12GB/s on a single node. Somewhat less with small block reads.

Thanks,
Gary

4

The swift backend doesn't upload large files in parallel, so each chunk will be uploaded just after when you see the

	fs.Debugf(o, "Uploading segment file %q into %q", segmentPath, segmentsContainer)

What happens at the end is rclone uploads the manifest which shouldn't take very long and then it will remove the old segments if there were any.

So I'm not sure why the long delay, unless rclone has a lot of old segments to delete?

If you add -vv --dump headers then you can see the transactions to the swift storage which may help.

5

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