Transfer of large file to B2 slows drastically for last few percent

ctonsing · April 2, 2020, 1:53pm

What is the problem you are having with rclone?

It has happened to me on numerous occasions now that when transferring a large file (e.g. 10GB file obtainable here ) the transfer progresses at expected speed up to about 98% and then grinds to an extremely slow speed for the remaining 2% or so.

I've tried to run the command with --dump-headers, but so far I couldn't see anything noteworthy. Could somebody please try this to see if you get the same behaviour?

What is your rclone version (output from `rclone version`)

1.51.0

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

Windows 10, 64 bit

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

B2

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

rclone.exe copy C:\ :b2:rcloneTesting/test --filter "+ /path/to/folder/containing/large/file/**" --filter "- *" -vvv --stats 1s --stats-one-line --fast-list --transfers 14 --b2-account YYY... --b2-key ZZZ...

A log from the command with the `-vv` flag (eg output from `rclone -vv copy /tmp remote:tmp`)

the log is too big to attach, but at around 98%, the transferred amount starts creeping up slowly, the transfer speed keeps getting lower and lower and it takes a very long time for the last 2 percent to complete

Animosity022 · April 2, 2020, 2:03pm

I would surmise that's the checksum happening on the other side. If you can run the command with -vv and share the log, we can validate.

ctonsing · April 2, 2020, 2:08pm

Thank you @Animosity022, I see. It's just that the log is way too long. I'm busy running the test again at the moment, the last 2 percent has been going for a few hours. I'm running with -vvv, what would I expect to see if as you surmise it is checksum related?

Animosity022 · April 2, 2020, 2:19pm

Hmm, I think I'm flipped. I think the SHA1 calculates before uploading not at the end. I don't use B2 myself so I can test.

You can validate with a small file and see the log with -vv in it, which makes me wonder why the end would take longer.

ctonsing · April 2, 2020, 2:43pm

Here is a log from a small file transferred to B2:

2020/04/02 16:36:39 NOTICE: Config file "C:\Users\user\.config\rclone\rclone.conf" not found - using defaults
2020/04/02 16:36:42 NOTICE: Documents and Settings: Can't follow symlink without -L/--copy-links
2020/04/02 16:36:42 DEBUG : $Recycle.Bin: Excluded
2020/04/02 16:36:42 DEBUG : Intel: Excluded
2020/04/02 16:36:42 DEBUG : PerfLogs: Excluded
2020/04/02 16:36:42 DEBUG : Program Files: Excluded
2020/04/02 16:36:42 DEBUG : Program Files (x86): Excluded
2020/04/02 16:36:42 DEBUG : ProgramData: Excluded
2020/04/02 16:36:42 DEBUG : Recovery: Excluded
2020/04/02 16:36:42 DEBUG : System Volume Information: Excluded
2020/04/02 16:36:42 DEBUG : Users: Excluded
2020/04/02 16:36:42 DEBUG : Windows: Excluded
2020/04/02 16:36:42 INFO : B2 bucket rcloneTesting path test: Waiting for checks to finish
2020/04/02 16:36:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Size and modification time the same (differ by -33.6µs, within tolerance 1ms)
2020/04/02 16:36:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Unchanged skipping
2020/04/02 16:36:42 INFO : B2 bucket rcloneTesting path test: Waiting for transfers to finish
2020/04/02 16:36:43 INFO : 0 / 4.933 MBytes, 0%, 0 Bytes/s, ETA -

2020/04/02 16:36:44 INFO : 476k / 4.933 MBytes, 9%, 264.121 kBytes/s, ETA 17s

2020/04/02 16:36:45 INFO : 4.933M / 4.933 MBytes, 100%, 1.759 MBytes/s, ETA 0s

2020/04/02 16:36:46 INFO : 4.933M / 4.933 MBytes, 100%, 1.297 MBytes/s, ETA 0s

2020/04/02 16:36:46 DEBUG : path/to/folder/containing/large/file/combined-02-03-2020.log: SHA-1 = e940817b7a8900f009d15983de83401d114e3141 OK
2020/04/02 16:36:46 INFO : path/to/folder/containing/large/file/combined-02-03-2020.log: Copied (new)
2020/04/02 16:36:46 INFO : 4.933M / 4.933 MBytes, 100%, 1.131 MBytes/s, ETA 0s

2020/04/02 16:36:46 DEBUG : 7 go routines active

Animosity022 · April 2, 2020, 2:51pm

Yeah, the SHA1 happens in your log prior to the upload

ctonsing · April 2, 2020, 2:59pm

I see. Thanks for confirming!

Any other ideas are welcome, or somebody with a B2 account who can maybe try to replicate, pretty please

ncw · April 2, 2020, 7:09pm

If you run with -vv then you'll get more info. What might be happening is that one of the chunks times out and then needs to be retried. Default chunk size is 100MB which is more or less 1% of 10GB so that theory looks plausible...

ctonsing · April 3, 2020, 6:28am

Thank you @ncw. I did run with -vvv which I thought would be more verbose than -vv, but I will try again. I doubt that it is just one or a few of the chunks that need to be retried. Why I doubt that that is the cause is because the last 2% take much longer than the first 98%. I don't have exact numbers right now (I will try to get those today), but I think it would be something along the lines of the first 98% of the transfer take about 20-30mins and then the remaining 2% take about 2-3hours.

ctonsing · April 3, 2020, 9:30am

Ok, so I did the transfer of the 10GB file to B2 again with the following command:

rclone.exe copy C:\ :b2:rcloneTesting/test --filter "+ /path/to/folder/containing/large/file/**" --filter "- *" -vv --stats 60s --stats-one-line --fast-list --transfers 14 --b2-account YYY... --b2-key ZZZ...

Here is the log (I removed the leading date value for each line since else my post contains too many characters):

09:07:12 NOTICE: Config file "C:\Users\user\.config\rclone\rclone.conf" not found - using defaults
09:07:14 NOTICE: Documents and Settings: Can't follow symlink without -L/--copy-links
09:07:14 DEBUG : $Recycle.Bin: Excluded
09:07:14 DEBUG : Intel: Excluded
09:07:14 DEBUG : PerfLogs: Excluded
09:07:14 DEBUG : Program Files: Excluded
09:07:14 DEBUG : Program Files (x86): Excluded
09:07:14 DEBUG : ProgramData: Excluded
09:07:14 DEBUG : Recovery: Excluded
09:07:14 DEBUG : System Volume Information: Excluded
09:07:14 DEBUG : Users: Excluded
09:07:14 DEBUG : Windows: Excluded
09:07:15 INFO : B2 bucket rcloneTesting path test: Waiting for checks to finish
09:07:15 INFO : B2 bucket rcloneTesting path test: Waiting for transfers to finish
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Starting upload of large file in 107 chunks (id "4_z9d1c4c8f82d7f04e64e6001c_f20100023a188d335_d20200403_m070727_c003_v0312001_t0013")
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 1 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 2 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 3 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 4 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 5 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 6 length 100663296
09:07:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 7 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 8 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 9 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 10 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 11 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 12 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 13 length 100663296
09:07:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 14 length 100663296
09:08:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 2
09:08:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 15 length 100663296
09:08:14 INFO : 1.009G / 10 GBytes, 10%, 17.277 MBytes/s, ETA 8m52s

