Long wait between Creating backend and starting to upload

Jacob_Briggs · March 24, 2021, 8:25pm

Hi All

What is the problem you are having with rclone?

I'm attempting to upload 50,000 odd files to backblaze, and there is a large delay between the start of the upload and the actual upload. A 3 hour delay and an upload that takes 11 minutes.

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

rclone: Version "v1.53.2"

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

Ubuntu 18.04.1 LTS, 64 bit

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

Backblaze (b2)

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

rclone -vv copy /root/Documents/MapBox/export/newcastle__c_/json/NC_456 sunspot:sunspot1/json/newcastle__c_/NC_456 --transfers 150 --ignore-existing --no-traverse --log-file=/root/logs/sunspot1/json/newcastle__c_/NC_456.log

The rclone config contents with secrets removed.

[sunspot]
type = b2
account = <removed secret>
key = <removed secret>
hard_delete = true
versions = false

A log from the command with the `-vv` flag

https://drive.google.com/file/d/1zw1sHHzoMbzmQJlygCSeLVtj0Gv5oJg3/view?usp=sharing

Here is a redacted for length version showing the highlights.

2021/03/24 16:22:52 DEBUG : rclone: Version "v1.53.2" starting with parameters ["rclone" "-vv" "copy" "/root/Documents/MapBox/export/newcastle__c_/json/NC_456" "sunspot:sunspot1/json/newcastle__c_/NC_456" "--transfers" "150" "--ignore-existing" "--no-traverse" "--log-file=/root/logs/sunspot1/json/newcastle__c_/NC_456.log"]
2021/03/24 16:22:52 DEBUG : Creating backend with remote "/root/Documents/MapBox/export/newcastle__c_/json/NC_456"
2021/03/24 16:22:52 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/03/24 16:22:52 DEBUG : Creating backend with remote "sunspot:sunspot1/json/newcastle__c_/NC_456"
2021/03/24 16:23:54 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       1m2.1s

2021/03/24 16:24:54 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       2m2.1s
...
...
2021/03/24 19:25:54 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:     3h3m2.1s

2021/03/24 19:26:54 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:     3h4m2.1s

2021/03/24 19:27:35 DEBUG : NC_456_1.json: SHA-1 = 0709f52c30990952676b60ca5625901c89cdb41e OK
2021/03/24 19:27:35 INFO  : NC_456_1.json: Copied (new)
2021/03/24 19:27:35 DEBUG : NC_456_10001.json: SHA-1 = 5bc0e74c23663337ce2d29b3c2824ade495fcb8e OK
2021/03/24 19:27:35 INFO  : NC_456_10001.json: Copied (new)
...
...
2021/03/24 19:27:54 DEBUG : NC_456_1177.json: SHA-1 = 8ef03f3f3e24280c44c46b14b59575687d10127e OK
2021/03/24 19:27:54 INFO  : NC_456_1177.json: Copied (new)
2021/03/24 19:27:54 INFO  :
Transferred:        1.293M / 7.795 MBytes, 17%, 25.238 kBytes/s, ETA 4m23s
Transferred:         1946 / 12097, 16%
Elapsed time:     3h5m2.1s
Transferring:
 *                             NC_456_10814.json:100% /675, 56/s, 0s
 *                             NC_456_10865.json:100% /676, 61/s, 0s
...
...
*                             NC_456_11883.json:  0% /677, 0/s, -
 *                             NC_456_11884.json:  0% /677, 0/s, -

2021/03/24 19:27:54 DEBUG : NC_456_11780.json: SHA-1 = 97437e26460b11b23318a8b1aac4a57833b47755 OK
2021/03/24 19:27:54 INFO  : NC_456_11780.json: Copied (new)
...
...
2021/03/24 19:36:39 DEBUG : NC_456_9941.json: SHA-1 = a913011d191d4a24c03bb27d2d6ee83d2a4d8136 OK
2021/03/24 19:36:39 INFO  : NC_456_9941.json: Copied (new)
2021/03/24 19:36:39 DEBUG : NC_456_9906.json: SHA-1 = 89f753fabed68fba4225d31386bec0b04fa2c061 OK
2021/03/24 19:36:39 INFO  : NC_456_9906.json: Copied (new)
2021/03/24 19:36:39 INFO  :
Transferred:       33.467M / 33.467 MBytes, 100%, 59.383 kBytes/s, ETA 0s
Transferred:        51927 / 51927, 100%
Elapsed time:   3h13m46.7s

2021/03/24 19:36:39 DEBUG : 305 go routines active

asdffdsa · March 24, 2021, 8:43pm

hello and welcome to the forum,

not able to read that log, requires me to login to google?
a lot of rcloners use https://pastebin.com/

to get a better idea what is going on, perhaps copy a single file

also consider updating to latest stable, v1.54.1

Jacob_Briggs · March 24, 2021, 8:44pm

Sorry about that, I changed the sharing options so it should be viewable now

https://drive.google.com/file/d/1zw1sHHzoMbzmQJlygCSeLVtj0Gv5oJg3/view?usp=sharing

asdffdsa · March 24, 2021, 8:51pm

