Commands running slowly

Support
1

Hi,

I’m just getting started here, playing around and tuning my setup. Any kopia command takes a long time to run, specifically it takes a long while before any output is printed. I would expect that something like kopia policy set ... or kopia snapshot list ... would take all of several seconds to complete, but they run for many minutes before even printing anything. This is quite frustrating, especially now when I am doing a bunch of tuning and manipulation.

I’m syncing to an rsync.net account and am using external ssh in order to get the ssh key from ssh-agent.

It is also taking a while (several minutes) to run “quick maintenance” after each command, which is a bit frustrating when just trying to manipulate policies or the like.

Any pointers on where to look, or is this expected?

2

That’s completely unexpected. Due to caching the interactive performance should be quite reasonable even with high latency connections.

Can you add —log-level=debug and look for STORAGE lines? Perhaps your backend is very slow. What storage are you using?

3

I ran the command kopia policy set --use-keyring --compression=none Videos/ --log-level=debug twice just now, with --log-level=debug. The first run took 765 seconds, and did a lot of quick maintenance. The second run is pasted below, which completed in 236 seconds.

The backend is rsync.net. I’m using --external to enable ssh getting the key from ssh-agent.

Upload rates to rsync.net are perfectly reasonable, and transfe/browsing VIA sftp is responsive and fast. Also browsing with kopia mount --browse is perfectly snappy once it opens, but it again takes several minutes for the command to print output and the mounting to happen.

Edit: For what its worth, judging by looking at System Monitor, most of the time the process is not using CPU or Network, so basically it seems to pause for long lengths of time to do nothing…

USER@HOSTNAME ~> time kopia policy set --use-keyring --compression=none Videos/ --log-level=debug
build version v0.8.4, available v0.8.4
no updated version available
password for /home/USER/.config/kopia/repository.config retrieved from OS keyring
launching external SSH process ssh LOGIN@LOGIN.rsync.net -s sftp
[STORAGE] ListBlobs("m")=<nil> returned 2 items and took 18.607903035s
saving 2 blobs with prefix m to cache
listed 2 index blobs with prefix m from source
finished sweeping metadata cache in 10.366221ms and retained 179625097/5242880000 bytes (3 %)
finished sweeping content cache in 15.625795ms and retained 764153951/5242880000 bytes (14 %)
finished sweeping metadata cache in 30.124535ms and retained 179625097/5242880000 bytes (3 %)
finished sweeping content cache in 33.12314ms and retained 764153951/5242880000 bytes (14 %)
finished sweeping metadata cache in 23.926403ms and retained 179625097/5242880000 bytes (3 %)
finished sweeping content cache in 26.823246ms and retained 764153951/5242880000 bytes (14 %)
[STORAGE] ListBlobs("n")=<nil> returned 10 items and took 3m50.071852465s
saving 10 blobs with prefix n to cache
listed 10 index blobs with prefix n from source
updating timestamp on /home/USER/.cache/kopia/641dec413f3d4abb/metadata/mb/9687de4503c2f656a2461aa911b01f8.f to 2021-07-25 18:45:23.020753696 +0200 CEST m=+231.785225538
combined 2 into 2 index segments
keeping unused nff77b0b397027d2f6e3140f6f44f671e-s6ec5f4f77001812a106.sndx because it's too new 2021-07-25 18:32:20.445575155 +0200 CEST
keeping unused n03714a006edd92e15f2a02005e0d8641-sf10a8af9369186ac106.sndx because it's too new 2021-07-25 18:18:48.863360271 +0200 CEST
keeping unused nb88e7fe193585d087d6890067cf5af4c-s8bc2ad6f5b0565fc106.sndx because it's too new 2021-07-25 18:12:51.985094869 +0200 CEST
keeping unused n5f12252f90fe40753fd4c8129d439122-scd53a1bede4ef613106.sndx because it's too new 2021-07-25 18:01:50.445138988 +0200 CEST
keeping unused n779432fd3638ea9a440cd739c3495551-sa0108ae682b30b49106.sndx because it's too new 2021-07-25 18:32:06.271793444 +0200 CEST
keeping unused nd66822f7611bc8de1c1a29f0a22bfb9e-s9266b8acc11dcad3106.sndx because it's too new 2021-07-25 17:51:06.156895116 +0200 CEST
keeping unused n5994b233e030ab24a8b08f87dcc21e65-sf12973f98d7c6940106.sndx because it's too new 2021-07-25 18:32:03.336838645 +0200 CEST
listing manifest contents
updating timestamp on /home/USER/.cache/kopia/641dec413f3d4abb/metadata/qe/1da489c34d8f09ee6026c7137d51f6d-sa0108ae682b30b49106.f to 2021-07-25 18:45:23.022139851 +0200 CEST m=+231.786611693
Setting policy for USER@HOSTNAME:/home/USER/Videos

 - setting compression algorithm to none

[STORAGE] PutBlob("sbf76f45b81b4da4b1cb2a32d087e3e2d-sdd9598cb7d79e284106",len=203)=<nil> took 579.661784ms
[STORAGE] PutBlob("q4e247175a5ffb4ee5bb4a17c88e35286-sdd9598cb7d79e284106",len=4282)=<nil> took 598.888107ms
[STORAGE] PutBlob("nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106",len=159)=<nil> took 722.701258ms
[STORAGE] GetMetadata("nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106")=({nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106 159 2021-07-25 18:45:22 +0200 CEST}, <nil>) took 129.232865ms
[STORAGE] DeleteBlob("sbf76f45b81b4da4b1cb2a32d087e3e2d-sdd9598cb7d79e284106")=<nil> took 70.108216ms
not closing shared manager, remaining = 1
listing manifest contents
[STORAGE] GetBlob("q4e247175a5ffb4ee5bb4a17c88e35286-sdd9598cb7d79e284106",0,-1)=({4282 bytes}, <nil>) took 810.251531ms
[STORAGE] GetBlob("kopia.maintenance",0,-1)=({3955 bytes}, <nil>) took 731.58367ms
not due for full manintenance cycle until 2021-07-26 12:49:55.667996921 +0200 CEST
not due for quick manintenance cycle until 2021-07-25 19:32:08.708823569 +0200 CEST
not due for maintenance
not closing shared manager, remaining = 1
closing shared manager
finished sweeping metadata cache in 6.856855ms and retained 179629379/5242880000 bytes (3 %)
[STORAGE] Close()=<nil> took 81.103733ms
in use heap 4038656 (delta 4038656 max 0) stack 491520 (delta 491520 max 0)

________________________________________________________
Executed in  235,54 secs      fish           external
   usr time  665,25 millis   54,00 micros  665,20 millis
   sys time  529,86 millis  643,00 micros  529,22 millis
4

It’s unclear what’s taking long time here. Can you share the log file from this run? It will have precise timestamps. The log files are in $HOME/.cache/kopia/cli-logs/ on Linux.

5

I believe this is the one:

2021-07-25 18:41:31.244 D [logger.go:254] build version v0.8.4, available v0.8.4
2021-07-25 18:41:31.244 D [logger.go:254] no updated version available
2021-07-25 18:41:31.251 D [logger.go:254] password for /home/USER/.config/kopia/repository.config retrieved from OS keyring
2021-07-25 18:41:31.251 D [logger.go:254] launching external SSH process ssh LOGIN@LOGIN.rsync.net -s sftp
2021-07-25 18:41:51.554 D [logger.go:254] [STORAGE] ListBlobs("m")=<nil> returned 2 items and took 18.607903035s
2021-07-25 18:41:51.554 D [logger.go:254] saving 2 blobs with prefix m to cache
2021-07-25 18:41:51.555 D [logger.go:254] listed 2 index blobs with prefix m from source
2021-07-25 18:42:32.957 D [logger.go:254] finished sweeping metadata cache in 10.366221ms and retained 179625097/5242880000 bytes (3 %)
2021-07-25 18:42:32.962 D [logger.go:254] finished sweeping content cache in 15.625795ms and retained 764153951/5242880000 bytes (14 %)
2021-07-25 18:43:32.987 D [logger.go:254] finished sweeping metadata cache in 30.124535ms and retained 179625097/5242880000 bytes (3 %)
2021-07-25 18:43:32.996 D [logger.go:254] finished sweeping content cache in 33.12314ms and retained 764153951/5242880000 bytes (14 %)
2021-07-25 18:44:33.014 D [logger.go:254] finished sweeping metadata cache in 23.926403ms and retained 179625097/5242880000 bytes (3 %)
2021-07-25 18:44:33.024 D [logger.go:254] finished sweeping content cache in 26.823246ms and retained 764153951/5242880000 bytes (14 %)
2021-07-25 18:45:23.018 D [logger.go:254] [STORAGE] ListBlobs("n")=<nil> returned 10 items and took 3m50.071852465s
2021-07-25 18:45:23.018 D [logger.go:254] saving 10 blobs with prefix n to cache
2021-07-25 18:45:23.019 D [logger.go:254] listed 10 index blobs with prefix n from source
2021-07-25 18:45:23.020 D [logger.go:254] updating timestamp on /home/USER/.cache/kopia/641dec413f3d4abb/metadata/mb/9687de4503c2f656a2461aa911b01f8.f to 2021-07-25 18:45:23.020753696 +0200 CEST m=+231.785225538
2021-07-25 18:45:23.021 D [logger.go:254] combined 2 into 2 index segments
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused nff77b0b397027d2f6e3140f6f44f671e-s6ec5f4f77001812a106.sndx because it's too new 2021-07-25 18:32:20.445575155 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused n03714a006edd92e15f2a02005e0d8641-sf10a8af9369186ac106.sndx because it's too new 2021-07-25 18:18:48.863360271 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused nb88e7fe193585d087d6890067cf5af4c-s8bc2ad6f5b0565fc106.sndx because it's too new 2021-07-25 18:12:51.985094869 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused n5f12252f90fe40753fd4c8129d439122-scd53a1bede4ef613106.sndx because it's too new 2021-07-25 18:01:50.445138988 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused n779432fd3638ea9a440cd739c3495551-sa0108ae682b30b49106.sndx because it's too new 2021-07-25 18:32:06.271793444 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused nd66822f7611bc8de1c1a29f0a22bfb9e-s9266b8acc11dcad3106.sndx because it's too new 2021-07-25 17:51:06.156895116 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] keeping unused n5994b233e030ab24a8b08f87dcc21e65-sf12973f98d7c6940106.sndx because it's too new 2021-07-25 18:32:03.336838645 +0200 CEST
2021-07-25 18:45:23.021 D [logger.go:254] listing manifest contents
2021-07-25 18:45:23.022 D [logger.go:254] updating timestamp on /home/USER/.cache/kopia/641dec413f3d4abb/metadata/qe/1da489c34d8f09ee6026c7137d51f6d-sa0108ae682b30b49106.f to 2021-07-25 18:45:23.022139851 +0200 CEST m=+231.786611693
2021-07-25 18:45:23.024 I [logger.go:244] Setting policy for USER@falketind:/home/USER/Videos
2021-07-25 18:45:23.024 I [logger.go:244]  - setting compression algorithm to none
2021-07-25 18:45:23.605 D [logger.go:254] [STORAGE] PutBlob("sbf76f45b81b4da4b1cb2a32d087e3e2d-sdd9598cb7d79e284106",len=203)=<nil> took 579.661784ms
2021-07-25 18:45:24.209 D [logger.go:254] [STORAGE] PutBlob("q4e247175a5ffb4ee5bb4a17c88e35286-sdd9598cb7d79e284106",len=4282)=<nil> took 598.888107ms
2021-07-25 18:45:24.932 D [logger.go:254] [STORAGE] PutBlob("nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106",len=159)=<nil> took 722.701258ms
2021-07-25 18:45:25.062 D [logger.go:254] [STORAGE] GetMetadata("nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106")=({nc7c4395270d8f67dadee7fc7de0d97bf-sdd9598cb7d79e284106 159 2021-07-25 18:45:22 +0200 CEST}, <nil>) took 129.232865ms
2021-07-25 18:45:25.132 D [logger.go:254] [STORAGE] DeleteBlob("sbf76f45b81b4da4b1cb2a32d087e3e2d-sdd9598cb7d79e284106")=<nil> took 70.108216ms
2021-07-25 18:45:25.132 D [logger.go:254] not closing shared manager, remaining = 1
2021-07-25 18:45:25.133 D [logger.go:254] listing manifest contents
2021-07-25 18:45:25.943 D [logger.go:254] [STORAGE] GetBlob("q4e247175a5ffb4ee5bb4a17c88e35286-sdd9598cb7d79e284106",0,-1)=({4282 bytes}, <nil>) took 810.251531ms
2021-07-25 18:45:26.675 D [logger.go:254] [STORAGE] GetBlob("kopia.maintenance",0,-1)=({3955 bytes}, <nil>) took 731.58367ms
2021-07-25 18:45:26.676 D [logger.go:254] not due for full manintenance cycle until 2021-07-26 12:49:55.667996921 +0200 CEST
2021-07-25 18:45:26.676 D [logger.go:254] not due for quick manintenance cycle until 2021-07-25 19:32:08.708823569 +0200 CEST
2021-07-25 18:45:26.676 D [logger.go:254] not due for maintenance
2021-07-25 18:45:26.676 D [logger.go:254] not closing shared manager, remaining = 1
2021-07-25 18:45:26.676 D [logger.go:254] closing shared manager
2021-07-25 18:45:26.683 D [logger.go:254] finished sweeping metadata cache in 6.856855ms and retained 179629379/5242880000 bytes (3 %)
2021-07-25 18:45:26.765 D [logger.go:254] [STORAGE] Close()=<nil> took 81.103733ms
2021-07-25 18:45:26.766 D [logger.go:254] in use heap 4038656 (delta 4038656 max 0) stack 491520 (delta 491520 max 0)
6

I’m having the same problem. I’m running Kopia on both Windows and Raspberry Pi Ubuntu 21.04. The repository is on a ZFS pool. All three (Windows, Pi, and ZFS pool) are currently somewhat busy and somewhat slow, but as you’ll see, that’s not the (full) explanation. I will report back if/when things change after restarting the devices.

Now, on to the logs. There’s something distinctly buggy going on with the timestamps of the “sweeping content cache” lines - a delay of exactly 1 minute at each one! I see the same in jaykayes’s log.

On the Ubuntu-Pi:
kopia policy list --log-level 'debug'

2021-08-18 19:55:10.016 D [logger.go:254] build version v0.8.4, available v0.8.4
2021-08-18 19:55:10.018 D [logger.go:254] no updated version available
2021-08-18 19:55:10.018 D [logger.go:254] password for /home/steve/.config/kopia/repository.config retrieved from password file
2021-08-18 19:55:30.128 D [logger.go:254] [STORAGE] ListBlobs("m")=<nil> returned 3 items and took 19.333527195s
2021-08-18 19:55:30.129 D [logger.go:254] saving 3 blobs with prefix m to cache
2021-08-18 19:55:30.131 D [logger.go:254] listed 3 index blobs with prefix m from source
2021-08-18 19:56:10.798 D [logger.go:254] finished sweeping content cache in 5.099931ms and retained 0/5242880000 bytes (0 %)
2021-08-18 19:56:10.811 D [logger.go:254] finished sweeping metadata cache in 15.850579ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:57:10.808 D [logger.go:254] finished sweeping content cache in 386.197µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:57:10.833 D [logger.go:254] finished sweeping metadata cache in 21.257248ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:58:10.811 D [logger.go:254] finished sweeping content cache in 721.154µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:58:10.858 D [logger.go:254] finished sweeping metadata cache in 23.905223ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:58:26.230 D [logger.go:254] [STORAGE] ListBlobs("n")=<nil> returned 45 items and took 3m15.435048591s
2021-08-18 19:58:26.230 D [logger.go:254] saving 45 blobs with prefix n to cache
2021-08-18 19:58:26.236 D [logger.go:254] listed 45 index blobs with prefix n from source
2021-08-18 19:58:26.277 D [logger.go:254] [STORAGE] GetBlob("m6fe5e244e81ebd414acff166a9307edf",0,-1)=({5057 bytes}, <nil>) took 29.970492ms
2021-08-18 19:58:26.287 D [logger.go:254] updating timestamp on /home/steve/.cache/kopia/90dd96712b38984b/metadata/mc/3757a9468a311abbce8c031b601450e.f to 2021-08-18 19:58:26.287297502 +0200 CEST m=+196.317531917
2021-08-18 19:58:26.290 D [logger.go:254] updating timestamp on /home/steve/.cache/kopia/90dd96712b38984b/metadata/me/c6a3c0e24fad126d31d336eabc10b5c.f to 2021-08-18 19:58:26.29027471 +0200 CEST m=+196.320509126
2021-08-18 19:58:26.292 D [logger.go:254] blob n65d4a7a4e8219269e3b435754cd48e92 referenced by compaction log is not found
2021-08-18 19:58:26.297 D [logger.go:254] downloading 3 new index blobs (372061 bytes)...
2021-08-18 19:58:26.330 D [logger.go:254] [STORAGE] GetBlob("n3cd96cbbc4ab283ce6bf79dfcb80bef6-sa7ed0f938cd7a661107",0,-1)=({20134 bytes}, <nil>) took 26.495291ms
2021-08-18 19:58:26.342 D [logger.go:254] [STORAGE] GetBlob("nc7d006b2d0fb939f76d3ec13b6ec4bd4-sbe8a2f6247e0e643107",0,-1)=({159 bytes}, <nil>) took 38.958803ms
2021-08-18 19:58:26.597 D [logger.go:254] [STORAGE] GetBlob("n0be7699b3b9046db58c884dce44e0b87",0,-1)=({351768 bytes}, <nil>) took 261.935614ms
2021-08-18 19:58:26.614 D [logger.go:254] Index contents downloaded.
2021-08-18 19:58:26.615 D [logger.go:254] combined 6 into 6 index segments
2021-08-18 19:58:26.617 D [logger.go:254] listing manifest contents
2021-08-18 19:58:26.673 D [logger.go:254] [STORAGE] GetBlob("qe98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107",0,-1)=({4319 bytes}, <nil>) took 55.606965ms
2021-08-18 19:58:26.717 D [logger.go:254] [STORAGE] GetBlob("q6e49d67917af9d07bd6911f5407ae9b4-s4e977fdacd1f8af6107",0,-1)=({168345 bytes}, <nil>) took 98.874768ms
2021-08-18 19:58:26.749 D [logger.go:254] [STORAGE] GetBlob("q3246b18d0e503525d2e8567552ada843-s187ec56dbe6f2e85107",0,-1)=({26219 bytes}, <nil>) took 129.437954ms
2021-08-18 19:58:26.772 D [logger.go:254] [STORAGE] GetBlob("q1fbdc3a94c22ab6c12062350a946a24e-s7ca27f789fdcf7da107",0,-1)=({4282 bytes}, <nil>) took 96.872562ms
2021-08-18 19:58:26.781 D [logger.go:254] [STORAGE] GetBlob("qc0c8bcac8b327282fafcc4506a5d80d5-s191538e03c11e466107",0,-1)=({4282 bytes}, <nil>) took 162.673409ms
2021-08-18 19:58:26.817 D [logger.go:254] [STORAGE] GetBlob("q470927153e125846dc196bc7ac7005b4-sbe8a2f6247e0e643107",0,-1)=({4282 bytes}, <nil>) took 189.17307ms
2021-08-18 19:58:26.822 D [logger.go:254] closing shared manager
2021-08-18 19:58:26.831 D [logger.go:254] finished sweeping metadata cache in 8.102418ms and retained 58721847/5242880000 bytes (1 %)
2021-08-18 19:58:26.831 D [logger.go:254] [STORAGE] Close()=<nil> took 666ns
2021-08-18 19:58:26.834 D [logger.go:254] in use heap 2826240 (delta 2826240 max 0) stack 622592 (delta 622592 max 0)