09:08:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 1
09:08:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 16 length 100663296
09:08:20 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 14
09:08:20 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 17 length 100663296
09:08:20 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 7
09:08:20 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 18 length 100663296
09:08:24 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 13
09:08:24 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 19 length 100663296
09:08:25 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 5
09:08:25 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 20 length 100663296
09:08:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 12
09:08:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 21 length 100663296
09:08:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 4
09:08:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 22 length 100663296
09:08:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 11
09:08:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 23 length 100663296
09:08:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 9
09:08:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 24 length 100663296
09:08:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 8
09:08:34 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 25 length 100663296
09:08:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 6
09:08:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 26 length 100663296
09:08:38 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 10
09:08:38 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 27 length 100663296
09:08:45 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 15
09:08:45 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 28 length 100663296
09:09:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 16
09:09:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 29 length 100663296
09:09:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 21
09:09:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 30 length 100663296
09:09:11 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Error sending chunk 30 (retry=true): c003_v0312001_t0022 is too busy (503 service_unavailable): &pacer.retryAfterError{error:(*api.Error)(0xc055dda570), retryAfter:1000000000}
09:09:11 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Clearing part upload URL because of error: c003_v0312001_t0022 is too busy (503 service_unavailable)
09:09:11 DEBUG : pacer: low level retry 1/10 (error c003_v0312001_t0022 is too busy (503 service_unavailable))
09:09:11 DEBUG : pacer: Rate limited, increasing sleep to 1s
09:09:11 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 30 length 100663296
09:09:12 DEBUG : pacer: Reducing sleep to 500ms
09:09:12 DEBUG : pacer: Reducing sleep to 250ms
09:09:12 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 17
09:09:13 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 31 length 100663296
09:09:14 DEBUG : pacer: Reducing sleep to 125ms
09:09:14 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 18
09:09:14 INFO : 2.385G / 10 GBytes, 24%, 20.382 MBytes/s, ETA 6m22s

09:09:15 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 32 length 100663296
09:09:23 DEBUG : pacer: Reducing sleep to 62.5ms
09:09:23 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 20
09:09:24 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 33 length 100663296
09:09:26 DEBUG : pacer: Reducing sleep to 31.25ms
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 25
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 34 length 100663296
09:09:26 DEBUG : pacer: Reducing sleep to 15.625ms
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 28
09:09:26 DEBUG : pacer: Reducing sleep to 10ms
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 26
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 35 length 100663296
09:09:26 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 36 length 100663296
09:09:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 27
09:09:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 37 length 100663296
09:09:32 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 22
09:09:32 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 38 length 100663296
09:09:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 24
09:09:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 39 length 100663296
09:09:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 19
09:09:35 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 40 length 100663296
09:09:52 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 23
09:09:52 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 41 length 100663296
09:09:55 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 30
09:09:55 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 42 length 100663296
09:10:03 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 29
09:10:03 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 43 length 100663296
09:10:05 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 32
09:10:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 44 length 100663296
09:10:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 31
09:10:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 45 length 100663296
09:10:14 INFO : 3.699G / 10 GBytes, 37%, 21.065 MBytes/s, ETA 5m6s

09:10:15 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 36
09:10:15 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 46 length 100663296
09:10:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 35
09:10:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 47 length 100663296
09:10:19 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 37
09:10:19 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 48 length 100663296
09:10:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 34
09:10:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 49 length 100663296
09:10:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 39
09:10:28 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 50 length 100663296
09:10:30 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 33
09:10:30 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 51 length 100663296
09:10:37 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 40
09:10:38 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 52 length 100663296
09:10:38 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 38
09:10:39 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 53 length 100663296
09:10:41 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 42
09:10:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 54 length 100663296
09:10:48 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 43
09:10:48 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 55 length 100663296
09:10:52 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 44
09:10:52 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 56 length 100663296
09:11:00 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 41
09:11:00 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 57 length 100663296
09:11:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 49
09:11:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 58 length 100663296
09:11:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 47
09:11:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 59 length 100663296
09:11:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 48
09:11:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 60 length 100663296
09:11:14 INFO : 4.981G / 10 GBytes, 50%, 21.271 MBytes/s, ETA 4m1s

09:11:16 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 45
09:11:16 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 61 length 100663296
09:11:17 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 50
09:11:17 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 62 length 100663296
09:11:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 46
09:11:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 63 length 100663296
09:11:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 54
09:11:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 64 length 100663296
09:11:32 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 53
09:11:32 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 65 length 100663296
09:11:41 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 55
09:11:41 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 66 length 100663296
09:11:41 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 51
09:11:41 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 67 length 100663296
09:11:50 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 56
09:11:50 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 68 length 100663296
09:11:54 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 52
09:11:55 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 69 length 100663296
09:12:00 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 58
09:12:00 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 70 length 100663296
09:12:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 60
09:12:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 71 length 100663296
09:12:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 59
09:12:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 72 length 100663296
09:12:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 63
09:12:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 73 length 100663296
09:12:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 61
09:12:10 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 74 length 100663296
09:12:14 INFO : 6.265G / 10 GBytes, 63%, 21.399 MBytes/s, ETA 2m58s

09:12:15 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 62
09:12:15 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 75 length 100663296
09:12:17 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 57
09:12:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 76 length 100663296
09:12:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 64
09:12:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 77 length 100663296
09:12:30 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 66
09:12:30 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 78 length 100663296
09:12:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 65
09:12:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 79 length 100663296
09:12:39 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 68
09:12:39 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 80 length 100663296
09:12:46 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 70
09:12:46 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 81 length 100663296
09:12:47 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 67
09:12:47 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 82 length 100663296
09:12:48 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 69
09:12:48 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 83 length 100663296
09:12:50 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 72
09:12:50 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 84 length 100663296
09:12:53 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 71
09:12:53 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 85 length 100663296
09:13:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 74
09:13:06 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 86 length 100663296
09:13:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 76
09:13:07 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 87 length 100663296
09:13:11 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 78
09:13:11 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 88 length 100663296
09:13:14 INFO : 7.592G / 10 GBytes, 76%, 21.607 MBytes/s, ETA 1m54s

09:13:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 73
09:13:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 89 length 100663296
09:13:24 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 77
09:13:24 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 90 length 100663296
09:13:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 79
09:13:27 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 91 length 100663296
09:13:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 75
09:13:31 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 92 length 100663296
09:13:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 81
09:13:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 93 length 100663296
09:13:36 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 82
09:13:36 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 94 length 100663296
09:13:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 84
09:13:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 95 length 100663296
09:13:45 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 80
09:13:45 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 96 length 100663296
09:13:51 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 83
09:13:51 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 97 length 100663296
09:13:55 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 85
09:13:55 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 98 length 100663296
09:14:04 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 86
09:14:04 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 99 length 100663296
09:14:08 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 88
09:14:08 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 100 length 100663296
09:14:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 87
09:14:09 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 101 length 100663296
09:14:14 INFO : 8.902G / 10 GBytes, 89%, 21.713 MBytes/s, ETA 51s

