Repeated slow snapshots with b2

aebrett · March 20, 2019, 11:26pm

I’ve been trying restic out with b2, and I’ve noticed that just getting a listing of the current snapshots is very slow, even with repeated invocations of the same command. My understanding was that a cache would be used to improve performance, but that doesn’t seem to be the case for me. I’ve got a repo with 3 snapshots; the first one is very small and the other two are, I would guess, around 500GB. Here’s what I get if I run restic snapshots twice in succession - are these timings expected?

root@maine:~# time restic -vv snapshots; time restic -vv snapshots
repository d16610ba opened successfully, password is correct
ID        Date                 Host        Tags        Directory
----------------------------------------------------------------------
804c3403  2018-07-31 22:46:13  maine                   /home/andrew/tmp/restic-test
646c7f68  2018-09-02 23:51:53  maine                   /var/media/photos/library
df4b4e00  2018-09-21 08:13:24  maine                   /var/media/photos/library
----------------------------------------------------------------------
3 snapshots

real    41m32.095s
user    0m7.173s
sys     0m1.567s
repository d16610ba opened successfully, password is correct
ID        Date                 Host        Tags        Directory
----------------------------------------------------------------------
804c3403  2018-07-31 22:46:13  maine                   /home/andrew/tmp/restic-test
646c7f68  2018-09-02 23:51:53  maine                   /var/media/photos/library
df4b4e00  2018-09-21 08:13:24  maine                   /var/media/photos/library
----------------------------------------------------------------------
3 snapshots

real    60m0.810s
user    0m7.162s
sys     0m1.635s

cdhowie · March 20, 2019, 11:31pm

What’s the combined size of the repository index files?

aebrett · March 20, 2019, 11:38pm

How can I determine the size of the index files?

cdhowie · March 20, 2019, 11:50pm

You can use rclone size from the command line. Alternatively, the B2 web user interface should be able to tell you this.

764287 · March 21, 2019, 8:17am

Can you check the latency from your host to Backblaze? This can make a huge difference.

aebrett · March 21, 2019, 10:48pm

Not sure if this is what you’re looking for, but here’s what the web interface tells me about the bucket:
Type: Private
File Lifecycle: Keep all versions
Snapshots: 0
Current Files: 97,374
Current Size: 475 GB

aebrett · March 21, 2019, 10:52pm

Latency to api002.backblazeb2.com is around 140ms.

cdhowie · March 22, 2019, 12:09am

I’m asking about the size of the index/ prefix, not the total bucket size.

fd0 · March 22, 2019, 7:26am

Not at all, it should be much faster, something is going on here. If you want, you can try building restic with debug support and write a log, it will include all requests and responses to B2. Maybe you can see something there.

What restic does when the snapshots command is run is just the following:

Create new lock file in the repo
List snapshot files
Load all snapshot files from the repo (or the local cache)
Print matching snapshots (or all)

All in all I’d expect at most a megabyte of data transferred between your client and B2.

B2 is a bit peculiar: all error handling is pushed to the client, so if the service has as temporary issue, the clients are mandated to try over and over again. Maybe this happened here? You should be able to see that in the debug log.

If you chose to upload the debug log somewhere, please make sure that you B2 access credentials are removed!

aebrett · March 25, 2019, 10:26pm

Thanks. I’ve built restic with debugging turned on; note that ‘restic snapshot’ is still running but terms of the requests it makes what I see is:

$ cat /tmp/restic-debug.log | egrep '(GET|POST)'
GET /b2api/v1/b2_authorize_account HTTP/1.1
POST /b2api/v1/b2_list_buckets HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
POST /b2api/v1/b2_get_file_info HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/keys/d42c2145ee763a90a73c68f56117c5e0ba8c7524cc04ddfe681698908f3319f1 HTTP/1.1
GET /file/bretts-restic/keys/d42c2145ee763a90a73c68f56117c5e0ba8c7524cc04ddfe681698908f3319f1 HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
***snip around 2000 similar pairs of GET requests for lock files***
GET /file/bretts-restic/locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01 HTTP/1.1
GET /file/bretts-restic/locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01 HTTP/1.1