kopia policy set global --snapshot-time 02:00 --log-level debug
[Edit: oops, I just realized ‘global’ should be in quotes] [Edit: nope that didn’t work either]

2021-08-18 19:53:55.428 D [logger.go:254] build version v0.8.4, available v0.8.4
2021-08-18 19:53:55.430 D [logger.go:254] no updated version available
2021-08-18 19:53:55.431 D [logger.go:254] password for /home/steve/.config/kopia/repository.config retrieved from password file
2021-08-18 19:54:17.716 D [logger.go:254] [STORAGE] ListBlobs("m")=<nil> returned 3 items and took 21.466538299s
2021-08-18 19:54:17.716 D [logger.go:254] saving 3 blobs with prefix m to cache
2021-08-18 19:54:17.719 D [logger.go:254] listed 3 index blobs with prefix m from source
2021-08-18 19:54:56.243 D [logger.go:254] finished sweeping content cache in 289.069µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:54:56.294 D [logger.go:254] finished sweeping metadata cache in 48.716153ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:55:56.243 D [logger.go:254] finished sweeping content cache in 191.885µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:55:56.304 D [logger.go:254] finished sweeping metadata cache in 8.982734ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:56:56.246 D [logger.go:254] finished sweeping content cache in 394.734µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:56:56.317 D [logger.go:254] finished sweeping metadata cache in 11.840742ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:57:56.246 D [logger.go:254] finished sweeping content cache in 208.941µs and retained 0/5242880000 bytes (0 %)
2021-08-18 19:57:56.326 D [logger.go:254] finished sweeping metadata cache in 7.48465ms and retained 58133000/5242880000 bytes (1 %)
2021-08-18 19:58:26.230 D [logger.go:254] [STORAGE] ListBlobs("n")=<nil> returned 45 items and took 4m29.982880332s
2021-08-18 19:58:26.231 D [logger.go:254] saving 45 blobs with prefix n to cache
2021-08-18 19:58:26.233 D [logger.go:254] listed 45 index blobs with prefix n from source
2021-08-18 19:58:26.275 D [logger.go:254] [STORAGE] GetBlob("m6fe5e244e81ebd414acff166a9307edf",0,-1)=({5057 bytes}, <nil>) took 28.704754ms
2021-08-18 19:58:26.287 D [logger.go:254] updating timestamp on /home/steve/.cache/kopia/90dd96712b38984b/metadata/mc/3757a9468a311abbce8c031b601450e.f to 2021-08-18 19:58:26.287452536 +0200 CEST m=+271.281918761
2021-08-18 19:58:26.290 D [logger.go:254] updating timestamp on /home/steve/.cache/kopia/90dd96712b38984b/metadata/me/c6a3c0e24fad126d31d336eabc10b5c.f to 2021-08-18 19:58:26.290318247 +0200 CEST m=+271.284784471
2021-08-18 19:58:26.291 D [logger.go:254] blob n65d4a7a4e8219269e3b435754cd48e92 referenced by compaction log is not found
2021-08-18 19:58:26.297 D [logger.go:254] downloading 3 new index blobs (372061 bytes)...
2021-08-18 19:58:26.332 D [logger.go:254] [STORAGE] GetBlob("n3cd96cbbc4ab283ce6bf79dfcb80bef6-sa7ed0f938cd7a661107",0,-1)=({20134 bytes}, <nil>) took 28.908954ms
2021-08-18 19:58:26.342 D [logger.go:254] [STORAGE] GetBlob("nc7d006b2d0fb939f76d3ec13b6ec4bd4-sbe8a2f6247e0e643107",0,-1)=({159 bytes}, <nil>) took 38.803083ms
2021-08-18 19:58:26.469 D [logger.go:254] [STORAGE] GetBlob("n0be7699b3b9046db58c884dce44e0b87",0,-1)=({351768 bytes}, <nil>) took 133.159187ms
2021-08-18 19:58:26.505 D [logger.go:254] Index contents downloaded.
2021-08-18 19:58:26.519 D [logger.go:254] combined 6 into 6 index segments
2021-08-18 19:58:26.523 D [logger.go:254] removing unused n0045f0d4e8a9155b8d61979ad296f0f8-scec216cb7369952b107.sndx 2021-08-18 17:41:23.608507626 +0200 CEST
2021-08-18 19:58:26.523 D [logger.go:254] removing unused n30f8bed4ed149661669f9ff99cc7d8ad-s7fe3ed801d2a820e107.sndx 2021-08-18 17:30:46.880897652 +0200 CEST
2021-08-18 19:58:26.524 D [logger.go:254] removing unused n7904c62e253a585b009156cea1dfb0d1.sndx 2021-08-18 17:30:47.32489025 +0200 CEST
2021-08-18 19:58:26.524 D [logger.go:254] removing unused n5d85ca46b65c90c0572e86430ee5a767-s1a377b9fecc45679107.sndx 2021-08-18 17:30:47.15689305 +0200 CEST
2021-08-18 19:58:26.524 D [logger.go:254] removing unused n9bccb80eccbc60086fcdff4420f34a3e-s1b336a16aa83d10f107.sndx 2021-08-18 17:30:47.436888382 +0200 CEST
2021-08-18 19:58:26.525 D [logger.go:254] removing unused n9d0cb743cb50b0d010eec7f3c5812a95-s936e573491b37855107.sndx 2021-08-18 17:30:47.432888449 +0200 CEST
2021-08-18 19:58:26.525 D [logger.go:254] removing unused n452936990575d598bda8d1f68e89dc1f-s859f27a99feb3554107.sndx 2021-08-18 17:30:46.880897652 +0200 CEST
2021-08-18 19:58:26.526 D [logger.go:254] removing unused n70e966d959eb5d1bc432305804f0ba15-s23a78f3765737df6107.sndx 2021-08-18 17:30:46.016912056 +0200 CEST
2021-08-18 19:58:26.526 D [logger.go:254] removing unused n974677f4c9454c4c10e76d1f5cbb33fb-sa1dde7799b15b2a2107.sndx 2021-08-18 17:30:46.392905788 +0200 CEST
2021-08-18 19:58:26.526 D [logger.go:254] removing unused n0f91d2a079ed0be61fa72fb129bbeddf-sae1aec03afc9d074107.sndx 2021-08-18 17:30:46.148909855 +0200 CEST
2021-08-18 19:58:26.526 D [logger.go:254] removing unused nb4c6a498c38c5e0ae2453f1e03ea2e9b-sc32ad59859a5e8d2107.sndx 2021-08-18 17:30:46.312907121 +0200 CEST
2021-08-18 19:58:26.527 D [logger.go:254] removing unused nd97243ebd450b4714251f1fa81a12793-sbc23bfee57b3d074107.sndx 2021-08-18 17:30:46.896897385 +0200 CEST
2021-08-18 19:58:26.527 D [logger.go:254] removing unused ne28b107a63140f1198d5c89c968c564a-scb43c93ed7ff60b2107.sndx 2021-08-18 17:41:23.648507135 +0200 CEST
2021-08-18 19:58:26.527 D [logger.go:254] removing unused n167747e728408a806820fafcae7b269f-se78e1f237bde8cce107.sndx 2021-08-18 17:30:47.580885981 +0200 CEST
2021-08-18 19:58:26.528 D [logger.go:254] removing unused n1edac404faf4cc9a987ff7bbf312343a-s03aa88c346d267bf107.sndx 2021-08-18 17:30:47.112893784 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused n31c0a6dfd9fe06eff5f7f37094327ea0-s447724627af1af92107.sndx 2021-08-18 17:30:47.760882981 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused n87337cd8e78571a1f4012e0c41262436-s6d127163dc5ad5ca107.sndx 2021-08-18 17:30:46.364906254 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused nd509339b4a089bc44ab0396a85ac751c-s4b72e77568e2eb1e107.sndx 2021-08-18 17:30:47.196892384 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused n6195042f9ef2d8a109e66d6b36d04836-s8244f56d2e6e00a8107.sndx 2021-08-18 17:30:46.196909055 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused n7ce260a2b5ffd62864b8f8bc736252fe-s5fbdb09772e97feb107.sndx 2021-08-18 17:30:46.028911856 +0200 CEST
2021-08-18 19:58:26.533 D [logger.go:254] removing unused n8d8d31f1b796366a4810aa7cdcc255cf-sc39db22371c51308107.sndx 2021-08-18 17:41:23.41251003 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n0552c5314cf960ebf91369b4ab12379c-sbf77458ce7608502107.sndx 2021-08-18 17:30:47.428888516 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n2b4fe52768dd210d12c5247a20249228-sce760dc68002180f107.sndx 2021-08-18 17:30:46.58890252 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n677b57d087bcaf42f4288c10642d5f64-s3cd16d9724f27e6b107.sndx 2021-08-18 17:30:47.680884314 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n778964aab6cf8b9acc8b6722acae7988-s7ef6437f1e767e67107.sndx 2021-08-18 17:30:47.428888516 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n16cae66cc81669adaafe2a3c203474d1-sc26d136a7e760cc1107.sndx 2021-08-18 17:30:46.700900653 +0200 CEST
2021-08-18 19:58:26.534 D [logger.go:254] removing unused n3787763970e2d81c3ed2195250aedca5-s39474d94d65170a8107.sndx 2021-08-18 17:30:46.848898185 +0200 CEST
2021-08-18 19:58:26.535 D [logger.go:254] listing manifest contents
2021-08-18 19:58:26.675 D [logger.go:254] [STORAGE] GetBlob("qe98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107",0,-1)=({4319 bytes}, <nil>) took 79.251768ms
2021-08-18 19:58:26.717 D [logger.go:254] [STORAGE] GetBlob("q6e49d67917af9d07bd6911f5407ae9b4-s4e977fdacd1f8af6107",0,-1)=({168345 bytes}, <nil>) took 121.190853ms
2021-08-18 19:58:26.745 D [logger.go:254] [STORAGE] GetBlob("q3246b18d0e503525d2e8567552ada843-s187ec56dbe6f2e85107",0,-1)=({26219 bytes}, <nil>) took 149.139046ms
2021-08-18 19:58:26.772 D [logger.go:254] [STORAGE] GetBlob("q1fbdc3a94c22ab6c12062350a946a24e-s7ca27f789fdcf7da107",0,-1)=({4282 bytes}, <nil>) took 94.416399ms
2021-08-18 19:58:26.781 D [logger.go:254] [STORAGE] GetBlob("qc0c8bcac8b327282fafcc4506a5d80d5-s191538e03c11e466107",0,-1)=({4282 bytes}, <nil>) took 184.654684ms
2021-08-18 19:58:26.817 D [logger.go:254] [STORAGE] GetBlob("q470927153e125846dc196bc7ac7005b4-sbe8a2f6247e0e643107",0,-1)=({4282 bytes}, <nil>) took 209.37695ms
2021-08-18 19:58:26.819 I [logger.go:244] Setting policy for steve@pi:/media/steve/O2-4TB-ext4/timeshift/snapshots/global
2021-08-18 19:58:26.820 I [logger.go:244]  - setting snapshot times to [2:00]
2021-08-18 19:58:26.904 D [logger.go:254] [STORAGE] PutBlob("s6db8dd2e72fa77b7a7817ff361711290-sd89ff28cbf77cb17107",len=197)=<nil> took 80.717817ms
2021-08-18 19:58:26.963 D [logger.go:254] [STORAGE] PutBlob("qefcda4d6c7f3fdaf605ff90202623d37-sd89ff28cbf77cb17107",len=4282)=<nil> took 37.204017ms
2021-08-18 19:58:26.979 D [logger.go:254] [STORAGE] PutBlob("n70a661cedf10d32b21c8039798d7ec72-sd89ff28cbf77cb17107",len=159)=<nil> took 15.547366ms
2021-08-18 19:58:26.979 D [logger.go:254] [STORAGE] GetMetadata("n70a661cedf10d32b21c8039798d7ec72-sd89ff28cbf77cb17107")=({n70a661cedf10d32b21c8039798d7ec72-sd89ff28cbf77cb17107 159 2021-08-18 19:58:26.972894748 +0200 CEST}, <nil>) took 40.259µs
2021-08-18 19:58:26.980 D [logger.go:254] [STORAGE] DeleteBlob("s6db8dd2e72fa77b7a7817ff361711290-sd89ff28cbf77cb17107")=<nil> took 295.143µs
2021-08-18 19:58:26.981 D [logger.go:254] not closing shared manager, remaining = 1
2021-08-18 19:58:26.983 D [logger.go:254] listing manifest contents
2021-08-18 19:58:26.986 D [logger.go:254] [STORAGE] GetBlob("qefcda4d6c7f3fdaf605ff90202623d37-sd89ff28cbf77cb17107",0,-1)=({4282 bytes}, <nil>) took 350.235µs
2021-08-18 19:58:26.994 D [logger.go:254] not closing shared manager, remaining = 1
2021-08-18 19:58:26.995 D [logger.go:254] closing shared manager
2021-08-18 19:58:27.004 D [logger.go:254] finished sweeping metadata cache in 8.212583ms and retained 58726129/5242880000 bytes (1 %)
2021-08-18 19:58:27.004 D [logger.go:254] [STORAGE] Close()=<nil> took 593ns
2021-08-18 19:58:27.007 D [logger.go:254] in use heap 3694592 (delta 3694592 max 0) stack 622592 (delta 622592 max 0)

