Duplicati hangs on deleting unwanted files

Hi,

I’m using Version 2.0.6.1_beta_2021-05-03 in Win10. The backup destination is an USB3 spinnning drive.

Until I added some additional folders the Version worked very fast and reliable.

Then I added folders and startet the backup again to add this folders.

After 15 Minutes “deleting unwanted files” I killed all duplicati processes, because this long time was not normal behaviour.

I checked the logfile, but the last entry was several minutes old:

[Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b59d8be2eac814173a4f434478a2394a7.dblock.zip (609.85 KB)

The resource monitor told me for the System proces (duplicati processed the second one file with 04 at the end as well):

I can recognize, that a tmp-File will be copied during the time I waited.

Is this observation normal? How long do I have to wait for normal finishing?

Regards,

Onurbi

The deletion phase could be due to version pruning and/or compaction.

Have you customized the “Remote Volume Size” setting? The default is 50MB. Using a large value here can cause compaction to take longer.

No, dblock-size is still default at 50MB.

If the UI gets stuck, there’s a good chance its some code error that happened within their code loop for the backups - certain errors there cause the loop to be unable to end. Bit of a bugger there. But, you’d have to let it sit longer to be sure.

At least for me, on one computer its a few specific files that it often has problems with as it a specific issue where it isn’t coded to deal with that and wallops it. But the errors can be others than the one(s) I had seen as its was never hardened against all errors. Anything that errors could potentially cause that loop to freeze and the UI to stay stuck though there are errors that don’t.

On some computers and/or backups, 15 minutes on one thing may not be much depending on what has to done for the backup. So if it stays that way for two hours when it normally completes in 10 minutes then its definitely buggered. Some dramatic time longer than you’ve ever seen.

Eliminating something from the backup or changing something should workaround it and keep the problem from happening at least until the code can be fixed someday. Should it be the UI freezing.

Hopefully it wasn’t frozen and was just taking longer.

1 Like

One reason for taking longer – sometimes – is Compacting files at the backend, which this likely was, because there’s no other reason why “Deleting unwanted files” should do the Get (typically multiple to repackage contents into a new dblock for a Put and then Delete of the now-fully-transferred dblocks).

Did you see the rather high transfer rate for a long time on those same two files? That would seem odd.
Usually maximum file size is about the Remote volume size (your 50 MB), also known as dblock-size.
Typically, though, there’s a stream of such not-huge files flowing through. A 15 minute pause is unusual.

This is written as after the kill, so is it a separate log-file (as opposed to live log)? What level did you get?
If you actually have more information, can you please post file action from any Delete to the point of kill?

There are options to tune a compact, but for testing you can set no-auto-compact, and do a manual run.
If you suspect a hang, please see if profiling log (e.g. About → Show log → Live → Profiling) has activity.

Yes indeed. The screenshot shows the two files.

I set verbose as log level. BTW my backup size is 11.5GB. Another Backup task with 5GB runs in a perfect short time. There seems to be a threshold. When a backup does Increase a certain amount of size the compacting process get a problem and runs uneffectively.

That are the last lines before I killed all duplicati processes:

2021-10-10 12:01:38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bfcbe4a4fe90f4669b931f14334808a56.dblock.zip (15.27 MB)
2021-10-10 12:01:38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-bfcbe4a4fe90f4669b931f14334808a56.dblock.zip (15.27 MB)
2021-10-10 12:01:38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b976de689cbd145d098bbddfeb1c23d53.dblock.zip (8.54 GB)
2021-10-10 12:03:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b976de689cbd145d098bbddfeb1c23d53.dblock.zip (8.54 GB)
2021-10-10 12:03:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b59d8be2eac814173a4f434478a2394a7.dblock.zip (609.85 KB)
2021-10-10 12:03:27 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b59d8be2eac814173a4f434478a2394a7.dblock.zip (609.85 KB)

In this case “deleting unwanted files” takes only one miiliisecond!

Running compact as a separate task, the same problem takes place!
The state is “Backup will be started” for a long time.

As a separate task or with auto-compact active, at first some sqlite actions will be processed in a relative short time (< 1 minute or so). But then one tmp file will copied to another much too slow.

The one file from where is read is 10GB big. I can observe, that the destination file grows in the size of the source file as time goes by with only 10Mb/s (SSD!).

When I would kill dupicati yet in this phase, it is not dangerous. A following test is successful at least.

After this long action, the backup destination drive is written with a *dblock.zip file.

This separate compacting task finished indeed: “Running Compact took 0:00:23:14.630”.

After this observation that compacting takes a certain amount of time and does really finish, I tried to activate auto-compact again an started a backup manually:

Now the phase “deleting unwanted files” was fast. But now “Checking files” takes a long time.

This means obviously, that I have to set no-auto-compact but wasting space. That’s reall unsatisfying!

I activated it.

It shows about a 5 MByte/second write rate, so if it went for 10 minutes (and you saw it), that’s 3 GBytes.
Because you did a kill, are either of the files still laying around to be examined, e.g. for length or opening?

That’s the kind of thing a compact would do – download dblock files with wasted space to rebuild a fresh one out of the blocks that are still in use. Before encryption, I think it’s just a .zip file (without that suffix).

Depending on what Backup retention you chose on Options screen, it might not have anything to do.
If it does wind up deleting a version per your configuration, you would see a Delete done, then maybe a compact, however compact only runs per configured parameters, e.g. % wasted space, so may not run.

Perhaps “Sicherung wird gestartet”. English phrase would be “Starting backup” and it (sadly) says backup regardless of what it’s starting. I took a guess at the code bug here, but there seems to be no followup yet.

Feel free to file an issue and cite that comment or this post. Regardless, I don’t think there’s much detail in a compact operation seen on the status bar. Some operations, such as backup, go through more phases.

How big is it? Actually, if you can sort destination by size, do you have any files larger than roughly 50 MB?
I’m not sure what the 10 GB file would be, but if any such large dup-* files remain, you can see what opens them, e.g. add a .zip suffix and see if it can be opened that way. Seeing that you don’t encrypt avoids the question of whether it’s an encrypted zip file (which could be tested). Unfortunately the file name is no help.

Yes, I assume, that there are open steps. The files in tmp folder are stll there. Also after a successfull manual compact task!

Yes I plan this.

I am confused, that dblock files have a size of max. 10G, although dblock-size is set to 50MB!

How do you mean this, I can see what opens them?

After the successfull compacting task there are still files > 50MB.

How could I understand this fact? I mentioned an assumption, that something goes wrong, from a certain backiup size on.

This seems wrong. After kill though, I’d expect it… Before filing issue, let’s try figuring out the big picture.

If you saw multiple that size, then maybe backup (rather than compact) put them there. I don’t know why, provided both the Remote volume size and (generally absent) dblock-size are 50 MB. There’s also a Settings screen where options can be set. Regardless, is there any size besides --dblock-size=50MB visible in Export As Command-line? Beware of any without a suffix, because the unit might be surprising.

The next part of that was:

so you might rename a dup-something file to dup-something.zip, click in Explorer, see if it can be opened.
If not, it might not have been a .zip file. If you suspected an encrypted file (might not apply) test AES Crypt (GUI) or SharpAESCrypt.exe (CLI) from Duplicati. If you suspect something else, find the appropriate tool. Sometimes these are even databases, but most likely guess (from big dblock) is it’s a dblock .zip forming.

Compact trims out wasted space in old dblock files, and makes new dblock files no larger than configured, however if there is already a big dblock file, it’s not going to cut it down. You can look over the dblock dates.

I doubt it. There are many-terabyte backups around. Please continue looking at dblocks and configurations.

It remains the questio what reason is, why the runtime increased suddenly since I added additonal files with some GBs.

Thank you for your insights into working with duplicate!

I’ll continue watching the run times for the next backups with and without no-auto-compact option.

How big was it earlier? A tiny backup would not get 10 GB dblock files. Even your 5 GB source wouldn’t.
Those huge files will hurt you after backup too, e.g.

Possibly means Dateien überprüfen and has English text of Verifying files, described at Verifying backend files. You can see the results in the regular job log. Typically it’s 1 set of dlist, dindex, and dblock (10 GB?):

image

Test phase is optional (but helps safety). For test purposes, you can set backup-test-samples to 0, which should make the backup fast, assuming it doesn’t compact that time. Compact is in job log too. Example:

image

Above example had no need to compact. This won’t always be the case, so total job run time may vary…

Please look very carefully at your configuration, or (if you wish) post it after carefully redacting the content.