It all just seems to be pairs of GET requests for lockfiles, with gradually increasing IDs (I’m guessing it will complete when it gets to ‘ff…’. An example of the two request/response pairs for a sample lockfile is:

2019/03/25 22:19:32 repository/repository.go:72 repository.(*Repository).LoadAndDecrypt 1       load lock with id 650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01
2019/03/25 22:19:32 cache/backend.go:196        cache.(*Backend).Load   1       Load(<lock/650fcf97f0>, 0, 0): delegating to backend
2019/03/25 22:19:32 b2/b2.go:151        b2.(*b2Backend).openReader      1       Load <lock/650fcf97f0>, length 0, offset 0 from locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01
2019/03/25 22:19:32 debug/round_tripper_debug.go:77     debug.loggingRoundTripper.RoundTrip     14190   ------------  HTTP REQUEST -----------
GET /file/bretts-restic/locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01 HTTP/1.1
Host: f002.backblazeb2.com
User-Agent: blazer/0.5.3
Authorization: 4_00280cb5feede320000000000_018b1c51_fb1425_acct_o0lhy3tz5ZHl0mvqo8438TeYF7c=
Range: bytes=0-9999999
X-Blazer-Method: b2_download_file_by_name
X-Blazer-Request-Id: 2180


2019/03/25 22:19:32 debug/round_tripper_debug.go:90     debug.loggingRoundTripper.RoundTrip     14190   ------------  HTTP RESPONSE ----------
HTTP/1.1 200 
Content-Length: 144
Accept-Ranges: bytes
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/octet-stream
Date: Mon, 25 Mar 2019 22:19:31 GMT
X-Bz-Content-Sha1: 2f017b5888556b552442b1637c05d706e1d4afcd
X-Bz-File-Id: 4_z98c04cfb25dffe2e6d4e0312_f10134d8b88e72300_d20180919_m161446_c002_v0001110_t0052
X-Bz-File-Name: locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01
X-Bz-Upload-Timestamp: 1537373686000


2019/03/25 22:19:32 debug/round_tripper_debug.go:77     debug.loggingRoundTripper.RoundTrip     14190   ------------  HTTP REQUEST -----------
GET /file/bretts-restic/locks/650fcf97f067fdb04bbd4835df9780eaed6af028ec2a2623e7377e80e217be01 HTTP/1.1
Host: f002.backblazeb2.com
User-Agent: blazer/0.5.3
Authorization: 4_00280cb5feede320000000000_018b1c51_fb1425_acct_o0lhy3tz5ZHl0mvqo8438TeYF7c=
Range: bytes=10000000-19999999
X-Blazer-Method: b2_download_file_by_name
X-Blazer-Request-Id: 2181


2019/03/25 22:19:32 debug/round_tripper_debug.go:90     debug.loggingRoundTripper.RoundTrip     14190   ------------  HTTP RESPONSE ----------
HTTP/1.1 416 
Content-Length: 130
Cache-Control: max-age=0, no-cache, no-store
Content-Type: application/json;charset=utf-8
Date: Mon, 25 Mar 2019 22:19:31 GMT

Immediately following that I see the next “load lock” log line for a different ID. When I originally uploaded the snapshots (around 6 months ago), I was on a pretty slow connection (about 1Mbit/s upload); my broadband was recently upgraded to 50Mbit/s upload, which is why I’m picking this up again. Could it be that, when originally backing up, commands were timing out and leaving behind stale lockfiles, which never got deleted and so just built up over time?

Let me know if you’d like any more logging.

aebrett · March 25, 2019, 10:57pm

OK, the snapshots command has now completed. Here’s the list of requests (with almost all the lockfile GET requests excluded). It looks like the lock files are actually each requested four times (in two pairs of two):

$ cat /tmp/restic-debug.log | egrep '(GET|POST)' | grep -v 'locks/[1-f]' | grep -v 'locks/0[1-f]'
GET /b2api/v1/b2_authorize_account HTTP/1.1
POST /b2api/v1/b2_list_buckets HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
POST /b2api/v1/b2_get_file_info HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/keys/d42c2145ee763a90a73c68f56117c5e0ba8c7524cc04ddfe681698908f3319f1 HTTP/1.1
GET /file/bretts-restic/keys/d42c2145ee763a90a73c68f56117c5e0ba8c7524cc04ddfe681698908f3319f1 HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
GET /file/bretts-restic/config HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
GET /file/bretts-restic/locks/00f24b73f4ae8790c7ebac80e58b5504e985a8d4265b964a7aa91c4f79f7afc8 HTTP/1.1
GET /file/bretts-restic/locks/00f24b73f4ae8790c7ebac80e58b5504e985a8d4265b964a7aa91c4f79f7afc8 HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
POST /b2api/v1/b2_get_upload_url HTTP/1.1
POST /b2api/v1/b2_upload_file/98c04cfb25dffe2e6d4e0312/c002_v0001121_t0008 HTTP/1.1
POST /b2api/v1/b2_get_upload_url HTTP/1.1
POST /b2api/v1/b2_upload_file/98c04cfb25dffe2e6d4e0312/c002_v0001121_t0026 HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/000aa166caee9c39477aeecef2a6607e55df1efe3b81c8cc6fff967a03b14cd3 HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/001d8ce71c4ecde939af7d91c446244e8c7e084373178eddede6746dccfb813b HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/00609dda43c07c1fff4a701aa61a57f4cf2649b8ee29709ba981c248ee958d7e HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/0068539bf07a719dc3c9b2298a5a0d0fb366817f9e04116a7e43a68704dc5b90 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/006fc0906532bcce7d9eb23cc6174c358f8e9bb71d5f13d9789bd8b2acb75229 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/007ad03bace5c09a340219e975cd6c927421ca8ee065f8f6d11f6bc53c26abc3 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00e291bdac01f9ef737859a3c7bc801f4a84cdc4f5ca3cdd7fc376efc2fce153 HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00ea96d579147578eabdd72dce1b1a84edc27a7acd84df49bbb36688b510eb6d HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
GET /file/bretts-restic/locks/00f0da1c4594943d75f73cb11dbf038b44f9ee6f9c855d0e9ba0d81f496206bb HTTP/1.1
GET /file/bretts-restic/locks/00f24b73f4ae8790c7ebac80e58b5504e985a8d4265b964a7aa91c4f79f7afc8 HTTP/1.1
GET /file/bretts-restic/locks/00f24b73f4ae8790c7ebac80e58b5504e985a8d4265b964a7aa91c4f79f7afc8 HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
POST /b2api/v1/b2_list_file_names HTTP/1.1
GET /file/bretts-restic/snapshots/646c7f680c0fcd42766f3d83be3d45a64a9c61002c62df3f10f87e7c8efd225d HTTP/1.1
GET /file/bretts-restic/snapshots/646c7f680c0fcd42766f3d83be3d45a64a9c61002c62df3f10f87e7c8efd225d HTTP/1.1
GET /file/bretts-restic/snapshots/df4b4e00f21c80237ba71e66bbeed2efd292491b6d986b508d19a714fce27740 HTTP/1.1
GET /file/bretts-restic/snapshots/df4b4e00f21c80237ba71e66bbeed2efd292491b6d986b508d19a714fce27740 HTTP/1.1
POST /b2api/v1/b2_delete_file_version HTTP/1.1

cdhowie · March 26, 2019, 12:46am

Restic is trying to make sure that something doesn’t have an exclusive lock on the repository. To do this, it has to download all of the lock files.

However, it looks like you have a ton of lock files left behind. Consider using restic unlock --remove-all to delete them all (when there is no restic instance running, of course – we don’t want to delete a lock that’s in use).

I speculate that your B2 application key doesn’t permit deletions, which would make restic unable to clean up its lock files. This would result in the situation you see: lots and lots of orphaned lock files, and restic checking every single one every time it does anything at all.

aebrett · March 26, 2019, 7:52am

‘restic unlock’ fixed the slowness, ‘restic snapshots’ now takes about 15 seconds. The unlock worked fine, so I don’t think it was a limitation of the application key; I guess at some point in time restic just created a whole bunch of lock files.

Thanks for all your help.

cdhowie · March 26, 2019, 1:43pm

If it created that many, it would definitely be a bug.

It’s also possible that B2 had an issue where deletions didn’t work, or perhaps the bucket has versioning enabled and somehow a bunch of locks got undeleted.