09:14:16 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 91
09:14:16 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 102 length 100663296
09:14:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 89
09:14:18 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 103 length 100663296
09:14:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 92
09:14:21 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 104 length 100663296
09:14:29 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 90
09:14:29 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 93
09:14:29 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 105 length 100663296
09:14:29 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 106 length 100663296
09:14:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 96
09:14:33 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Sending chunk 107 length 67108864
09:14:34 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 94
09:14:37 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 95
09:14:40 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 97
09:14:42 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 98
09:14:50 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 101
09:14:59 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 102
09:15:01 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 104
09:15:03 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 100
09:15:03 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 107
09:15:08 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 99
09:15:12 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 106
09:15:14 INFO : 9.915G / 10 GBytes, 99%, 21.161 MBytes/s, ETA 4s

09:15:14 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 103
09:15:20 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 105
09:16:14 INFO : 9.916G / 10 GBytes, 99%, 18.810 MBytes/s, ETA 4s

09:17:14 INFO : 9.917G / 10 GBytes, 99%, 16.930 MBytes/s, ETA 5s

09:18:14 INFO : 9.917G / 10 GBytes, 99%, 15.392 MBytes/s, ETA 5s

09:19:14 INFO : 9.918G / 10 GBytes, 99%, 14.110 MBytes/s, ETA 5s

09:20:14 INFO : 9.919G / 10 GBytes, 99%, 13.025 MBytes/s, ETA 6s

09:21:14 INFO : 9.920G / 10 GBytes, 99%, 12.096 MBytes/s, ETA 6s

09:22:14 INFO : 9.921G / 10 GBytes, 99%, 11.290 MBytes/s, ETA 7s

09:23:14 INFO : 9.922G / 10 GBytes, 99%, 10.585 MBytes/s, ETA 7s

09:24:14 INFO : 9.922G / 10 GBytes, 99%, 9.963 MBytes/s, ETA 7s

09:25:14 INFO : 9.923G / 10 GBytes, 99%, 9.410 MBytes/s, ETA 8s

09:26:14 INFO : 9.924G / 10 GBytes, 99%, 8.916 MBytes/s, ETA 8s

09:27:14 INFO : 9.925G / 10 GBytes, 99%, 8.470 MBytes/s, ETA 9s

09:28:14 INFO : 9.926G / 10 GBytes, 99%, 8.068 MBytes/s, ETA 9s

09:29:14 INFO : 9.926G / 10 GBytes, 99%, 7.702 MBytes/s, ETA 9s

09:30:14 INFO : 9.927G / 10 GBytes, 99%, 7.367 MBytes/s, ETA 10s

09:31:14 INFO : 9.928G / 10 GBytes, 99%, 7.061 MBytes/s, ETA 10s

09:32:14 INFO : 9.929G / 10 GBytes, 99%, 6.779 MBytes/s, ETA 10s

09:33:14 INFO : 9.930G / 10 GBytes, 99%, 6.519 MBytes/s, ETA 11s

09:34:14 INFO : 9.930G / 10 GBytes, 99%, 6.278 MBytes/s, ETA 11s

09:35:14 INFO : 9.931G / 10 GBytes, 99%, 6.054 MBytes/s, ETA 11s

09:36:14 INFO : 9.932G / 10 GBytes, 99%, 5.846 MBytes/s, ETA 11s

09:37:14 INFO : 9.933G / 10 GBytes, 99%, 5.651 MBytes/s, ETA 12s

09:38:14 INFO : 9.934G / 10 GBytes, 99%, 5.469 MBytes/s, ETA 12s

09:39:14 INFO : 9.934G / 10 GBytes, 99%, 5.299 MBytes/s, ETA 12s

09:40:14 INFO : 9.935G / 10 GBytes, 99%, 5.139 MBytes/s, ETA 12s

09:41:14 INFO : 9.936G / 10 GBytes, 99%, 4.988 MBytes/s, ETA 13s

09:42:14 INFO : 9.937G / 10 GBytes, 99%, 4.846 MBytes/s, ETA 13s

09:43:14 INFO : 9.938G / 10 GBytes, 99%, 4.712 MBytes/s, ETA 13s

09:44:14 INFO : 9.939G / 10 GBytes, 99%, 4.585 MBytes/s, ETA 13s

09:45:14 INFO : 9.940G / 10 GBytes, 99%, 4.465 MBytes/s, ETA 13s

09:46:14 INFO : 9.941G / 10 GBytes, 99%, 4.350 MBytes/s, ETA 13s

09:47:14 INFO : 9.941G / 10 GBytes, 99%, 4.242 MBytes/s, ETA 14s

09:48:14 INFO : 9.942G / 10 GBytes, 99%, 4.139 MBytes/s, ETA 14s

09:49:14 INFO : 9.943G / 10 GBytes, 99%, 4.041 MBytes/s, ETA 14s

09:50:14 INFO : 9.944G / 10 GBytes, 99%, 3.947 MBytes/s, ETA 14s

09:51:14 INFO : 9.945G / 10 GBytes, 99%, 3.858 MBytes/s, ETA 14s

09:52:14 INFO : 9.945G / 10 GBytes, 99%, 3.772 MBytes/s, ETA 14s

09:53:14 INFO : 9.946G / 10 GBytes, 99%, 3.690 MBytes/s, ETA 14s

09:54:14 INFO : 9.947G / 10 GBytes, 99%, 3.612 MBytes/s, ETA 15s

09:55:14 INFO : 9.948G / 10 GBytes, 99%, 3.537 MBytes/s, ETA 15s

09:56:14 INFO : 9.949G / 10 GBytes, 99%, 3.465 MBytes/s, ETA 15s

09:57:14 INFO : 9.949G / 10 GBytes, 99%, 3.396 MBytes/s, ETA 15s

09:58:14 INFO : 9.950G / 10 GBytes, 100%, 3.330 MBytes/s, ETA 15s

09:59:14 INFO : 9.951G / 10 GBytes, 100%, 3.266 MBytes/s, ETA 15s

10:00:14 INFO : 9.952G / 10 GBytes, 100%, 3.205 MBytes/s, ETA 15s

10:01:14 INFO : 9.953G / 10 GBytes, 100%, 3.146 MBytes/s, ETA 15s

10:02:14 INFO : 9.953G / 10 GBytes, 100%, 3.089 MBytes/s, ETA 15s

10:03:14 INFO : 9.954G / 10 GBytes, 100%, 3.034 MBytes/s, ETA 15s

10:04:14 INFO : 9.955G / 10 GBytes, 100%, 2.981 MBytes/s, ETA 15s

10:05:14 INFO : 9.956G / 10 GBytes, 100%, 2.930 MBytes/s, ETA 15s

