Poorer copy performance after version 1.63.1

Suspected Bug
1

What is the problem you are having with rclone?

I have noticed that the performance of "rclone copy" in combination with Dropbox has become significantly worse between version v.1.63.1 and 1.64. In several tests I was able to confirm that the performance has deteriorated by up to 50%. I have also tested other versions before, up to version v1.56.0 and the performance has improved up to v.1.63.1 but not worse than v.1.64.

I have also tested the latest beta, which also reproduces the problem.

I have of course run the tests several times with different versions, on the same host system, always installing the other version.

The problem does not only occur with Copy, which also results in poorer performance in the mount, for example. That was the starting point where I noticed it and wanted to validate the bandwidth.

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

rclone v1.63.1

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.15.0-91-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.20.6
  • go/linking: static
  • go/tags: none

rclone v1.65.2

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.15.0-91-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.21.6
  • go/linking: static
  • go/tags: none

rclone v1.66.0-beta.7694.137f7f62f

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.15.0-91-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.22.0
  • go/linking: static
  • go/tags: none

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

Dropbox

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

rclone copy 'dbx_storage:tmpfile' /home/user/ --progress --bwlimit 0

The rclone config contents with secrets removed.

[dbx_storage]
type = dropbox
client_id = xxx
client_secret = xxx
token = xxx

Copy Tests (Average Speed)

rclone v1.65.2

max. 60.962Mi/s

rclone v.1.63.1 (better results)

max. 110.209Mi/s

@ncw Do you have any direct suspicions as to what the problem might be?

2

If you post some log files, perhaps someone else can help out..

3

Also, with dropbox you want to use a tps limit around 12 seems to be the sweet spot for a single client iD/secret pair.

Dropbox is pretty rough on throttling.

4

I have been working with a tpslimit of 12 in my mount command for a long time, but I did not do this in the test case for the copy. But I just validated again and even with tpslimit 12 the difference remains.

5

If you can share the log files, that’s how we can help.

6

v1.63.1

2024/02/15 23:46:31 INFO  : Starting transaction limiter: max 12 transactions/s with burst 1
2024/02/15 23:46:31 DEBUG : rclone: Version "v1.63.1" starting with parameters ["rclone" "copy" "dbx_storage:/tmpfile" "/home/user/" "--progress" "--bwlimit" "0" "--tpslimit" "12" "-vv"]
2024/02/15 23:46:31 DEBUG : Creating backend with remote "dbx_storage:tmpfile"
2024/02/15 23:46:31 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2024/02/15 23:46:31 DEBUG : dbx_storage: Loaded invalid token from config file - ignoring
2024/02/15 23:46:31 DEBUG : Saving config "token" in section "dbx_storage" of the config file
2024/02/15 23:46:31 DEBUG : Keeping previous permissions for config file: -rw-r--r--
2024/02/15 23:46:31 DEBUG : dbx_storage: Saved new token in config file
2024/02/15 23:46:31 DEBUG : fs cache: adding new entry for parent of "dbx_storage:tmpfile", "dbx_storage:"
2024/02/15 23:46:31 DEBUG : Creating backend with remote "/home/user/"
2024/02/15 23:46:31 DEBUG : fs cache: renaming cache item "/home/user/" to be canonical "/home/user"
2024-02-15 23:46:31 DEBUG : tmpfile: Sizes differ (src 20295320559 vs dst 15882993619)
2024-02-15 23:46:31 DEBUG : tmpfile: Starting multi-thread copy with 4 parts of size 4.725Gi
2024-02-15 23:46:31 DEBUG : tmpfile: multi-thread copy: stream 4/4 (15221587968-20295320559) size 4.725Gi starting
2024-02-15 23:46:31 DEBUG : tmpfile: multi-thread copy: stream 2/4 (5073862656-10147725312) size 4.725Gi starting
2024-02-15 23:46:31 DEBUG : tmpfile: multi-thread copy: stream 3/4 (10147725312-15221587968) size 4.725Gi starting
2024-02-15 23:46:31 DEBUG : tmpfile: multi-thread copy: stream 1/4 (0-5073862656) size 4.725Gi starting
2024-02-15 23:46:32 DEBUG : tmpfile: multi-thread copy: write buffer set to 128Ki
2024-02-15 23:46:33 DEBUG : tmpfile: multi-thread copy: write buffer set to 128Ki
2024-02-15 23:46:33 DEBUG : tmpfile: multi-thread copy: write buffer set to 128Ki
2024-02-15 23:46:33 DEBUG : tmpfile: multi-thread copy: write buffer set to 128Ki
2024-02-15 23:47:08 INFO  : Signal received: interrupt
2024-02-15 23:47:08 INFO  : Dropbox root '': Committing uploads - please wait...
2024-02-15 23:47:08 INFO  : Exiting...
Transferred:   	    3.716 GiB / 18.901 GiB, 20%, 106.145 MiB/s, ETA 2m26s
Transferred:            0 / 1, 0%
Elapsed time:        37.4s
Transferring:
 * tmpfile: 19% /18.901Gi, 106.144Mi/s, 2m26s

