Restic mount takes 5 minutes

Getting Help
1

restic 0.18.0 compiled with go1.24.4 on linux/amd64

# set RESTIC_REPOSITORY=foo RESTIC_PASSWORD_FILE=/tmp/tmp.xxxx
# restic --verbose=2 mount /tmp/restore
repository 97473a5f opened (version 2, compression level auto)
[2:45] 100.00% 959 / 959 index files loaded
Now serving the repository at /tmp/restore
Use another terminal or tool to browse the contents of this folder.
When finished, quit with Ctrl-c here or umount the mountpoint.

(In another shell, some point after the “Now Serving” message but not immediately)

$ /usr/bin/time ls -l /tmp/restore
hosts ids snapshots tags
0.00user 0.00system 2:23.94elapsed 0%CPU (0avgtext+0avgdata 2444maxresident)k
544inputs+0outputs (5major+138minor)pagefaults 0swaps

The index files reach 959/959 in 24 seconds, it sits at loaded 959/959 for another 2.5 minutes before it says “Now serving the repository”, there’s a short burst of getattr() calls to NFS for about 10 seconds,
then after that it’s another 3 minutes of restic pegging a single core of the CPU 100% and slowly increasing memory usage before the filesystem returns the first ls. After that, everything works as expected and quite snappy. I’ve even run games off the snapshot rather than re-installing them!

Similar deal with restic stats: indexes load in 24 seconds using all cores, whole process takes another 8 minutes of single-core work.

# time restic stats c3fcf9e6
repository 97473a5f opened (version 2, compression level auto)
[2:17] 100.00% 959 / 959 index files loaded
scanning…
Stats in restore-size mode:
Snapshots processed: 1
Total File Count: 21997687
Total Size: 1.990 TiB
920.10user 39.81system 8:20.72elapsed 191%CPU (0avgtext+0avgdata 17129652maxresident)k
13474576inputs+1369952outputs (18487major+4413046minor)pagefaults 0swaps

Is there any way to determine what’s going on in those extra 5/8 minutes? Yes, 21 million files per snapshot over hundreds of snapshots is large, I expect it to take some time, but I don’t expect it to stall for 3-4 minutes after it says it’s ready.

2

That final step is merging the indexes in memory, which should be rather quick. How much memory is restic using? Have you set any special environment variables like GOGC?

What does restic stats --mode debug report in terms of repository size?

1 Like
3

[ this reply was stuck in my browser for about a week ]

@harikattar is your repository hosted on NFS storage?? then i’d say you have very good performance as I can imagine with your repo size there is a ton of IOPS to go through.

I like your observations for “all-core” and “single-core” usage at restic ls and restic stats. You could file a request on github and maybe in the future restic can be improved to all-core operation.

Then I did some quick trial on a few of my repositories, i also noticed somthing.
For example one repository ~500GB with 735 snapshots mostly static data served via NFS, processed on a 12C Ryzen 5600G CPU with 64GB RAM and restic cache and tmp in RAM does restic stats in about 8.5minutes.
During that time all cpu cores are used but only around 8% and network (NFS) seems to be my bottleneck.

repository 9b60fc67 opened (version 2, compression level auto)
[0:00] 100.00% 744 / 744 index files loaded
scanning…
Stats in restore-size mode:
Snapshots processed: 735
Total File Count: 52036432
Total Size: 169.909 TiB

1 Like
4

It says it in the initial post:
17129652k maxresident
so 17gb, give or take. I have no GO related environment variables set. I’ve got 32gb on this machine so that all fits in RAM. I killed off other memory hogs to make sure I wasn’t swapping.

$ sudo /usr/bin/time restic2 -r . stats --no-lock --mode debug
repository 97473a5f opened (version 2, compression level auto)
[2:24] 100.00%  959 / 959 index files loaded
Collecting size statistics

File Type: key
Count: 1
Total Size: 447 B
Size            Count
---------------------
100 - 999 Byte  1
---------------------

File Type: lock
Count: 1
Total Size: 142 B
Size            Count
---------------------
100 - 999 Byte  1
---------------------

