OneDrive sync checking very slow

Help and Support
1

What is the problem you are having with rclone?

When running sync, file checking takes a very long time in v1.68.2 as compared to v1.65.0.

Run the command 'rclone version' and share the full output of the command.

rclone v1.68.2

  • os/version: Microsoft Windows 10 Pro 22H2 (64 bit)
  • os/kernel: 10.0.19045.5131 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.23.3
  • go/linking: static
  • go/tags: cmount

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

OneDrive

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

start cmd.exe /k C:\rclone\rclone.exe sync D:\Backup_Duplicati OneDrive:Backup_PC --progress

Please run 'rclone config redacted' and share the full output. If you get command not found, please make sure to update rclone.

[OneDrive]
type = onedrive
token = XXX
drive_id = XXX
drive_type = personal

A log from the command that you were trying to run with the -vv flag

Transferred:              0 B / 0 B, -, 0 B/s, ETA -
Checks:               354 / 6956, 5%
Elapsed time:        30.8s
Checking:
 * UserFiles/duplicati-b0…e0cbf51.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…6b9b936.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…bfa04f3.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…b01beb5.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…5b44584.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…28bd5a3.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…be6fca8.dblock.zip.aes: checking
 * UserFiles/duplicati-b0…84daaf0.dblock.zip.aes: checking

More info:

I've been using this sync for probably about a year without any issues until a few days ago I started getting an error. I was using v1.65.0. This is the error (which I'm including in case it's of any relevance):

2024/11/19 17:02:21 DEBUG : test123/123.txt: Need to transfer - File not found at Destination
2024/11/19 17:02:21 DEBUG : test123/123.txt: Starting multipart upload
2024/11/19 17:02:22 DEBUG : test123/123.txt: Uploading segment 0/13 size 13
2024/11/19 17:02:22 DEBUG : test123/123.txt: Cancelling multipart upload: unauthenticated: Unauthenticated
2024/11/19 17:02:23 NOTICE: test123/123.txt: Failed to cancel multipart upload: unauthenticated: Unauthenticated (upload failed due to: unauthenticated: Unauthenticated)
2024/11/19 17:02:23 ERROR : test123/123.txt: Failed to copy: unauthenticated: Unauthenticated
2024/11/19 17:03:13 DEBUG : OneDrive root 'Backup_PC': Waiting for transfers to finish
2024/11/19 17:03:13 ERROR : OneDrive root 'Backup_PC': not deleting files as there were IO errors
2024/11/19 17:03:13 ERROR : OneDrive root 'Backup_PC': not deleting directories as there were IO errors
2024/11/19 17:04:02 DEBUG : OneDrive root 'Backup_PC': Waiting for transfers to finish
2024/11/19 17:04:02 ERROR : OneDrive root 'Backup_PC': not deleting files as there were IO errors
2024/11/19 17:04:02 ERROR : OneDrive root 'Backup_PC': not deleting directories as there were IO errors

After this error happened I updated to v1.68.2 and that resolved the issue, but now the file checking is insanely slow. There are four folders I am syncing and the total number of files is about 16k. They range anywhere from 1kb to 50mb. They are compressed Duplicati backup files.

Three sections up in my above post where it shows "Checks 354/6956 , 5%" -- in v1.65.0 this never used to count up slowly from 0 to 6956, it always just showed 6956/6956 instantly. But now in v1.68.2 it seems to check each file slowly and what used to take maybe 2-3 minutes now takes about 2 hours.

Is there something that changed in the recent versions? How do I regain the quick checking speed from 1.65.0? If I revert back to v1.65.0, file checking is quick, but of course I get that authentication error.

2

Can't say much without a debug log attached of rclone while stuck doing checks. If I had to guess, you are being throttled by OneDrive with so many checks back to back. I would try using your own client id and maybe limit the tps until you are not getting rate limited. Microsoft is very sensitive and random on their throttling, so it really depends on what works for you.

If you need further help troubleshooting please provide a debug log of the sync in action and what it shows when it all gets stuck in checking.

3

welcome to the forum,

https://rclone.org/onedrive/#fast-list
have you tried that?

are you sure you need sync, every thing you run rclone?

not sure exactly how duplicati deals with backups files. i use veeam, 7zip and some other tools.
to prevent rclone from having to list all the dest files every time, i use something like
rclone copy --no-traverse --max-age=1d

1 Like
4

My apologies, log file here:

(I noticed a lot of time-related errors, but I had re-synced the system time before running sync a few times)

I have not, will give it a shot, thanks.

Yes all files need to sync, due to the way Duplicati works. I don't remember the technical term but basically one file on my computer would be spread out over multiple compressed and encrypted Duplicati backup files. So any/all changes do need to be checked. The backup gets done locally and then I rclone the backup files from local drive to OneDrive. It's about 390 GB total but any day it's really only ever updating around 10mb to 250mb.

5

ok, but still might want to use --max-age, as that reduces the number of total checks.

1 Like
6

Alrighty:
-fast-list helped a wee bit, but not a lot
--max-age can't use this due to backup schedule, if any file is missed it would corrupt other parts of the backup
--onedrive-delta --checkers 20 from this thread helped, but also not by a lot
client id via this method is depreciated as per Microsoft (need Enterprise or Azure subscription) :frowning:

So for kicks and giggles I installed v1.65.1 and boom, no authentication error and checking is quick again -- sync completed in 59 seconds (versus 2 hrs with v1.68.2) without any errors. Weird? I'm not sure I would call this 'solved' but definitely a band aid until this pops up again :slight_smile:

7

Could you run your sync with --dry-run and see how long it takes? It will tell us whether problem is with checking what to transfer or rather with uploads/updates sync phase. Maybe metadata unnecessary updates cause this issue (which won't happen when using dry run)?

1 Like
8

Because for every file which does not require transferring we can see the following sequence:

2024/11/20 06:45:39 DEBUG : GameData/duplicati-b2c500ac0359a47cb9ac4aeceb82d26d7.dblock.zip.aes: quickxor = 66ade83984c26192c9a2f6c2db6074f650d6bbe5 OK
2024/11/20 06:45:40 INFO  : GameData/duplicati-b2c500ac0359a47cb9ac4aeceb82d26d7.dblock.zip.aes: Updated modification time in destination
2024/11/20 06:45:40 DEBUG : GameData/duplicati-b2c500ac0359a47cb9ac4aeceb82d26d7.dblock.zip.aes: Unchanged skipping

I have to admit I am not sure why rclone does "Updated modification time in destination"

There were few issues recently caused by mod times (e.g. this one) and maybe this is one more.

Try also to run sync with --modify-window 1s flag.

1 Like
9

That's really interesting, would you be able to share a debug log from 1.65.1 to check the difference? I wonder if there's something about mod times as @kapitainsky noticed that is slowing it down. If 1.65.1 does not have it we might have a clue.

1 Like
10

tl;dr, this should be a one-time issue, let rclone do its thing, as explained below.
tho, as mentioned, a workaround is --modify-window 1s

this is do to rclone having to calculate the hash for each local file.
a consequence of changes onedrive made to the handling of modtimes.

 ./rclone_v1.65.1 backend features onedrive: | grep "Precision"
        "Precision": 1000000000,
./rclone_v1.68.2 backend features onedrive: | grep "Precision"
        "Precision": 1000000,

rclone uses Precision, in nanoseconds, as value for --modify-window

let's use a real file from the debug log you posted,

# check modtimes, notice modtimes do not match
DEBUG : GameData/duplicati-20240211T092112Z.dlist.zip.aes: Modification times differ by -681.7093ms: 2024-02-11 02:21:18.6817093 -0700 MST, 2024-02-11 09:21:18 +0000 UTC
# check hash of the files
DEBUG : GameData/duplicati-20240211T092112Z.dlist.zip.aes: quickxor = 00eddfe3594014a059648cdb10be041f71b4e5b9 OK
# update the modtime
INFO  : GameData/duplicati-20240211T092112Z.dlist.zip.aes: Updated modification time in destination
# double check the files are equivalent
DEBUG : GameData/duplicati-20240211T092112Z.dlist.zip.aes: Unchanged skipping

681ms is 681000000ns

* v1.65.1 - 681000000ns is less    than 	1000000000ns
* v1.68.2 - 681000000ns is greater than 	1000000ns

in both versions, the modtime has changed, the files are not identical. should rclone re-copy the file or not?

* v1.65.1 - rclone considers the files are equivalent, rclone does nothing.
* v1.68.2 - rclone considers the files not equivalent, rclone has to do something.

so, let's do something
rclone is cloud based, can be expensive to re-copy a file, uses internet bandwidth, api calls, unnecessary new version of files, etc..

  • the dumb way, re-upload the file.
  • the smart way, notice the file sizes are identical. then compare the hashes.
    if the hashes match, then no need to slow, expensive re-upload the file, just quick, cheap change of modtime.

the downside to being smart is rclone has to calculate the hash of each local file.
that takes time and slow down the entire sync command.
but hopefully, this is a one-time painful upgrade from an old version of rclone to the new version of rclone.

3 Likes
11

You mean that after updating mod times it should not happen when running sync second time? It would be not bad. Let's see if OP can test it.

1 Like
12

yes, that is what i mean
after rclone checks the hash and updates the modtime, it does another check and outputs Unchanged skipping
so next time rclone is run, rclone will check and consider the files unchanged and skip it.

the OP can rclone copy a single file, then run that same command again.
then post the full debug output of each command.

1 Like
13

Ah yes, --modify-window 1s gave me very quick checking in v1.68.2, same speed as v1.65.1.

However even before creating this thread, I did try multiple syncs and it never got faster after the first completed sync, it was 2 hrs every time. So -- I ran two more syncs and have included logs for that because why not.

Logs below, tested (in v.1.68.2) in this order :

--modify-window 1s
Completed in 48.4s :slight_smile:

--dry-run
Completed in 1h49m8.0s

Sync, first time (No additional arguments)
Completed in 1h55m18.1s

Sync, second time (No additional arguments)
Completed in 2h1m3.1s

Copy 1 file, first time (No additional arguments)

Copy 1 file, second time (No additional arguments)

14

ok, good that you ran that test.

Modification times differ by -887.7254ms: 2024-11-22 12:22:57.8877254 -0700 MST, 2024-11-22 19:22:57 +0000 UTC
i think your onedrive account is returning a precision of 1s, whereas rclone is using 1ms.

so, for now, need to --modify-window 1s, but not in the next version.
in the upcoming v1.69.0 rclone will revert back to the behavior as v1.65.0

for all the dirty details, can check out this github issue
I've decided to revert the precision back to 1s

well, maybe, going forward, that should be:
"but hopefully, this is a one-time painfree upgrade from an old version of rclone to the new version of rclone"

1 Like
15

So all ends well:) v1.69 should be out soon.

1 Like
16

"What a Long Strange Trip It's Been"

2 Likes
17

Thanks guys, much appreciated for your help.

18

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