v1.66.0-beta.7694.137f7f62f

2024/02/15 23:51:05 INFO  : Starting transaction limiter: max 12 transactions/s with burst 1
2024/02/15 23:51:05 DEBUG : rclone: Version "v1.66.0-beta.7694.137f7f62f" starting with parameters ["rclone" "copy" "dbx_storage:tmpfile" "/home/user/" "--progress" "--bwlimit" "0" "--tpslimit" "12" "-vvv"]
2024/02/15 23:51:05 DEBUG : Creating backend with remote "dbx_storage:tmpfile"
2024/02/15 23:51:05 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2024/02/15 23:51:06 DEBUG : fs cache: adding new entry for parent of "dbx_storage:tmpfile", "dbx_storage:bf42i5hs8j05hv5qbpjkmtm1e48mkf1cmbkelqq9gn8jijripth5m0vak7j6the9dgjsh2lnc8ori"
2024/02/15 23:51:06 DEBUG : Creating backend with remote "/home/user/"
2024/02/15 23:51:06 DEBUG : fs cache: renaming cache item "/home/user/" to be canonical "/home/user"
2024/02/15 23:51:06 DEBUG : tmpfile: Sizes differ (src 20295320559 vs dst 15882993619)
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: disabling buffering because destination uses OpenWriterAt
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: write buffer set to 131072
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: using backend concurrency of 4 instead of --multi-thread-streams 4
2024/02/15 23:51:06 DEBUG : tmpfile: Starting multi-thread copy with 303 chunks of size 64Mi with 4 parallel streams
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: chunk 4/303 (201326592-268435456) size 64Mi starting
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: chunk 1/303 (0-67108864) size 64Mi starting
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: chunk 2/303 (67108864-134217728) size 64Mi starting
2024/02/15 23:51:06 DEBUG : tmpfile: multi-thread copy: chunk 3/303 (134217728-201326592) size 64Mi starting
2024/02/15 23:51:07 DEBUG : tmpfile.gejelas5.partial: writing chunk 2
2024/02/15 23:51:07 DEBUG : tmpfile.gejelas5.partial: writing chunk 3
2024/02/15 23:51:08 DEBUG : tmpfile.gejelas5.partial: writing chunk 1
2024/02/15 23:51:08 DEBUG : tmpfile.gejelas5.partial: writing chunk 0
2024/02/15 23:51:10 DEBUG : tmpfile: multi-thread copy: chunk 4/303 (201326592-268435456) size 64Mi finished
2024/02/15 23:51:10 DEBUG : tmpfile: multi-thread copy: chunk 5/303 (268435456-335544320) size 64Mi starting
2024/02/15 23:51:11 DEBUG : tmpfile: multi-thread copy: chunk 1/303 (0-67108864) size 64Mi finished
2024/02/15 23:51:11 DEBUG : tmpfile: multi-thread copy: chunk 6/303 (335544320-402653184) size 64Mi starting
2024/02/15 23:51:11 DEBUG : tmpfile.gejelas5.partial: writing chunk 4
2024/02/15 23:51:11 DEBUG : tmpfile: multi-thread copy: chunk 2/303 (67108864-134217728) size 64Mi finished
2024/02/15 23:51:11 DEBUG : tmpfile: multi-thread copy: chunk 7/303 (402653184-469762048) size 64Mi starting
2024/02/15 23:51:12 DEBUG : tmpfile.gejelas5.partial: writing chunk 5
2024/02/15 23:51:12 DEBUG : tmpfile.gejelas5.partial: writing chunk 6
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 3/303 (134217728-201326592) size 64Mi finished
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 8/303 (469762048-536870912) size 64Mi starting
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 5/303 (268435456-335544320) size 64Mi finished
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 9/303 (536870912-603979776) size 64Mi starting
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 7/303 (402653184-469762048) size 64Mi finished
2024/02/15 23:51:14 DEBUG : tmpfile: multi-thread copy: chunk 10/303 (603979776-671088640) size 64Mi starting
2024/02/15 23:51:15 DEBUG : tmpfile.gejelas5.partial: writing chunk 8
2024/02/15 23:51:15 DEBUG : tmpfile.gejelas5.partial: writing chunk 9
2024/02/15 23:51:15 DEBUG : tmpfile.gejelas5.partial: writing chunk 7
2024/02/15 23:51:16 DEBUG : tmpfile: multi-thread copy: chunk 6/303 (335544320-402653184) size 64Mi finished
2024/02/15 23:51:16 DEBUG : tmpfile: multi-thread copy: chunk 11/303 (671088640-738197504) size 64Mi starting
2024/02/15 23:51:16 DEBUG : tmpfile.gejelas5.partial: writing chunk 10
2024/02/15 23:51:17 DEBUG : tmpfile: multi-thread copy: chunk 9/303 (536870912-603979776) size 64Mi finished
2024/02/15 23:51:17 DEBUG : tmpfile: multi-thread copy: chunk 12/303 (738197504-805306368) size 64Mi starting
2024/02/15 23:51:17 DEBUG : tmpfile.gejelas5.partial: writing chunk 11
2024/02/15 23:51:18 DEBUG : tmpfile: multi-thread copy: chunk 8/303 (469762048-536870912) size 64Mi finished
2024/02/15 23:51:18 DEBUG : tmpfile: multi-thread copy: chunk 13/303 (805306368-872415232) size 64Mi starting
2024/02/15 23:51:18 DEBUG : tmpfile: multi-thread copy: chunk 11/303 (671088640-738197504) size 64Mi finished
2024/02/15 23:51:18 DEBUG : tmpfile: multi-thread copy: chunk 14/303 (872415232-939524096) size 64Mi starting
2024/02/15 23:51:19 DEBUG : tmpfile: multi-thread copy: chunk 10/303 (603979776-671088640) size 64Mi finished
2024/02/15 23:51:19 DEBUG : tmpfile: multi-thread copy: chunk 15/303 (939524096-1006632960) size 64Mi starting
2024/02/15 23:51:19 DEBUG : tmpfile: multi-thread copy: chunk 12/303 (738197504-805306368) size 64Mi finished
2024/02/15 23:51:19 DEBUG : tmpfile: multi-thread copy: chunk 16/303 (1006632960-1073741824) size 64Mi starting
2024/02/15 23:51:20 DEBUG : tmpfile.gejelas5.partial: writing chunk 14
2024/02/15 23:51:20 DEBUG : tmpfile.gejelas5.partial: writing chunk 13
2024/02/15 23:51:20 DEBUG : tmpfile.gejelas5.partial: writing chunk 15
2024/02/15 23:51:21 INFO  : Signal received: interrupt
2024/02/15 23:51:21 INFO  : tmpfile.gejelas5.partial: Removing failed copy
2024/02/15 23:51:21 DEBUG : tmpfile: multi-thread copy: cancelling transfer on exit
2024/02/15 23:51:21 DEBUG : tmpfile: multi-thread copy: chunk 16/303 failed: multi-thread copy: failed to write chunk: context canceled
2024/02/15 23:51:21 DEBUG : tmpfile: multi-thread copy: chunk 17/303 (1073741824-1140850688) size 64Mi starting
2024/02/15 23:51:21 DEBUG : tmpfile: multi-thread copy: chunk 14/303 failed: multi-thread copy: failed to write chunk: context canceled
2024/02/15 23:51:21 DEBUG : tmpfile: multi-thread copy: abort failed: multi-thread copy: failed to find temp file when aborting chunk writer: object not found
2024/02/15 23:51:21 INFO  : Dropbox root '': Committing uploads - please wait...
2024/02/15 23:51:21 INFO  : Exiting...
Transferred:   	  844.875 MiB / 18.901 GiB, 4%, 55.528 MiB/s, ETA 5m33s
Transferred:            0 / 1, 0%
Elapsed time:        15.6s
Transferring:
 * tmpfile:  4% /18.901Gi, 55.751Mi/s, 5m32s