10:06:14 INFO : 9.956G / 10 GBytes, 100%, 2.880 MBytes/s, ETA 15s

10:07:14 INFO : 9.957G / 10 GBytes, 100%, 2.832 MBytes/s, ETA 15s

10:08:14 INFO : 9.958G / 10 GBytes, 100%, 2.786 MBytes/s, ETA 15s

10:09:14 INFO : 9.959G / 10 GBytes, 100%, 2.741 MBytes/s, ETA 15s

10:10:14 INFO : 9.960G / 10 GBytes, 100%, 2.698 MBytes/s, ETA 15s

10:11:14 INFO : 9.960G / 10 GBytes, 100%, 2.656 MBytes/s, ETA 15s

10:12:14 INFO : 9.961G / 10 GBytes, 100%, 2.616 MBytes/s, ETA 15s

10:13:14 INFO : 9.962G / 10 GBytes, 100%, 2.576 MBytes/s, ETA 15s

10:14:14 INFO : 9.963G / 10 GBytes, 100%, 2.538 MBytes/s, ETA 14s

10:15:14 INFO : 9.964G / 10 GBytes, 100%, 2.501 MBytes/s, ETA 14s

10:16:14 INFO : 9.965G / 10 GBytes, 100%, 2.465 MBytes/s, ETA 14s

10:17:14 INFO : 9.966G / 10 GBytes, 100%, 2.430 MBytes/s, ETA 14s

10:18:14 INFO : 9.966G / 10 GBytes, 100%, 2.396 MBytes/s, ETA 14s

10:19:14 INFO : 9.967G / 10 GBytes, 100%, 2.363 MBytes/s, ETA 14s

10:20:14 INFO : 9.968G / 10 GBytes, 100%, 2.331 MBytes/s, ETA 14s

10:21:14 INFO : 9.969G / 10 GBytes, 100%, 2.299 MBytes/s, ETA 13s

10:22:14 INFO : 9.970G / 10 GBytes, 100%, 2.269 MBytes/s, ETA 13s

10:23:14 INFO : 9.970G / 10 GBytes, 100%, 2.239 MBytes/s, ETA 13s

10:24:14 INFO : 9.971G / 10 GBytes, 100%, 2.210 MBytes/s, ETA 13s

10:25:14 INFO : 9.972G / 10 GBytes, 100%, 2.182 MBytes/s, ETA 13s

10:26:14 INFO : 9.973G / 10 GBytes, 100%, 2.155 MBytes/s, ETA 12s

10:27:14 INFO : 9.974G / 10 GBytes, 100%, 2.128 MBytes/s, ETA 12s

10:28:14 INFO : 9.974G / 10 GBytes, 100%, 2.102 MBytes/s, ETA 12s

10:29:14 INFO : 9.975G / 10 GBytes, 100%, 2.076 MBytes/s, ETA 12s

10:30:14 INFO : 9.976G / 10 GBytes, 100%, 2.051 MBytes/s, ETA 11s

10:31:14 INFO : 9.977G / 10 GBytes, 100%, 2.027 MBytes/s, ETA 11s

10:32:14 INFO : 9.978G / 10 GBytes, 100%, 2.003 MBytes/s, ETA 11s

10:33:14 INFO : 9.979G / 10 GBytes, 100%, 1.980 MBytes/s, ETA 11s

10:34:14 INFO : 9.979G / 10 GBytes, 100%, 1.958 MBytes/s, ETA 10s

10:35:14 INFO : 9.980G / 10 GBytes, 100%, 1.936 MBytes/s, ETA 10s

10:36:14 INFO : 9.981G / 10 GBytes, 100%, 1.914 MBytes/s, ETA 10s

10:37:14 INFO : 9.982G / 10 GBytes, 100%, 1.893 MBytes/s, ETA 9s

10:38:14 INFO : 9.983G / 10 GBytes, 100%, 1.872 MBytes/s, ETA 9s

10:39:14 INFO : 9.984G / 10 GBytes, 100%, 1.852 MBytes/s, ETA 9s

10:40:14 INFO : 9.984G / 10 GBytes, 100%, 1.832 MBytes/s, ETA 8s

10:41:14 INFO : 9.985G / 10 GBytes, 100%, 1.813 MBytes/s, ETA 8s

10:42:14 INFO : 9.986G / 10 GBytes, 100%, 1.794 MBytes/s, ETA 8s

10:43:14 INFO : 9.987G / 10 GBytes, 100%, 1.775 MBytes/s, ETA 7s

10:44:14 INFO : 9.988G / 10 GBytes, 100%, 1.757 MBytes/s, ETA 7s

10:45:14 INFO : 9.988G / 10 GBytes, 100%, 1.740 MBytes/s, ETA 6s

10:46:14 INFO : 9.989G / 10 GBytes, 100%, 1.722 MBytes/s, ETA 6s

10:47:14 INFO : 9.990G / 10 GBytes, 100%, 1.705 MBytes/s, ETA 5s

10:48:14 INFO : 9.991G / 10 GBytes, 100%, 1.688 MBytes/s, ETA 5s

10:49:14 INFO : 9.991G / 10 GBytes, 100%, 1.672 MBytes/s, ETA 5s

10:50:14 INFO : 9.992G / 10 GBytes, 100%, 1.656 MBytes/s, ETA 4s

10:51:14 INFO : 9.993G / 10 GBytes, 100%, 1.640 MBytes/s, ETA 4s

10:52:14 INFO : 9.994G / 10 GBytes, 100%, 1.624 MBytes/s, ETA 3s

10:53:14 INFO : 9.995G / 10 GBytes, 100%, 1.609 MBytes/s, ETA 3s

10:54:14 INFO : 9.995G / 10 GBytes, 100%, 1.594 MBytes/s, ETA 2s

10:55:14 INFO : 9.996G / 10 GBytes, 100%, 1.580 MBytes/s, ETA 2s

10:56:14 INFO : 9.997G / 10 GBytes, 100%, 1.565 MBytes/s, ETA 2s

10:57:14 INFO : 9.998G / 10 GBytes, 100%, 1.551 MBytes/s, ETA 1s

10:58:14 INFO : 9.998G / 10 GBytes, 100%, 1.537 MBytes/s, ETA 1s

10:59:14 INFO : 9.999G / 10 GBytes, 100%, 1.524 MBytes/s, ETA 0s

11:00:14 INFO : 10.000G / 10 GBytes, 100%, 1.510 MBytes/s, ETA 0s

11:01:14 INFO : 10.001G / 10 GBytes, 100%, 1.497 MBytes/s, ETA -

11:02:14 INFO : 10.001G / 10 GBytes, 100%, 1.484 MBytes/s, ETA -

11:03:14 INFO : 10.002G / 10 GBytes, 100%, 1.472 MBytes/s, ETA -

