Multithread upload speed slowed down to single-thread-speed for Koofr

Suspected Bug
1

What is the problem you are having with rclone?

  • roughly a month ago transfer speed for multi-file-transfer ("--transfers 16")¹ slowed down from 32 Mbps² to the speed of a single transfer/thread³ (12 Mbps)
  • happens only when transferring to Koofr⁴, not to pCloud or HiDrive
  • 32 Mbps are still achievable by running multiple separate instances of rclone in parallel⁵
    That's why I think it must be a problem/bug within rclone, not Koofr
    .
    .

¹ same results with --transfers 6, 8 or 12
² max upload of my line
³ command "--transfers 1" or just copying a single file
⁴ Koofr support states not to have changed anything on their side
⁵ that's my actual workaround: I do start 4+ instances using a VB script using one line
objShell.ShellExecute "C:\[snipped]\rclone", "sync D:\src koofr:\dst --include [selection] --transfers 1 ", "", "", 0
per instance.

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

rclone v1.61.1

  • os/version: Microsoft Windows 10 Pro 21H1 (64 bit)
  • os/kernel: 10.0.19043.1288 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.19.4
  • go/linking: static
  • go/tags: cmount

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

Koofr

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

rclone sync D:\src koofr:\dst --transfers 16

The rclone config contents with secrets removed.

[koofr]
type = koofr
provider = koofr
user = [snipped]
password = [snipped]

A log from the command with the -vv flag

C:\>rclone sync S:\tst koofr:\tst --transfers 16 -vv
2023/01/13 10:59:15 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "sync" "S:\\tst" "koofr:\\tst" "--transfers" "16" "-vv"]
2023/01/13 10:59:15 DEBUG : Creating backend with remote "S:\\tst"
2023/01/13 10:59:15 DEBUG : Using config file from "C:\\Users\\[snipped]\\AppData\\Roaming\\rclone\\rclone.conf"
2023/01/13 10:59:15 DEBUG : fs cache: renaming cache item "S:\\tst" to be canonical "//?/S:/tst"
2023/01/13 10:59:15 DEBUG : Creating backend with remote "koofr:\\tst"
2023/01/13 10:59:16 DEBUG : fs cache: renaming cache item "koofr:\\tst" to be canonical "koofr:/tst"
2023/01/13 10:59:17 DEBUG : koofr:e1[snipped]5f:/tst: Waiting for checks to finish
2023/01/13 10:59:17 DEBUG : koofr:e1[snipped]5f:/tst: Waiting for transfers to finish
2023/01/13 11:00:16 INFO  :
Transferred:      102.969 MiB / 781.911 MiB, 13%, 1.674 MiB/s, ETA 6m45s
Transferred:            0 / 8, 0%
Elapsed time:       1m1.6s
Transferring:
 *                                         1.tst: 13% /97.739Mi, 201.521Ki/s, 7m10s
 *                                         2.tst: 13% /97.739Mi, 231.648Ki/s, 6m14s
 *                                         3.tst: 13% /97.739Mi, 243.111Ki/s, 5m56s
 *                                         4.tst: 13% /97.739Mi, 194.292Ki/s, 7m26s
 *                                         5.tst: 13% /97.739Mi, 195.877Ki/s, 7m23s
 *                                         6.tst: 13% /97.739Mi, 248.097Ki/s, 5m49s
 *                                         7.tst: 13% /97.739Mi, 193.635Ki/s, 7m28s
 *                                         8.tst: 12% /97.739Mi, 206.099Ki/s, 7m6s

2023/01/13 11:01:16 INFO  :
Transferred:      187.969 MiB / 781.911 MiB, 24%, 1.383 MiB/s, ETA 7m9s
Transferred:            0 / 8, 0%
Elapsed time:       2m1.6s
Transferring:
 *                                         1.tst: 23% /97.739Mi, 170.288Ki/s, 7m29s
 *                                         2.tst: 24% /97.739Mi, 201.554Ki/s, 6m14s
 *                                         3.tst: 24% /97.739Mi, 214.387Ki/s, 5m52s
 *                                         4.tst: 23% /97.739Mi, 165.604Ki/s, 7m42s
 *                                         5.tst: 23% /97.739Mi, 168.631Ki/s, 7m33s
 *                                         6.tst: 24% /97.739Mi, 156.593Ki/s, 8m2s
 *                                         7.tst: 24% /97.739Mi, 162.721Ki/s, 7m44s
 *                                         8.tst: 23% /97.739Mi, 176.114Ki/s, 7m14s

