Restore Very Slow - Local Disks no network

Hi
I’m having problems with Backup Restores being very slow, I have read various other related posts but not found any explanation that I can put to my senario.

This is my setup:

  1. Backups are made to Onedrive (V2)
  2. Onedrive is synced down to my remote backup machine.
  3. I take a snapshot of the OneDrive folders once the sync is completed.
  4. I run a local restore from the disk snapshot of the backups to another disk on the machine (I/O balancing)
  5. Keep a copy of the backed up files locally.

Stage 4 is incredibly slow taking upto 12 hours to restore from a 67GB backup containing 2,600 files. Given that this is reading and writing to local disks in the machine where can the bottleneck be. Looking at resorce monitor the CPU, Memory & IO are all low usage.
I’m struggleing to understand why a 67GB backup can take 12 hours to extract and write the backed up files totalling 105GB?
Any help would be welcome as at the moment it would take more than a week to restore all of my backups which is not a acceptable DR plan.

Thanks
David

Because you are talking about DR, does that refer to when you continue from this?

image

If so, there should be information on where it is, e.g. Building partial temporary database …
and I think there’s a progress bar that you can measure. Going beyond 70% is worrisome and slow because it’s searching all the files in search of missing data. But that conflicts with your lack of I/O.

You can look at the destination to see when files start showing up. Is the slow spot there or before?
You can also watch file rebuild in About → Show log → Live → Verbose for “Patching” messages.

As a note, files rebuild a block at a time, and before backup files are read, source files are checked.
There have been some odd situations where the check was slow because a bad drive got old letter.
no-local-blocks in job Advanced options can stop such optimization. For direct restore, it’s a type-in.

I used Duplicati in the past, it was a very good backup solution until I needed to do a restore. I had a backup of 1.8Tb, just tried to recover a few files and it was literally impossible to restore because it was soooooo slow that in the practical was unusable. And slow means days waiting for a response.

I did some tests with other PCs, SSD disks, Raids…same result, the speed was very very poor and it’s not 100% hardware related since exactly same environment with Veeam runs fast. I was forced to choose another product, now I came here to take a test for the actual version of Duplicati but seems that the problem remains.

If you find a solution for the speed, please share.

By DR I mean Disaster Recovery (my office burns down and all is lost), so I’m recovering to a different machine. By Stage 4 I’m referring to my list of actions and No 4 the restore is very slow.

I’m using this command line to restore:
“C:\Program Files\Duplicati 2\Duplicati.CommandLine.exe” restore “E:\Snapshot\psdc1” --overwrite=true --restore-path=“C:\Restores\psdc1” --passphrase= >restore_psdc1.log

The log has no timestamp elements so it’s impossible to see where the delay is actually happpening. I know it takes ages before it writes any files. So I guess it’s slow evaluating the contents of the backup itself. But if it’s not a big backup and not bound by CPU or IO what is the blockage?

Is there somethig on the backup itself, perhaps using a different retention policy might help speed up the restore? Below is my Backup config:

{
“CreatedByVersion”: “2.0.5.1”,
“Schedule”: {
“ID”: 4,
“Tags”: [
“ID=4”
],
“Time”: “2020-11-25T22:59:00Z”,
“Repeat”: “1D”,
“LastRun”: “2020-11-24T22:59:00Z”,
“Rule”: “AllowedWeekDays=Monday,Tuesday,Wednesday,Thursday,Friday,Saturday,Sunday”,
“AllowedDays”: [
“mon”,
“tue”,
“wed”,
“thu”,
“fri”,
“sat”,
“sun”
]
},
“Backup”: {
“ID”: “4”,
“Name”: “psdc1”,
“Description”: “psdc1”,
“Tags”: ,
“TargetURL”: “onedrivev2://psmf1\psdc1?authid=”,
“DBPath”: “C:\Users\administrator.POWERSOFT\AppData\Local\Duplicati\VHARMXIBZA.sqlite”,
“Sources”: [
“C:\Data\Backups\psdc1\”
],
“Settings”: [
{
“Filter”: “”,
“Name”: “encryption-module”,
“Value”: “aes”,
“Argument”: null
},
{
“Filter”: “”,
“Name”: “compression-module”,
“Value”: “zip”,
“Argument”: null
},
{
“Filter”: “”,
“Name”: “dblock-size”,
“Value”: “200MB”,
“Argument”: null
},
{
“Filter”: “”,
“Name”: “passphrase”,
“Value”: “”,
“Argument”: null
},
{
“Filter”: “”,
“Name”: “retention-policy”,
“Value”: “1W:1D,4W:1W,12M:1M”,
“Argument”: null
}
],
“Filters”: ,
“Metadata”: {
“LastBackupDate”: “20201124T225900Z”,
“BackupListCount”: “10”,
“TotalQuotaSpace”: “1099511627776”,
“FreeQuotaSpace”: “248479076385”,
“AssignedQuotaSpace”: “-1”,
“TargetFilesSize”: “18263251670”,
“TargetFilesCount”: “686”,
“TargetSizeString”: “17.01 GB”,
“SourceFilesSize”: “89891296444”,
“SourceFilesCount”: “21”,
“SourceSizeString”: “83.72 GB”,
“LastBackupStarted”: “20201124T225900Z”,
“LastBackupFinished”: “20201124T232709Z”,
“LastBackupDuration”: “00:28:09.2606790”,
“LastCompactDuration”: “00:00:14.1813090”,
“LastCompactStarted”: “20201123T000324Z”,
“LastCompactFinished”: “20201123T000338Z”
},
“IsTemporary”: false
},
“DisplayNames”: {
“C:\Data\Backups\psdc1\”: “psdc1”
}
}