11:03:46 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Done sending chunk 3
11:03:46 DEBUG : path/to/folder/containing/large/file/10000mb.bin: Finishing large file upload with 107 parts
11:03:49 DEBUG : path/to/folder/containing/large/file/10000mb.bin: SHA-1 = a0b6e2ca4e28360a929943e8eb966f703a69dc44 OK
11:03:49 INFO : path/to/folder/containing/large/file/10000mb.bin: Copied (new)
11:03:49 INFO : 10.003G / 10.003 GBytes, 100%, 1.464 MBytes/s, ETA 0s

So we have one successful retry for chunk 30 and then no other apparent problems aftwerwards, except the slowdown again at 99%. First 99% are transferred in about 8mins, the remaining 1% then takes almost another 2 hours. All this time is spent on one single chunk, chunk 3. Similar behaviour has been observed on numerous occasions.

ncw · April 3, 2020, 9:52am

Very interesting log - thank you.

So why did chunk 3 take so long?

Rclone will be doing 14 separate TCP transfers. I'm wondering if somehow the bandwidth for the chunk 3 TCP stream got squeezed right down and never recovered. Maybe it got lost packets and the TCP window got shut right down.

I suspect this is something specific to your computer or network since I've not seen this reported before. It might be setting --transfers to larger than default. It could also be the b2 end...

Are you running any QoS on your network? Could you try this from a linux VM to see if you get the same result?

You could also try lowering the number of --transfers

I don't think this is an rclone bug but there might be something rclone could do to help.

ctonsing · April 3, 2020, 11:46am

Thank you @ncw, I'm trying to get that setup so I can test on Ubuntu on the same network.

ctonsing · April 6, 2020, 7:44am

So I did the test again on the same network. This time on an Ubuntu VM running on Proxmox. The network connection is a 1Gbps fibre connection with no shaping or similar, no QoS management happening. Here is the log file from the transfer (only difference to previous test on Windows is that there were 2 files in the directory to be transferred):

14:49:20 NOTICE: Config file "/home/user/.config/rclone/rclone.conf" not found - using defaults
14:49:23 NOTICE: vmlinuz: Can't follow symlink without -L/--copy-links
14:49:23 NOTICE: initrd.img: Can't follow symlink without -L/--copy-links
14:49:23 NOTICE: initrd.img.old: Can't follow symlink without -L/--copy-links
14:49:23 NOTICE: vmlinuz.old: Can't follow symlink without -L/--copy-links
14:49:23 DEBUG : etc: Excluded
14:49:23 DEBUG : cdrom: Excluded
14:49:23 DEBUG : srv: Excluded
14:49:23 DEBUG : lost+found: Excluded
14:49:23 DEBUG : proc: Excluded
14:49:23 DEBUG : run: Excluded
14:49:23 DEBUG : mnt: Excluded
14:49:23 DEBUG : var: Excluded
14:49:23 DEBUG : boot: Excluded
14:49:23 DEBUG : snap: Excluded
14:49:23 DEBUG : lib: Excluded
14:49:23 DEBUG : sys: Excluded
14:49:23 DEBUG : media: Excluded
14:49:23 DEBUG : bin: Excluded
14:49:23 DEBUG : tmp: Excluded
14:49:23 DEBUG : opt: Excluded
14:49:23 DEBUG : root: Excluded
14:49:23 DEBUG : dev: Excluded
14:49:23 DEBUG : sbin: Excluded
14:49:23 DEBUG : usr: Excluded
14:49:23 DEBUG : lib64: Excluded
14:49:23 INFO : B2 bucket rcloneTesting path test: Waiting for checks to finish
14:49:23 INFO : B2 bucket rcloneTesting path test: Waiting for transfers to finish
14:49:28 DEBUG : chosenPath/10000mb.bin: Starting upload of large file in 13 chunks (id "4_z9d1c4c8f82d7f04e64e6001c_f200c0ff6883ebde0_d20200403_m144928_c003_v0312001_t0021")
14:49:29 DEBUG : chosenPath/10000mb.bin: Sending chunk 1 length 100663296
14:49:29 DEBUG : chosenPath/10000mb.bin: Sending chunk 2 length 100663296
14:49:30 DEBUG : chosenPath/10000mb.bin: Sending chunk 3 length 100663296
14:49:31 DEBUG : chosenPath/10000mb.bin: Sending chunk 4 length 100663296
14:49:32 DEBUG : chosenPath/10000mb.bin: Sending chunk 5 length 100663296
14:49:33 DEBUG : chosenPath/10000mb.bin: Sending chunk 6 length 100663296
14:49:34 DEBUG : chosenPath/10000mb.bin: Sending chunk 7 length 100663296
14:49:35 DEBUG : chosenPath/10000mb.bin: Sending chunk 8 length 100663296
14:49:36 DEBUG : chosenPath/10000mb.bin: Sending chunk 9 length 100663296
14:49:37 DEBUG : chosenPath/10000mb.bin: Sending chunk 10 length 100663296
14:49:38 DEBUG : chosenPath/10000mb.bin: Sending chunk 11 length 100663296
14:49:38 DEBUG : chosenPath/10000mb.bin: Sending chunk 12 length 100663296
14:49:39 DEBUG : chosenPath/10000mb.bin: Sending chunk 13 length 98369536
14:49:55 DEBUG : chosenPath/10000mb.bin: Done sending chunk 5
14:49:56 DEBUG : chosenPath/10000mb.bin: Done sending chunk 1
14:50:01 DEBUG : chosenPath/10000mb.bin: Done sending chunk 8
14:50:03 DEBUG : chosenPath/10000mb.bin.1: Starting upload of large file in 107 chunks (id "4_z9d1c4c8f82d7f04e64e6001c_f20100023a188e368_d20200403_m145003_c003_v0312000_t0003")
14:50:04 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 1 length 100663296
14:50:05 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 2 length 100663296
14:50:06 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 3 length 100663296
14:50:06 DEBUG : chosenPath/10000mb.bin: Done sending chunk 4
14:50:06 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 4 length 100663296
14:50:07 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 5 length 100663296
14:50:11 DEBUG : chosenPath/10000mb.bin: Done sending chunk 10
14:50:12 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 6 length 100663296
14:50:15 DEBUG : chosenPath/10000mb.bin: Done sending chunk 7
14:50:16 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 7 length 100663296
14:50:18 DEBUG : chosenPath/10000mb.bin: Done sending chunk 12
14:50:19 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 8 length 100663296
14:50:19 DEBUG : chosenPath/10000mb.bin: Done sending chunk 13
14:50:20 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 9 length 100663296
14:50:23 INFO : 1.387G / 11.217 GBytes, 12%, 23.742 MBytes/s, ETA 7m3s