2023/01/13 11:02:16 INFO  :
Transferred:      294.969 MiB / 781.911 MiB, 38%, 1.718 MiB/s, ETA 4m43s
Transferred:            0 / 8, 0%
Elapsed time:       3m1.6s
Transferring:
 *                                         1.tst: 37% /97.739Mi, 199.960Ki/s, 5m11s
 *                                         2.tst: 37% /97.739Mi, 226.001Ki/s, 4m35s
 *                                         3.tst: 37% /97.739Mi, 238.496Ki/s, 4m20s
 *                                         4.tst: 37% /97.739Mi, 194.472Ki/s, 5m19s
 *                                         5.tst: 37% /97.739Mi, 195.049Ki/s, 5m18s
 *                                         6.tst: 37% /97.739Mi, 247.106Ki/s, 4m11s
 *                                         7.tst: 37% /97.739Mi, 254.276Ki/s, 4m4s
 *                                         8.tst: 36% /97.739Mi, 202.176Ki/s, 5m12s

2023/01/13 11:03:16 INFO  :
Transferred:      394.969 MiB / 781.911 MiB, 51%, 1.624 MiB/s, ETA 3m58s
Transferred:            0 / 8, 0%
Elapsed time:       4m1.6s
Transferring:
 *                                         1.tst: 50% /97.739Mi, 211.398Ki/s, 3m56s
 *                                         2.tst: 51% /97.739Mi, 241.073Ki/s, 3m22s
 *                                         3.tst: 51% /97.739Mi, 188.235Ki/s, 4m19s
 *                                         4.tst: 50% /97.739Mi, 205.662Ki/s, 4m2s
 *                                         5.tst: 50% /97.739Mi, 206.171Ki/s, 4m2s
 *                                         6.tst: 51% /97.739Mi, 193.387Ki/s, 4m12s
 *                                         7.tst: 50% /97.739Mi, 201.287Ki/s, 4m7s
 *                                         8.tst: 50% /97.739Mi, 215.354Ki/s, 3m51s

2023/01/13 11:04:16 INFO  :
Transferred:      497.969 MiB / 781.911 MiB, 64%, 1.720 MiB/s, ETA 2m45s
Transferred:            0 / 8, 0%
Elapsed time:       5m1.6s
Transferring:
 *                                         1.tst: 63% /97.739Mi, 221.721Ki/s, 2m45s
 *                                         2.tst: 64% /97.739Mi, 252.358Ki/s, 2m20s
 *                                         3.tst: 64% /97.739Mi, 199.432Ki/s, 2m58s
 *                                         4.tst: 63% /97.739Mi, 217.390Ki/s, 2m48s
 *                                         5.tst: 63% /97.739Mi, 220.535Ki/s, 2m45s
 *                                         6.tst: 63% /97.739Mi, 206.836Ki/s, 2m56s
 *                                         7.tst: 63% /97.739Mi, 213.957Ki/s, 2m51s
 *                                         8.tst: 63% /97.739Mi, 229.194Ki/s, 2m39s

2023/01/13 11:05:16 INFO  :
Transferred:      603.969 MiB / 781.911 MiB, 77%, 1.713 MiB/s, ETA 1m43s
Transferred:            0 / 8, 0%
Elapsed time:       6m1.6s
Transferring:
 *                                         1.tst: 76% /97.739Mi, 216.042Ki/s, 1m47s
 *                                         2.tst: 77% /97.739Mi, 240.795Ki/s, 1m32s
 *                                         3.tst: 77% /97.739Mi, 255.656Ki/s, 1m27s
 *                                         4.tst: 76% /97.739Mi, 208.873Ki/s, 1m51s
 *                                         5.tst: 76% /97.739Mi, 210.455Ki/s, 1m50s
 *                                         6.tst: 77% /97.739Mi, 198.087Ki/s, 1m52s
 *                                         7.tst: 77% /97.739Mi, 205.679Ki/s, 1m48s
 *                                         8.tst: 76% /97.739Mi, 218.756Ki/s, 1m46s

