Resuming interrupted backup takes hours (incomplete snapshots should be saved)

[Christoph]

In the process of creating the initial backup of a large (1TB+) repository, I noticed that whenever I interrupted (i.e. stopped) the backup process, resuming the backup afterwards takes increasingly long time. From what I understand, this is because duplicacy has no index of all previously uploaded files and therefore has to “discover” what chunks already exist, until it finds some that it actually still needs to upload.

But I wonder whether it is correct that this literally takes hours (almost 6 at this point, and still counting). If this is by design, I wonder if there is not room for improvement here (though I have no suggestion as to how).

If this is not by design, I wonder what might be causing this. My only guess, at the moment, is that it has something to do that I tried resuming the backup not via the GUI but via the CLI instead (it was initiated, stopped, and resumed via the GUI several times before without problems, except for the increasingly long waiting time). Are there any pitfalls when switching between CLI and GUI?

My hunch is that this long waiting time is by design after all (my backup archive has now exceeds 900 GB in size). My main reason for believing this is that duplicacy is still actively reading files from the repository, according to the windows task manager.

My main reason for doubting that everything is in order is that my understanding was that whenever duplicacy is skipping chunks to upload, it says so in the backup -stats. But so far, the only output the job produced is this:

Storage set to P:\Backup\duplicacy
No previous backup found
Creating a shadow copy for D:\
Shadow copy {E8237DE6-EC1B-4E41-BF96-660929B660BC} created
Indexing D:\christoph
Loaded 21 include/exclude pattern(s)

In contrast, a different job a couple of days ago produced this when resumed:

Storage set to P:\Backup\duplicacy
No previous backup found
Indexing T:\
Incomplete snapshot loaded from c:\duplicacy\prefs/incomplete
Listing all chunks
Skipped 2299 files from previous incomplete backup
Skipped chunk 1 size 8427437, 8.04MB/s 00:24:38 0.0%
Skipped chunk 2 size 2007431, 9.95MB/s 00:19:54 0.0%
Skipped chunk 3 size 6222934, 15.89MB/s 00:12:28 0.1%
Skipped chunk 4 size 2979547, 18.73MB/s 00:10:34 0.1%
Skipped chunk 5 size 1059019, 19.74MB/s 00:10:02 0.1%
Skipped chunk 6 size 8930050, 28.25MB/s 00:07:00 0.2%
Skipped chunk 7 size 10986522, 38.73MB/s 00:05:06 0.3%
Skipped chunk 8 size 1392134, 40.06MB/s 00:04:56 0.3%
Skipped chunk 9 size 2115144, 42.08MB/s 00:04:42 0.3%
...

The difference is that the latter job never had anything to do with the GUI. And there is no -vss involved, because the repository is on a samba share (accessed from the windows pc).

So this is why I’m confused…

[gchen]

If you don’t see Incomplete snapshot loaded then it means the previous incomplete backup didn’t leave an incomplete file. Was the previous backup interrupted or stopped due to an error?

[Christoph]

Was the previous backup interrupted or stopped due to an error?

No error. Just me pressing the stop button in the GUI.

If you don’t see Incomplete snapshot loaded then it means the previous incomplete backup didn’t leave an incomplete file.

So you are suggesting that the reason it takes so long to resume some interrupted backup is that there is no incomplete file? What exactly does that file do that saves duplicacy so much time?

If the presence absence of this file explains the why resume takes so long, it leaves us with two questions:

1. Why is the file sometimes absent?
2. Why is duplicacy not talking to me (when the file is absent?

I suppose Q2 is a request for UX improvement, i.e. duplicacy should produce a message about what it is doing (when -stats is enabled) since it is obviously doing something (in my case it looks like it is successfully continuing to upload stuff (though I haven’t verified that), but without providing any stats).

[gchen]

The incomplete file records what files have been scanned and their chunks. So when the next backup reads this file, it knows which files to skip without rescanning them.

Why is the file sometimes absent?

This is a flaw of Windows – there isn’t an easy way to interrupt a running process other than killing it. But if the Duplicacy process gets killed it won’t get the the chance to save the incomplete file. The CLI version doesn’t have this issue when you press Ctrl-C.

Why is duplicacy not talking to me (when the file is absent)?

If the initial backup isn’t interrupted or stopped by an error, there won’t be such a file. So by default Duplicacy assumes this file doesn’t exist.

[Christoph]

Why is duplicacy not talking to me (when the file is absent)?

If the initial backup isn’t interrupted or stopped by an error, there won’t be such a file. So by default Duplicacy assumes this file doesn’t exist.

No, that’s not what I meant. Or not quite.

So you’re saying that those Skipped chunk 1 size 8427437... messages are only produced when duplicacy has the incomplete file to check which files to skip? In other words: when duplicacy attempts to upload a file that turns out to already exist (and hence skips it) then this is not reported as Skipped chunk...? Fine.

But my point was: it doesn’t talk to me at all. Nada. Even when it reaches the point where it has skipped all the chunks and starts uploading again, there is no message whatsoever.

So that was the situation at my previous post. In the meantime, I noticed that it may be relevant to say that the command duplicacy.exe backup -vss -stats -limit-rate 4000 was issued via a PowerShell script, which in turn was started (manually) via the Windows Task Scheduler (since the script runs in the background, it writes any duplicacy output to a log file). Because when I at some point ended the task in Windows, thousands of logfile entries about uploaded chunks were suddenly written to the logfile.

Under other circumstances, the messages from duplicacy are written to the log file already before the end of the task. So there may be something specific about how duplicacy produces its when it resumes a backup in absence of the incompletefile?

[gchen]

So you’re saying that those Skipped chunk 1 size 8427437… messages are only produced when duplicacy has the incomplete file to check which files to skip? In other words: when duplicacy attempts to upload a file that turns out to already exist (and hence skips it) then this is not reported as Skipped chunk…? Fine.

No, it is the opposite: if there is an incomplete file Duplicacy will know which files to skip so it won’t produce many Skipped chunk messages. If that file is absent, it doesn’t know which files had been uploaded in the previous backup (nor does it know there was a previous backup), so it will start from the first file and attempt to upload every chunk. But a lot of chunks had indeed been uploaded and that was why you saw so many Skipped chunk messages.

[Christoph]

Okay. Fine. What about the issue that duplicacy did not log anything until the PowerShell was closed?

[gchen]

Duplicacy only writes to stdout. It is normal for Windows to create a buffer to take the output from a running process and only when the buffer is full will the content of the buffer be flushed to the file on disk.

[Christoph]

Ah, thanks for explaining. But I’m afraid this doesn’t explain much of what I’m seeing because the first six lines appeared within a few seconds of starting the backup. But the following 236000 (sic!) appeared only when I stopped the task. So if there is a buffer, it is max 6 lines long. Which leaves the question why the other 236000 lines were kept in the buffer (or wherever they were kept)?

I understand that this is probably not a bug in duplicacy, but I suspect that there may be some room for improvement in how it interacts with windows.

Or maybe there is something wrong with my script? Here it is:

# Basic setup (edit here!)
$backupID = "PC_D_christoph"
$repositorypath = "D:\christoph"
# Construct logfile name for the day
$logfiledate = get-date -format yyyy-MM-dd
$logfilename = "backup_$backupID-$logfiledate.log" 
# Go to repository 
Set-Location -Path $repositorypath >> "C:\duplicacy\logs\$logfilename"
$(get-date -Format "yyyy-MM-dd HH:mm:ss") + " *** Starting new backup of " + $(convert-path $(get-location).Path) + " ***" >> "C:\duplicacy\logs\$logfilename"
# Start backup (edit here!)
& "c:\Program Files (x86)\Duplicacy\duplicacy.exe" backup -vss -stats -limit-rate 4000 >> "C:\duplicacy\logs\$logfilename"
$(get-date -Format "yyyy-MM-dd HH:mm:ss") + " *** Backup of " + $(convert-path $(get-location).Path) + " stopped ***" >> "C:\duplicacy\logs\$logfilename"

[gchen]

Your script looks ok to me although I must admit that I have little experience with PowerShell.

[Christoph]

if the Duplicacy process gets killed it won’t get the the chance to save the incomplete file. The CLI version doesn’t have this issue when you press Ctrl-C

if there is an incomplete file Duplicacy will know which files to skip so it won’t produce many Skipped chunk messages. If that file is absent, it doesn’t know which files had been uploaded in the previous backup (nor does it know there was a previous backup), so it will start from the first file and attempt to upload every chunk.

I have to come back to this because I cannot confirm the above. I’ve had the suspicion for a while but never was entirely sure. Now I am: when I stop an ongoing backup with Ctrl + C in PowerShell and then restart the same backup, I will see skipped chunk message for hours (literally) before it resumes the actual upload.

[gchen]

If you don’t see a log message “Incomplete snapshot saved to”, then it means Duplicacy isn’t getting the Ctrl-C signal. I’m not sure if PowerShell would pass the signal to Duplicacy when it is running inside a script, but if you run Duplicacy from the command line it should get the signal.

[Christoph]

I’m not running it as a script. I’m running it directly from the powershell command line.

[Christoph]

Today the backup failed/stopped because the destination drive became unavailable. I’d assume that in this situation duplicacy had all the time in the world to write the incomplete snapshot, but it didn’t:

Now it will have to skip chunks again for hours. Is there any way I can get it to save the incomplete snapshots?

[gchen]

Any change you’re not running the latest version?

[Christoph]

It’s one of the v2.1.0 betas. Not sure if it’s the latest one though. Does it matter which beta?

[gchen]

Sorry, I forgot the partial snapshot file is saved for incomplete initial backups only. After the initial backup is done, it always uses the last complete backup as the base to determine which files are new. So if you add a lot of new files after the initial backup, you won’t be able to fast-resume after the backup is interrupted.

[Christoph]

Oh. Well, that is bad news. Why are incomplete snapshots not saved for subsequent backups?

I have about 1 TB of data to back up and for various reasons, that won’t go through without interruptions. Without incomplete snapshots, I lose several hours every time during which duplicacy just skips chunks. And as the backup progresses, the longer that waiting time becomes.

May I suggest that in v2.1.0 this limitation to incomplete snapshots is taken away? Or if there are some serious downsides of that, to at least make it available as an option, -save-incomplete or something?

[Christoph]

This is really becoming a major issue for me.

What if I delete the first two snapshots? As a work around, will duplicacy save the ongoing incomplete snapshot again? If so, would duplicacy prune -r 1-2 -storage <storage url> be the correct way of doing this? Or should I just delete the two files in the snapshot folder? (I obviously don’t want the chunks to be deleted, only the snapshots.)