are you sure you need these flags, perhaps, as a test, copy a single file without them
--ignore-existing --no-traverse`

Animosity022 · March 24, 2021, 9:00pm

Takes a bit because you are overloading your local IO with 150 transfers.

Try defaults first and see how things go.

Jacob_Briggs · March 24, 2021, 9:56pm

I have in the past tried a handful of files to b2 and its fast.

Jacob_Briggs · March 24, 2021, 10:02pm

Right, I'll try this.

The issue is that I have 500 directories each with 50,000 files in them. I am shelling out from ruby, which kicks off 8 processes at once to upload 8 of these directories - 1 each. I wonder if that means the 150 transfers is actually 150 * 8 transfers since there are 8 processes at once.

I can't really stop the process, nor change it, and its going to take days to finish before I can make a change and rerun it.

I might see about grabbing a copy of one of those directories and doing it by hand locally, to see if I can't recreate the issue.

Jacob_Briggs · March 24, 2021, 11:06pm

Here we are with just one file:

root@9fc6693c0a52:~/Documents# rclone -vv copy NC_217-test  sunspot:sunspot5/testb2 --ignore-existing --no-traverse
2021/03/24 22:56:45 DEBUG : rclone: Version "v1.53.2" starting with parameters ["rclone" "-vv" "copy" "NC_217-test" "sunspot:sunspot5/testb2" "--ignore-existing" "--no-traverse"]
2021/03/24 22:56:45 DEBUG : Creating backend with remote "NC_217-test"
2021/03/24 22:56:45 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/03/24 22:56:45 DEBUG : fs cache: renaming cache item "NC_217-test" to be canonical "/root/Documents/NC_217-test"
2021/03/24 22:56:45 DEBUG : Creating backend with remote "sunspot:sunspot5/testb2"
2021/03/24 22:56:47 DEBUG : B2 bucket sunspot5 path testb2: Waiting for checks to finish
2021/03/24 22:56:47 DEBUG : B2 bucket sunspot5 path testb2: Waiting for transfers to finish
2021/03/24 22:56:48 DEBUG : NC_217_2794.json: SHA-1 = e63cdfbd85c5babcdc652594106ce1c77b317d19 OK
2021/03/24 22:56:48 INFO  : NC_217_2794.json: Copied (new)
2021/03/24 22:56:48 INFO  : 
Transferred:   	       675 / 675 Bytes, 100%, 569 Bytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:         3.5s

2021/03/24 22:56:48 DEBUG : 8 go routines active
root@9fc6693c0a52:~/Documents#

and with 168624 files:

root@9fc6693c0a52:~/Documents# ls -1 NC_217 | wc -l
168624
root@9fc6693c0a52:~/Documents# rclone -vv copy NC_217 sunspot:sunspot5/testb2 --ignore-existing --no-traverse
2021/03/24 22:59:35 DEBUG : rclone: Version "v1.53.2" starting with parameters ["rclone" "-vv" "copy" "NC_217" "sunspot:sunspot5/testb2" "--ignore-existing" "--no-traverse"]
2021/03/24 22:59:35 DEBUG : Creating backend with remote "NC_217"
2021/03/24 22:59:35 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/03/24 22:59:35 DEBUG : fs cache: renaming cache item "NC_217" to be canonical "/root/Documents/NC_217"
2021/03/24 22:59:35 DEBUG : Creating backend with remote "sunspot:sunspot5/testb2"
2021/03/24 23:00:37 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Elapsed time:       1m2.0s

well, I presume its gonna do the same thing and take for ages.

BUT when I get rid of no-traverse

root@9fc6693c0a52:~/Documents# rclone -vv copy NC_217 sunspot:sunspot5/testb2 --ignore-existing
2021/03/24 23:03:58 DEBUG : rclone: Version "v1.53.2" starting with parameters ["rclone" "-vv" "copy" "NC_217" "sunspot:sunspot5/testb2" "--ignore-existing"]
2021/03/24 23:03:58 DEBUG : Creating backend with remote "NC_217"
2021/03/24 23:03:58 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/03/24 23:03:58 DEBUG : fs cache: renaming cache item "NC_217" to be canonical "/root/Documents/NC_217"
2021/03/24 23:03:58 DEBUG : Creating backend with remote "sunspot:sunspot5/testb2"
2021/03/24 23:04:21 DEBUG : NC_217_100043.json: SHA-1 = b2754fcba41c6224e18c2d0c26bf17058409ee62 OK
2021/03/24 23:04:21 INFO  : NC_217_100043.json: Copied (new)
2021/03/24 23:04:22 DEBUG : NC_217_100045.json: SHA-1 = 00e516a957bb814fba8d8d1a499c1a34bc903e70 OK
2021/03/24 23:04:22 INFO  : NC_217_100045.json: Copied (new)
2021/03/24 23:04:22 DEBUG : NC_217_100048.json: SHA-1 = 5aacfde1d4ea5f296be9512a2e873509bf14168b OK
2021/03/24 23:04:22 INFO  : NC_217_100048.json: Copied (new)
2021/03/24 23:04:22 DEBUG : NC_217_100046.json: SHA-1 = f34e2d6a77ee7d02b7da3eda6748481bb1089957 OK
2021/03/24 23:04:22 INFO  : NC_217_100046.json: Copied (new)
2021/03/24 23:04:22 DEBUG : NC_217_100044.json: SHA-1 = c2eae72c5450e4ad0d1b8d510b36b9c4a8820811 OK

No real wait, 30 seconds....

asdffdsa · March 24, 2021, 11:09pm

yes, that is better.

i found the less flags the better, using the defaults as much as possible.
really, the only way to learn rclone is testing out different sets of flags and compare the outcomes.

Jacob_Briggs · March 25, 2021, 12:33am

Thanks for the help!

system · May 24, 2021, 8:33pm

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