B2 server side copy doesn't show cumulative progress

ctonsing · August 5, 2019, 1:22pm

What is the problem you are having with rclone?

When doing a server side copy on the B2 platform and using the flags "-vv --stats 1s --stats-one-line", I expect to get output similar to

22.988M / 186.061 MBytes, 12%, 2.671 MBytes/s, ETA 1m1s

where the progress percentage is the cumulative progress across all files to be transferred.

Instead, I am seeing output similar to

  X / X Bytes, 100%, 10 Bytes/s, ETA 0s

where the percentage is alway 100%, ETA is always 0s and X simply keeps increasing until all files have been transferred.

When doing a server side copy on the Wasabi platform, the stats show as expected, but only with B2 server side copy do they show up as explained above. Could this maybe be fixed?

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

v1.48.0

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

Ubuntu 64bit

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

B2 and Wasabi

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

rclone copy :b2:bucketName/folder1 :b2:bucketName/folder2 -vv --stats 1s --stats-one-line --fast-list --transfers 14

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

2019/08/05 14:43:54 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucketName/folder1" ":b2:bucketName/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "xxx" "--b2-key" "yyy"]
2019/08/05 14:43:54 DEBUG : Using config file from "path/to/rcloneconf/rclone.conf"
2019/08/05 14:43:58 INFO : B2 bucket bucketName path folder1/: Waiting for checks to finish
2019/08/05 14:43:58 INFO : B2 bucket bucketName path folder2/: Waiting for transfers to finish
2019/08/05 14:43:58 INFO : 0 / 0 Bytes, -, 0 Bytes/s, ETA -
2019/08/05 14:43:58 INFO : test/test1.txt: Copied (server side copy)
2019/08/05 14:43:59 INFO : 64 / 64 Bytes, 100%, 10 Bytes/s, ETA 0s
2019/08/05 14:44:00 INFO : 64 / 64 Bytes, 100%, 9 Bytes/s, ETA 0s
2019/08/05 14:44:01 INFO : 64 / 64 Bytes, 100%, 8 Bytes/s, ETA 0s
2019/08/05 14:44:02 INFO : test/test2.txt: Copied (server side copy)
2019/08/05 14:44:02 INFO : 53.149M / 53.149 MBytes, 100%, 5.933 MBytes/s, ETA 0s
2019/08/05 14:44:03 INFO : 53.149M / 53.149 MBytes, 100%, 5.337 MBytes/s, ETA 0s
2019/08/05 14:44:04 INFO : 53.149M / 53.149 MBytes, 100%, 4.850 MBytes/s, ETA 0s
2019/08/05 14:44:05 INFO : 53.149M / 53.149 MBytes, 100%, 4.445 MBytes/s, ETA 0s
2019/08/05 14:44:06 INFO : test/test3.txt: Copied (server side copy)
2019/08/05 14:44:06 INFO : 53.149M / 53.149 MBytes, 100%, 4.102 MBytes/s, ETA 0s
2019/08/05 14:44:07 INFO : test/test4.txt: Copied (server side copy)
2019/08/05 14:44:07 INFO : 121.876M / 121.876 MBytes, 100%, 8.732 MBytes/s, ETA 0s
2019/08/05 14:44:08 INFO : 121.876M / 121.876 MBytes, 100%, 8.148 MBytes/s, ETA 0s
2019/08/05 14:44:09 INFO : 121.876M / 121.876 MBytes, 100%, 7.637 MBytes/s, ETA 0s
2019/08/05 14:44:10 INFO : test/test5.txt: Copied (server side copy)
2019/08/05 14:44:10 INFO : 186.061M / 186.061 MBytes, 100%, 11.599 MBytes/s, ETA 0s
2019/08/05 14:44:10 DEBUG : 13 go routines active
2019/08/05 14:44:10 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucketName/folder1" ":b2:bucketName/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "xxx" "--b2-key" "yyy"]

thestigma · August 5, 2019, 1:29pm

I don't know if this is the only issue in your case, but try upping the --max-backlog limit (10000 by default I believe).

If this limit is passed then rclone stops checking ahead for more until some of the current one have finished. That's why your total seems to keep growing over time. Without being able to fit all files of the transfer into the backlog the time estimates will be useless.

Note that increasing the backlog size does take some more RAM, but it's on the order of a few dozen MB (linear N scaling according to documentation). I increased it by 10x for my current use and I could barely notice it on the resource manager. Still, if you have very low RAM or an insane amount of files, then be aware of this.

ctonsing · August 5, 2019, 1:35pm

Thanks for the hint @thestigma. I tried this but the problem is the same. The above-mentioned output occurs for only 5 files being server side copied...

