Upgrading rclone will increase copy time

Help and Support
1

Copy a file of size 1.4T local to s3

v1.64.2 Elapsed time 4h47m32s
v1.65.2 Elapsed time 10h07m01s

Please tell me what is causing the 5 hour delay?

Why is there a difference in completion time between v1.64.2 and v1.65.2 ?
Am I missing an optional parameter required by v1.65.2 ?
Downgrading from v1.65.2 to v1.64.2 will improve the situation.

command

rclone copy /local/file.tar zzzzz:/bucket/remote --config=/etc/rclone.conf --checksum --fast-list --s3-list-version=2

memory

total: 58Gi
free: 25Gi

/etc/rclone.conf

[zzzzz]
type = s3
provider = AWS
access_key_id = zzz
secret_access_key = zzz
region = ap-northeast-1
location_constraint = ap-northeast-1
acl = bucket-owner-full-control

rclone v1.64.2
- os/version: almalinux 8.9 (64 bit)
- os/kernel: 4.18.0-513.9.1.el8_9.x86_64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.3
- go/linking: static
- go/tags: none

2024/02/24 19:31:56 DEBUG : rclone: Version "v1.64.2" starting with parameters ["rclone" "copy" "/local/file.tar" "zzzzz:/bucket/remote" "--config=/etc/rclone.conf" "--checksum" "--fast-list" "--s3-list-version=2" "--stats=0" "--log-level=DEBUG" "--log-file=./rclone1642.log"]
2024/02/24 19:31:56 DEBUG : Creating backend with remote "/local/file.tar"
2024/02/24 19:31:56 DEBUG : Using config file from "/etc/rclone.conf"
2024/02/24 19:31:56 DEBUG : fs cache: adding new entry for parent of "/local/file.tar", "/local"
2024/02/24 19:31:56 DEBUG : Creating backend with remote "zzzzz:/bucket/remote"
2024/02/24 19:31:56 DEBUG : zzzzz: detected overridden config - adding "{-7vZW}" suffix to name
2024/02/24 19:31:56 DEBUG : fs cache: renaming cache item "zzzzz:/bucket/remote" to be canonical "zzzzz{-7vZW}:bucket/remote"
2024/02/24 19:31:56 DEBUG : file.tar: Need to transfer - File not found at Destination
2024/02/24 20:46:09 DEBUG : file.tar: size: 1.352Ti, parts: 10000, default: 5Mi, new: 142Mi; default chunk size insufficient, returned new chunk size
2024/02/24 20:46:09 DEBUG : file.tar: open chunk writer: started multipart upload: DNW0Lh_izyGTjtxjopur33hfLNaPp_T_XToR6453ZAkZ4d--
2024/02/24 20:46:09 DEBUG : file.tar: multi-thread copy: using backend concurrency of 4 instead of --multi-thread-streams 4
2024/02/24 20:46:09 DEBUG : file.tar: Starting multi-thread copy with 9986 chunks of size 142Mi with 4 parallel streams
2024/02/24 20:46:09 DEBUG : file.tar: multi-thread copy: chunk 4/9986 (446693376-595591168) size 142Mi starting
2024/02/24 20:46:09 DEBUG : file.tar: multi-thread copy: chunk 2/9986 (148897792-297795584) size 142Mi starting
2024/02/24 20:46:09 DEBUG : file.tar: multi-thread copy: chunk 3/9986 (297795584-446693376) size 142Mi starting
2024/02/24 20:46:09 DEBUG : file.tar: multi-thread copy: chunk 1/9986 (0-148897792) size 142Mi starting
2024/02/24 20:46:16 DEBUG : file.tar: multipart upload wrote chunk 4 with 148897792 bytes and etag "5075e97cfb3d0ac490c69f23ca17bd5a"
2024/02/24 20:46:16 DEBUG : file.tar: multi-thread copy: chunk 4/9986 (446693376-595591168) size 142Mi finished
2024/02/24 20:46:16 DEBUG : file.tar: multi-thread copy: chunk 5/9986 (595591168-744488960) size 142Mi starting