Meanwhile, while running the above commands, I benchmarked the directory which holds the Kopia repository:

# Random read benchmark. Note: a minute earlier, this was 4 MiB/s; again, the system is somewhat busy.
--- /tank/--- Backups/Kopia (zfs pool/steve 6.27 TiB) ioping statistics ---
837 requests completed in 3.01 s, 3.27 MiB read, 277 iops, 1.09 MiB/s
generated 838 requests in 3.02 s, 3.27 MiB, 277 iops, 1.09 MiB/s
min/avg/max/mdev = 14.3 us / 3.60 ms / 168.2 ms / 17.0 ms

# Linear write benchmark:
$ ioping -RLW -- '/tank/--- Backups/Kopia'

--- /tank/--- Backups/Kopia (zfs pool/steve 6.27 TiB) ioping statistics ---
213 requests completed in 23.2 s, 53.2 MiB written, 9 iops, 2.29 MiB/s
generated 214 requests in 23.2 s, 53.5 MiB, 9 iops, 2.30 MiB/s
min/avg/max/mdev = 235.8 us / 108.9 ms / 23.1 s / 1.58 s

[Probably not relevant, but I do notice that on the bottom line, there was apparently one write which took 23 seconds! When I ran it again, the bottom line read min/avg/max/mdev = 198.6 us / 478.3 us / 2.23 s / 23.2 ms. I don’t know whether this is related to the Kopia slowness, but regardless, Kopia’s commands are running faaaaar slower than anything else on either system.]

Note: I ran the same commands both with and without “sudo ionice -c 1 nice -n -10” in front. This causes them to run with “realtime” I/O priority and high CPU priority.

7

On Windows, the same 1-minute delays happened. These constituted the entirety of the delay for .\kopia.exe policy list.

But here’s a hint! On Windows, “finished sweeping metadata cache” comes before “content”, and it’s the one associated with the one-minute delay.

