B2 server side copy doesn't show cumulative progress

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.

1 Like

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...

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?

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.

Yes, when doing it with Wasabi, it definitely says

Copied (server side copy)

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

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

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"]

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).

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?

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

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!

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.

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.

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?

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?

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"]

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)

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?

The fix was to use the stats framework properly rather than attempting to bodge the stats in :wink:

I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.50

Thanks a lot Nick!

1 Like

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