2023/01/13 11:06:16 INFO  :
Transferred:      707.969 MiB / 781.911 MiB, 91%, 1.653 MiB/s, ETA 44s
Transferred:            0 / 8, 0%
Elapsed time:       7m1.6s
Transferring:
 *                                         1.tst: 90% /97.739Mi, 206.072Ki/s, 48s
 *                                         2.tst: 91% /97.739Mi, 234.499Ki/s, 38s
 *                                         3.tst: 91% /97.739Mi, 250.084Ki/s, 35s
 *                                         4.tst: 90% /97.739Mi, 199.828Ki/s, 49s
 *                                         5.tst: 90% /97.739Mi, 202.335Ki/s, 49s
 *                                         6.tst: 91% /97.739Mi, 188.969Ki/s, 47s
 *                                         7.tst: 91% /97.739Mi, 198.491Ki/s, 45s
 *                                         8.tst: 90% /97.739Mi, 212.654Ki/s, 46s

2023/01/13 11:06:57 DEBUG : 2.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:57 INFO  : 2.tst: Copied (new)
2023/01/13 11:06:57 DEBUG : 3.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:57 INFO  : 3.tst: Copied (new)
2023/01/13 11:06:57 DEBUG : 6.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:57 INFO  : 6.tst: Copied (new)
2023/01/13 11:06:57 DEBUG : 4.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:57 INFO  : 4.tst: Copied (new)
2023/01/13 11:06:57 DEBUG : 7.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:57 INFO  : 7.tst: Copied (new)
2023/01/13 11:06:58 DEBUG : 1.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:58 INFO  : 1.tst: Copied (new)
2023/01/13 11:06:58 DEBUG : 5.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:58 INFO  : 5.tst: Copied (new)
2023/01/13 11:06:58 DEBUG : 8.tst: md5 = dcdf8787bc80a954319556b86d742ccc OK
2023/01/13 11:06:58 INFO  : 8.tst: Copied (new)
2023/01/13 11:06:58 DEBUG : Waiting for deletions to finish
2023/01/13 11:06:58 INFO  :
Transferred:      781.911 MiB / 781.911 MiB, 100%, 1.865 MiB/s, ETA 0s
Transferred:            8 / 8, 100%
Elapsed time:      7m43.1s

2023/01/13 11:06:58 DEBUG : 4 go routines active

C:\>

What are line/environment capable off?

This job (tst.vbs) is finished in <4 minutes, maxing out the 32 Mbps.

Set objShell = CreateObject("Shell.Application")
Set fso = CreateObject("scripting.FilesystemObject")

' sync to KOOFR
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *0.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *1.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *2.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *3.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *4.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *5.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *6.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *7.tst* --transfers 1", "", "", 0
objShell.ShellExecute "C:\[snipped]\rclone", "sync S:\tst koofr:\tst --include *8.tst* --transfers 1", "", "", 0
2

Hi rcRsc,

Very good tests and post!

I cannot explain nor see how this should suddenly change unless something changed in yours or Koofr's setup a month ago. Sure nothing changed a month ago? (rclone (self)update, network/router update, Windows update,...)

It has sometimes helped to add --disable-http2 in situations like these, did you try that?

1 Like
3

indeed, --disable-http2 did the trick.

My sync jobs are automated, I am sure I didn't change anything before the drop (I don't update Windows (I do block all (known) MS-Addresses in the firewall) and usually don't update rclone ("never touch a running system")).
As told, Koofr support said "There were no changes done.", but Hetzner (the host of Koofr servers) might have changed sth?

Anyway, this switch helps, thank you!

2 Likes
4

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