Long time before start uploading data

scat · April 4, 2018, 6:59pm

Hi all,

I am a new user of rclone, but there is one thing I dont understand :
When I test an upload of one big file of 2GB (on S3, CEPH RadosGW), the transfer begin only after 22s.
Here the output of my transfer :
rclone copy “C:\Users\siic\Desktop\Nouveau dossier\2G.bin” S3-CLOUD:backup/ --stats=2s -vv
2018/04/04 20:44:44 DEBUG : rclone: Version “v1.40-040-gef58b6a5-s3-chunk-size” starting with parameters [“rclone” “copy” “C:\Users\siic\Desktop\Nouveau dossier\2G.bin” “S3-CLOUD:backup/” “–stats=2s” “-vv”]
2018/04/04 20:44:44 DEBUG : Using config file from “C:\Users\siic\.config\rclone\rclone.conf”
2018/04/04 20:44:44 INFO : S3 bucket backup: Modify window is 100ns
2018/04/04 20:44:44 INFO : S3 bucket backup: Waiting for checks to finish
2018/04/04 20:44:44 INFO : S3 bucket backup: Waiting for transfers to finish
2018/04/04 20:44:46 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 2s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:48 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 4s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:50 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 6s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:52 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 8s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:54 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 10s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:56 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 12s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:44:58 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 14s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:45:00 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 16s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:45:02 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 18s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:45:04 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 20s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:45:06 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 22s
Transferring:

                                   2G.bin:  0% /2G, 0/s, -

