I’m currently running Duplicati - 126.96.36.199_canary_2018-04-13, have been avoiding the latest Canary due to people reporting speed issues.
I’ve just noticed that one of my daily backups is taking a very long time today. On further investigation, I’m getting lots of messages like this:
10 May 2018 15:12: Checking file for changes /var/spool/music/tagged/FLAC/P/Pink Floyd/The Dark Side of the Moon/Pink Floyd - The Dark Side of the Moon (CD 2).flac, new: False, timestamp changed: True, size changed: False, metadatachanged: True, 29/07/2015 08:29:39 vs 29/07/2015 08:29:39
This seems to be saying the timestamp of a file has changed, but the timestamps it’s listing are the same.
It’s now moved onto another backup job, and it seems to be doing the same thing with that one.
I have recently updated my linux kernel and mono, could it be related to that do you think?
The good news is that now it’s re-run the daily job (that yesterday took over a day instead of about 30 minutes) it’s zipped through it again at about the normal rate.
Looks like something has happened recently (perhaps in the mono update?) that has caused it to look like a load of files have changed, forcing Duplicati to actually read the files instead of just ignoring them.
Sorry for the delayed response - but I’m glad to hear you solved your issue with…patience!
I suspect you are correct that either the kernel or mono update changed something in how times were recorded or reported (perhaps a type change more for accuracy or higher values) and Duplicati could see the difference but the logged value didn’t show it.
Like saying 1 and 00001 are not the same number or a timestamp of 08:29:39.0 not being the same as 08:29:39.001 but because the display rounds up to the second you can’t see the difference.
Either way, you’re right - once the new dates (whatever was different about them) were recorded Duplicati could go back to just using timestamps instead of full file scans.
I went ahead and flagged your post as the solution - please let me know if you disagree.
It’s been a bit of a pain because it’s taking a long time for some of the larger jobs, due to it having to inspect a lot more files than it should have. Will keep an eye on it, but I think it’s probably something to do with the mono update.
I experience this especially after a recreate of a db. Timestamp in logs are the same, but are marked as different. Are those timestamps stored in same format in db as in remote files?
For a sample updated file in the UTC-5 time zone
Windows File Explorer says Wednesday, November 27, 2019, 6:58:13 PM
Remote dlist file says “time”:“20191127T235813Z”
Lastmodified in DB FilesetEntry says 637104958932588928
- round down: 1574899093
- with fractional part: 1574899093.2588928
GMT / UTC Date Time: 2019-11-27 23:58:13 + 0.2588928 second
so what might be happening is that the DB has high resolution normally, but Recreate rounds it down.
There is also other metadata stored separately (such as ACLs on Windows), but I don’t know formats.
This is rather reminiscent of an issue @drwtsn32 ran into here where a mono upgrade to 5.12.0 and later picks up more resolution than it used to, thus triggers scans, but shouldn’t upload any file blocks.
I don’t know why the dlist file saves the file time in second resolution. .NET ticks are 100 ns resolution.
Yep I have also seen that. I’m not sure if it’s intentional or accidental, but I don’t mind it happening. It’s like an extra sanity check that your data is backed up properly.