2024/02/25 00:19:28 DEBUG : file.tar: multipart upload wrote chunk 9983 with 148897792 bytes and etag "bbbea5e7b829deba6fb92c65fde63b42"
2024/02/25 00:19:28 DEBUG : file.tar: multi-thread copy: chunk 9983/9986 (1486297759744-1486446657536) size 142Mi finished
2024/02/25 00:19:31 DEBUG : file.tar: multipart upload wrote chunk 9986 with 46418163 bytes and etag "a8649d066289ac7c4bf2d8e24b2e2240"
2024/02/25 00:19:31 DEBUG : file.tar: multi-thread copy: chunk 9986/9986 (1486744453120-1486790871283) size 44.268Mi finished
2024/02/25 00:19:32 DEBUG : file.tar: multipart upload wrote chunk 9985 with 148897792 bytes and etag "965dc39fdf5831c38635d840482d1bbd"
2024/02/25 00:19:32 DEBUG : file.tar: multi-thread copy: chunk 9985/9986 (1486595555328-1486744453120) size 142Mi finished
2024/02/25 00:19:34 DEBUG : file.tar: multipart upload "DNW0Lh_izyGTjtxjopur33hfLNaPp_T_XToR6453ZAkZ4d--" finished
2024/02/25 00:19:34 DEBUG : file.tar: Finished multi-thread copy with 9986 parts of size 142Mi
2024/02/25 00:19:34 DEBUG : file.tar: md5 = 58e8ecd447a45ab1b7ee26bfb5b19938 OK
2024/02/25 00:19:34 INFO  : file.tar: Multi-thread Copied (new)
2024/02/25 00:19:34 DEBUG : 13 go routines active

Start 2024/02/24 19:31:56
End 2024/02/25 00:19:34
Elapsed time 4h47m32s

rclone v1.65.2
- os/version: almalinux 8.9 (64 bit)
- os/kernel: 4.18.0-513.9.1.el8_9.x86_64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.6
- go/linking: static
- go/tags: none

2024/02/25 02:04:57 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "copy" "/local/file.tar" "zzzzz:/bucket/remote" "--config=/etc/rclone.conf" "--checksum" "--fast-list" "--s3-list-version=2" "--stats=0" "--log-level=DEBUG" "--log-file=./aaaa.log.7"]
2024/02/25 02:04:57 DEBUG : Creating backend with remote "/local/file.tar"
2024/02/25 02:04:57 DEBUG : Using config file from "/etc/rclone.conf"
2024/02/25 02:04:57 DEBUG : fs cache: adding new entry for parent of "/local/file.tar", "/local"
2024/02/25 02:04:57 DEBUG : Creating backend with remote "zzzzz:/bucket/remote"
2024/02/25 02:04:57 DEBUG : zzzzz: detected overridden config - adding "{-7vZW}" suffix to name
2024/02/25 02:04:58 DEBUG : fs cache: renaming cache item "zzzzz:/bucket/remote" to be canonical "zzzzz{-7vZW}:bucket/remote"
2024/02/25 02:04:58 DEBUG : file.tar: Need to transfer - File not found at Destination
2024/02/25 02:04:58 DEBUG : file.tar: multi-thread copy: disabling buffering because source is local disk
2024/02/25 03:17:21 DEBUG : file.tar: size: 1.352Ti, parts: 10000, default: 5Mi, new: 142Mi; default chunk size insufficient, returned new chunk size
2024/02/25 03:17:21 DEBUG : file.tar: open chunk writer: started multipart upload: WYG70V_xN1iRLS3oKY0APjt--
2024/02/25 03:17:21 DEBUG : file.tar: multi-thread copy: using backend concurrency of 4 instead of --multi-thread-streams 4
2024/02/25 03:17:21 DEBUG : file.tar: Starting multi-thread copy with 9986 chunks of size 142Mi with 4 parallel streams
2024/02/25 03:17:21 DEBUG : file.tar: multi-thread copy: chunk 4/9986 (446693376-595591168) size 142Mi starting
2024/02/25 03:17:21 DEBUG : file.tar: multi-thread copy: chunk 1/9986 (0-148897792) size 142Mi starting
2024/02/25 03:17:21 DEBUG : file.tar: multi-thread copy: chunk 2/9986 (148897792-297795584) size 142Mi starting
2024/02/25 03:17:21 DEBUG : file.tar: multi-thread copy: chunk 3/9986 (297795584-446693376) size 142Mi starting
2024/02/25 03:17:26 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:26 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:27 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:27 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:32 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:32 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:33 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:34 DEBUG : file.tar: Seek from 148897792 to 0
2024/02/25 03:17:37 DEBUG : file.tar: multipart upload wrote chunk 2 with 148897792 bytes and etag "692ad40514c0b748d9df8a9a9aefe43f"
2024/02/25 03:17:37 DEBUG : file.tar: multi-thread copy: chunk 2/9986 (148897792-297795584) size 142Mi finished
2024/02/25 03:17:37 DEBUG : file.tar: multi-thread copy: chunk 5/9986 (595591168-744488960) size 142Mi starting
2024/02/25 03:17:38 DEBUG : file.tar: multipart upload wrote chunk 1 with 148897792 bytes and etag "8ad5f1dca446702ba56464f809b5d48f"
2024/02/25 03:17:38 DEBUG : file.tar: multi-thread copy: chunk 1/9986 (0-148897792) size 142Mi finished
2024/02/25 03:17:38 DEBUG : file.tar: multi-thread copy: chunk 6/9986 (744488960-893386752) size 142Mi starting