2018/04/04 20:45:08 INFO :
Transferred: 55 MBytes (2.286 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 24s
Transferring:

                                   2G.bin:  2% /2G, 35.001M/s, 56s

2018/04/04 20:45:10 INFO :
Transferred: 115 MBytes (4.412 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 26s
Transferring:

                                   2G.bin:  5% /2G, 34.375M/s, 56s

2018/04/04 20:45:12 INFO :
Transferred: 175 MBytes (6.236 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 28s
Transferring:

                                   2G.bin:  8% /2G, 33.181M/s, 56s

2018/04/04 20:45:14 INFO :
Transferred: 235 MBytes (7.817 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 30s
Transferring:

                                   2G.bin: 11% /2G, 32.983M/s, 54s

2018/04/04 20:45:16 INFO :
Transferred: 295 MBytes (9.201 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 32s
Transferring:

                                   2G.bin: 14% /2G, 33.032M/s, 53s

2018/04/04 20:45:18 INFO :
Transferred: 345 MBytes (10.128 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 34s
Transferring:

                                   2G.bin: 16% /2G, 32.008M/s, 53s

2018/04/04 20:45:20 INFO :
Transferred: 415 MBytes (11.508 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 36s
Transferring:

                                   2G.bin: 20% /2G, 31.758M/s, 51s

2018/04/04 20:45:22 INFO :
Transferred: 475 MBytes (12.479 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 38s
Transferring:

                                   2G.bin: 23% /2G, 31.539M/s, 49s

2018/04/04 20:45:24 INFO :
Transferred: 530 MBytes (13.229 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 40s
Transferring:

                                   2G.bin: 25% /2G, 31.324M/s, 48s

2018/04/04 20:45:26 INFO :
Transferred: 600 MBytes (14.264 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 42s
Transferring:

                                   2G.bin: 29% /2G, 31.463M/s, 46s

2018/04/04 20:45:28 INFO :
Transferred: 655 MBytes (14.865 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 44s
Transferring:

                                   2G.bin: 31% /2G, 30.956M/s, 44s

2018/04/04 20:45:30 INFO :
Transferred: 715 MBytes (15.522 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 46s
Transferring:

                                   2G.bin: 34% /2G, 30.838M/s, 43s

2018/04/04 20:45:32 INFO :
Transferred: 780 MBytes (16.228 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 48s
Transferring:

                                   2G.bin: 38% /2G, 31.358M/s, 40s

2018/04/04 20:45:34 INFO :
Transferred: 845 MBytes (16.879 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 50s
Transferring:

                                   2G.bin: 41% /2G, 31.510M/s, 38s

2018/04/04 20:45:36 INFO :
Transferred: 905 MBytes (17.378 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 52s
Transferring:

                                   2G.bin: 44% /2G, 31.320M/s, 36s

2018/04/04 20:45:38 INFO :
Transferred: 970 MBytes (17.938 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 54s
Transferring:

                                   2G.bin: 47% /2G, 31.177M/s, 34s

2018/04/04 20:45:40 INFO :
Transferred: 1020 MBytes (18.194 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 56s
Transferring:

                                   2G.bin: 49% /2G, 31.007M/s, 33s

2018/04/04 20:45:42 INFO :
Transferred: 1.060 GBytes (18.686 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 58s
Transferring:

                                   2G.bin: 52% /2G, 30.883M/s, 31s

2018/04/04 20:45:44 INFO :
Transferred: 1.123 GBytes (19.146 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m0s
Transferring:

                                   2G.bin: 56% /2G, 30.772M/s, 29s

2018/04/04 20:45:46 INFO :
Transferred: 1.182 GBytes (19.496 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m2s
Transferring:

                                   2G.bin: 59% /2G, 31.299M/s, 26s

2018/04/04 20:45:48 INFO :
Transferred: 1.240 GBytes (19.824 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m4s
Transferring:

                                   2G.bin: 62% /2G, 31.139M/s, 24s

2018/04/04 20:45:50 INFO :
Transferred: 1.304 GBytes (20.208 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m6s
Transferring:

                                   2G.bin: 65% /2G, 30.801M/s, 23s

2018/04/04 20:45:52 INFO :
Transferred: 1.367 GBytes (20.569 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m8s
Transferring:

                                   2G.bin: 68% /2G, 30.883M/s, 20s

2018/04/04 20:45:54 INFO :
Transferred: 1.426 GBytes (20.838 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m10s
Transferring:

                                   2G.bin: 71% /2G, 30.773M/s, 19s

2018/04/04 20:45:56 INFO :
Transferred: 1.484 GBytes (21.093 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m12s
Transferring:

                                   2G.bin: 74% /2G, 30.676M/s, 17s

2018/04/04 20:45:58 INFO :
Transferred: 1.543 GBytes (21.333 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m14s
Transferring:

                                   2G.bin: 77% /2G, 30.916M/s, 15s

2018/04/04 20:46:00 INFO :
Transferred: 1.611 GBytes (21.692 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m16s
Transferring:

                                   2G.bin: 80% /2G, 31.101M/s, 12s

2018/04/04 20:46:02 INFO :
Transferred: 1.670 GBytes (21.905 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m18s
Transferring:

                                   2G.bin: 83% /2G, 30.965M/s, 10s

2018/04/04 20:46:04 INFO :
Transferred: 1.729 GBytes (22.107 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m20s
Transferring:

                                   2G.bin: 86% /2G, 31.467M/s, 8s

2018/04/04 20:46:06 INFO :
Transferred: 1.782 GBytes (22.239 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m22s
Transferring:

                                   2G.bin: 89% /2G, 30.962M/s, 7s

2018/04/04 20:46:08 INFO :
Transferred: 1.846 GBytes (22.483 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m24s
Transferring:

                                   2G.bin: 92% /2G, 30.842M/s, 5s

2018/04/04 20:46:10 INFO :
Transferred: 1.909 GBytes (22.716 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m26s
Transferring:

                                   2G.bin: 95% /2G, 31.061M/s, 2s

2018/04/04 20:46:12 INFO :
Transferred: 1.973 GBytes (22.938 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m28s
Transferring:

                                   2G.bin: 98% /2G, 30.930M/s, 0s

2018/04/04 20:46:14 INFO :
Transferred: 2 GBytes (22.740 MBytes/s)
Errors: 0
Checks: 0
Transferred: 0
Elapsed time: 1m30s
Transferring:

                                   2G.bin: 100% /2G, 30.651M/s, 0s

2018/04/04 20:46:14 INFO : 2G.bin: Copied (new)
2018/04/04 20:46:14 INFO :
Transferred: 2 GBytes (22.723 MBytes/s)
Errors: 0
Checks: 0
Transferred: 1
Elapsed time: 1m30.1s

2018/04/04 20:46:14 DEBUG : 6 go routines active
2018/04/04 20:46:14 DEBUG : rclone: Version “v1.40-040-gef58b6a5-s3-chunk-size” finishing with parameters [“rclone” “copy” “C:\Users\siic\Desktop\Nouveau dossier\2G.bin” “S3-CLOUD:backup/” “–stats=2s” “-vv”]

What does rclone do before the upload ?
Is there a way to start the upload immediately ?

I tested --ignore-checksum --ignore-existing --ignore-size --ignore-times --buffer-size=1024M --s3-chunk-size=500M … but every time, the upload begin after 22s.

Thanks,

Sébastien

ncw · April 5, 2018, 9:32am

rclone will be creating an MD5 checksum for the file.

This has to be done before the file is uploaded so it can be put as metadata on the file.

If you just have a single file to upload you can do this

rclone rcat S3-CLOUD:backup/2G.bin < "C:\Users\siic\Desktop\Nouveau dossier\2G.bin"

which will avoid making the checksum. Note that since rclone didn’t make the checksum, it can’t check it on transfer…

scat · April 5, 2018, 10:53am

Thanks for your light !
I think it will be a good thing to have an option like “–s3-disable-checksum” on S3 tranfer to let the users make this choice or not.
Some others softs offer this possibility, it’s very interresting to have the bests performances and transfers are reliables without this checksum (thanks to TCP).
To my point of view, the control of the checksum is not essential and should be a choice because of the impact on transfer time.

scat · April 5, 2018, 11:40am

May be there is an other way to speed up the transfer of big file and keep the checksum : https://www.savjee.be/2015/10/Verifying-Amazon-S3-multi-part-uploads-with-ETag-hash/

Amazon does not calculate the checksum of the entire file but combine the checksum off all part. Perhaps the md5 could localy be calculate in the same way : on one chunck, upload this chunk, compare md5 for this part then start again with others chunks(or parallelize all the upload part and md5 operations ).

Anyway, it will be interresting to have the choice of disable this checksum.

ncw · April 5, 2018, 1:50pm

If you’d like to see that, then please make a new issue on github and even better contribute a patch! I’d be happy to talk you through adding that feature.

We thought about using that in rclone but there are several problems with it. Firstly it isn’t documented by amazon so subject to change and secondly it depends on the size of the parts that got uploaded which you can’t discover after you’ve uploaded something.

scat · April 5, 2018, 3:27pm

Thanks, this subject is also discuss here : https://stackoverflow.com/questions/12186993/what-is-the-algorithm-to-compute-the-amazon-s3-etag-for-a-file-larger-than-5gb