Very strange execution times for restic check

On my desktop machine I have set up two cron jobs that backup to bb2 cloud storage every night: one for my regular user and one for root. Both jobs backup to separate restic repositories that both have their own separate bucket in bb2.

The bucket sizes in bb2 are:

  • restic-user: 208.3 GB (42,094 files)
  • restic-root: 15 GB (3,861 files)

The execution times for restic backup are:

  • restic-user: 4 min, 2 sec
  • restic-root: 0 min, 18 sec

This seems reasonable to me: the backup to the larger repository takes longer than that of the smaller one.

But the execution times for restic check are:

  • restic-user: 3 min, 49 sec
  • restic-root: 49 min, 14 sec

So far I have really failed to come up with an explanation for the fact that the check on the smaller repository takes more than twelve times longer than the check on the much larger repository.

Maybe someone of you guys has some ideas? - I am using “restic 0.9.6 compiled with go1.14.4 on linux/amd64”.


Here are the log files from the last runs:

1 - regular user:

---------- 03.10.2020 04:15:01 - starting restic backup
command line for backup: /usr/bin/nice -n 19 /usr/bin/ionice -c3 /usr/bin/restic --verbose --exclude-file=/home/td/restic/restic_excludes.txt backup /home/td /harddisk/home-td/MyData
open repository
lock repository
load index files
using parent snapshot 7b54841b
start scan on [/home/td /harddisk/home-td/MyData]
start backup on [/home/td /harddisk/home-td/MyData]
scan finished in 12.276s: 137709 files, 179.784 GiB

Files:          99 new,   107 changed, 137503 unmodified
Dirs:            0 new,     1 changed,     2 unmodified
Data Blobs:    497 new
Tree Blobs:      2 new
Added to the repo: 240.695 MiB

processed 137709 files, 179.784 GiB in 3:58
snapshot fc25b820 saved
---------- 03.10.2020 04:19:03 - starting restic check
using temporary cache in /harddisk/restic-temp-check-cache/restic-check-cache-887773829
created new cache in /harddisk/restic-temp-check-cache/restic-check-cache-887773829
create exclusive lock for repository
load indexes
check all packs
check snapshots, trees and blobs
no errors were found
---------- 03.10.2020 04:22:52 - end of script

2 - root:

---------- 03.10.2020 02:35:01 - starting restic backup
command line for backup: /usr/bin/nice -n 19 /usr/bin/ionice -c3 /usr/bin/restic --verbose --exclude-file=/root/restic/restic_excludes.txt backup /root /etc
open repository
lock repository
load index files
using parent snapshot 31315fbf
start scan on [/root /etc]
start backup on [/root /etc]
scan finished in 6.399s: 2435 files, 24.968 MiB

Files:           1 new,     3 changed,  2431 unmodified
Dirs:            0 new,     0 changed,     0 unmodified
Data Blobs:      3 new
Tree Blobs:      1 new
Added to the repo: 2.564 KiB

processed 2435 files, 24.968 MiB in 0:13
snapshot 17c20a14 saved
---------- 03.10.2020 02:35:19 - starting restic check
using temporary cache in /harddisk/restic-temp-check-cache/restic-check-cache-293750398
created new cache in /harddisk/restic-temp-check-cache/restic-check-cache-293750398
create exclusive lock for repository
load indexes
check all packs
check snapshots, trees and blobs
no errors were found
---------- 03.10.2020 03:24:33 - end of script

How many snapshots do both repositories have? The time required by the check command increases with the number of snapshots for restic 0.9.6. This has been fixed in restic 0.10.0 which should be significantly faster for checking both repositories.

Here are the number of snapshots:

  • restic-user: 109
  • restic-root: 106

I upgraded yesterday and the latest runs executed with “restic 0.10.0 compiled with go1.15.2 on linux/amd64”. The execution times for restic check last night were:

  • restic-user: 1 m, 23 sec
  • restic-root: 15 m, 52 sec

Even with the latest version (restic 0.10.0) the execution time of restic check on the smaller repository takes more than eleven times longer than the check on the much larger repository, that has not only much more data (208.7 GB vs. 15 GB), but also many more files (42,187 vs. 3,871) and slightly more snapshots (110 vs. 107).

How is that possible?

That looks indeed strange. Could you take a look at how large the cache folder for both the user and root backup is (restic cache prints the basepath of the cache directory)? How many files has the index of both repositories? Could you use /usr/bin/time ... to run the commands, such that we know how much CPU was used?