File Type: index
Count: 959
Total Size: 6.040 GiB
Size                      Count
-------------------------------
            10 - 99 Byte  1
          100 - 999 Byte  0
        1000 - 9999 Byte  2
      10000 - 99999 Byte  51
    100000 - 999999 Byte  60
  1000000 - 9999999 Byte  718
10000000 - 99999999 Byte  127
-------------------------------

File Type: data
Count: 29708
Total Size: 3.434 TiB
Size                        Count
---------------------------------
    1000000 - 9999999 Byte  30
  10000000 - 99999999 Byte  2060
100000000 - 268435456 Byte  27618
---------------------------------

Blob Type: data
Count: 16193751
Total Size: 3.321 TiB
Size                    Count
-------------------------------
          10 - 99 Byte  542091
        100 - 999 Byte  3237839
      1000 - 9999 Byte  4957889
    10000 - 99999 Byte  2604717
  100000 - 999999 Byte  3787087
1000000 - 9999999 Byte  1064128
-------------------------------


Blob Type: tree
Count: 124268339
Total Size: 110.175 GiB
Size                    Count
---------------------------------
          10 - 99 Byte  1
        100 - 999 Byte  105153033
      1000 - 9999 Byte  18210942
    10000 - 99999 Byte  879694
  100000 - 999999 Byte  23435
1000000 - 9999999 Byte  1234
---------------------------------


596.58user 15.62system 2:32.02elapsed 402%CPU (0avgtext+0avgdata 16829924maxresident)k
12115968inputs+14784outputs (60947major+3343133minor)pagefaults 0swaps

This should be directly comparable as my fileserver does zfs snapshots, and the daily for 1-25 hasn’t expired yet. I exported the snapshot via NFS so everything should be exactly the same as it was when I posted.

There’s very little nfs IOPS going on until you restore, the indexes are cached locally on nvme. I tried the same command on the server and it takes the same amount of time ± a few seconds. You can see that system time (waiting on disk, generally) is only a few seconds of the total. stats of a specific snapshot hit the iops a bit harder, but that was still only 40s of the 8m 25.

Here, same command, same snapshot. restic stats c3fcf9e One run locally on the server, the other over nfs:

980.79user 23.73system 8:27.79elapsed 197%CPU (0avgtext+0avgdata 17138356maxresident)k
923.36user 40.88system 8:25.84elapsed 190%CPU (0avgtext+0avgdata 16983356maxresident)k

17 seconds less (out of 500) spent on NFS IO but the server’s single-core performance is a bit slower so it ends up being the same.

I’ve got 40g fiber to my NAS. It’s good enough that I can play games off restic mount. Once whatever single-threaded portion is done it’s really fast.

I will revise one thing from my initial observation: it’s not a single thread, it’s two. The majority of the time is spent with 2 cores pegged 100%. You can see that total CPU usage is slightly less than two cores, despite it starting out using 8 or so in the very initial index read.

So the longest-running portion does use multiple threads… but only two?

I ran a prune which got rid of 400 snapshots (down to 510). Tree blobs went from 125m to 77 million, data blobs still ~16million. Time for restic stats went from 8:25 to 7:50, not a significant decrease. Time for restic stats –mode debug dropped from 2:32 to 1:47.

5

That’s still a quite high number of tree blobs. Even at 22 million files the number of tree blobs shouldn’t be that high.

Are you maybe backing up from zfs snapshots? If yes, you might want to look at restic/changelog/0.17.0_2024-07-26/pull-4006 at master · restic/restic · GitHub which should significantly reduce the growth of tree blobs. Currently, all tree blobs are rewritten when backing up from a different zfs snapshot, this changes with that feature flag. (The RESTIC_FEATURES=device-id-for-hardlinks alpha feature is fully compatible with the normal restic data format except that the tree serialization slightly changes. In the worst case this can prevent some deduplication, but the snapshots will remain perfectly readable.)

For my repository with 10 million blobs total, loading the index takes roughly 7 seconds, which is a bit faster than 1 million blobs per second. The performance numbers you’ve posted also seem to be in the same range. I’ll try to see whether I can find a way to speed things up.

6