2024/02/25 12:11:53 DEBUG : file.tar: multipart upload wrote chunk 9984 with 148897792 bytes and etag "6693462a9f4e63eaa6a570864a151a6a"
2024/02/25 12:11:53 DEBUG : file.tar: multi-thread copy: chunk 9984/9986 (1486446657536-1486595555328) size 142Mi finished
2024/02/25 12:11:54 DEBUG : file.tar: multipart upload wrote chunk 9986 with 46418163 bytes and etag "a8649d066289ac7c4bf2d8e24b2e2240"
2024/02/25 12:11:54 DEBUG : file.tar: multi-thread copy: chunk 9986/9986 (1486744453120-1486790871283) size 44.268Mi finished
2024/02/25 12:11:56 DEBUG : file.tar: multipart upload wrote chunk 9985 with 148897792 bytes and etag "965dc39fdf5831c38635d840482d1bbd"
2024/02/25 12:11:56 DEBUG : file.tar: multi-thread copy: chunk 9985/9986 (1486595555328-1486744453120) size 142Mi finished
2024/02/25 12:11:58 DEBUG : file.tar: multipart upload "WYG70V_xN1iRLS3oKY0APjt--" finished
2024/02/25 12:11:58 DEBUG : file.tar: Finished multi-thread copy with 9986 parts of size 142Mi
2024/02/25 12:11:58 DEBUG : file.tar: md5 = 58e8ecd447a45ab1b7ee26bfb5b19938 OK
2024/02/25 12:11:58 INFO  : file.tar: Multi-thread Copied (new)
2024/02/25 12:11:58 DEBUG : 13 go routines active

Start 2024/02/25 02:04:57
End 2024/02/25 12:11:58
Elapsed time 10h07m01s
2

See:

Poorer copy performance after version 1.63.1 - Suspected Bug - rclone forum

3

Tried with v1.62.2 which is older than 1.63.1
v1.62.2 and v1.64.2 were equivalent.
Is it really the "Poorer copy performance after version 1.63.1" ?

Copy a file of size 1.4T to s3
v1.64.2 Elapsed time 4h47m32s
v1.65.2 Elapsed time 10h07m01s
v1.62.2 Elapsed time 5h06m40s

rclone v1.62.2
- os/version: almalinux 8.9 (64 bit)
- os/kernel: 4.18.0-513.9.1.el8_9.x86_64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.20.2
- go/linking: static
- go/tags: none