thestigma · August 5, 2019, 1:41pm

Then I'm not sure. Very curious that it only happens on one backend - and that might indicate some limitation spesific to that backend. I have no personal experience with B2 unfortunately and can't verify the issue for you. Hopefully someone else can assist in that.

ncw · August 5, 2019, 6:05pm

For a server side copy, the data doesn't flow through rclone so rclone can't account for it byte by byte - it just says the whole lot is done when the copy completes.

Rclone computes the ETA based entirely on the transfer speed which isn't a good way of doing things with server side copies as there is no transfer!

Rclone could estimate overhead per copy and account for that - that would be a bit trickier but might work...

ctonsing · August 6, 2019, 6:37am

Thank you for the response @ncw. I see... But with server side copy on Wasabi, the progress shows as expected. Is this because the S3 protocol supports something which B2 doesn't?

ncw · August 6, 2019, 10:47am

Are you sure it is doing a server side copy? Does it say Copied (server side copy) in the log? I suspect that it is doing a normal download then upload copy.

ctonsing · August 6, 2019, 1:04pm

Yes, when doing it with Wasabi, it definitely says

Copied (server side copy)

in the log. I tried it again now to verify.

ncw · August 6, 2019, 1:48pm

Hmm, I'd expect the output to look very similar to this you posted. How does it look?

ctonsing:

Instead, I am seeing output similar to
  X / X Bytes, 100%, 10 Bytes/s, ETA 0s
where the percentage is alway 100%, ETA is always 0s and X simply keeps increasing until all files have been transferred.

ctonsing · August 6, 2019, 2:34pm

Ok, I ran some tests again on Wasabi. I must admit that the stats don't look quite the way I thought after my previous brief test, but still the output seems better than in the B2 case. It seems to aim to show the overall progress and keeps re-estimating, or maybe I'm misinterpreting something...

So here is the output for a Wasabi server side copy within the same bucket:

/path/to/rclone/bin/rclone copy :s3:bucket-name/folder1 :s3:bucket-name/folder2 --s3-access-key-id XXX --s3-secret-access-key YYY --s3-region eu-central-1 --s3-endpoint https://s3.eu-central-1.wasabisys.com --s3-provider Wasabi -vv --stats 1s --stats-one-line
2019/08/06 16:19:13 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]
2019/08/06 16:19:13 DEBUG : Using config file from "/path/to/rcloneconf/rclone.conf"
2019/08/06 16:19:14 INFO : S3 bucket bucket-name path folder2/: Waiting for checks to finish
2019/08/06 16:19:14 INFO : S3 bucket bucket-name path folder2/: Waiting for transfers to finish
2019/08/06 16:19:14 INFO : test1 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1.pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test2 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test2 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2.pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (3rd copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (4th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (5th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (6th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : 1.414G / 1.549 GBytes, 91%, 1010.244 MBytes/s, ETA 0s (xfr#24/32)
2019/08/06 16:19:15 INFO : test3 (7th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (8th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (another copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (9th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3.zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test1.txt: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2.txt: Copied (server side copy)
2019/08/06 16:19:15 INFO : 1.817G / 1.817 GBytes, 100%, 1.101 GBytes/s, ETA 0s
2019/08/06 16:19:15 DEBUG : 28 go routines active
2019/08/06 16:19:15 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]

And here is the output for a Wasabi server side copy between 2 different buckets:

/path/to/rclone/bin/rclone copy :s3:bucket-name/folder1 :s3:bucket-name2/folder2 --s3-access-key-id XXX --s3-secret-access-key YYY --s3-region eu-central-1 --s3-endpoint https://s3.eu-central-1.wasabisys.com --s3-provider Wasabi -vv --stats 1s --stats-one-line
2019/08/06 16:19:35 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name2/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]
2019/08/06 16:19:35 DEBUG : Using config file from "/path/to/rcloneconf/rclone.conf"
2019/08/06 16:19:36 INFO : S3 bucket bucket-name2 path folder2/: Waiting for checks to finish
2019/08/06 16:19:36 INFO : S3 bucket bucket-name2 path folder2/: Waiting for transfers to finish
2019/08/06 16:19:36 INFO : 0 / 1.661 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/06 16:19:37 INFO : 0 / 1.661 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/06 16:19:38 INFO : 0 / 1.661 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/06 16:19:39 INFO : S3 bucket bucket-name2 path folder2/: Bucket created with ACL "private"
2019/08/06 16:19:39 INFO : 0 / 1.661 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/06 16:19:40 INFO : test2.txt: Copied (server side copy)
2019/08/06 16:19:40 INFO : 64 / 1.609 GBytes, 0%, 10 Bytes/s, ETA 43948h5m23s (xfr#1/32)
2019/08/06 16:19:41 INFO : test1 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:41 INFO : test1 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:41 INFO : test1 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:41 INFO : 159.447M / 1.609 GBytes, 10%, 23.246 MBytes/s, ETA 1m4s (xfr#4/32)
2019/08/06 16:19:42 INFO : test1 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:42 INFO : 212.596M / 1.609 GBytes, 13%, 27.050 MBytes/s, ETA 53s (xfr#5/32)
2019/08/06 16:19:43 INFO : test1 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:43 INFO : test1 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:43 INFO : 318.894M / 1.609 GBytes, 19%, 35.994 MBytes/s, ETA 36s (xfr#7/32)
2019/08/06 16:19:44 INFO : test1 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:44 INFO : test1 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:44 INFO : test1.pdf: Copied (server side copy)
2019/08/06 16:19:44 INFO : test1 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:44 INFO : 531.490M / 1.566 GBytes, 33%, 53.907 MBytes/s, ETA 19s (xfr#11/32)
2019/08/06 16:19:45 INFO : test2 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:45 INFO : test2 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:45 INFO : test2 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:45 INFO : 724.046M / 1.566 GBytes, 45%, 66.673 MBytes/s, ETA 13s (xfr#14/32)
2019/08/06 16:19:45 INFO : test2 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:46 INFO : test2 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:46 INFO : test2 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:46 INFO : test2 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:46 INFO : 980.788M / 1.562 GBytes, 61%, 82.699 MBytes/s, ETA 7s (xfr#18/32)
2019/08/06 16:19:47 INFO : test2 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:47 INFO : 1.020G / 1.557 GBytes, 66%, 81.260 MBytes/s, ETA 6s (xfr#19/32)
2019/08/06 16:19:48 INFO : test2.pdf: Copied (server side copy)
2019/08/06 16:19:48 INFO : test2 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:48 INFO : test3 (3rd copy).zip: Copied (server side copy)
2019/08/06 16:19:48 INFO : test3 (4th copy).zip: Copied (server side copy)
2019/08/06 16:19:48 INFO : 1.280G / 1.549 GBytes, 83%, 94.576 MBytes/s, ETA 2s (xfr#23/32)
2019/08/06 16:19:49 INFO : test3 (6th copy).zip: Copied (server side copy)
2019/08/06 16:19:49 INFO : test3 (5th copy).zip: Copied (server side copy)
2019/08/06 16:19:49 INFO : test3 (7th copy).zip: Copied (server side copy)
2019/08/06 16:19:49 INFO : test3 (8th copy).zip: Copied (server side copy)
2019/08/06 16:19:49 INFO : 1.549G / 1.549 GBytes, 100%, 106.712 MBytes/s, ETA 0s (xfr#27/32)
2019/08/06 16:19:50 INFO : test3 (another copy).zip: Copied (server side copy)
2019/08/06 16:19:50 INFO : test3 (9th copy).zip: Copied (server side copy)
2019/08/06 16:19:50 INFO : test3 (copy).zip: Copied (server side copy)
2019/08/06 16:19:50 INFO : test1.txt: Copied (server side copy)
2019/08/06 16:19:50 INFO : test3.zip: Copied (server side copy)
2019/08/06 16:19:50 INFO : 1.817G / 1.817 GBytes, 100%, 118.544 MBytes/s, ETA 0s
2019/08/06 16:19:50 DEBUG : 15 go routines active
2019/08/06 16:19:50 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name2/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]

ncw · August 6, 2019, 9:39pm

I think what is happening here is that the b2 server side copies are happening much quicker than the wasabi ones.

storage	speed
b2	1.817G / 1.817 GBytes, 100%, 1.101 GBytes/s, ETA 0s
wasabi	1.817G / 1.817 GBytes, 100%, 118.544 MBytes/s, ETA 0s

So when b2 prints the first estimation 1.414G / 1.549 GBytes, 91%, 1010.244 MBytes/s, ETA 0s (xfr#24/32) there is already 0 seconds left, rounded to the nearest second.

So I think they are behaving the same (certainly there is no code which does anything other do the server side copy, then add the bytes copied).

ctonsing · August 7, 2019, 6:43am

Thank you for the reply! Just to clarify, those two log outputs are both from Wasabi, one doing a server side copy within a bucket (faster) and one doing a server side copy between 2 buckets (slower). The B2 log output I was comparing these with is the one given in my original post, which does look quite different. However, I did a test again with the exact same files, doing a server side copy within 1 bucket (since B2 can't copy between 2 buckets afaik), and here is the comparison:

Wasabi:

/path/to/rclone/bin/rclone copy :s3:bucket-name/folder1 :s3:bucket-name/folder2 --s3-access-key-id XXX --s3-secret-access-key YYY --s3-region eu-central-1 --s3-endpoint https://s3.eu-central-1.wasabisys.com --s3-provider Wasabi -vv --stats 1s --stats-one-line
2019/08/06 16:19:13 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]
2019/08/06 16:19:13 DEBUG : Using config file from "/path/to/rcloneconf/rclone.conf"
2019/08/06 16:19:14 INFO : S3 bucket bucket-name path folder2/: Waiting for checks to finish
2019/08/06 16:19:14 INFO : S3 bucket bucket-name path folder2/: Waiting for transfers to finish
2019/08/06 16:19:14 INFO : test1 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test1.pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test2 (3rd copy).pdf: Copied (server side copy)
2019/08/06 16:19:14 INFO : test2 (4th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (5th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (6th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (7th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (8th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (9th copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (another copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2 (copy).pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2.pdf: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (3rd copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (4th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (5th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (6th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : 1.414G / 1.549 GBytes, 91%, 1010.244 MBytes/s, ETA 0s (xfr#24/32)
2019/08/06 16:19:15 INFO : test3 (7th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (8th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (another copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (9th copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3 (copy).zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test3.zip: Copied (server side copy)
2019/08/06 16:19:15 INFO : test1.txt: Copied (server side copy)
2019/08/06 16:19:15 INFO : test2.txt: Copied (server side copy)
2019/08/06 16:19:15 INFO : 1.817G / 1.817 GBytes, 100%, 1.101 GBytes/s, ETA 0s
2019/08/06 16:19:15 DEBUG : 28 go routines active
2019/08/06 16:19:15 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":s3:bucket-name/folder1" ":s3:bucket-name/folder2" "--s3-access-key-id" "XXX" "--s3-secret-access-key" "YYY" "--s3-region" "eu-central-1" "--s3-endpoint" "https://s3.eu-central-1.wasabisys.com" "--s3-provider" "Wasabi" "-vv" "--stats" "1s" "--stats-one-line"]

B2:

/path/to/rclone/bin/rclone copy :b2:bucket-name-test/folder1 :b2:bucket-name-test/folder2 -vv --stats 1s --stats-one-line --fast-list --transfers 14 --b2-account XXX --b2-key YYY
2019/08/07 08:22:26 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucket-name-test/folder1" ":b2:bucket-name-test/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "XXX" "--b2-key" "YYY"]
2019/08/07 08:22:26 DEBUG : Using config file from "/path/to/rcloneconf/rclone.conf"
2019/08/07 08:22:31 INFO : B2 bucket bucket-name-test path folder2/: Waiting for checks to finish
2019/08/07 08:22:31 INFO : B2 bucket bucket-name-test path folder2/: Waiting for transfers to finish
2019/08/07 08:22:32 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:33 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:33 INFO : test1.txt: Copied (server side copy)
2019/08/07 08:22:34 INFO : 66 / 1.047 GBytes, 0%, 8 Bytes/s, ETA 36100h35m21s (xfr#1/32)
2019/08/07 08:22:34 INFO : test1 (3rd copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : 53.149M / 1.036 GBytes, 5%, 6.160 MBytes/s, ETA 2m43s (xfr#2/32)
2019/08/07 08:22:35 INFO : test1 (8th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test1 (another copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test1 (7th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test2 (5th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test2 (6th copy).pdf: Copied (server side copy)
2019/08/07 08:22:36 INFO : 340.967M / 1.004 GBytes, 33%, 35.414 MBytes/s, ETA 19s (xfr#7/32)
2019/08/07 08:22:36 INFO : test2 (3rd copy).pdf: Copied (server side copy)
2019/08/07 08:22:36 INFO : test1.pdf: Copied (server side copy)
2019/08/07 08:22:37 INFO : 458.301M / 1.052 GBytes, 43%, 43.122 MBytes/s, ETA 14s (xfr#9/32)
2019/08/07 08:22:38 INFO : 458.301M / 1.052 GBytes, 43%, 39.413 MBytes/s, ETA 15s (xfr#9/32)
2019/08/07 08:22:38 INFO : test2 (7th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test1 (4th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2 (4th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2 (9th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2.pdf: Copied (server side copy)
2019/08/07 08:22:39 INFO : 768.192M / 1.019 GBytes, 74%, 60.832 MBytes/s, ETA 4s (xfr#14/32)
2019/08/07 08:22:39 INFO : test2 (8th copy).pdf: Copied (server side copy)
2019/08/07 08:22:40 INFO : 832.377M / 1.014 GBytes, 80%, 61.078 MBytes/s, ETA 3s (xfr#15/32)
2019/08/07 08:22:40 INFO : test1 (6th copy).pdf: Copied (server side copy)
2019/08/07 08:22:41 INFO : 885.526M / 1022.980 MBytes, 87%, 60.536 MBytes/s, ETA 2s (xfr#16/32)
2019/08/07 08:22:41 INFO : test3 (4th copy).zip: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2 (another copy).pdf: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2.txt: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2 (copy).pdf: Copied (server side copy)
2019/08/07 08:22:42 INFO : 1.057G / 1.057 GBytes, 100%, 69.274 MBytes/s, ETA 0s
2019/08/07 08:22:42 INFO : test3 (8th copy).zip: Copied (server side copy)
2019/08/07 08:22:42 INFO : test1 (9th copy).pdf: Copied (server side copy)
2019/08/07 08:22:43 INFO : 1.176G / 1.176 GBytes, 100%, 72.438 MBytes/s, ETA 0s
2019/08/07 08:22:43 INFO : test3 (another copy).zip: Copied (server side copy)
2019/08/07 08:22:43 INFO : test3 (6th copy).zip: Copied (server side copy)
2019/08/07 08:22:43 INFO : test3 (9th copy).zip: Copied (server side copy)
2019/08/07 08:22:44 INFO : 1.378G / 1.378 GBytes, 100%, 80.025 MBytes/s, ETA 0s
2019/08/07 08:22:45 INFO : 1.378G / 1.378 GBytes, 100%, 75.729 MBytes/s, ETA 0s
2019/08/07 08:22:45 INFO : test3 (copy).zip: Copied (server side copy)
2019/08/07 08:22:45 INFO : test3 (3rd copy).zip: Copied (server side copy)
2019/08/07 08:22:45 INFO : test3 (5th copy).zip: Copied (server side copy)
2019/08/07 08:22:46 INFO : 1.579G / 1.579 GBytes, 100%, 82.375 MBytes/s, ETA 0s
2019/08/07 08:22:46 INFO : test3.zip: Copied (server side copy)
2019/08/07 08:22:47 INFO : 1.646G / 1.646 GBytes, 100%, 81.713 MBytes/s, ETA 0s
2019/08/07 08:22:48 INFO : 1.646G / 1.646 GBytes, 100%, 77.935 MBytes/s, ETA 0s
2019/08/07 08:22:49 INFO : 1.646G / 1.646 GBytes, 100%, 74.491 MBytes/s, ETA 0s
2019/08/07 08:22:49 INFO : test1 (5th copy).pdf: Copied (server side copy)
2019/08/07 08:22:50 INFO : 1.698G / 1.698 GBytes, 100%, 73.588 MBytes/s, ETA 0s
2019/08/07 08:22:51 INFO : 1.698G / 1.698 GBytes, 100%, 70.600 MBytes/s, ETA 0s
2019/08/07 08:22:51 INFO : test3 (7th copy).zip: Copied (server side copy)
2019/08/07 08:22:52 INFO : 1.765G / 1.765 GBytes, 100%, 70.527 MBytes/s, ETA 0s
2019/08/07 08:22:53 INFO : 1.765G / 1.765 GBytes, 100%, 67.878 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : 1.765G / 1.765 GBytes, 100%, 65.421 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : test1 (copy).pdf: Copied (server side copy)
2019/08/07 08:22:54 INFO : 1.817G / 1.817 GBytes, 100%, 66.032 MBytes/s, ETA 0s
2019/08/07 08:22:54 DEBUG : 7 go routines active
2019/08/07 08:22:54 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucket-name-test/folder1" ":b2:bucket-name-test/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "XXX" "--b2-key" "YYY"]

So B2 is the slower one but the stats do look quite similar. Apologies, I should have done the test with the same data to start with... For interest sake: how does rclone estimate the total data to be copied in this scenario?

ncw · August 8, 2019, 9:09am

No worries! Rclone has a queue of objects which need to be copied. This queue can have up to 10,000 objects in by default (see --max-backlog). Rclone adds up the size of these objects to work out the size that needs to be copied.

Relatively recently rclone started accounting for server side copies too, so adding the amount copied by a server side copy into the stats (before this rclone only measured bytes actually read from the source).

In this bit of code

github.com

rclone/rclone/blob/d0c65b4c5ee2615d35a8727d9a80536cfbe3d0ed/fs/operations/operations.go#L279-L294


		// Try server side copy first - if has optional interface and
		// is same underlying remote
		actionTaken = "Copied (server side copy)"
		if doCopy := f.Features().Copy; doCopy != nil && (SameConfig(src.Fs(), f) || (SameRemoteType(src.Fs(), f) && f.Features().ServerSideAcrossConfigs)) {
			// Check transfer limit for server side copies
			if fs.Config.MaxTransfer >= 0 && accounting.Stats(ctx).GetBytes() >= int64(fs.Config.MaxTransfer) {
				return nil, accounting.ErrorMaxTransferLimitReached
			}
			newDst, err = doCopy(ctx, src, remote)
			if err == nil {
				dst = newDst
				accounting.Stats(ctx).Bytes(dst.Size()) // account the bytes for the server side transfer
			}
		} else {
			err = fs.ErrorCantCopy
		}

You can see rclone doing the server side copies and accounting for their transfers after the copy is complete (line 290). You'll note there is no mechanism for updating the transfer as it continues, it is either all done or not done. However rclone will turn this chunk of data copied into an estimate MB/s of the transfer rate and use that for estimating the remaining time to transfer.

It probably isn't terribly accurate for server side copies!

ctonsing · August 28, 2019, 8:13am

Thank you for the detailed response @ncw. I can't say I understand exactly how this piece of code is working, so my comment may not make sense in this case, but if I think about this at a high level:

assume we're working with less than 10,000 objects to be server-side copied (with default --max-backlog setting)
we know up front which files need to be copied and each of their exact sizes on the server
we thus know the total size to be copied
if we server-side copy each file one-by-one, we can keep pretty accurate track of the speed at which the transfer is happening, as we know exactly how much data has been transferred in what amount of time
we also know exactly how much data there is to be transferred in total, thus can make a pretty accurate estimate of remaining time

As I said, this may not be how rclone is performing the server-side copy, but if it is, then I would think the stats would look somewhat different from what I posted above. E.g. the total size to be transferred would remain stable during the entire transfer.

ncw · August 28, 2019, 12:51pm

That is pretty nearly exactly what rclone does.

However rclone only knows when the server side transfer has finished so it either adds the size of the file to the transferred state or doesn't. It could estimate that the file is halfway transferred and add half the bytes to the transferred count. That would add more complexity to the accounting that I'm happy with though as it would mean altering every backend to do it.

ctonsing · August 28, 2019, 1:23pm

Sure, it makes sense that we can only update the stats after an entire file has been server-side copied. But why does the rclone output show a fluctuating total size to be transferred during the operation?
The progression as per my previous B2 test is as follows:

2019/08/07 08:22:32 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:33 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:34 INFO : 66 / 1.047 GBytes, 0%, 8 Bytes/s, ETA 36100h35m21s (xfr#1/32)
2019/08/07 08:22:35 INFO : 53.149M / 1.036 GBytes, 5%, 6.160 MBytes/s, ETA 2m43s (xfr#2/32)
2019/08/07 08:22:36 INFO : 340.967M / 1.004 GBytes, 33%, 35.414 MBytes/s, ETA 19s (xfr#7/32)
2019/08/07 08:22:37 INFO : 458.301M / 1.052 GBytes, 43%, 43.122 MBytes/s, ETA 14s (xfr#9/32)
2019/08/07 08:22:38 INFO : 458.301M / 1.052 GBytes, 43%, 39.413 MBytes/s, ETA 15s (xfr#9/32)
2019/08/07 08:22:39 INFO : 768.192M / 1.019 GBytes, 74%, 60.832 MBytes/s, ETA 4s (xfr#14/32)
2019/08/07 08:22:40 INFO : 832.377M / 1.014 GBytes, 80%, 61.078 MBytes/s, ETA 3s (xfr#15/32)
2019/08/07 08:22:41 INFO : 885.526M / 1022.980 MBytes, 87%, 60.536 MBytes/s, ETA 2s (xfr#16/32)
2019/08/07 08:22:42 INFO : 1.057G / 1.057 GBytes, 100%, 69.274 MBytes/s, ETA 0s
2019/08/07 08:22:43 INFO : 1.176G / 1.176 GBytes, 100%, 72.438 MBytes/s, ETA 0s
2019/08/07 08:22:44 INFO : 1.378G / 1.378 GBytes, 100%, 80.025 MBytes/s, ETA 0s
2019/08/07 08:22:45 INFO : 1.378G / 1.378 GBytes, 100%, 75.729 MBytes/s, ETA 0s
2019/08/07 08:22:46 INFO : 1.579G / 1.579 GBytes, 100%, 82.375 MBytes/s, ETA 0s
2019/08/07 08:22:47 INFO : 1.646G / 1.646 GBytes, 100%, 81.713 MBytes/s, ETA 0s
2019/08/07 08:22:48 INFO : 1.646G / 1.646 GBytes, 100%, 77.935 MBytes/s, ETA 0s
2019/08/07 08:22:49 INFO : 1.646G / 1.646 GBytes, 100%, 74.491 MBytes/s, ETA 0s
2019/08/07 08:22:50 INFO : 1.698G / 1.698 GBytes, 100%, 73.588 MBytes/s, ETA 0s
2019/08/07 08:22:51 INFO : 1.698G / 1.698 GBytes, 100%, 70.600 MBytes/s, ETA 0s
2019/08/07 08:22:52 INFO : 1.765G / 1.765 GBytes, 100%, 70.527 MBytes/s, ETA 0s
2019/08/07 08:22:53 INFO : 1.765G / 1.765 GBytes, 100%, 67.878 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : 1.765G / 1.765 GBytes, 100%, 65.421 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : 1.817G / 1.817 GBytes, 100%, 66.032 MBytes/s, ETA 0s

So I'm just wondering why the total size to be transferred doesn't remain the same at 1.817 GBytes?

ncw · August 28, 2019, 1:29pm

Rclone starts copying as soon as it has stuff to copy, so it might be that the scan of the source filesystem hasn't finished. What do the longer stats say?

ctonsing · August 28, 2019, 1:37pm

Understood. With longer stats, do you mean the entire rclone output for the test?

/path/to/rclone/bin/rclone copy :b2:bucket-name-test/folder1 :b2:bucket-name-test/folder2 -vv --stats 1s --stats-one-line --fast-list --transfers 14 --b2-account XXX --b2-key YYY
2019/08/07 08:22:26 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucket-name-test/folder1" ":b2:bucket-name-test/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "XXX" "--b2-key" "YYY"]
2019/08/07 08:22:26 DEBUG : Using config file from "/path/to/rcloneconf/rclone.conf"
2019/08/07 08:22:31 INFO : B2 bucket bucket-name-test path folder2/: Waiting for checks to finish
2019/08/07 08:22:31 INFO : B2 bucket bucket-name-test path folder2/: Waiting for transfers to finish
2019/08/07 08:22:32 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:33 INFO : 0 / 1.110 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/32)
2019/08/07 08:22:33 INFO : test1.txt: Copied (server side copy)
2019/08/07 08:22:34 INFO : 66 / 1.047 GBytes, 0%, 8 Bytes/s, ETA 36100h35m21s (xfr#1/32)
2019/08/07 08:22:34 INFO : test1 (3rd copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : 53.149M / 1.036 GBytes, 5%, 6.160 MBytes/s, ETA 2m43s (xfr#2/32)
2019/08/07 08:22:35 INFO : test1 (8th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test1 (another copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test1 (7th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test2 (5th copy).pdf: Copied (server side copy)
2019/08/07 08:22:35 INFO : test2 (6th copy).pdf: Copied (server side copy)
2019/08/07 08:22:36 INFO : 340.967M / 1.004 GBytes, 33%, 35.414 MBytes/s, ETA 19s (xfr#7/32)
2019/08/07 08:22:36 INFO : test2 (3rd copy).pdf: Copied (server side copy)
2019/08/07 08:22:36 INFO : test1.pdf: Copied (server side copy)
2019/08/07 08:22:37 INFO : 458.301M / 1.052 GBytes, 43%, 43.122 MBytes/s, ETA 14s (xfr#9/32)
2019/08/07 08:22:38 INFO : 458.301M / 1.052 GBytes, 43%, 39.413 MBytes/s, ETA 15s (xfr#9/32)
2019/08/07 08:22:38 INFO : test2 (7th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test1 (4th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2 (4th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2 (9th copy).pdf: Copied (server side copy)
2019/08/07 08:22:38 INFO : test2.pdf: Copied (server side copy)
2019/08/07 08:22:39 INFO : 768.192M / 1.019 GBytes, 74%, 60.832 MBytes/s, ETA 4s (xfr#14/32)
2019/08/07 08:22:39 INFO : test2 (8th copy).pdf: Copied (server side copy)
2019/08/07 08:22:40 INFO : 832.377M / 1.014 GBytes, 80%, 61.078 MBytes/s, ETA 3s (xfr#15/32)
2019/08/07 08:22:40 INFO : test1 (6th copy).pdf: Copied (server side copy)
2019/08/07 08:22:41 INFO : 885.526M / 1022.980 MBytes, 87%, 60.536 MBytes/s, ETA 2s (xfr#16/32)
2019/08/07 08:22:41 INFO : test3 (4th copy).zip: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2 (another copy).pdf: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2.txt: Copied (server side copy)
2019/08/07 08:22:41 INFO : test2 (copy).pdf: Copied (server side copy)
2019/08/07 08:22:42 INFO : 1.057G / 1.057 GBytes, 100%, 69.274 MBytes/s, ETA 0s
2019/08/07 08:22:42 INFO : test3 (8th copy).zip: Copied (server side copy)
2019/08/07 08:22:42 INFO : test1 (9th copy).pdf: Copied (server side copy)
2019/08/07 08:22:43 INFO : 1.176G / 1.176 GBytes, 100%, 72.438 MBytes/s, ETA 0s
2019/08/07 08:22:43 INFO : test3 (another copy).zip: Copied (server side copy)
2019/08/07 08:22:43 INFO : test3 (6th copy).zip: Copied (server side copy)
2019/08/07 08:22:43 INFO : test3 (9th copy).zip: Copied (server side copy)
2019/08/07 08:22:44 INFO : 1.378G / 1.378 GBytes, 100%, 80.025 MBytes/s, ETA 0s
2019/08/07 08:22:45 INFO : 1.378G / 1.378 GBytes, 100%, 75.729 MBytes/s, ETA 0s
2019/08/07 08:22:45 INFO : test3 (copy).zip: Copied (server side copy)
2019/08/07 08:22:45 INFO : test3 (3rd copy).zip: Copied (server side copy)
2019/08/07 08:22:45 INFO : test3 (5th copy).zip: Copied (server side copy)
2019/08/07 08:22:46 INFO : 1.579G / 1.579 GBytes, 100%, 82.375 MBytes/s, ETA 0s
2019/08/07 08:22:46 INFO : test3.zip: Copied (server side copy)
2019/08/07 08:22:47 INFO : 1.646G / 1.646 GBytes, 100%, 81.713 MBytes/s, ETA 0s
2019/08/07 08:22:48 INFO : 1.646G / 1.646 GBytes, 100%, 77.935 MBytes/s, ETA 0s
2019/08/07 08:22:49 INFO : 1.646G / 1.646 GBytes, 100%, 74.491 MBytes/s, ETA 0s
2019/08/07 08:22:49 INFO : test1 (5th copy).pdf: Copied (server side copy)
2019/08/07 08:22:50 INFO : 1.698G / 1.698 GBytes, 100%, 73.588 MBytes/s, ETA 0s
2019/08/07 08:22:51 INFO : 1.698G / 1.698 GBytes, 100%, 70.600 MBytes/s, ETA 0s
2019/08/07 08:22:51 INFO : test3 (7th copy).zip: Copied (server side copy)
2019/08/07 08:22:52 INFO : 1.765G / 1.765 GBytes, 100%, 70.527 MBytes/s, ETA 0s
2019/08/07 08:22:53 INFO : 1.765G / 1.765 GBytes, 100%, 67.878 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : 1.765G / 1.765 GBytes, 100%, 65.421 MBytes/s, ETA 0s
2019/08/07 08:22:54 INFO : test1 (copy).pdf: Copied (server side copy)
2019/08/07 08:22:54 INFO : 1.817G / 1.817 GBytes, 100%, 66.032 MBytes/s, ETA 0s
2019/08/07 08:22:54 DEBUG : 7 go routines active
2019/08/07 08:22:54 DEBUG : rclone: Version "v1.48.0" finishing with parameters ["/path/to/rclone/bin/rclone" "copy" ":b2:bucket-name-test/folder1" ":b2:bucket-name-test/folder2" "-vv" "--stats" "1s" "--stats-one-line" "--fast-list" "--transfers" "14" "--b2-account" "XXX" "--b2-key" "YYY"]

ncw · August 28, 2019, 4:37pm

Sorry I meant without the --stats-one-line flag however the full log answers my question too...

I can see that there are only a few files from the log so the scanning is unlikely to be a problem...

I managed to replicate this myself... there is definitely something weird going on!

Try this beta

https://beta.rclone.org/branch/v1.49.0-006-g7560f92b-fix-server-side-accounting-beta/ (uploaded in 15-30 mins)

ctonsing · August 29, 2019, 8:35am

Thank you @ncw, I tried that beta version and it looks good. Doing the same test with the same files results in the total size to be copied remaining constant throughout the transfer! For interest's sake, what was the fix?