Rclone default log is not ideal if your objective is to understand what was done by Rclone, since all the files are processed in a pretty random order.
Is disabling multithreading with --checkers 1 and --transfers 1 the only way to get more readable logs?
Sounds like that would have a major performance impact.
PS
Ordered = files are grouped by folder, at least.
Good idea. Most accurate with --check-first and will work without changing transfers or checkers. The log won't be perfectly ordered as the transfers will start in order but may not finish in order (when the log is written).
In Windows, I usually output the command to a log file, load it into Notepad++ and let it order the lines with Edit > Line Operations > Sort Lines Lexicographically Ascending. It's immediate and it can handle big files with no issues.
Thanks!
"--check-first --order-by=name,asc" seems like the best option for now. I have not tried to use " --order-by=name,asc" without "--check-first", should I?
This is great for one log. However, I usually have multiple logs output to a single file (so I can scroll up to see previous operations without having to open up many files). So it might work well enough for a single big operation, but not many small ones.
Probably not as it is for ordering which files get processed first, but there is no way to order the subsequent move / deletes which happen as part of a transfer.
My problem is that if I delete, move, or rename a folder with many files, rclone sync takes days, sometimes weeks, to finish the move to backup dir in Dropbox.
In the log, all the moves to backup dir are randomly ordered, and there is no indication of how many are left. So I have no idea when it will finally finish or even where we are in the process.
The only way to get a vague idea of how many are left is to login to the Dropbox web interface and check the size of the folders that were moved/deleted/renamed. They slowly go to 0.
PS
Why is the move to backup dir (server-side move) so slow with Dropbox? Am I doing something wrong? It does 32k files a day, that means 0.3 files a second. (the command I am running is on my previous topic)
The rclone stats should also be giving you an idea? If you use -v you'll gets stats printed in the log every 1 minute by default (change with --stats) which will give you an idea of the overall progress.
That does sound slow. Rclone should be doing --checkers of these in parallel.
I suggest you examine the log for clues. A debug log with -vv is recommended.
Maybe the suffix adding is also adding to the slowness?
I'm seeing a lot of too_many_write_operations.
I don't know why. I'm using --tpslimit 12 --tpslimit-burst 0 and every rclone instance has its own Dropbox App ID. I even tried to make sure that no other rclone operation was running, same result.
The -vv log is a lot of this:
2023/05/11 16:44:33 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft/WoWScrnShot_010711_013914.jpg: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft/WoWScrnShot_010711_013914 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:33 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft/WoWScrnShot_010711_013914.jpg: Moved into backup dir
2023/05/11 16:44:36 DEBUG : pacer: Reducing sleep to 843.75ms
2023/05/11 16:44:36 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Dungeon (Northrend) - Ahn'kahet The Old Kingdom/WoWScrnShot_091709_172322.jpg: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Dungeon (Northrend) - Ahn'kahet The Old Kingdom/WoWScrnShot_091709_172322 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:36 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Dungeon (Northrend) - Ahn'kahet The Old Kingdom/WoWScrnShot_091709_172322.jpg: Moved into backup dir
2023/05/11 16:44:37 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/..)
2023/05/11 16:44:37 DEBUG : pacer: Rate limited, increasing sleep to 1.6875s
2023/05/11 16:44:37 DEBUG : pacer: Reducing sleep to 1.265625s
2023/05/11 16:44:37 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Bioshock Infinite/2013-03-26_00125.jpg: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Bioshock Infinite/2013-03-26_00125 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:37 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Bioshock Infinite/2013-03-26_00125.jpg: Moved into backup dir
2023/05/11 16:44:37 DEBUG : pacer: Reducing sleep to 949.21875ms
2023/05/11 16:44:40 DEBUG : pacer: Reducing sleep to 711.914062ms
2023/05/11 16:44:40 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Kalimdor - Winterspring/WoWScrnShot_060710_191447.jpg: Moved (server-side) to: - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Kalimdor - Winterspring/WoWScrnShot_060710_191447 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:40 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Kalimdor - Winterspring/WoWScrnShot_060710_191447.jpg: Moved into backup dir
2023/05/11 16:44:40 DEBUG : pacer: Reducing sleep to 533.935546ms
2023/05/11 16:44:40 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100710091926113.jpg: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100710091926113 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:40 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100710091926113.jpg: Moved into backup dir
2023/05/11 16:44:42 DEBUG : pacer: Reducing sleep to 400.451659ms
2023/05/11 16:44:42 DEBUG : pacer: Reducing sleep to 300.338744ms
2023/05/11 16:44:42 DEBUG : pacer: Reducing sleep to 225.254058ms
2023/05/11 16:44:42 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Eastern Kingdoms - Eversong Woods/WoWScrnShot_060310_225836.jpg: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Eastern Kingdoms - Eversong Woods/WoWScrnShot_060310_225836 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:44:42 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/World of Warcraft SAVE AZEROTH/Eastern Kingdoms - Eversong Woods/WoWScrnShot_060310_225836.jpg: Moved into backup dir
2023/05/11 16:44:43 DEBUG : pacer: Reducing sleep to 168.940543ms
2023/05/11 16:44:43 DEBUG : pacer: Reducing sleep to 126.705407ms
2023/05/11 16:44:43 DEBUG : pacer: Reducing sleep to 95.029055ms
2023/05/11 16:44:43 DEBUG : pacer: Reducing sleep to 71.271791ms
2023/05/11 16:44:43 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Assassin's Creed Odyssey/Assassin's Creed Odyssey Screenshot 2020.03.19 - 15.19.45.73.png: Moved (server-side) to: - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Assassin's Creed Odyssey/Assassin's Creed Odyssey Screenshot 2020.03.19 - 15.19.45.73 -saved 2023-05-11 15.09.07.png
2023/05/11 16:44:43 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Assassin's Creed Odyssey/Assassin's Creed Odyssey Screenshot 2020.03.19 - 15.19.45.73.png: Moved into backup dir
2023/05/11 16:44:44 DEBUG : pacer: Reducing sleep to 53.453843ms
2023/05/11 16:44:44 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/...)
2023/05/11 16:44:44 DEBUG : pacer: Rate limited, increasing sleep to 106.907686ms
2023/05/11 16:44:44 DEBUG : pacer: Reducing sleep to 80.180764ms
2023/05/11 16:44:45 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/.)
2023/05/11 16:44:45 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/)
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 160.361528ms
2023/05/11 16:44:45 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/...)
2023/05/11 16:44:45 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/)
2023/05/11 16:44:45 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/...)
2023/05/11 16:44:45 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/...)
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 320.723056ms
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 641.446112ms
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 1.282892224s
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 2s
2023/05/11 16:44:45 DEBUG : pacer: Reducing sleep to 1.5s
2023/05/11 16:44:45 INFO : - 10 - Dropbox/censoredfile1.pdf: Moved (server-side) to: - 10 - Dropbox/censoredfile1 -saved 2023-05-11 15.09.07.pdf
2023/05/11 16:44:45 INFO : - 10 - Dropbox/censoredfile1.pdf: Moved into backup dir
2023/05/11 16:44:45 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/...)
2023/05/11 16:44:45 DEBUG : pacer: Rate limited, increasing sleep to 2s
2023/05/11 16:44:46 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/...)
2023/05/11 16:44:46 DEBUG : pacer: Reducing sleep to 1.5s
2023/05/11 16:44:46 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/App Docs/Playgrounds/Learn to Code 1.playgroundbook/Contents/Modules/Document5_Challenge2.playgroundmodule/Sources/Commands.swift: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/App Docs/Playgrounds/Learn to Code 1.playgroundbook/Contents/Modules/Document5_Challenge2.playgroundmodule/Sources/Commands -saved 2023-05-11 15.09.07.swift
2023/05/11 16:44:46 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/App Docs/Playgrounds/Learn to Code 1.playgroundbook/Contents/Modules/Document5_Challenge2.playgroundmodule/Sources/Commands.swift: Moved into backup dir
2023/05/11 16:44:49 DEBUG : pacer: Reducing sleep to 1.125s
2023/05/11 16:44:49 INFO : - 10 - Dropbox/censoredfile2.pdf: Moved (server-side) to: - 10 - Dropbox/censoredfile2 -saved 2023-05-11 15.09.07.pdf
2023/05/11 16:44:49 INFO : - 10 - Dropbox/censoredfile2.pdf: Moved into backup dir
2023/05/11 16:44:49 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/.)
2023/05/11 16:44:49 DEBUG : pacer: Rate limited, increasing sleep to 2s
2023/05/11 16:44:51 DEBUG : pacer: Reducing sleep to 1.5s
2023/05/11 16:44:51 INFO : - 10 - Dropbox/- 10 - Libraries/Images/- 2 - List/Worth a Buy Channel youtube-dl Backup 2018-01-22/Worth A Buy - 324 - 20160316 - Stardew Valley Review - Worthabuy - 1920x1080 60.mp4: Moved (server-side) to: - 10 - Dropbox/- 10 - Libraries/Images/- 2 - List/Worth a Buy Channel youtube-dl Backup 2018-01-22/Worth A Buy - 324 - 20160316 - Stardew Valley Review - Worthabuy - 1920x1080 60 -saved 2023-05-11 15.09.07.mp4
2023/05/11 16:44:51 INFO : - 10 - Dropbox/- 10 - Libraries/Images/- 2 - List/Worth a Buy Channel youtube-dl Backup 2018-01-22/Worth A Buy - 324 - 20160316 - Stardew Valley Review - Worthabuy - 1920x1080 60.mp4: Moved into backup dir
2023/05/11 16:44:53 DEBUG : pacer: Reducing sleep to 1.125s
2023/05/11 16:44:54 DEBUG : pacer: Reducing sleep to 843.75ms
2023/05/11 16:44:54 INFO : - 10 - Dropbox/- 10 - Libraries/Movies Screenshots/- 3 - Unsorted/Star.Trek.Discovery.S03E03.People.of.Earth.1080p.mkv_003515.625.png: Moved (server-side) to: - 10 - Dropbox/- 10 - Libraries/Movies Screenshots/- 3 - Unsorted/Star.Trek.Discovery.S03E03.People.of.Earth.1080p.mkv_003515.625 -saved 2023-05-11 15.09.07.png
2023/05/11 16:44:54 INFO : - 10 - Dropbox/- 10 - Libraries/Movies Screenshots/- 3 - Unsorted/Star.Trek.Discovery.S03E03.People.of.Earth.1080p.mkv_003515.625.png: Moved into backup dir
2023/05/11 16:44:56 DEBUG : pacer: low level retry 3/10 (error too_many_write_operations/..)
2023/05/11 16:44:56 DEBUG : pacer: Rate limited, increasing sleep to 1.6875s
2023/05/11 16:44:56 DEBUG : pacer: Reducing sleep to 1.265625s
2023/05/11 16:44:57 DEBUG : pacer: Reducing sleep to 949.21875ms
2023/05/11 16:44:57 INFO : - 10 - Dropbox/All Dupes Probably/Libraries (shared folder conflict)/App Docs/Playgrounds/Learn to Code 2.playgroundbook/Contents/Chapters/Document13.playgroundchapter/Pages/08.playgroundpage/PrivateResources/tr.lproj/Hints.plist: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/Libraries (shared folder conflict)/App Docs/Playgrounds/Learn to Code 2.playgroundbook/Contents/Chapters/Document13.playgroundchapter/Pages/08.playgroundpage/PrivateResources/tr.lproj/Hints -saved 2023-05-11 15.09.07.plist
2023/05/11 16:44:57 INFO : - 10 - Dropbox/All Dupes Probably/Libraries (shared folder conflict)/App Docs/Playgrounds/Learn to Code 2.playgroundbook/Contents/Chapters/Document13.playgroundchapter/Pages/08.playgroundpage/PrivateResources/tr.lproj/Hints.plist: Moved into backup dir
2023/05/11 16:44:58 DEBUG : pacer: Reducing sleep to 711.914062ms
2023/05/11 16:45:00 DEBUG : pacer: Reducing sleep to 533.935546ms
2023/05/11 16:45:01 DEBUG : pacer: Reducing sleep to 400.451659ms
2023/05/11 16:45:02 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/..)
2023/05/11 16:45:02 DEBUG : pacer: Rate limited, increasing sleep to 800.903318ms
2023/05/11 16:45:02 DEBUG : pacer: Reducing sleep to 600.677488ms
2023/05/11 16:45:02 INFO : - 10 - Dropbox/censoredName1/My Mac (wheatley-4.home)/Movies/SDR.fcpbundle/2022-02-06 Kittten/Render Files/Thumbnail Media/E6215C25945ACFB68E41B16364C10910/Frame 107520 - 108543: Moved (server-side) to: - 10 - Dropbox/censoredName1/My Mac (wheatley-4.home)/Movies/SDR.fcpbundle/2022-02-06 Kittten/Render Files/Thumbnail Media/E6215C25945ACFB68E41B16364C10910/Frame 107520 - 108543 -saved 2023-05-11 15.09.07
2023/05/11 16:45:02 INFO : - 10 - Dropbox/censoredName1/My Mac (wheatley-4.home)/Movies/SDR.fcpbundle/2022-02-06 Kittten/Render Files/Thumbnail Media/E6215C25945ACFB68E41B16364C10910/Frame 107520 - 108543: Moved into backup dir
2023/05/11 16:45:03 DEBUG : pacer: Reducing sleep to 450.508116ms
2023/05/11 16:45:03 DEBUG : pacer: Reducing sleep to 337.881087ms
2023/05/11 16:45:03 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100427095521193.jpg: Moved (server-side) to: - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100427095521193 -saved 2023-05-11 15.09.07.jpg
2023/05/11 16:45:03 INFO : - 10 - Dropbox/- 10 - Libraries/Ives Screenshots/- 2 - List/Dragon Age - N5/Screenshot20100427095521193.jpg: Moved into backup dir
2023/05/11 16:45:05 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/)
2023/05/11 16:45:05 DEBUG : pacer: Rate limited, increasing sleep to 675.762174ms
2023/05/11 16:45:05 DEBUG : pacer: Reducing sleep to 506.82163ms
2023/05/11 16:45:05 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age Origins/Dragon Age - Audio/Alistair/Main/30359_m.wav.mp3: Moved (server-side) to: - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age Origins/Dragon Age - Audio/Alistair/Main/30359_m.wav -saved 2023-05-11 15.09.07.mp3
2023/05/11 16:45:05 INFO : - 10 - Dropbox/All Dupes Probably/- 10 - Libraries (view-only conflicts 2022-07-19)/Ives Screenshots/- 2 - List/Dragon Age Origins/Dragon Age - Audio/Alistair/Main/30359_m.wav.mp3: Moved into backup dir
2023/05/11 16:45:05 DEBUG : pacer: Reducing sleep to 380.116222ms
2023/05/11 16:45:05 DEBUG : pacer: Reducing sleep to 285.087166ms
Sorry, I did have to censor some file names. (Which took a while, is there a fast way to do it?)
That looks like it is the problem. You can see in your log that rclone is spending a lot of time sleeping as it has been told to slow down by dropbox, eg "Rate limited, increasing sleep to 800.903318ms"
Are you running multiple rclone instances from the same IP? It might be that it is being rate limited per source IP address rather than per App ID.
It looks like your transfer is finished except for the renames. I guess rclone expects server side moves to be quick.
Sometimes I have multiple rclone instances running. However, I have not noticed the speed of the server-side move to backup dir to change when other instances are running, compared to when it's the only one.
I have checked with no other operation running, the too_many_write_operations errors are still there, and the sleeping times seem the same.
Also, when both operations are running, I'm not seeing errors or sleeping on the -vv log of the other operation. The other operation is on another machine (macOS), but same IP, uploading a lot of small files from local to Dropbox (same account, different App ID). Only the one doing server-side moves is being limited.
⠀
⠀
PS
Sorry, this topic was about an ordered log, and it changed to this problem of the slow moving to backup dir. Though they are related, since an ordered log for the move to backup dir would at least give me an indication of progress. A slow process with no ETA ior % ior count of completed/left vs total is... not great.
It looks like Dropbox hates server side moves more than uploads so you'll have to choose a lower --tpslimit I think. Try halving it and see if you can get the too_many_write_operations errors to disappear.
The operation finally finished, after something like a week and a half (they were something like 400k files).
Next time I delete many files, I'll try to lower the tpslimit and see if it's faster.
Thank you for looking into this, have a nice Sunday.