14:50:23 DEBUG : chosenPath/10000mb.bin: Done sending chunk 3
14:50:24 DEBUG : chosenPath/10000mb.bin: Done sending chunk 2
14:50:24 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 10 length 100663296
14:50:25 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 11 length 100663296
14:50:28 DEBUG : chosenPath/10000mb.bin: Done sending chunk 9
14:50:28 DEBUG : chosenPath/10000mb.bin: Done sending chunk 11
14:50:29 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 12 length 100663296
14:50:30 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 13 length 100663296
14:50:33 DEBUG : chosenPath/10000mb.bin: Done sending chunk 6
14:50:33 DEBUG : chosenPath/10000mb.bin: Finishing large file upload with 13 parts
14:50:34 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 14 length 100663296
14:50:34 DEBUG : chosenPath/10000mb.bin: SHA-1 = d42dcd62fd94da66a8ff77a8ee145e2e8fca0b45 OK
14:50:34 INFO : chosenPath/10000mb.bin: Copied (new)
14:50:44 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 4
14:50:45 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 15 length 100663296
14:50:45 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 3
14:50:46 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 16 length 100663296
14:50:47 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 5
14:50:47 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 17 length 100663296
14:50:48 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 2
14:50:49 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 18 length 100663296
14:50:50 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 7
14:50:51 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 19 length 100663296
14:50:58 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 11
14:50:58 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 20 length 100663296
14:51:02 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 8
14:51:02 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 13
14:51:02 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 21 length 100663296
14:51:03 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 22 length 100663296
14:51:05 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 10
14:51:06 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 23 length 100663296
14:51:10 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 14
14:51:11 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 24 length 100663296
14:51:15 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 15
14:51:16 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 9
14:51:16 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 25 length 100663296
14:51:17 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 16
14:51:17 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 26 length 100663296
14:51:18 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 27 length 100663296
14:51:20 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 18
14:51:21 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 28 length 100663296
14:51:23 INFO : 2.997G / 11.217 GBytes, 27%, 25.612 MBytes/s, ETA 5m28s

14:51:23 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 19
14:51:24 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 29 length 100663296
14:51:28 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 20
14:51:29 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 30 length 100663296
14:51:30 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 17
14:51:31 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 31 length 100663296
14:51:51 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 21
14:51:52 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 30
14:51:52 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 32 length 100663296
14:51:52 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 22
14:51:53 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 33 length 100663296
14:51:54 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 34 length 100663296
14:51:56 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 24
14:51:57 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 35 length 100663296
14:52:00 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 25
14:52:00 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 36 length 100663296
14:52:01 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 28
14:52:01 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 27
14:52:02 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 37 length 100663296
14:52:03 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 38 length 100663296
14:52:04 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 23
14:52:05 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 39 length 100663296
14:52:06 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 31
14:52:07 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 40 length 100663296
14:52:11 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 26
14:52:12 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 41 length 100663296
14:52:17 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 29
14:52:18 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 42 length 100663296
14:52:18 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 33
14:52:19 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 43 length 100663296
14:52:23 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 32
14:52:23 INFO : 4.536G / 11.217 GBytes, 40%, 25.832 MBytes/s, ETA 4m24s

14:52:23 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 44 length 100663296
14:52:28 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 36
14:52:29 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 45 length 100663296
14:52:31 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 35
14:52:32 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 34
14:52:32 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 46 length 100663296
14:52:32 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 47 length 100663296
14:52:38 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 39
14:52:39 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 48 length 100663296
14:52:40 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 43
14:52:40 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 49 length 100663296
14:52:43 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 37
14:52:44 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 50 length 100663296
14:52:45 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 40
14:52:46 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 51 length 100663296
14:52:47 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 38
14:52:48 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 42
14:52:48 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 52 length 100663296
14:52:49 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 53 length 100663296
14:53:00 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 41
14:53:00 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 44
14:53:01 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 54 length 100663296
14:53:02 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 55 length 100663296
14:53:10 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 47
14:53:10 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 45
14:53:11 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 56 length 100663296
14:53:12 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 57 length 100663296
14:53:14 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 48
14:53:15 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 58 length 100663296
14:53:15 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 53
14:53:16 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 46
14:53:16 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 50
14:53:16 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 59 length 100663296
14:53:17 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 49
14:53:17 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 60 length 100663296
14:53:18 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 61 length 100663296
14:53:19 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 62 length 100663296
14:53:20 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 52
14:53:20 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 63 length 100663296
14:53:23 INFO : 6.153G / 11.217 GBytes, 55%, 26.272 MBytes/s, ETA 3m17s

14:53:38 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 55
14:53:39 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 51
14:53:39 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 64 length 100663296
14:53:40 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 65 length 100663296
14:53:46 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 57
14:53:47 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 66 length 100663296
14:53:49 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 60
14:53:50 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 67 length 100663296
14:53:51 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 59
14:53:51 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 54
14:53:51 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 68 length 100663296
14:53:52 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 69 length 100663296
14:53:53 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 58
14:53:54 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 70 length 100663296
14:53:54 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 63
14:53:55 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 71 length 100663296
14:53:56 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 56
14:53:56 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 62
14:53:56 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 72 length 100663296
14:53:57 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 73 length 100663296
14:53:59 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 61
14:54:00 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 74 length 100663296
14:54:08 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 64
14:54:08 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 75 length 100663296
14:54:18 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 65
14:54:19 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 76 length 100663296
14:54:23 INFO : 7.794G / 11.217 GBytes, 69%, 26.620 MBytes/s, ETA 2m11s

14:54:24 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 72
14:54:24 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 77 length 100663296
14:54:26 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 73
14:54:26 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 78 length 100663296
14:54:27 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 66
14:54:28 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 79 length 100663296
14:54:28 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 69
14:54:29 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 80 length 100663296
14:54:29 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 67
14:54:30 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 74
14:54:30 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 81 length 100663296
14:54:31 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 82 length 100663296
14:54:34 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 68
14:54:35 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 83 length 100663296
14:54:41 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 71
14:54:41 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 70
14:54:41 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 84 length 100663296
14:54:42 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 85 length 100663296
14:54:43 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 75
14:54:44 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 86 length 100663296
14:54:56 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 77
14:54:57 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 87 length 100663296
14:55:00 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 76
14:55:01 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 88 length 100663296
14:55:04 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 82
14:55:05 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 89 length 100663296
14:55:06 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 84
14:55:07 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 81
14:55:07 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 90 length 100663296
14:55:08 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 79
14:55:08 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 91 length 100663296
14:55:09 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 92 length 100663296
14:55:11 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 83
14:55:11 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 85
14:55:12 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 93 length 100663296
14:55:12 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 86
14:55:13 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 94 length 100663296
14:55:14 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 95 length 100663296
14:55:23 INFO : 9.373G / 11.217 GBytes, 84%, 26.675 MBytes/s, ETA 1m10s

14:55:24 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 78
14:55:25 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 96 length 100663296
14:55:30 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 80
14:55:31 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 97 length 100663296
14:55:34 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 87
14:55:35 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 98 length 100663296
14:55:39 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 88
14:55:40 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 99 length 100663296
14:55:44 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 89
14:55:44 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 100 length 100663296
14:55:47 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 92
14:55:48 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 101 length 100663296
14:55:52 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 96
14:55:53 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 102 length 100663296
14:55:53 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 93
14:55:54 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 95
14:55:54 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 103 length 100663296
14:55:55 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 91
14:55:55 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 104 length 100663296
14:55:56 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 90
14:55:56 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 105 length 100663296
14:55:57 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 106 length 100663296
14:55:59 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 98
14:56:00 DEBUG : chosenPath/10000mb.bin.1: Sending chunk 107 length 67108864
14:56:02 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 94
14:56:11 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 97
14:56:19 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 99
14:56:19 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 100
14:56:20 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 101
14:56:23 INFO : 10.863G / 11.217 GBytes, 97%, 26.497 MBytes/s, ETA 13s