7

Can definitely tell the beta is doing something very different.

Is it also the same on 1.65.2? Can you share that log?

8

Actually, I see some changes in 1.65. If you can, try 1.64.2 and see if that does similiar and if 1.65 breaks it. I'd be super curious.

9

After v.1.63.1 it gets worse. I haven't actually tried every version now. But I can test it again tomorrow with 1.64.2.

10

It looks like this was the problematic change:

Can you try bumping up the value of --multi-thread-chunk-size to 4G (to make it consistent with v1.63.1) and see if that fixes the speeds?

1 Like
11

Yep, that's what I saw as well albeit I saw the changes in the release notes which is why I was honing in on the version :slight_smile:

1 Like
12

Tested with v1.65.2: Significantly better, the increase to the maximum bandwidth is slow but it reaches the 102 Mi/s as maximum in.

Version 1.63.1 in comparison still reaches the maximum speed significantly faster. The latest beta is also a little slower in comparison v1.65.2.

By the way, I am testing with a 10 Gbit direct-peering to dropbox.

13

Can you add the debug logs for this attempt too please?

14 
2024/02/16 12:22:39 INFO  : Starting transaction limiter: max 12 transactions/s with burst 1
2024/02/16 12:22:39 DEBUG : rclone: Version "v1.65.2" starting with parameters ["rclone" "copy" "dbx_storage:/tmpfile" "." "--progress" "--bwlimit" "0" "--tpslimit" "12" "--multi-thread-chunk-size" "4G" "-vv"]
2024/02/16 12:22:39 DEBUG : Creating backend with remote "dbx_storage:/tmpfile"
2024/02/16 12:22:39 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2024/02/16 12:22:39 DEBUG : fs cache: adding new entry for parent of "dbx_storage:/tmpfile", "dbx_storage:"
2024/02/16 12:22:39 DEBUG : Creating backend with remote "."
2024/02/16 12:22:39 DEBUG : fs cache: renaming cache item "." to be canonical "/root"
2024/02/16 12:22:39 DEBUG : tmpfile: Need to transfer - File not found at Destination
2024/02/16 12:22:39 DEBUG : tmpfile: multi-thread copy: disabling buffering because destination uses OpenWriterAt
2024/02/16 12:22:39 DEBUG : tmpfile: multi-thread copy: write buffer set to 131072
2024/02/16 12:22:39 DEBUG : tmpfile: multi-thread copy: using backend concurrency of 4 instead of --multi-thread-streams 4
2024/02/16 12:22:39 DEBUG : tmpfile: Starting multi-thread copy with 5 chunks of size 4Gi with 4 parallel streams
2024/02/16 12:22:40 DEBUG : tmpfile: multi-thread copy: chunk 2/5 (4294967296-8589934592) size 4Gi starting
2024/02/16 12:22:40 DEBUG : tmpfile: multi-thread copy: chunk 3/5 (8589934592-12884901888) size 4Gi starting
2024/02/16 12:22:40 DEBUG : tmpfile: multi-thread copy: chunk 4/5 (12884901888-17179869184) size 4Gi starting
2024/02/16 12:22:40 DEBUG : tmpfile: multi-thread copy: chunk 1/5 (0-4294967296) size 4Gi starting
2024/02/16 12:22:41 DEBUG : tmpfile.yoxaluh0.partial: writing chunk 3
2024/02/16 12:22:41 DEBUG : tmpfile.yoxaluh0.partial: writing chunk 0
2024/02/16 12:22:42 DEBUG : tmpfile.yoxaluh0.partial: writing chunk 1
2024/02/16 12:22:42 DEBUG : tmpfile.yoxaluh0.partial: writing chunk 2
15

May be worth increasing it further to 4.725GB to exactly match the previous value and get 4 chunks but I don't think that will help a lot.

The other change that I see from the same commit is that it used to buffer the reads too at 32KB, which doesn't happen anymore.

Anyway, this is about all I know of this section of the codebase so @ncw will need to chime in about what is expected and if any changes are required.

3 Likes
16

It sounds like we've found the root cause of most of the speed issue.

Setting --multi-thread-chunk-size 4G should make the code do more or less the same thing as it used to.

I think increasing --multi-thread-streams and decreasing --multi-thread-chunk-size should make it run faster. You could try --multi-thread-chunk-size 1G and --multi-thread-streams 16 and see what difference that makes. You should find just using --multi-thread-streams 16 on its own works quite well too.

3 Likes
17

I am currently very busy at work. But I will test it again.

1 Like
18

Much better! Now I get bandwidths of 350 MiB/s on average. I have a 10 Gbit line, would I theoretically be able to play with the values even more to get even more out of it or do you have experience whether there are limitations on the part of Dropbox that take effect?

19

So what are your final copy command?

20

I just took the suggestion and added --multi-thread-chunk-size 1G and --multi-thread-streams 16.

1 Like