index: speed up masterindex merging by MichaelEischer · Pull Request #5713 · restic/restic · GitHub should optimize the index merging step by a factor 3 or more. Right now I don’t have a good idea how to optimize this much further as most of the time required for merging a single index entry is by now spent on the single RAM access required to check whether an identical entry already exists. (Inserting the index entry afterwards is rather cheap as the previous check already fetched the required data into the CPU cache.)

Parallelizing the index merging also won’t help much, that is, as long as the goal is to merge all of them into a single index. It might be an option to keep multiple indexes around, although I’m not yet entirely sure how much of a performance impact that will have on commands like check or prune.

7

E: Sorry, I dislike the discourse UI and it ended up posting a half-written message. Fixed.

That sounds exactly like why my tree growth is so high. Not ZFS, but I am using BTRFS snapshots and backing up from those. BTRFS subvolume 0 is not the root, the parent of the root. That’s pretty normal in btrfs deployments. the real root is mounted at /.root (and /.home, for that filesystem)

backup script as as follows:

btrfs su snap /.root/root -r /.root/nightly-backup
btrfs su snap /.home/home -r /.home/nightly-backup
mount /.home/nightly-backup /.root/nightly-backup/home -o bind
<bind mount in /root/.cache/restic and the repo NFS here, as well as a writable /tmp>
chroot /.root/nightly-backup <restic backup of />

I’ve added the flag to the nightly backups. What stat should I check tomorrow to see if it made a difference?

What does “prevent some deduplication” entail? I would assume of tree data, not of data blobs, as those should be chunk-deduplicated.

I’ve begin a new cold storage repo for my monthlies using restic copy (properly initialized with copied chunking parameters) and I’m pulling all the monthlies out of my ‘hot’ repo as they’re copied. So the tree blobs should drop as the daily/weekly snapshots expire.

Is it possible to rewrite older backups to reduce the metadata use? It will stop growing so fast at least, and each new month won’t add many more tree blobs, but it’s still a big overhead. Worst case I’ll make a split, keeping all the oldest snapshots on their own repo and starting a fresh monthly cold storage with the newer, less metadata-heavy snapshots.

Thank you very much for looking into this! I see your next message that you’ve made some changes, I’ll try to do a build from the official docker container and test it.

8

That’s quite the speedup. Testing on my pathological repo sample, simple commands went from ~150 seconds to 40 or so.

There’s still the minor issue that restic mount reports the mountpoint is ready before it is actually ready, but that’s only another 30 seconds now instead of 3-4 minutes before. A minor irritant rather than “go get a drink while waiting”.

(repeating what was in the op but Restic outputs Now serving the repository at /mountpoint but any access of /mountpoint hangs until whatever second stage processing is complete. Total time before I can use the mount down from 5 minutes to roughly 60 seconds.)
All times for the patch and stock freshly re-run as for whatever reason I have only 550 indexes instead of 1000 now, even when using the repo snapshot from the day I posted.

restic stats <snapshot> down to 6:49 from 8:20.
restic stats –mode debugcompletes in 41 seconds, stock 110s.

Appreciate it! I’m going to use this for read-only commands while keeping the official binary for backups until it’s had more testing, but I haven’t seen any issues.

9

With the feature flag, the deviceID is only stored for hardlinks, where it is necessary to detect the hardlinks. That leads to a different serialization than before, but solves the duplicate trees problem in most cases.

There’s currently no such filter implemented.

10

Ok, so the next backup will still have the full 22 million tree entries due to the change in serialization, but then the one after that should mostly dedupe the tree properly? That’s reasonable.

Thank you for your time.

11

Each backup usually adds at least one index. Prune is often able to merge them. BUt for the loading speed the number of indexes should barely matter.

Thanks for testing! I just took a look at the mount command and it currently loads the index twice :see_no_evil_monkey: .

12

There will be a new tree blob for every directory, not file. But other than that yes.

13

mount: avoid duplicate index loading by MichaelEischer · Pull Request #5720 · restic/restic · GitHub should take care of the extra delay that occurred when using the mount command. Note that this PR does not include the other index optimizations.

1 Like