14:56:25 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 103
14:56:27 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 107
14:56:27 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 105
14:56:27 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 104
14:56:31 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 102
14:56:39 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 106
14:57:23 INFO : 10.957G / 11.217 GBytes, 98%, 23.384 MBytes/s, ETA 11s

14:58:23 INFO : 10.960G / 11.217 GBytes, 98%, 20.791 MBytes/s, ETA 12s

14:59:23 INFO : 10.963G / 11.217 GBytes, 98%, 18.716 MBytes/s, ETA 13s

15:00:23 INFO : 10.966G / 11.217 GBytes, 98%, 17.019 MBytes/s, ETA 15s

15:01:23 INFO : 10.969G / 11.217 GBytes, 98%, 15.605 MBytes/s, ETA 16s

15:02:23 INFO : 10.972G / 11.217 GBytes, 98%, 14.408 MBytes/s, ETA 17s

15:03:23 INFO : 10.975G / 11.217 GBytes, 98%, 13.382 MBytes/s, ETA 18s

15:04:23 INFO : 10.978G / 11.217 GBytes, 98%, 12.493 MBytes/s, ETA 19s

15:05:23 INFO : 10.981G / 11.217 GBytes, 98%, 11.715 MBytes/s, ETA 20s

15:06:23 INFO : 10.984G / 11.217 GBytes, 98%, 11.029 MBytes/s, ETA 21s

15:07:23 INFO : 10.987G / 11.217 GBytes, 98%, 10.420 MBytes/s, ETA 22s

15:08:23 INFO : 10.990G / 11.217 GBytes, 98%, 9.874 MBytes/s, ETA 23s

15:09:23 INFO : 10.993G / 11.217 GBytes, 98%, 9.382 MBytes/s, ETA 24s

15:10:23 INFO : 10.996G / 11.217 GBytes, 98%, 8.938 MBytes/s, ETA 25s

15:11:23 INFO : 10.999G / 11.217 GBytes, 98%, 8.534 MBytes/s, ETA 26s

15:12:23 INFO : 11.002G / 11.217 GBytes, 98%, 8.165 MBytes/s, ETA 26s

15:13:23 INFO : 11.005G / 11.217 GBytes, 98%, 7.826 MBytes/s, ETA 27s

15:14:23 INFO : 11.008G / 11.217 GBytes, 98%, 7.516 MBytes/s, ETA 28s

15:15:23 INFO : 11.011G / 11.217 GBytes, 98%, 7.228 MBytes/s, ETA 29s

15:16:23 INFO : 11.014G / 11.217 GBytes, 98%, 6.963 MBytes/s, ETA 29s

15:17:23 INFO : 11.016G / 11.217 GBytes, 98%, 6.715 MBytes/s, ETA 30s

15:18:23 INFO : 11.020G / 11.217 GBytes, 98%, 6.486 MBytes/s, ETA 31s

15:19:23 INFO : 11.022G / 11.217 GBytes, 98%, 6.271 MBytes/s, ETA 31s

15:20:23 INFO : 11.025G / 11.217 GBytes, 98%, 6.071 MBytes/s, ETA 32s

15:21:23 INFO : 11.028G / 11.217 GBytes, 98%, 5.882 MBytes/s, ETA 32s

15:22:23 INFO : 11.031G / 11.217 GBytes, 98%, 5.706 MBytes/s, ETA 33s

15:23:23 INFO : 11.034G / 11.217 GBytes, 98%, 5.539 MBytes/s, ETA 33s

15:24:23 INFO : 11.037G / 11.217 GBytes, 98%, 5.382 MBytes/s, ETA 34s

15:25:23 INFO : 11.040G / 11.217 GBytes, 98%, 5.234 MBytes/s, ETA 34s

15:26:23 INFO : 11.043G / 11.217 GBytes, 98%, 5.094 MBytes/s, ETA 34s

15:27:23 INFO : 11.046G / 11.217 GBytes, 98%, 4.961 MBytes/s, ETA 35s

15:28:23 INFO : 11.049G / 11.217 GBytes, 99%, 4.836 MBytes/s, ETA 35s

15:29:23 INFO : 11.052G / 11.217 GBytes, 99%, 4.716 MBytes/s, ETA 35s

15:30:23 INFO : 11.055G / 11.217 GBytes, 99%, 4.602 MBytes/s, ETA 35s

15:31:23 INFO : 11.059G / 11.217 GBytes, 99%, 4.494 MBytes/s, ETA 36s

15:32:23 INFO : 11.062G / 11.217 GBytes, 99%, 4.391 MBytes/s, ETA 36s

15:33:23 INFO : 11.065G / 11.217 GBytes, 99%, 4.292 MBytes/s, ETA 36s

15:34:23 INFO : 11.068G / 11.217 GBytes, 99%, 4.198 MBytes/s, ETA 36s

15:35:23 INFO : 11.071G / 11.217 GBytes, 99%, 4.108 MBytes/s, ETA 36s

15:36:23 INFO : 11.074G / 11.217 GBytes, 99%, 4.021 MBytes/s, ETA 36s

15:37:23 INFO : 11.077G / 11.217 GBytes, 99%, 3.939 MBytes/s, ETA 36s

15:38:23 INFO : 11.079G / 11.217 GBytes, 99%, 3.859 MBytes/s, ETA 36s

15:39:23 INFO : 11.082G / 11.217 GBytes, 99%, 3.783 MBytes/s, ETA 36s

15:40:23 INFO : 11.085G / 11.217 GBytes, 99%, 3.710 MBytes/s, ETA 36s

15:41:23 INFO : 11.088G / 11.217 GBytes, 99%, 3.639 MBytes/s, ETA 36s

15:42:23 INFO : 11.091G / 11.217 GBytes, 99%, 3.572 MBytes/s, ETA 35s

15:43:23 INFO : 11.094G / 11.217 GBytes, 99%, 3.506 MBytes/s, ETA 35s

15:44:23 INFO : 11.097G / 11.217 GBytes, 99%, 3.444 MBytes/s, ETA 35s

15:45:23 INFO : 11.100G / 11.217 GBytes, 99%, 3.383 MBytes/s, ETA 35s

15:46:23 INFO : 11.103G / 11.217 GBytes, 99%, 3.324 MBytes/s, ETA 35s

15:47:23 INFO : 11.106G / 11.217 GBytes, 99%, 3.268 MBytes/s, ETA 34s

15:48:23 INFO : 11.109G / 11.217 GBytes, 99%, 3.214 MBytes/s, ETA 34s