Windows: .\kopia.exe policy list (without --log-level debug)`

2021-08-18 18:12:27.100 D [logger.go:254] unable to check for updates: unable to open update state file: open C:\Users\steve\AppData\Roaming\kopia\repository.config.update-info.json: The system cannot find the file specified.
2021-08-18 18:12:27.108 D [logger.go:254] password for C:\Users\steve\AppData\Roaming\kopia\repository.config retrieved from OS keyring
2021-08-18 18:13:34.925 D [logger.go:254] finished sweeping metadata cache in 37.5943ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:13:35.169 D [logger.go:254] finished sweeping content cache in 281.6361ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:14:34.962 D [logger.go:254] finished sweeping metadata cache in 33.1926ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:14:35.443 D [logger.go:254] finished sweeping content cache in 262.3564ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:15:35.016 D [logger.go:254] finished sweeping metadata cache in 50.0018ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:15:35.748 D [logger.go:254] finished sweeping content cache in 294.5279ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:16:35.091 D [logger.go:254] finished sweeping metadata cache in 66.0869ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:16:36.023 D [logger.go:254] finished sweeping content cache in 266.5322ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:17:35.140 D [logger.go:254] finished sweeping metadata cache in 35.0618ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:17:36.313 D [logger.go:254] finished sweeping content cache in 282.4032ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:18:35.189 D [logger.go:254] finished sweeping metadata cache in 33.5929ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:18:36.573 D [logger.go:254] finished sweeping content cache in 246.9369ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:19:35.241 D [logger.go:254] finished sweeping metadata cache in 41.1881ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:19:36.066 D [logger.go:254] [STORAGE] ListBlobs("m")=<nil> returned 2 items and took 7m1.1790864s
2021-08-18 18:19:36.069 D [logger.go:254] saving 2 blobs with prefix m to cache
2021-08-18 18:19:36.078 D [logger.go:254] listed 2 index blobs with prefix m from source
2021-08-18 18:19:37.042 D [logger.go:254] finished sweeping content cache in 458.8276ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:20:35.286 D [logger.go:254] finished sweeping metadata cache in 40.2111ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:20:37.308 D [logger.go:254] finished sweeping content cache in 261.3295ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:21:35.330 D [logger.go:254] finished sweeping metadata cache in 33.7316ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:21:37.580 D [logger.go:254] finished sweeping content cache in 257.5337ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:22:35.372 D [logger.go:254] finished sweeping metadata cache in 39.496ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:22:37.837 D [logger.go:254] finished sweeping content cache in 245.5003ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:23:35.415 D [logger.go:254] finished sweeping metadata cache in 31.7883ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:23:38.341 D [logger.go:254] finished sweeping content cache in 496.1323ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:24:35.454 D [logger.go:254] finished sweeping metadata cache in 32.0017ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:24:38.647 D [logger.go:254] finished sweeping content cache in 299.6965ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:25:35.503 D [logger.go:254] finished sweeping metadata cache in 36.612ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:25:38.982 D [logger.go:254] finished sweeping content cache in 325.0981ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:26:35.543 D [logger.go:254] finished sweeping metadata cache in 36.433ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:26:39.288 D [logger.go:254] finished sweeping content cache in 292.8188ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:27:35.589 D [logger.go:254] finished sweeping metadata cache in 33.1192ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:27:39.600 D [logger.go:254] finished sweeping content cache in 308.9999ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:28:35.640 D [logger.go:254] finished sweeping metadata cache in 39.3245ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:28:39.869 D [logger.go:254] finished sweeping content cache in 266.4236ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:29:35.686 D [logger.go:254] finished sweeping metadata cache in 38.5163ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:29:40.165 D [logger.go:254] finished sweeping content cache in 287.8973ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:30:35.833 D [logger.go:254] finished sweeping metadata cache in 133.8513ms and retained 1456396931/5242880000 bytes (27 %)
2021-08-18 18:30:40.535 D [logger.go:254] finished sweeping content cache in 357.3806ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:31:35.875 D [logger.go:254] finished sweeping metadata cache in 38.0765ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:31:40.907 D [logger.go:254] finished sweeping content cache in 357.9353ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:32:35.925 D [logger.go:254] finished sweeping metadata cache in 49.2384ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:32:41.224 D [logger.go:254] finished sweeping content cache in 303.0125ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:33:35.972 D [logger.go:254] finished sweeping metadata cache in 45.404ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:33:41.539 D [logger.go:254] finished sweeping content cache in 309.48ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:34:36.033 D [logger.go:254] finished sweeping metadata cache in 57.063ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:34:42.097 D [logger.go:254] finished sweeping content cache in 550.2118ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:35:36.145 D [logger.go:254] finished sweeping metadata cache in 109.7605ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:35:42.473 D [logger.go:254] finished sweeping content cache in 365.824ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:36:36.258 D [logger.go:254] finished sweeping metadata cache in 109.8749ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:36:42.784 D [logger.go:254] finished sweeping content cache in 308.801ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:37:36.385 D [logger.go:254] finished sweeping metadata cache in 123.7814ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:37:43.219 D [logger.go:254] finished sweeping content cache in 423.2413ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:38:36.501 D [logger.go:254] finished sweeping metadata cache in 102.7661ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:38:43.510 D [logger.go:254] finished sweeping content cache in 288.5197ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:39:36.608 D [logger.go:254] finished sweeping metadata cache in 98.0263ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:39:43.814 D [logger.go:254] finished sweeping content cache in 299.0091ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:40:36.772 D [logger.go:254] finished sweeping metadata cache in 149.2412ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:40:44.181 D [logger.go:254] finished sweeping content cache in 362.3572ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 18:41:36.874 D [logger.go:254] finished sweeping metadata cache in 102.5215ms and retained 1456431713/5242880000 bytes (27 %)
2021-08-18 18:41:36.875 D [logger.go:254] [STORAGE] ListBlobs("n")=<nil> returned 56 items and took 29m1.9896318s
2021-08-18 18:41:36.876 D [logger.go:254] saving 56 blobs with prefix n to cache
2021-08-18 18:41:36.884 D [logger.go:254] listed 56 index blobs with prefix n from source
2021-08-18 18:41:36.894 D [logger.go:254] own-writes-cache-expired: {n2535303b835d63e9252a0d95f3157ef4-s3cfa71c53d6066d0107 125 2021-08-18 18:26:17.7945858 +0200 CEST} (15m19.0995585s)
2021-08-18 18:41:36.896 D [logger.go:254] own-writes-cache-expired: {n2b1e9a5e2a8fc68e5d9f752c83f68e12-s540eb613ec534610107 125 2021-08-18 18:16:07.4862565 +0200 CEST} (25m29.4098863s)
2021-08-18 18:41:36.900 D [logger.go:254] own-writes-cache-expired: {n98a519d44185b907407192ca8e97541b-se44f84726cb29a2b107 125 2021-08-18 18:05:36.1036145 +0200 CEST} (36m0.7965287s)
2021-08-18 18:41:36.914 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/mc/3757a9468a311abbce8c031b601450e.f to 2021-08-18 18:41:36.9141422 +0200 CEST m=+1749.871508001
2021-08-18 18:41:36.921 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/me/c6a3c0e24fad126d31d336eabc10b5c.f to 2021-08-18 18:41:36.9211414 +0200 CEST m=+1749.878507201
2021-08-18 18:41:36.984 D [logger.go:254] combined 35 into 8 index segments
2021-08-18 18:41:36.985 D [logger.go:254] keeping unused n2535303b835d63e9252a0d95f3157ef4-s3cfa71c53d6066d0107.sndx because it's too new 2021-08-18 18:26:18.5943009 +0200 CEST
2021-08-18 18:41:36.994 D [logger.go:254] listing manifest contents
2021-08-18 18:41:37.005 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q3/246b18d0e503525d2e8567552ada843-s187ec56dbe6f2e85107.f to 2021-08-18 18:41:37.005462 +0200 CEST m=+1749.962827801
2021-08-18 18:41:37.251 D [logger.go:254] [STORAGE] GetBlob("qe98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107",0,-1)=({4319 bytes}, <nil>) took 246.175ms
2021-08-18 18:41:37.270 D [logger.go:254] closing shared manager
2021-08-18 18:41:37.310 D [logger.go:254] finished sweeping metadata cache in 39.0003ms and retained 1456436032/5242880000 bytes (27 %)
2021-08-18 18:41:37.310 D [logger.go:254] [STORAGE] Close()=<nil> took 0s
2021-08-18 18:41:37.312 D [logger.go:254] in use heap 2908160 (delta 2908160 max 0) stack 327680 (delta 327680 max 0)
8

However, .\kopia.exe policy set global --snapshot-time 02:00 --log-level debug had some quite significant [STORAGE] delays. I can’t be sure whether that’s my system’s fault, or a Kopia bug – though some of them do seem very long, even for this system, while others are almost instantaneous. Note that these [STORAGE] delays actually report how long they take (e.g. “took 10.0399251s”) whereas the “sweeping metadata cache” lines don’t.

Possibly another hint! There’s a pair of “sweeping metadata/content cache” lines after the " - setting snapshot times to [2:00]" line, and there’s no corresponding 1-minute delay.

Windows .\kopia.exe policy set global --snapshot-time 02:00 --log-level debug
This log is 11KB so I had to cut out some (uninteresting) lines in the middle.

2021-08-18 19:50:46.871 D [logger.go:254] unable to check for updates: unable to open update state file: open C:\Users\steve\AppData\Roaming\kopia\repository.config.update-info.json: The system cannot find the file specified.
2021-08-18 19:50:46.883 D [logger.go:254] password for C:\Users\steve\AppData\Roaming\kopia\repository.config retrieved from OS keyring
2021-08-18 19:52:08.990 D [logger.go:254] finished sweeping metadata cache in 101.4959ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:52:09.170 D [logger.go:254] finished sweeping content cache in 281.7228ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:53:09.102 D [logger.go:254] finished sweeping metadata cache in 101.5123ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:53:09.511 D [logger.go:254] finished sweeping content cache in 326.0739ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:54:09.224 D [logger.go:254] finished sweeping metadata cache in 108.4654ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:54:09.803 D [logger.go:254] finished sweeping content cache in 292.0479ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:55:09.329 D [logger.go:254] finished sweeping metadata cache in 102.7041ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:55:10.105 D [logger.go:254] finished sweeping content cache in 287.1826ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:56:09.463 D [logger.go:254] finished sweeping metadata cache in 123.9879ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:56:10.472 D [logger.go:254] finished sweeping content cache in 352.599ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:57:09.598 D [logger.go:254] finished sweeping metadata cache in 125.2912ms and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:57:10.825 D [logger.go:254] finished sweeping content cache in 338.3498ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:58:10.722 D [logger.go:254] finished sweeping metadata cache in 1.123308s and retained 1456757639/5242880000 bytes (27 %)
2021-08-18 19:58:13.173 D [logger.go:254] finished sweeping content cache in 2.3377485s and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 19:59:04.938 D [logger.go:254] [STORAGE] ListBlobs("m")=<nil> returned 3 items and took 7m56.0574129s
2021-08-18 19:59:04.941 D [logger.go:254] saving 3 blobs with prefix m to cache
2021-08-18 19:59:04.959 D [logger.go:254] listed 3 index blobs with prefix m from source
2021-08-18 19:59:30.009 D [logger.go:254] finished sweeping metadata cache in 174.1437ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 19:59:30.212 D [logger.go:254] finished sweeping content cache in 377.3701ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:00:30.128 D [logger.go:254] finished sweeping metadata cache in 115.1935ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:00:30.518 D [logger.go:254] finished sweeping content cache in 305.2103ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:01:30.264 D [logger.go:254] finished sweeping metadata cache in 125.9005ms and retained 1456757809/5242880000 bytes (27 %)
[...46 lines of the same ...]
2021-08-18 20:24:33.589 D [logger.go:254] finished sweeping metadata cache in 115.1467ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:24:39.309 D [logger.go:254] finished sweeping content cache in 333.1389ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:25:33.802 D [logger.go:254] finished sweeping metadata cache in 204.3694ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:25:39.619 D [logger.go:254] finished sweeping content cache in 295.4521ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:26:33.928 D [logger.go:254] finished sweeping metadata cache in 114.5284ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:26:39.932 D [logger.go:254] finished sweeping content cache in 308.5999ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:27:34.043 D [logger.go:254] finished sweeping metadata cache in 105.4975ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:27:40.257 D [logger.go:254] finished sweeping content cache in 321.8769ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:28:34.157 D [logger.go:254] finished sweeping metadata cache in 103.3651ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:28:40.554 D [logger.go:254] finished sweeping content cache in 286.9184ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:29:34.289 D [logger.go:254] finished sweeping metadata cache in 121.2961ms and retained 1456757809/5242880000 bytes (27 %)
2021-08-18 20:29:40.880 D [logger.go:254] finished sweeping content cache in 319.9225ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:29:48.009 D [logger.go:254] [STORAGE] ListBlobs("n")=<nil> returned 48 items and took 38m39.1295418s
2021-08-18 20:29:48.009 D [logger.go:254] saving 48 blobs with prefix n to cache
2021-08-18 20:29:48.034 D [logger.go:254] listed 48 index blobs with prefix n from source
2021-08-18 20:29:48.046 D [logger.go:254] own-writes-cache-expired: {n05054d6ab0cf523bfbc1084c581965e2-s7ca27f789fdcf7da107 124 2021-08-18 19:45:43.6095602 +0200 CEST} (44m4.4371957s)
2021-08-18 20:29:48.051 D [logger.go:254] own-writes-cache-expired: {n06e7cc1e12e734164f13f0b1e754a18f-sec3c1bdcb0f894e2107 123 2021-08-18 19:50:37.0301413 +0200 CEST} (39m11.021751s)
2021-08-18 20:29:48.053 D [logger.go:254] own-writes-cache-expired: {n0be7699b3b9046db58c884dce44e0b87 105 2021-08-18 19:47:50.2551527 +0200 CEST} (41m57.7983831s)
2021-08-18 20:29:48.055 D [logger.go:254] own-writes-cache-expired: {n16cf4564636c4b60469fa90d0cf7d9f2-sccc8739bd18c2779107 123 2021-08-18 19:50:40.6940737 +0200 CEST} (39m7.3614963s)
2021-08-18 20:29:48.056 D [logger.go:254] own-writes-cache-expired: {n19536f7500dc894e145ed55e2835d2f0-s8d5db7a023d38174107 123 2021-08-18 19:50:43.652123 +0200 CEST} (39m4.4044328s)
2021-08-18 20:29:48.057 D [logger.go:254] own-writes-cache-expired: {n1b9b70bc5e98f418e7ce0800c49b1efe-s3887725ade2312b9107 123 2021-08-18 19:50:41.2071913 +0200 CEST} (39m6.8503589s)
[... 40 more lines of the same]
2021-08-18 20:29:48.156 D [logger.go:254] own-writes-cache-expired: {nf4392b0fa704329a75763f95b6cbec9f-s1bf0552491686108107 123 2021-08-18 19:50:38.3307166 +0200 CEST} (39m9.8258979s)
2021-08-18 20:29:48.158 D [logger.go:254] own-writes-cache-expired: {nf9f222dd0d74e0e1a88243f549e9cf1d-s3f1a62bc3e3f0786107 123 2021-08-18 19:50:38.6460706 +0200 CEST} (39m9.5125457s)
2021-08-18 20:29:48.159 D [logger.go:254] own-writes-cache-expired: {nfc824992e89b82067ef043c8e8dfc868-s0a56b601490e729d107 123 2021-08-18 19:50:42.5225597 +0200 CEST} (39m5.6370525s)
2021-08-18 20:29:48.161 D [logger.go:254] own-writes-cache-expired: {nff931723c533c5771301adf9250861af-s14d4171590acddc8107 123 2021-08-18 19:50:41.0267646 +0200 CEST} (39m7.1348485s)
2021-08-18 20:29:48.184 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/m6/fe5e244e81ebd414acff166a9307edf.f to 2021-08-18 20:29:48.1846172 +0200 CEST m=+2341.378963801
2021-08-18 20:29:48.196 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/mc/3757a9468a311abbce8c031b601450e.f to 2021-08-18 20:29:48.1962471 +0200 CEST m=+2341.390593701
2021-08-18 20:29:48.215 D [logger.go:254] downloading 2 new index blobs (351927 bytes)...
2021-08-18 20:29:48.355 D [logger.go:254] [STORAGE] GetBlob("n70a661cedf10d32b21c8039798d7ec72-sd89ff28cbf77cb17107",0,-1)=({159 bytes}, <nil>) took 131.6399ms
2021-08-18 20:29:48.449 D [logger.go:254] [STORAGE] GetBlob("n0be7699b3b9046db58c884dce44e0b87",0,-1)=({351768 bytes}, <nil>) took 227.6838ms
2021-08-18 20:29:48.463 D [logger.go:254] Index contents downloaded.
2021-08-18 20:29:48.471 D [logger.go:254] combined 10 into 9 index segments
2021-08-18 20:29:48.473 D [logger.go:254] removing unused n452936990575d598bda8d1f68e89dc1f-s859f27a99feb3554107.sndx 2021-08-18 14:03:04.848096 +0200 CEST
2021-08-18 20:29:48.476 D [logger.go:254] removing unused n5d85ca46b65c90c0572e86430ee5a767-s1a377b9fecc45679107.sndx 2021-08-18 17:20:47.5558943 +0200 CEST
2021-08-18 20:29:48.478 D [logger.go:254] removing unused ne28b107a63140f1198d5c89c968c564a-scb43c93ed7ff60b2107.sndx 2021-08-18 17:32:36.492416 +0200 CEST
2021-08-18 20:29:48.480 D [logger.go:254] removing unused n6195042f9ef2d8a109e66d6b36d04836-s8244f56d2e6e00a8107.sndx 2021-08-18 16:53:50.4747741 +0200 CEST
2021-08-18 20:29:48.481 D [logger.go:254] removing unused n98a519d44185b907407192ca8e97541b-se44f84726cb29a2b107.sndx 2021-08-18 18:05:36.5791369 +0200 CEST
[...30 lines...]
2021-08-18 20:29:48.543 D [logger.go:254] removing unused n677b57d087bcaf42f4288c10642d5f64-s3cd16d9724f27e6b107.sndx 2021-08-18 16:47:11.310901 +0200 CEST
2021-08-18 20:29:48.565 D [logger.go:254] removing unused nb4c6a498c38c5e0ae2453f1e03ea2e9b-sc32ad59859a5e8d2107.sndx 2021-08-18 16:32:11.7270906 +0200 CEST
2021-08-18 20:29:48.569 D [logger.go:254] removing unused nf8dc8a173c6840c993c695bc4dc80cc6-s187ec56dbe6f2e85107.sndx 2021-08-18 18:31:06.3459744 +0200 CEST
2021-08-18 20:29:48.580 D [logger.go:254] listing manifest contents
2021-08-18 20:29:48.587 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qe/98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107.f to 2021-08-18 20:29:48.5877022 +0200 CEST m=+2341.782048801
2021-08-18 20:29:48.588 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q4/70927153e125846dc196bc7ac7005b4-sbe8a2f6247e0e643107.f to 2021-08-18 20:29:48.5882153 +0200 CEST m=+2341.782561901
2021-08-18 20:29:48.588 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qc/0c8bcac8b327282fafcc4506a5d80d5-s191538e03c11e466107.f to 2021-08-18 20:29:48.5882153 +0200 CEST m=+2341.782561901
2021-08-18 20:29:48.588 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q6/e49d67917af9d07bd6911f5407ae9b4-s4e977fdacd1f8af6107.f to 2021-08-18 20:29:48.5888368 +0200 CEST m=+2341.783183401
2021-08-18 20:29:48.589 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q3/246b18d0e503525d2e8567552ada843-s187ec56dbe6f2e85107.f to 2021-08-18 20:29:48.5898099 +0200 CEST m=+2341.784156501
2021-08-18 20:29:48.590 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q1/fbdc3a94c22ab6c12062350a946a24e-s7ca27f789fdcf7da107.f to 2021-08-18 20:29:48.590324 +0200 CEST m=+2341.784670601
2021-08-18 20:29:48.651 D [logger.go:254] [STORAGE] GetBlob("qefcda4d6c7f3fdaf605ff90202623d37-sd89ff28cbf77cb17107",0,-1)=({4282 bytes}, <nil>) took 59.2313ms
2021-08-18 20:29:48.658 I [logger.go:244] Setting policy for steve@steven2020:C:\Program Files\KopiaUI\resources\server\global
2021-08-18 20:29:48.660 I [logger.go:244]  - setting snapshot times to [2:00]
2021-08-18 20:30:07.289 D [logger.go:254] [STORAGE] PutBlob("s19b7477264e89757e75a83c611fca075-s55af66339e67f922107",len=201)=<nil> took 18.622475s
2021-08-18 20:30:25.998 D [logger.go:254] [STORAGE] PutBlob("qef0715ef15f19832002dc3d8a7e8754c-s55af66339e67f922107",len=4282)=<nil> took 18.6929857s
2021-08-18 20:30:34.405 D [logger.go:254] finished sweeping metadata cache in 104.1872ms and retained 1457114018/5242880000 bytes (27 %)
2021-08-18 20:30:41.188 D [logger.go:254] finished sweeping content cache in 300.6624ms and retained 5241841987/5242880000 bytes (99 %)
2021-08-18 20:30:41.951 D [logger.go:254] [STORAGE] PutBlob("nb1c04aa26d24ecba462545dbc36d4e90-s55af66339e67f922107",len=159)=<nil> took 15.9504268s
2021-08-18 20:30:42.112 D [logger.go:254] [STORAGE] GetMetadata("nb1c04aa26d24ecba462545dbc36d4e90-s55af66339e67f922107")=({nb1c04aa26d24ecba462545dbc36d4e90-s55af66339e67f922107 159 2021-08-18 20:30:41.2902199 +0200 CEST}, <nil>) took 157.1552ms
2021-08-18 20:30:42.220 D [logger.go:254] [STORAGE] DeleteBlob("s19b7477264e89757e75a83c611fca075-s55af66339e67f922107")=<nil> took 100.5774ms
2021-08-18 20:30:42.226 D [logger.go:254] not closing shared manager, remaining = 1
2021-08-18 20:30:42.228 D [logger.go:254] listing manifest contents
2021-08-18 20:30:42.817 D [logger.go:254] [STORAGE] GetBlob("qef0715ef15f19832002dc3d8a7e8754c-s55af66339e67f922107",0,-1)=({4282 bytes}, <nil>) took 585.801ms
2021-08-18 20:30:42.955 D [logger.go:254] [STORAGE] GetBlob("kopia.maintenance",0,-1)=({4378 bytes}, <nil>) took 111.2848ms
2021-08-18 20:30:42.959 D [logger.go:254] not due for full manintenance cycle until 2021-08-19 05:15:32.9101578 +0200 CEST
2021-08-18 20:30:42.959 D [logger.go:254] due for quick manintenance cycle
2021-08-18 20:30:42.960 D [logger.go:254] [STORAGE] GetBlob("kopia.maintenance",0,-1)=({4378 bytes}, <nil>) took 0s
2021-08-18 20:30:42.960 D [logger.go:254] scheduling next quick cycle at 2021-08-18 19:55:02.7641605 +0200 CEST
2021-08-18 20:30:43.673 D [logger.go:254] [STORAGE] PutBlob("kopia.maintenance",len=4378)=<nil> took 712.2819ms
2021-08-18 20:30:43.674 D [logger.go:254] Acquiring maintenance lock in file C:\Users\steve\AppData\Roaming\kopia\repository.config.mlock
2021-08-18 20:30:43.678 I [logger.go:244] Running quick maintenance...
2021-08-18 20:30:43.784 D [logger.go:254] [STORAGE] GetBlob("kopia.maintenance",0,-1)=({4378 bytes}, <nil>) took 106.1662ms
2021-08-18 20:30:43.792 I [logger.go:244] Rewriting contents from short packs...
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k6409bdb7220360fa2bbd6d7a0a99355d (684 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m10.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k0875dc096a2fe6f1a22c1f0dc9ae5acf (487 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m11.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k41db19ce94471b7e02b38482c4642282 (748 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m8.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k36342e8dd60dd8f61bf47b0fb9ed7f17 (1406 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m6.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k40eb44f42cbae702763e09f5bfd9d953 (451 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m5.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k608779f7b9331dee6be7576e9aefef6b (13848 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m4.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k1a75a00980464b6c433400db4234cb5b (2634 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m11.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k5bbfaecc671e5b190cabfecf116fbf66 (894 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m11.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k61bbf6bb07e676c2e7e827df68ef1fd1 (1718 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m10.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k258325cdd7bb465df708bdbe45db2683 (515 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m6.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k3bc338a25dbaf36265a89701a2658f26 (427 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m11.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k1356bd66d73a3733dc12fdaa077eb82f (627 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m4.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k1706637d431f704718faff1e56bbf366 (879 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m5.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k12a2547c67ef65efae16f949bebbda93 (1411 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m11.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k0353c7a3ef0a9f75b385470a3c82437f (1686 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m8.2431367s
2021-08-18 20:30:46.243 D [logger.go:254] Rewriting content k0f1782eed133263b17ae6a463a7a4776 (619 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m8.2431367s
2021-08-18 20:30:46.245 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qa/393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107.f to 2021-08-18 20:30:46.2451403 +0200 CEST m=+2399.439486901
2021-08-18 20:30:47.742 D [logger.go:254] [STORAGE] PutBlob("s6d400c3df93e86aab240d901865edcc7-sb1b206f6e745eadd107",len=199)=<nil> took 1.4918897s
2021-08-18 20:30:47.742 D [logger.go:254] Rewriting content k6939ee45e69a6fe16fb4150e2c8d9ae2 (667 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m9.7420297s
2021-08-18 20:30:47.742 D [logger.go:254] Rewriting content kccff02be526e28783b0b5d59b3d2c7d8 (483 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m6.7425404s
2021-08-18 20:30:47.742 D [logger.go:254] Rewriting content k91d86145365703a32a53fcafd4ff9c9f (3254 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m6.7425404s
2021-08-18 20:30:47.742 D [logger.go:254] Rewriting content k695c1d42787d9e8948266e689d23f2fd (321 bytes) from pack qa393e5658aed8a05c90bd1cfcca13a00-sce760dc68002180f107 7h1m6.7425404s

[... 60 lines of the same...]

2021-08-18 20:30:47.776 D [logger.go:254] Rewriting content ke833558fc52b61bdf4d3eb4cb808ccd6 (1710 bytes) from pack q9626ca198b2deb38e6bb32d095acf965-s7d7d397d7b30d218107 7h51m50.7764585s
2021-08-18 20:30:47.776 D [logger.go:254] Not rewriting content m2f96b27d1b4e489f56db0a1c66b9e9ba (557 bytes) from pack q9626ca198b2deb38e6bb32d095acf965-s7d7d397d7b30d218107 (deleted) 1h59m50.7769686s, because it's too new.
2021-08-18 20:30:47.777 D [logger.go:254] Rewriting content xa7fdda858e48c9e848157d0ca6ff6816 (117102 bytes) from pack q9626ca198b2deb38e6bb32d095acf965-s7d7d397d7b30d218107 7h51m50.7775132s
2021-08-18 20:30:47.777 D [logger.go:254] Not rewriting content k8eaa41fb72186967de465ba5ad1044c6 (209 bytes) from pack qe98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107 1h59m38.7775132s, because it's too new.
2021-08-18 20:30:47.778 D [logger.go:254] Not rewriting content m337cdb2abebc0fd9f8b81fcd9fdfbb17 (515 bytes) from pack qe98eb1800a2279a16b16d742e0da4c2c-s6c1456c159765673107 1h59m38.7780574s, because it's too new.
2021-08-18 20:30:47.778 D [logger.go:254] Not rewriting content mdf4b1af8d9e271823631d1914855cdc3 (591 bytes) from pack q8f16384a04687ea182750acf7d417d40-scb43c93ed7ff60b2107 (deleted) 1h59m50.7781461s, because it's too new.
2021-08-18 20:30:47.778 D [logger.go:254] Rewriting content k01ceca90c7b8e143f62b4da5b1ffe4f9 (1548 bytes) from pack q1d0c25407e1958d02e8d1a73f8970928-s7290c99d67690202107 6h14m51.7786587s
2021-08-18 20:30:47.778 D [logger.go:254] Rewriting content x3d22bd8bbd2c4530e715f60886be65ee (4056 bytes) from pack qac60cf27dec24a5dc964182e486e59d8-s14d4171590acddc8107 6h45m32.7786587s
2021-08-18 20:30:47.780 D [logger.go:254] Rewriting content k052aa12e0bc393987b5f239a27cf70a8 (1248 bytes) from pack q1d0c25407e1958d02e8d1a73f8970928-s7290c99d67690202107 6h14m51.78033s
2021-08-18 20:30:48.247 D [logger.go:254] [STORAGE] GetBlob("qebc33aa6690ecde20d5f62d731a277a2-s03aa88c346d267bf107",0,-1)=({4430 bytes}, <nil>) took 482.1514ms
2021-08-18 20:30:48.248 D [logger.go:254] [STORAGE] GetBlob("qc8ee8670af15789aa83b862f3727efdc-s3cd16d9724f27e6b107",0,-1)=({4282 bytes}, <nil>) took 483.8144ms
2021-08-18 20:30:48.256 D [logger.go:254] Rewriting content k414fc54bb205e5fea4fa57fc45556a04 (1836 bytes) from pack q1d0c25407e1958d02e8d1a73f8970928-s7290c99d67690202107 6h14m52.2563669s
2021-08-18 20:30:48.257 D [logger.go:254] Rewriting content k6beac711ad15ef5a25e8c6bb444ebd11 (2554 bytes) from pack q1d0c25407e1958d02e8d1a73f8970928-s7290c99d67690202107 6h14m52.2573639s

[... 50 lines of the same...]

2021-08-18 20:30:48.307 D [logger.go:254] Rewriting content m11028c4b55b3dd587ac2c552f4c28453 (554 bytes) from pack qf5cf0bbd538b88555580dd956f732aef-sa8c9539ff543488b107 (deleted) 8h36m54.3068469s
2021-08-18 20:30:48.308 D [logger.go:254] Not rewriting content m72c78f0b7a475fdca1107d01d94ca1d5 (571 bytes) from pack qb9e6544a681dd29d918079f658db64f5-scec216cb7369952b107 (deleted) 1h59m51.308058s, because it's too new.
2021-08-18 20:30:48.308 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qb/00cb4d48391e6950060b9beac4f0cf9-sa46528d80e687527107.f to 2021-08-18 20:30:48.3085712 +0200 CEST m=+2401.502917801
2021-08-18 20:30:48.308 D [logger.go:254] Rewriting content m47c81f4c44dcdca4c297e3fbada534b5 (553 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.3085712s
2021-08-18 20:30:48.309 D [logger.go:254] Rewriting content m4ba56cb9875fabe4bee42205c5778ca1 (21023 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.3091126s
2021-08-18 20:30:48.308 D [logger.go:254] Rewriting content m407bb392893efef4a26ca4bb3ee5d2a7 (551 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.3085712s
2021-08-18 20:30:48.950 D [logger.go:254] [STORAGE] GetBlob("qac60cf27dec24a5dc964182e486e59d8-s14d4171590acddc8107",0,-1)=({8378 bytes}, <nil>) took 689.7657ms
2021-08-18 20:30:48.950 D [logger.go:254] [STORAGE] GetBlob("q4428ade481a14db86d8be139457af480-s1b336a16aa83d10f107",0,-1)=({8378 bytes}, <nil>) took 656.1311ms
2021-08-18 20:30:48.952 D [logger.go:254] [STORAGE] GetBlob("q9a94b042fe8b899e7d4f4c5a80148e10-s23a78f3765737df6107",0,-1)=({8526 bytes}, <nil>) took 661.5873ms
2021-08-18 20:30:48.956 D [logger.go:254] Rewriting content mb52ac03858d5e9652779db06fb9ac4a3 (563 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.9565975s
2021-08-18 20:30:48.957 D [logger.go:254] Rewriting content mb6a8949c9614dec6b892145ad202a504 (554 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.9572135s
2021-08-18 20:30:48.958 D [logger.go:254] Rewriting content md6f838d5248a60a5a0d1425b920f4420 (582 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.958936s
2021-08-18 20:30:48.958 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qf/052061078efafb7d3e2b371a2ddff1f-s9719b637a02e0c46107.f to 2021-08-18 20:30:48.958936 +0200 CEST m=+2402.153282601
2021-08-18 20:30:48.959 D [logger.go:254] Rewriting content md9f12d3819da03194a7dfc0048ce4e44 (582 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.9594825s
2021-08-18 20:30:48.960 D [logger.go:254] Rewriting content mebf9f4e9208f4de786a660bb2e575d7c (499 bytes) from pack qc9ca8ff284a3927bf3b5d72e9456a049-sca707a1559a0ff51107 (deleted) 8h36m54.9600428s
2021-08-18 20:30:48.960 D [logger.go:254] Rewriting content m922e02800a6b31ef6bc5495c75a03d37 (559 bytes) from pack q1d03e7e7c5d8e7f9569c424b86dfc633-s7af15f0a6666c671107 (deleted) 8h36m54.9600428s
2021-08-18 20:30:48.960 D [logger.go:254] Rewriting content x76aa936956bc982c41d5fb4cfdb619bc (449 bytes) from pack q3b470c4f94896cd73746d4ead891c7ac-se78e1f237bde8cce107 6h26m5.9605956s
2021-08-18 20:30:48.960 D [logger.go:254] Rewriting content x2e426057b0d0c4b4d98f91917e69b746 (251 bytes) from pack q3b470c4f94896cd73746d4ead891c7ac-se78e1f237bde8cce107 6h27m40.9600428s
2021-08-18 20:30:48.961 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qf/5cf0bbd538b88555580dd956f732aef-sa8c9539ff543488b107.f to 2021-08-18 20:30:48.9611437 +0200 CEST m=+2402.155490301
2021-08-18 20:30:48.961 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q1/d03e7e7c5d8e7f9569c424b86dfc633-s7af15f0a6666c671107.f to 2021-08-18 20:30:48.9618876 +0200 CEST m=+2402.156234201
2021-08-18 20:30:48.962 D [logger.go:254] Rewriting content xa3b12bfd0f4cbea996ac621b02af35a2 (384 bytes) from pack q3b470c4f94896cd73746d4ead891c7ac-se78e1f237bde8cce107 6h20m20.9623999s
2021-08-18 20:30:48.962 D [logger.go:254] Rewriting content xd7dab7b99f29f63317ce558c7026b6f9 (579 bytes) from pack q3b470c4f94896cd73746d4ead891c7ac-se78e1f237bde8cce107 6h27m40.9623999s
2021-08-18 20:30:59.131 D [logger.go:254] [STORAGE] GetBlob("qacbe4e4f000317cb31b487c7d9962bc6-sc26d136a7e760cc1107",0,-1)=({8452 bytes}, <nil>) took 10.8262302s
2021-08-18 20:30:59.131 D [logger.go:254] [STORAGE] GetBlob("qaf5b83773e8f17937c5fee458d98bc76-s8244f56d2e6e00a8107",0,-1)=({8378 bytes}, <nil>) took 10.8239094s
2021-08-18 20:30:59.137 D [logger.go:254] Rewriting content k06e222b15786cf8317438d298deb1618 (6441 bytes) from pack qac288e79ad7965a6618beeaf6d5746ef-sae1aec03afc9d074107 7h6m27.1378492s
2021-08-18 20:30:59.138 D [logger.go:254] Rewriting content k10df08b5d8d3386ae868a4c2cc991b86 (19703 bytes) from pack qac288e79ad7965a6618beeaf6d5746ef-sae1aec03afc9d074107 7h6m27.1383602s

[...~275 lines of the same...]

2021-08-18 20:30:59.693 D [logger.go:254] Rewriting content k59d0a9dfad2b2597a54c7663ef232820 (498 bytes) from pack q7951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107 8h37m7.6937395s
2021-08-18 20:30:59.695 D [logger.go:254] Rewriting content kde5c911048561e92889d8d7e9acf93a1 (1997 bytes) from pack q7951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107 8h37m7.6954613s
2021-08-18 20:31:00.055 D [logger.go:254] [STORAGE] GetBlob("q2fd3400863a6a14b886303db626cd7a6-s7ef6437f1e767e67107",0,-1)=({4356 bytes}, <nil>) took 428.3846ms
2021-08-18 20:31:00.058 D [logger.go:254] [STORAGE] GetBlob("q95e27a12edeff84442f1c07ab07a25ba-s6d127163dc5ad5ca107",0,-1)=({8415 bytes}, <nil>) took 424.0901ms
2021-08-18 20:31:00.061 D [logger.go:254] Rewriting content kf9c06f138e47bc1a4b7cb9294bbc2bad (1710 bytes) from pack q7951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107 8h37m8.0616635s
2021-08-18 20:31:00.061 D [logger.go:254] Rewriting content m30cd11eb31d7d8c7f6b89ff0c5d90a00 (21720 bytes) from pack q7951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107 (deleted) 2h0m3.0616635s
2021-08-18 20:31:00.062 D [logger.go:254] Rewriting content x9479ea2d1c4244f5509dea6091d24252 (88053 bytes) from pack q7951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107 8h37m8.0626654s
2021-08-18 20:31:00.063 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q7/951726ebc43ebbae4a40289923acaf1-s557efc7b777acd44107.f to 2021-08-18 20:31:00.0636663 +0200 CEST m=+2413.258012901
2021-08-18 20:31:00.063 D [logger.go:254] Rewriting content mc3bc6d18909596c6ab4a3e09992979ca (20886 bytes) from pack q3246b18d0e503525d2e8567552ada843-s187ec56dbe6f2e85107 2h0m3.0636663s
2021-08-18 20:31:00.063 D [logger.go:254] Rewriting content m64b786c3907eeeae1c9d0eda018b6af7 (557 bytes) from pack qc4dbf2597f52d8d5950f9325f25d65e2-s459eae110f97b535107 (deleted) 8h37m6.0636663s
2021-08-18 20:31:00.064 D [logger.go:254] Rewriting content m68a5f33da2c6f511083b32e03d719d7d (503 bytes) from pack q261d0f66761683951145fac100d92660-sb87333891d237c21107 (deleted) 8h37m6.0646655s
2021-08-18 20:31:00.065 D [logger.go:254] Rewriting content xc05b0523b15076c496fa7d8568aa15b9 (5062 bytes) from pack qd35478bd59c4c6f66b8b109730a7f302-s936e573491b37855107 4h25m59.0656709s
2021-08-18 20:31:00.065 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/qc/4dbf2597f52d8d5950f9325f25d65e2-s459eae110f97b535107.f to 2021-08-18 20:31:00.0656709 +0200 CEST m=+2413.260017501
2021-08-18 20:31:00.070 D [logger.go:254] updating timestamp on C:\Users\steve\AppData\Local\kopia\0c26e6d04904f8f2\metadata/q2/61d0f66761683951145fac100d92660-sb87333891d237c21107.f to 2021-08-18 20:31:00.070664 +0200 CEST m=+2413.265010601
2021-08-18 20:31:00.319 D [logger.go:254] [STORAGE] GetBlob("qd35478bd59c4c6f66b8b109730a7f302-s936e573491b37855107",0,-1)=({8378 bytes}, <nil>) took 253.6688ms
2021-08-18 20:31:00.370 D [logger.go:254] [STORAGE] GetBlob("qf4e24445e6f0c2cb10fbffc9bfc192e3-sf58b53f3b71c1877107",0,-1)=({74100 bytes}, <nil>) took 727.4883ms
2021-08-18 20:31:00.379 D [logger.go:254] Total bytes rewritten 7.6 MB
2021-08-18 20:31:02.410 D [logger.go:254] [STORAGE] PutBlob("q242bbf6c93d7b43b6f3106a2b213ca0c-sb1b206f6e745eadd107",len=7667278)=<nil> took 1.9763829s
2021-08-18 20:31:03.296 D [logger.go:254] [STORAGE] PutBlob("ne287c2f5ab538eb27112673d19b40a3b-sb1b206f6e745eadd107",len=15921)=<nil> took 873.7241ms
2021-08-18 20:31:03.416 D [logger.go:254] [STORAGE] GetMetadata("ne287c2f5ab538eb27112673d19b40a3b-sb1b206f6e745eadd107")=({ne287c2f5ab538eb27112673d19b40a3b-sb1b206f6e745eadd107 15921 2021-08-18 20:31:02.9102242 +0200 CEST}, <nil>) took 119.2752ms
2021-08-18 20:31:13.462 D [logger.go:254] [STORAGE] DeleteBlob("s6d400c3df93e86aab240d901865edcc7-sb1b206f6e745eadd107")=<nil> took 10.0399251s
2021-08-18 20:31:14.020 D [logger.go:254] [STORAGE] PutBlob("kopia.maintenance",len=4378)=<nil> took 551.0663ms
2021-08-18 20:31:14.021 I [logger.go:244] Skipping blob deletion because not enough time has passed yet (59m59s left).
2021-08-18 20:31:14.021 I [logger.go:244] Compacting indexes...
2021-08-18 20:31:14.021 D [logger.go:254] CompactIndexes({MaxSmallBlobs:8 AllIndexes:false DropDeletedBefore:0001-01-01 00:00:00 +0000 UTC DropContents:[] DisableEventualConsistencySafety:false})

(I acknowledge that I don’t know what the heck I’m talking about, but this seems like a whale of a lot of activity to add one line to a JSON file!)

Anyway, let me know if there’s any other info you need. For now, I’m done!

9

Running under strace may help here, but it looks like the filesystem is very slow indeed.

Kopia issues quite a lot of I/O in parallel, so 9 iops is going to be slow.

The sweeping lines are red herring since they are from a periodic process that runs every minute that deletes stuff from local cache, should not really impact anything.

10

Ahhhhh, gotcha with the sweeping lines. So then it’s the storage. 9 iops! I didn’t see that, jeez.

I suppose that if Kopia issues a lot of I/O requests, then one of them getting stuck would hold up the whole thing? And if so, would losing packets while communicating over the internet cause the same behavior?

The reason I ask is that I just had a kopia policy set take 2 minutes while ioping was getting 1-2k iops in both read and write. I don’t want to take up your time if my hacky Raspberry Pi ZFS thing is an edge case, but if it’s an analogue to an unstable internet connection, it might be worth looking into - i.e. if your min/avg/max ioping is 235.8 us / 108.9 ms / 23.1 s , then the outlier 23 second request should be reissued.

Question: does Kopia use synchronous or asynchronous writes for a) policy set and b) making a backup?

11

As much as I looove ZFS… I have switched my repo from ZFS to XFS, since ZFS was too slow for me. What you can do on your ZFS dataset (and should do) is to set atime=off and depending on your overall setup set primarycache=metadata.

Kopia will issue lots of random reads/writes and ZFS’s ARC will be only of little benefit, where caching ZFS’ metadata will be helpful.

12

I just lived with the slowness till recently, when I realized the cause: I had fallen victim to Ye Olde SMR Scandal. SMR (shingled magnetic recording) hard drives perform badly with sustained writes (e.g. a backup), and are notoriously terrible with ZFS. I’ve moved my ZFS pool to CMR disks and have had an order of magnitude improvement in throughput (2 orders of magnitude when really bogged down).

I suspect that Kopia (with its sustained, but not sequential, writes) might be terrible on SMR even without ZFS.

If that suspicion is correct, then this is likely to be a common problem, since most consumer-grade HDDs are SMR nowadays (e.g. all of Seagate’s 2.5" drives and all of their consumer-grade Barracuda line, not to mention even WD Reds). If so, I’d say it warrants a mention on the FAQs.

If helpful, I can offer to test Kopia through NTFS/ext4 on my SMR disks, though I can’t promise to be prompt with it.