Backup freezes for 10 minutes or more

Matthi · September 8, 2019, 7:18pm

My backup freeze regularly for ten minutes or more with CPU usage but no disk usage. My backend is a local harddisk. I also checked the file handles of the duplicati.server process with process explorer and at during the freezes it isn’t reading any files form the source of the backup.
Here is the verbose log:

* Sep 8, 2019 12:17 PM: All backups to delete:

* Sep 8, 2019 12:17 PM: Backups outside of all time frames and thus getting deleted:

* Sep 8, 2019 12:17 PM: Backups to consider: 07/09/2019 23:17:37, 07/09/2019 22:00:01, 06/09/2019 23:18:16, 01/09/2019 20:36:30

* Sep 8, 2019 12:17 PM: Time frames and intervals pairs: 7.00:00:00 / Keep all, 31.00:00:00 / 1.00:00:00, 59.00:00:00 / 2.00:00:00, 365.00:00:00 / 7.00:00:00

* Sep 8, 2019 12:17 PM: Start checking if backups can be removed

* Sep 8, 2019 12:17 PM: Backend event: Put - Completed: duplicati-20190908T095437Z.dlist.zip.aes (5.53 MB)

* Sep 8, 2019 12:17 PM: Backend event: Put - Started: duplicati-20190908T095437Z.dlist.zip.aes (5.53 MB)

* Sep 8, 2019 12:17 PM: Backend event: Put - Completed: duplicati-i61b0873b3cbb4a9794cc1ed907abf619.dindex.zip.aes (138.72 KB)

* Sep 8, 2019 12:17 PM: Backend event: Put - Started: duplicati-i61b0873b3cbb4a9794cc1ed907abf619.dindex.zip.aes (138.72 KB)

* Sep 8, 2019 12:17 PM: Backend event: Put - Completed: duplicati-bbfc221c957514f2ba8530a1eb04721b6.dblock.zip.aes (39.56 MB)

* Sep 8, 2019 12:17 PM: Backend event: Put - Started: duplicati-bbfc221c957514f2ba8530a1eb04721b6.dblock.zip.aes (39.56 MB)

* Sep 8, 2019 11:58 AM: Skipped checking file, because no metadata was updated C:\Users\Zinoo\.cisco\vpn\log\UIHistory_20190824_223151_log.txt

* Sep 8, 2019 11:58 AM: Including path as no filters matched: C:\Users\Zinoo\.cisco\vpn\log\UIHistory_20190824_223151_log.txt

* Sep 8, 2019 11:58 AM: Adding directory C:\Users\Zinoo\.cisco\vpn\log\

* Sep 8, 2019 11:58 AM: Adding directory C:\Users\Zinoo\.cisco\vpn\

* Sep 8, 2019 11:58 AM: Including path as no filters matched: C:\Users\Zinoo\.cisco\vpn\log\

* Sep 8, 2019 11:58 AM: Adding directory C:\Users\Zinoo\.cisco\

* Sep 8, 2019 11:58 AM: Including path as no filters matched: C:\Users\Zinoo\.cisco\vpn\

* Sep 8, 2019 11:58 AM: Skipped checking file, because no metadata was updated C:\Users\Zinoo\.GoLand2019.1\config\codestyles\Default.xml

* Sep 8, 2019 11:58 AM: Including path as no filters matched: C:\Users\Zinoo\.GoLand2019.1\config\codestyles\Default.xml

* Sep 8, 2019 11:58 AM: Adding directory C:\Users\Zinoo\.GoLand2019.1\config\codestyles\

* Sep 8, 2019 11:58 AM: Skipped checking file, because no metadata was updated C:\Users\Zinoo\.GoLand2019.1\config\options\window.manager.xml

* Sep 8, 2019 11:58 AM: Skipped checking file, because no metadata was updated C:\Users\Zinoo\.GoLand2019.1\config\options\usage.statistics.xml

* Sep 8, 2019 11:58 AM: Skipped checking file, because no metadata was updated C:\Users\Zinoo\.GoLand2019.1\config\options\updates.xml

* Sep 8, 2019 11:58 AM: Including path as no filters matched: C:\Users\Zinoo\.GoLand2019.1\config\options\window.manager.xml

I know that more logs are probably required so some guidance can be helpful to get those

ts678 · September 11, 2019, 6:01pm

Welcome to the forum @Matthi

–log-file with –log-file-log-level=profiling (also available as live log) is the highest possible level, but can be boosted a bit more with --profile-all-database-queries. This makes a whole lot of output, and slows things.

C:\ProgramData\Duplicati\duplicati-2.0.4.28_canary_2019-09-05>Duplicati.CommandLine.exe help profile-all-database-queries
  --profile-all-database-queries (Boolean): Activates logging of all database
    queries
    To improve performance of the backups, frequent database queries are not
    logged by default. Enable this option to log all database queries, and
    remember to set either --console-log-level=Profiling or
    --log-file-log-level=Profiling to report the additional log data
    * default value: false

C:\ProgramData\Duplicati\duplicati-2.0.4.28_canary_2019-09-05>

You could also watch the server with Sysinternals Process Monitor to see if you can see what it’s doing.

The whole backup looks like it uploaded about 40 MB, but how many files did it have to scan to find that?

Your job “Show log” has statistics. Scanning files isn’t instant. On Windows, –usn-policy can avoid scan.

I’m surprised your Verbose log isn’t putting out lots of lines like the below as it finds files needing backup:

2019-09-10 17:45:15 -04 - [Verbose-Duplicati.Library.Main.Operation.Backup.FilePreFilterProcess.FileEntry-CheckFileForChanges]: Checking file for changes C:\PortableApps\Notepad++Portable\App\Notepad++\backup\webpages.txt@2019-09-06_154119, new: False, timestamp changed: True, size changed: True, metadatachanged: True, 9/8/2019 12:12:06 PM vs 9/6/2019 7:58:56 PM