15:49:23 INFO : 11.112G / 11.217 GBytes, 99%, 3.161 MBytes/s, ETA 33s

15:50:23 INFO : 11.115G / 11.217 GBytes, 99%, 3.110 MBytes/s, ETA 33s

15:51:23 INFO : 11.117G / 11.217 GBytes, 99%, 3.060 MBytes/s, ETA 33s

15:52:23 INFO : 11.120G / 11.217 GBytes, 99%, 3.013 MBytes/s, ETA 32s

15:53:23 INFO : 11.123G / 11.217 GBytes, 99%, 2.966 MBytes/s, ETA 32s

15:54:23 INFO : 11.126G / 11.217 GBytes, 99%, 2.922 MBytes/s, ETA 31s

15:55:23 INFO : 11.129G / 11.217 GBytes, 99%, 2.878 MBytes/s, ETA 31s

15:56:23 INFO : 11.132G / 11.217 GBytes, 99%, 2.836 MBytes/s, ETA 30s

15:57:23 INFO : 11.135G / 11.217 GBytes, 99%, 2.795 MBytes/s, ETA 29s

15:58:23 INFO : 11.138G / 11.217 GBytes, 99%, 2.755 MBytes/s, ETA 29s

15:59:23 INFO : 11.142G / 11.217 GBytes, 99%, 2.717 MBytes/s, ETA 28s

16:00:23 INFO : 11.145G / 11.217 GBytes, 99%, 2.679 MBytes/s, ETA 27s

16:01:23 INFO : 11.148G / 11.217 GBytes, 99%, 2.642 MBytes/s, ETA 26s

16:02:23 INFO : 11.151G / 11.217 GBytes, 99%, 2.607 MBytes/s, ETA 25s

16:03:23 INFO : 11.154G / 11.217 GBytes, 99%, 2.573 MBytes/s, ETA 25s

16:04:23 INFO : 11.156G / 11.217 GBytes, 99%, 2.539 MBytes/s, ETA 24s

16:05:23 INFO : 11.159G / 11.217 GBytes, 99%, 2.506 MBytes/s, ETA 23s

16:06:23 INFO : 11.163G / 11.217 GBytes, 100%, 2.474 MBytes/s, ETA 22s

16:07:23 INFO : 11.166G / 11.217 GBytes, 100%, 2.443 MBytes/s, ETA 21s

16:08:23 INFO : 11.168G / 11.217 GBytes, 100%, 2.413 MBytes/s, ETA 20s

16:09:23 INFO : 11.172G / 11.217 GBytes, 100%, 2.383 MBytes/s, ETA 19s

16:10:23 INFO : 11.174G / 11.217 GBytes, 100%, 2.355 MBytes/s, ETA 18s

16:11:23 INFO : 11.177G / 11.217 GBytes, 100%, 2.326 MBytes/s, ETA 17s

16:12:23 INFO : 11.180G / 11.217 GBytes, 100%, 2.299 MBytes/s, ETA 16s

16:13:23 INFO : 11.183G / 11.217 GBytes, 100%, 2.272 MBytes/s, ETA 15s

16:14:23 INFO : 11.187G / 11.217 GBytes, 100%, 2.246 MBytes/s, ETA 13s

16:15:23 INFO : 11.189G / 11.217 GBytes, 100%, 2.221 MBytes/s, ETA 12s

16:16:23 INFO : 11.192G / 11.217 GBytes, 100%, 2.196 MBytes/s, ETA 11s

16:17:23 INFO : 11.195G / 11.217 GBytes, 100%, 2.171 MBytes/s, ETA 10s

16:18:23 INFO : 11.198G / 11.217 GBytes, 100%, 2.147 MBytes/s, ETA 8s

16:19:23 INFO : 11.201G / 11.217 GBytes, 100%, 2.124 MBytes/s, ETA 7s

16:20:23 INFO : 11.204G / 11.217 GBytes, 100%, 2.101 MBytes/s, ETA 5s

16:21:23 INFO : 11.207G / 11.217 GBytes, 100%, 2.079 MBytes/s, ETA 4s

16:22:23 INFO : 11.210G / 11.217 GBytes, 100%, 2.057 MBytes/s, ETA 3s

16:23:23 INFO : 11.213G / 11.217 GBytes, 100%, 2.036 MBytes/s, ETA 1s

16:23:45 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 12
16:24:23 INFO : 11.215G / 11.217 GBytes, 100%, 2.015 MBytes/s, ETA 0s

16:24:51 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 1
16:25:23 INFO : 11.216G / 11.217 GBytes, 100%, 1.994 MBytes/s, ETA 0s

16:25:49 DEBUG : chosenPath/10000mb.bin.1: Done sending chunk 6
16:25:49 DEBUG : chosenPath/10000mb.bin.1: Finishing large file upload with 107 parts
16:25:52 DEBUG : chosenPath/10000mb.bin.1: SHA-1 = a0b6e2ca4e28360a929943e8eb966f703a69dc44 OK
16:25:52 INFO : chosenPath/10000mb.bin.1: Copied (new)
16:25:52 INFO : 11.217G / 11.217 GBytes, 100%, 1.984 MBytes/s, ETA 0s

16:25:52 DEBUG : 7 go routines active

As you can see, there were no errors, no retries, and still the drastic slow-down for the last few percent...

ncw · April 7, 2020, 9:11am

Some of those chunks take a really long time don't they...

What if you try reducing --transfers does that help?

I tried reproducing this on a datacenter server with a 10GB file of random data (from /dev/urandom)

I got a lot of "503 too busy" errors but the transfer completed without any significant pause at the end

b2-10gb.log (31.8 KB)

This could conceivably be some kind of shaping in your router or ISP?

ctonsing · April 7, 2020, 10:10am

Hi @ncw, thanks a lot for testing this on your end, much appreciated! It does seem to be particular to our network setup...

I haven't tried reducing --transfers, but will give that a go. At least the problem is pretty repeatable, so I'll try to get to the bottom of what could be causing this on our setup.

ncw · April 8, 2020, 4:57pm

It is odd! It looks like something is squeezing TCP transfers down to nothing. So I'd check router QoS. It could also be something as mundane as packet loss so it might be worth trying some traceroutes to b2.

ctonsing · April 15, 2020, 8:05am

Hi @ncw, yes, it does look as though that is probably the case. It does seem as if there is quite some packet loss on the network for some reason, the suspect for now is the edge router. But I haven't been able to physically access the network in order to change things around a bit for testing further due to the covid-19 lockdown... It is strange though that almost all the chunks are hardly affected by the packet loss except the one or two which are strangled down to almost nothing... I don't understand that.
But as always, thanks so much for your kind assistance and the wonderful tool you've created!

ncw · April 15, 2020, 12:20pm

A bit of packet loss in TCP streams can cause the estimation of the TCP throughput to go down to very little which I think is what is happening to you. Also packet loss in routers might not be random, for example I conjecture they might try to throw away complete TCP streams when their buffers are getting full to affect 1 stream rather than all of them.

system · June 15, 2020, 8:20am

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