I went into About Show log and this is all I get:

I’m deleting the Target directory before starting the restore so tere are no local files to read, I’m not sure about the no-local-blocks option, how do I set this on the command line and will it help?

Thanks in advance for all your help.

Regards
David

You’re not exactly asking for a log file, just capturing output on your own. To get a log file with timestamps:

--log-file='<path>' --log-file-log-level=verbose or whatever you like. Both of these have help.

Here’s an example at verbose level that also shows that information level would still reveal the basics:

2020-11-25 13:19:42 -05 - [Information-GetGpgProgramPath-gpg]: C:\ProgramData\Duplicati\duplicati-2.0.5.111_canary_2020-09-26\win-tools\gpg.exe
2020-11-25 13:19:42 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2020-11-25 13:19:42 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-11-25 13:19:42 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)
2020-11-25 13:19:43 -05 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (11/25/2020 6:16:06 PM) ...
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreTargetFileCount]: Needs to restore 1 files (13 bytes)
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MappingRestorePath]: Mapping restore path prefix to "C:\backup source\" to "C:\tmp\"
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreSourceSize]: Restore list contains 2 blocks with a total size of 150 bytes
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TargetExistsInCorrectVersion]: Target file exists and is correct version: C:\tmp\short.txt
2020-11-25 13:19:43 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore
2020-11-25 13:19:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:19:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\short.txt
2020-11-25 13:19:43 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\short.txt
2020-11-25 13:19:43 -05 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-NoFilesRestored]: Restore completed without errors but no files were restored
2020-11-25 13:29:48 -05 - [Information-GetGpgProgramPath-gpg]: C:\ProgramData\Duplicati\duplicati-2.0.5.111_canary_2020-09-26\win-tools\gpg.exe
2020-11-25 13:29:48 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2020-11-25 13:29:48 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-NoLocalDatabase]: No local database, building a temporary database
2020-11-25 13:29:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-11-25 13:29:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)
2020-11-25 13:29:51 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 2 filelists
2020-11-25 13:29:51 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20201123T030432Z.dlist.zip.aes (893 bytes)
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20201123T030432Z.dlist.zip.aes (893 bytes)
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20201125T181606Z.dlist.zip.aes (957 bytes)
2020-11-25 13:29:52 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingFilelistVolumes]: Processing filelist volume 1 of 2
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20201125T181606Z.dlist.zip.aes (957 bytes)
2020-11-25 13:29:52 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingFilelistVolumes]: Processing filelist volume 2 of 2
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FilelistsRestored]: Filelists restored, downloading 2 index files
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i62811a114a5f4669892763bd4b19b4a6.dindex.zip.aes (925 bytes)
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i62811a114a5f4669892763bd4b19b4a6.dindex.zip.aes (925 bytes)
2020-11-25 13:29:52 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingIndexlistVolumes]: Processing indexlist volume 1 of 2
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-ibf951093abe8471687ba9a86989debad.dindex.zip.aes (893 bytes)
2020-11-25 13:29:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-ibf951093abe8471687ba9a86989debad.dindex.zip.aes (893 bytes)
2020-11-25 13:29:52 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingIndexlistVolumes]: Processing indexlist volume 2 of 2
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RecreateCompletedCheckingDatabase]: Recreate completed, verifying the database consistency
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RecreateCompleted]: Recreate completed, and consistency checks completed, marking database as complete
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (11/25/2020 6:16:06 PM) ...
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreTargetFileCount]: Needs to restore 1 files (13 bytes)
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MappingRestorePath]: Mapping restore path prefix to "C:\backup source\" to "C:\tmp\"
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreSourceSize]: Restore list contains 2 blocks with a total size of 150 bytes
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TargetExistsInCorrectVersion]: Target file exists and is correct version: C:\tmp\short.txt
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:29:53 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\short.txt
2020-11-25 13:29:53 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\short.txt
2020-11-25 13:29:53 -05 - [Warning-Duplicati.Library.Main.Operation.RestoreHandler-NoFilesRestored]: Restore completed without errors but no files were restored
2020-11-25 13:32:56 -05 - [Information-GetGpgProgramPath-gpg]: C:\ProgramData\Duplicati\duplicati-2.0.5.111_canary_2020-09-26\win-tools\gpg.exe
2020-11-25 13:32:56 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2020-11-25 13:32:56 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-NoLocalDatabase]: No local database, building a temporary database
2020-11-25 13:33:00 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-11-25 13:33:00 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)
2020-11-25 13:33:00 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 2 filelists
2020-11-25 13:33:00 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20201123T030432Z.dlist.zip.aes (893 bytes)
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20201123T030432Z.dlist.zip.aes (893 bytes)
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20201125T181606Z.dlist.zip.aes (957 bytes)
2020-11-25 13:33:01 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingFilelistVolumes]: Processing filelist volume 1 of 2
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20201125T181606Z.dlist.zip.aes (957 bytes)
2020-11-25 13:33:01 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingFilelistVolumes]: Processing filelist volume 2 of 2
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FilelistsRestored]: Filelists restored, downloading 2 index files
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i62811a114a5f4669892763bd4b19b4a6.dindex.zip.aes (925 bytes)
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i62811a114a5f4669892763bd4b19b4a6.dindex.zip.aes (925 bytes)
2020-11-25 13:33:01 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingIndexlistVolumes]: Processing indexlist volume 1 of 2
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-ibf951093abe8471687ba9a86989debad.dindex.zip.aes (893 bytes)
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-ibf951093abe8471687ba9a86989debad.dindex.zip.aes (893 bytes)
2020-11-25 13:33:01 -05 - [Verbose-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-ProcessingIndexlistVolumes]: Processing indexlist volume 2 of 2
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RecreateCompletedCheckingDatabase]: Recreate completed, verifying the database consistency
2020-11-25 13:33:01 -05 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RecreateCompleted]: Recreate completed, and consistency checks completed, marking database as complete
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (6 bytes)
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (11/25/2020 6:16:06 PM) ...
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreTargetFileCount]: Needs to restore 1 files (13 bytes)
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MappingRestorePath]: Mapping restore path prefix to "C:\backup source\" to "C:\tmp\"
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreSourceSize]: Restore list contains 2 blocks with a total size of 150 bytes
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MissingTargetFile]: Target file does not exist: C:\tmp\short.txt
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:33:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b9284e00299594f1996453493d6862e4a.dblock.zip.aes (1005 bytes)
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\tmp\short.txt
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\short.txt
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\short.txt
2020-11-25 13:33:02 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\tmp\short.txt

