How long to compact, and why no logging? Is it stuck?

Support
1

I have 2 systems that I recently changed to use smart retention. At the moment, both are sitting on "Deleting unwanted files … "

Both systems are running 2.0.5.114_canary_2021-03-10 and using backblaze for storage.

System 1:

  • last “live” verbose log entry is "Jul 21, 2021 7:59 PM: Backend event: Delete - Completed: duplicati-i38a882484de943d186c926b3fd482543.dindex.zip.aes (88.56 KB) "
  • Source: 5.03 TB
  • Backup: 8.24 TB / 22 Versions

System 2:

  • last “live” verbose log entry is "Jul 25, 2021 9:45 PM: Backend event: Delete - Completed: duplicati-if5bfd1cd7b054550997de03099dfa393.dindex.zip.aes (61.47 KB) "
  • Source: 698.69 GB
  • Backup: 2.88 TB / 27 Versions

I assume from googling around that both systems are running a “compact”:

  • is it normal for there to be no logging during the “compact”?
  • are these stuck, and should I abort them?
  • if not stuck, is there any reasonable way to estimate how much longer the “compact” phase is going to take?

Please let me know if there is any other information I can provide that would be helpful.

2

Did you customize the “Remote volume size” option? The default is 50MB.

3

Yes - both systems have a remote volume size of 100 MB. I had to increase it a while back due to errors I was seeing - IIRC it had something to do with listing files.

4

Ok, that size shouldn’t be an issue. Was just making sure it wasn’t set to something insanely large like 100+ GB.

Check the Live Log to make sure something is happening… go to About → Show Log → Live → and set the dropdown to Verbose. You should see activity there.

5

The most recent live log entries are in the first post :wink: No live log entries for days.

6

oops sorry, I see you mentioned “live” up there. Anything different if you set it to “profiling”?

7

With “profiling” it adds 1 additional line to each:
system 1 - "Jul 21, 2021 7:59 PM: RemoteOperationDelete took 0:00:00:00.105 "
system 2 - “Jul 25, 2021 9:45 PM: RemoteOperationDelete took 0:00:00:00.119”

8

Well it definitely seems like it’s stuck. You can try canceling the operation from the web UI, but I doubt it will work in this case. If it doesn’t, try killing/restarting Duplicati. Do this on just one system so we can see how it goes.

9

Yes, had to restart. On restart it immediately started a backup which failed with “Found 573 files that are missing from the remote storage, please run repair”, which I expected it might do based on past experience.

Running the repair as requested now.

10

Repair completed. I have started the backup - we’ll know tomorrow morning if all is now well.

11

Backups appear to be running properly on system 2 again. Proceeding with system 1 (stop/start/repair if needed).

12

Good to hear. Wonder what the underlying problem was.

13

All backups complete, no apparent errors.

Underlying problem had to be something to do with changing the retention schedule, as backups were running without any known issues prior to the change.

14

Thanks for the advice!

15

Agreed, but there must be some other variable at play, as many have adjusted retention policies without issue. Would be interesting to see if we could reproduce this on demand.

Out of curiosity have you customized your deduplication block size (default is 100KB)? Your backups are quite large, and the default block size of 100KB is probably too small. This results in a large local database and slow database operations.

16

Re: deduplication block size - no, I have not changed this

17

This morning the problem has reappeared. On both systems the last entries are similar to:

  • Jul 29, 2021 2:59 AM: RemoteOperationDelete took 0:00:00:00.154
  • Jul 29, 2021 2:59 AM: Backend event: Delete - Completed: duplicati-ie95c20328b0a41e8bbcd9658354aa4a0.dindex.zip.aes (448.65 KB)

and the mono-sgen process running Duplicati.Server.exe is consuming 100%+ CPU.

18

What version of mono are you using? Also, how large are your job sqlite databases?

19

Might as well take note of the modification and last access (ls -lu --full-time) times while there.

20

What version of mono are you using?

Installed Packages
mono-complete.x86_64 6.8.0-8.fc33 @updates
mono-core.x86_64 6.8.0-8.fc33 @updates
mono-data.x86_64 6.8.0-8.fc33 @updates
mono-data-oracle.x86_64 6.8.0-8.fc33 @updates
mono-data-sqlite.x86_64 6.8.0-8.fc33 @updates
mono-devel.x86_64 6.8.0-8.fc33 @updates
mono-extras.x86_64 6.8.0-8.fc33 @updates
mono-locale-extras.x86_64 6.8.0-8.fc33 @updates
mono-mvc.x86_64 6.8.0-8.fc33 @updates
mono-reactive.x86_64 6.8.0-8.fc33 @updates
mono-wcf.x86_64 6.8.0-8.fc33 @updates
mono-web.x86_64 6.8.0-8.fc33 @updates
mono-winforms.x86_64 6.8.0-8.fc33 @updates
mono-winfx.x86_64 6.8.0-8.fc33 @updates
monodoc.x86_64 6.8.0-8.fc33 @updates

These are the current versions for Fedora 33 (dnf does not show any available updates).

Also, how large are your job sqlite databases?

System 1:

ls -lu --full-time *.sqlite

-rw-------. 1 root root 233472 2021-07-29 10:20:00.149070786 -0400 Duplicati-server.sqlite
-rw-------. 1 root root 18098118656 2021-07-29 02:34:19.850664721 -0400 MYFGVUULA.sqlite

System 2:

ls -lu --full-time *.sqlite

-rw-------. 1 root root 233472 2021-07-29 10:20:00.149070786 -0400 Duplicati-server.sqlite
-rw-------. 1 root root 18098118656 2021-07-29 02:34:19.850664721 -0400 MYFGVUULA.sqlite

On the off chance that it is relevant, in the past I had to move the Duplicati directory to a different filesystem, and replaced /root/.config/Duplicati with a symlink. Systems have been running with this configuration for several weeks. Also, due to issues with disk space doing a rebuild, I have TMPDIR set in /usr/bin/duplicati-server to point to a temp direcotry on a filesystem that has more space - this is a more recent change.