2024/02/25 15:54:31 DEBUG : rclone: Version "v1.62.2" starting with parameters ["rclone" "copy" "/local/file.tar" "zzzzz:/bucket/remote" "--config=/etc/rclone.conf" "--checksum" "--fast-list" "--s3-list-version=2" "--stats=0" "--log-level=DEBUG" "--log-file=./aaaa.log.8"]
2024/02/25 15:54:31 DEBUG : Creating backend with remote "/local/file.tar"
2024/02/25 15:54:31 DEBUG : Using config file from "/etc/rclone.conf"
2024/02/25 15:54:31 DEBUG : fs cache: adding new entry for parent of "/local/file.tar", "/local"
2024/02/25 15:54:31 DEBUG : Creating backend with remote "zzzzz:/bucket/remote"
2024/02/25 15:54:31 DEBUG : zzzzz: detected overridden config - adding "{-7vZW}" suffix to name
2024/02/25 15:54:32 DEBUG : fs cache: renaming cache item "zzzzz:/bucket/remote" to be canonical "zzzzz{-7vZW}:bucket/remote"
2024/02/25 15:54:32 DEBUG : file.tar: Need to transfer - File not found at Destination
2024/02/25 17:07:07 DEBUG : file.tar: size: 1.352Ti, parts: 10000, default: 5Mi, new: 142Mi; default chunk size insufficient, returned new chunk size
2024/02/25 17:07:08 DEBUG : file.tar: multipart upload starting chunk 1 size 142Mi offset 0/1.352Ti
2024/02/25 17:07:09 DEBUG : file.tar: multipart upload starting chunk 2 size 142Mi offset 142Mi/1.352Ti
2024/02/25 17:07:10 DEBUG : file.tar: multipart upload starting chunk 3 size 142Mi offset 284Mi/1.352Ti
2024/02/25 17:07:11 DEBUG : file.tar: multipart upload starting chunk 4 size 142Mi offset 426Mi/1.352Ti
2024/02/25 17:07:12 DEBUG : file.tar: multipart upload starting chunk 5 size 142Mi offset 568Mi/1.352Ti
2024/02/25 17:07:13 DEBUG : file.tar: multipart upload starting chunk 6 size 142Mi offset 710Mi/1.352Ti
2024/02/25 17:07:15 DEBUG : file.tar: multipart upload starting chunk 7 size 142Mi offset 852Mi/1.352Ti
2024/02/25 17:07:19 DEBUG : file.tar: multipart upload starting chunk 8 size 142Mi offset 994Mi/1.352Ti

2024/02/25 21:00:55 DEBUG : file.tar: multipart upload starting chunk 9978 size 142Mi offset 1.351Ti/1.352Ti
2024/02/25 21:00:56 DEBUG : file.tar: multipart upload starting chunk 9979 size 142Mi offset 1.351Ti/1.352Ti
2024/02/25 21:00:57 DEBUG : file.tar: multipart upload starting chunk 9980 size 142Mi offset 1.351Ti/1.352Ti
2024/02/25 21:00:58 DEBUG : file.tar: multipart upload starting chunk 9981 size 142Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:01 DEBUG : file.tar: multipart upload starting chunk 9982 size 142Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:03 DEBUG : file.tar: multipart upload starting chunk 9983 size 142Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:04 DEBUG : file.tar: multipart upload starting chunk 9984 size 142Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:04 DEBUG : file.tar: multipart upload starting chunk 9985 size 142Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:07 DEBUG : file.tar: multipart upload starting chunk 9986 size 44.268Mi offset 1.352Ti/1.352Ti
2024/02/25 21:01:11 DEBUG : file.tar: Multipart upload Etag: da1b961065a5baab884de7790780cee3-9986 OK
2024/02/25 21:01:11 DEBUG : file.tar: md5 = 58e8ecd447a45ab1b7ee26bfb5b19938 OK
2024/02/25 21:01:11 INFO  : file.tar: Copied (new)
2024/02/25 21:01:11 DEBUG : 14 go routines active

Start 2024/02/25 15:54:31
End 2024/02/25 21:01:11
Elapsed time 5h06m40s
4

Did you read the thread I posted? It doesn't seem that way.

5

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