Do the other items I named apply? Note that on a multicore system, a pegged CPU is just a fraction of all.
Ability to benefit from multiple cores is not an automatic thing. In particular, I think SQL is mostly one core.
You’d have to go up to profiling level on the log to see that. It’d be a big file, but you can see times needed.

Choosing sizes in Duplicati can help speed DB rebuild if you set a larger --blocksize than default 100 KB. You’d lose some deduplication, but some files don’t have much duplicated data, either within or between.

Hard to say. It depends a lot on the data and its changes. One thing that can happen if, for example, a file constantly gets appended, is that the Duplicati practice of backing up only the changed portions can slow restore of the latest version because it will have to read data from lots of different updates over file history, however this slowing would be in the writing-files-block-by-block phase, and you think you’re not there yet.

If it’s spending a lot of time at “No local database, building a temporary database” in the log-file, you could look at progress messages to see what it’s working on and how fast. Ideally it’s just filelists and indexlists.

Duplicati.CommandLine.exe runs independently. The GUI can’t show that live log. Do you backup in GUI?

It reads from the source files (not target) when possible to avoid having to go to the destination for its data.
That’s what --no-local-blocks can prevent. I think an existing target file is also read. Why patch it if it’s OK? There’s probably no option to turn that off, however it doesn’t apply because you’ve emptied the target out.

Using Duplicati from the Command Line explains, but you’re already doing that, and setting up the options.
--no-local-blocks=true is one way to say that. It will save a little time in DR looking for the source files.

Your best path is to set up a --log-file at some level, and see where time is going. Then work on that…

Thank you so much for your detailed reply, I’ll work my way through the suggestions and report back.

Thank you for all your help. I have managed to resolve my particular problem by priming the target of the restore from the source via usb disk. The restore (of changed files) only takes 4-5 hours which is acceptable.

I had thought of splitting the backup into volatile & non volatile data but I think I have avoided that hassle by starting from a known point on my DR machine.

1 Like