I use kopia to create snapshots to an rclone remote on google drive. The folders I backup are rather small ( ~150 mb or less ) but the incremental snapshots take 30 seconds to 1 minute even if there was no change in the source directory. Is this normal behaviour?
EDIT: Significant delay is experienced when trying to edit policy too ( upto 60s ).
Can you add --log-level=debug to see if there’s any pattern? You should see STORAGE lines indicating how long each operation takes.
for mounting
DEBUG memory: before openRepository allocated 18446744073709292248(+1722664) max 1722664, sys: 8060928 total 49064(+3191296), allocs 359(+18960) frees 2228(+10197) alive 8763(+8763), goroutines 3
DEBUG build version v0.9.5, available v
DEBUG no updated version available
DEBUG password for ***\AppData\Roaming\kopia\repository.config retrieved from OS keyring
DEBUG generating new TLS certificate
DEBUG adding alternative IP to certificate: 127.0.0.1
DEBUG starting C:\Program Files\rclone\rclone.exe
DEBUG detected webdav address: https://127.0.0.1:58014/
DEBUG kopia.repository retrieved from cache
DEBUG [STORAGE] ListBlobs {"prefix": "xw", "resultCount": 0, "error": null, "duration": "1.1174977s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xn1_", "resultCount": 0, "error": null, "duration": "23.1069ms"}
DEBUG finished sweeping content cache in 600.5µs and retained 0/5242880000 bytes (0 %)
DEBUG finished sweeping metadata cache in 1.7801ms and retained 112455/5242880000 bytes (0 %)
DEBUG [STORAGE] ListBlobs {"prefix": "xn0_", "resultCount": 398, "error": null, "duration": "1m37.7492209s"}
DEBUG memory: after openRepository allocated 11311792(+11571160) max 13293824, sys: 112558080 total 104971688(+104922624), allocs 446485(+446126) frees 438979(+436751) alive 18138(+9375), goroutines 12
DEBUG creating webdav server...
DEBUG running C:\Windows\system32\net.exe [net use Z: http://127.0.0.1:58051]
DEBUG [STORAGE] ListBlobs {"prefix": "xn", "resultCount": 398, "error": null, "duration": "298.0835ms"}
DEBUG net use finished with The command completed successfully.
<nil>
Mounted 'all' on Z:
Press Ctrl-C to unmount.
DEBUG finished sweeping content cache in 0s and retained 0/5242880000 bytes (0 %)
DEBUG finished sweeping metadata cache in 0s and retained 112455/5242880000 bytes (0 %)
DEBUG [STORAGE] GetBlob {"blobID": "q6baee4dc1e73ffd1c01612bd4c9ff48f-s3ee7da795a1bfe8310a", "offset": 0, "length": -1, "outputLength": 4529, "error": null, "duration": "4.4062172s"}
DEBUG finished sweeping content cache in 0s and retained 0/5242880000 bytes (0 %)
DEBUG finished sweeping metadata cache in 0s and retained 116984/5242880000 bytes (0 %)
for policy list
DEBUG memory: before openRepository allocated 18446744073709279216(+1704736) max 1704736, sys: 8060928 total 35992(+3178288), allocs 272(+18876) frees 2233(+10211) alive 8665(+8665), goroutines 4
DEBUG build version v0.9.5, available v
DEBUG no updated version available
DEBUG password for ***\AppData\Roaming\kopia\repository.config retrieved from OS keyring
DEBUG generating new TLS certificate
DEBUG adding alternative IP to certificate: 127.0.0.1
DEBUG starting C:\Program Files\rclone\rclone.exe
DEBUG detected webdav address: https://127.0.0.1:58312/
DEBUG kopia.repository retrieved from cache
DEBUG [STORAGE] ListBlobs {"prefix": "xw", "resultCount": 0, "error": null, "duration": "1.3176952s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xs", "resultCount": 0, "error": null, "duration": "1.3199853s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xe", "resultCount": 0, "error": null, "duration": "1.3216849s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xr", "resultCount": 0, "error": null, "duration": "1.3232928s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xn1_", "resultCount": 0, "error": null, "duration": "31.3388ms"}
DEBUG finished sweeping content cache in 169µs and retained 0/5242880000 bytes (0 %)
DEBUG finished sweeping metadata cache in 2.7973ms and retained 116984/5242880000 bytes (0 %)
DEBUG [STORAGE] ListBlobs {"prefix": "xn0_", "resultCount": 398, "error": null, "duration": "1m43.2928504s"}
DEBUG memory: after openRepository allocated 10929456(+11201856) max 12906592, sys: 120913920 total 112504296(+112468304), allocs 625741(+625469) frees 617014(+614781) alive 19353(+10688), goroutines 12
DEBUG reloading committed manifest contents: rev=1 last=0
DEBUG listing manifest contents
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qf/bec3c4468b64c34c1b44aaa64e47e10-se4fa07a51590a49d10a.f to 2021-11-21 12:47:40.0367117 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q0/9e2896bb9e45cb953a6f8009acb55eb-s58e8f32a9e713f5010a.f to 2021-11-21 12:47:40.0374272 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qb/0a84e4100bdc600996fa88a476a403b-sce005c983dc414bf10a.f to 2021-11-21 12:47:40.0374272 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q5/7ac7ada345ddee025ccddfab03998e2-s3061d5595990046310a.f to 2021-11-21 12:47:40.0380392 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q9/6a9d5df349d3c13dac841ddcf6d6be4-s3073bdcd6ff7b01c10a.f to 2021-11-21 12:47:40.0379919 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q0/db1d73f7b94e48a7bb8d8aa142c3573-s8fd35b6761a43e5910a.f to 2021-11-21 12:47:40.0381582 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q1/368a1bce6b1bce57a9f97fca85272e9-sfafd7c30bfc08a1110a.f to 2021-11-21 12:47:40.0381582 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q6/9ae58fcb1294fe44e697ce933427093-s26ae3856a082a94010a.f to 2021-11-21 12:47:40.0381582 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qf/49c788d8b012522f3e7182e1aa45118-se9cbc1767beb2ee510a.f to 2021-11-21 12:47:40.0387332 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qb/08290fdecb9be56712aeccbbde72434-sb46587388b36e00d10a.f to 2021-11-21 12:47:40.0387332 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qf/3902162b8332fa6c3867e25cbcaa850-sc287ff0a5d1e2ca310a.f to 2021-11-21 12:47:40.0393092 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q7/bae13a5d6401eac7d94aee19127c250-sebcc4fd2c231030710a.f to 2021-11-21 12:47:40.0393092 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q1/960185fa62b66742211e3a1380759f1-s8770503f9d93d60210a.f to 2021-11-21 12:47:40.0393092 +0530 IST
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/qb/cdf25eeb1bbbe880e9531bb149069b2-s55f816dd1ae4c5b710a.f to 2021-11-21 12:47:40.0393092 +0530 IST
8b8fa04ecf8a76f6532008635d8021d3 (global)
f8c6b67eccdef25c3bb58127b1033851 ****
d6732998bcaf1201ed60bfa18ad567ae ****
a56c8d094f052b24e179aeab01f70c91 ****
2c65374978b97d4a8a50f8f7dba24b72 ****
DEBUG memory: before close repository allocated 11691840(+762384) max 13668976, sys: 120913920 total 114610720(+2106424), allocs 633489(+7748) frees 625684(+8670) alive 18431(-922), goroutines 12
DEBUG [STORAGE] ListBlobs {"prefix": "xn", "resultCount": 398, "error": null, "duration": "286.3366ms"}
DEBUG no writes in this session, no need to wait
DEBUG killing rclone
DEBUG [STORAGE] Close {"error": null, "duration": "36.1114ms"}
DEBUG memory: after close repository allocated 9851792(-1840048) max 13668976, sys: 120913920 total 119899704(+5288984), allocs 714337(+80848) frees 711395(+85711) alive 13568(-4863), goroutines 3
DEBUG default (64KiB) - allocated 58(17) chunks freed 58 alive 0 max 17 free list high water mark: 17
DEBUG typical-contig (8MiB128B) - allocated 15(1) chunks freed 15 alive 0 max 1 free list high water mark: 1
DEBUG contig (16MiB128B) - allocated 0(0) chunks freed 0 alive 0 max 0 free list high water mark: 0
DEBUG memory: final allocated 9743464(-108328) max 13668976, sys: 120913920 total 119913640(+13936), allocs 714459(+122) frees 711649(+254) alive 13436(-132), goroutines 3
for snapshot, incremental with no change in source
DEBUG memory: before openRepository allocated 18446744073709285176(+1707608) max 1707608, sys: 8060928 total 44304(+3190608), allocs 318(+18945) frees 2240(+10217) alive 8728(+8728), goroutines 4
DEBUG build version v0.9.5, available v
DEBUG no updated version available
DEBUG password for ***\AppData\Roaming\kopia\repository.config retrieved from OS keyring
DEBUG generating new TLS certificate
DEBUG adding alternative IP to certificate: 127.0.0.1
DEBUG starting C:\Program Files\rclone\rclone.exe
DEBUG detected webdav address: https://127.0.0.1:58523/
DEBUG kopia.repository could not be fetched from cache: cached file too old
DEBUG [STORAGE] GetBlob {"blobID": "kopia.repository", "offset": 0, "length": -1, "outputLength": 1118, "error": null, "duration": "4.4426007s"}
DEBUG [STORAGE] ListBlobs {"prefix": "xs", "resultCount": 0, "error": null, "duration": "30.7382ms"}
DEBUG [STORAGE] ListBlobs {"prefix": "xw", "resultCount": 0, "error": null, "duration": "34.6063ms"}
DEBUG [STORAGE] ListBlobs {"prefix": "xe", "resultCount": 0, "error": null, "duration": "35.4373ms"}
DEBUG [STORAGE] ListBlobs {"prefix": "xr", "resultCount": 0, "error": null, "duration": "32.3485ms"}
DEBUG [STORAGE] ListBlobs {"prefix": "xn1_", "resultCount": 0, "error": null, "duration": "30.917ms"}
DEBUG finished sweeping content cache in 513.5µs and retained 0/5242880000 bytes (0 %)
DEBUG finished sweeping metadata cache in 1.6964ms and retained 116984/5242880000 bytes (0 %)
DEBUG [STORAGE] ListBlobs {"prefix": "xn0_", "resultCount": 398, "error": null, "duration": "1m34.3719987s"}
DEBUG memory: after openRepository allocated 11381192(+11647632) max 13355240, sys: 116719616 total 113185984(+113141680), allocs 629807(+629489) frees 621725(+619485) alive 18732(+10004), goroutines 12
DEBUG reloading committed manifest contents: rev=1 last=0
DEBUG listing manifest contents
Snapshotting ***:***\Certificates ...
DEBUG found 4 policies for ***
DEBUG ***\Camera is not under ***\Certificates
DEBUG ***\Documents is not under ***\Certificates
DEBUG ***\Certificates is not under ***\Certificates
DEBUG ***\Pictures is not under ***\Certificates
DEBUG uploading ***:***\Certificates using 1 previous manifests
DEBUG Uploading ***:***\Certificates
DEBUG updating timestamp on ***\AppData\Local\kopia\cd19210fef236774\metadata/q6/baee4dc1e73ffd1c01612bd4c9ff48f-s3ee7da795a1bfe8310a.f to 2021-11-21 12:56:53.9972948 +0530 IST
| 0 hashing, 0 hashed (0 B), 1 cached (2.1 MB), uploaded 0 B, estimating...DEBUG deleting 2021-11-20 12:30:00.0204608 +0530 IST
DEBUG deleting 2021-11-20 13:51:52.0023397 +0530 IST
DEBUG deleting 2021-11-20 16:58:30.0093838 +0530 IST
DEBUG deleting 2021-11-20 17:57:47.0730455 +0530 IST
DEBUG deleting 2021-11-20 19:18:47.6688346 +0530 IST
DEBUG deleting 2021-11-20 22:51:29.651966 +0530 IST
DEBUG deleting 2021-11-20 23:58:01.563432 +0530 IST
DEBUG deleting 2021-11-21 00:18:00.0128509 +0530 IST
DEBUG deleting 2021-11-21 08:32:30.5036373 +0530 IST
DEBUG deleting 2021-11-21 08:33:00.021754 +0530 IST
DEBUG deleting 2021-11-21 08:36:00.0231066 +0530 IST
DEBUG deleting 2021-11-21 12:56:53.996206 +0530 IST
DEBUG [STORAGE] ListBlobs {"prefix": "xn", "resultCount": 398, "error": null, "duration": "283.1755ms"}
DEBUG [STORAGE] PutBlob {"blobID": "se96bd379699719869840e1af187f8735-s6d30fa6c8cdf5b0e10a", "length": 205, "error": null, "duration": "4.1699762s"}
/ 0 hashing, 0 hashed (0 B), 8 cached (22.9 MB), uploaded 4.5 KB, estimated 22.9 MB (100.0%) 0s leftDEBUG [STORAGE] PutBlob {"blobID": "qe83971b889286ebbace1a498f91702b8-s6d30fa6c8cdf5b0e10a", "length": 4298, "error": null, "duration": "3.9997284s"}
DEBUG [STORAGE] PutBlob {"blobID": "xn0_9fb6be5e737f2a1420d57a50dbe64541-s6d30fa6c8cdf5b0e10a-c1", "length": 143, "error": null, "duration": "2.0939834s"}
DEBUG [STORAGE] GetMetadata {"blobID": "xn0_9fb6be5e737f2a1420d57a50dbe64541-s6d30fa6c8cdf5b0e10a-c1", "result": {"id":"xn0_9fb6be5e737f2a1420d57a50dbe64541-s6d30fa6c8cdf5b0e10a-c1","length":143,"timestamp":"2021-11-21T07:27:02Z"}, "error": null, "duration": "3.8044ms"}
DEBUG [STORAGE] DeleteBlob {"blobID": "se96bd379699719869840e1af187f8735-s6d30fa6c8cdf5b0e10a", "error": null, "duration": "678.0547ms"}
* 0 hashing, 0 hashed (0 B), 8 cached (22.9 MB), uploaded 4.6 KB, estimated 22.9 MB (100.0%) 0s left
Created snapshot with root k5fa568e29a5bc175b8b0768582487847 and ID 13a17b1c36c200003a80adf0c4f3035e in 0s
DEBUG memory: before auto maintenance allocated 20020680(+8639488) max 21994728, sys: 116457472 total 129814704(+16628720), allocs 722467(+92660) frees 716967(+95242) alive 16150(-2582), goroutines 10
DEBUG reloading committed manifest contents: rev=2 last=0
DEBUG listing manifest contents
DEBUG [STORAGE] GetBlob {"blobID": "qe83971b889286ebbace1a498f91702b8-s6d30fa6c8cdf5b0e10a", "offset": 0, "length": -1, "outputLength": 4298, "error": null, "duration": "2.7040004s"}
DEBUG [STORAGE] GetBlob {"blobID": "kopia.maintenance", "offset": 0, "length": -1, "outputLength": 522, "error": null, "duration": "2.2522838s"}
DEBUG not due for full maintenance cycle until 2021-11-21 13:51:00.1470273 +0530 IST
DEBUG not due for quick maintenance cycle until 2021-11-21 13:44:33.2118925 +0530 IST
DEBUG not due for maintenance
DEBUG memory: after auto maintenance allocated 19920352(-100328) max 21994728, sys: 116457472 total 130910328(+1095624), allocs 728031(+5564) frees 722489(+5522) alive 16192(+42), goroutines 10
DEBUG memory: before close repository allocated 19895224(-25128) max 21994728, sys: 116457472 total 130920648(+10320), allocs 728086(+55) frees 722645(+156) alive 16091(-101), goroutines 10
DEBUG finished sweeping metadata cache in 0s and retained 121282/5242880000 bytes (0 %)
DEBUG [STORAGE] PutBlob {"blobID": "_log_20211121125519_caf3_1637479519_1637479629_1_628dc16bbb0d4dc7870c56feae448fdd", "length": 13172, "error": null, "duration": "2.8629524s"}
DEBUG waiting for background rclone transfers to complete...
DEBUG all background rclone transfers have completed.
DEBUG killing rclone
DEBUG [STORAGE] Close {"error": null, "duration": "30.1406ms"}
DEBUG memory: after close repository allocated 19112176(-783048) max 21994728, sys: 116457472 total 131077736(+157088), allocs 728934(+848) frees 723478(+833) alive 16106(+15), goroutines 5
DEBUG default (64KiB) - allocated 125(11) chunks freed 125 alive 0 max 11 free list high water mark: 11
DEBUG typical-contig (8MiB128B) - allocated 37(2) chunks freed 37 alive 0 max 2 free list high water mark: 2
DEBUG contig (16MiB128B) - allocated 0(0) chunks freed 0 alive 0 max 0 free list high water mark: 0
DEBUG memory: final allocated 17952992(-1159184) max 21994728, sys: 116457472 total 131090528(+12792), allocs 729042(+108) frees 723855(+377) alive 15837(-269), goroutines 5
There is significant delay in one storage line every time. It takes anywhere from 1m30s to 1m50s. I’ve tried creating a filesystem repository and there is almost no delay. It takes 1-2 seconds to complete an incremental snapshot.
rclone also is fast by itself. “rclone sync” command only takes ~2 seconds to complete if there is no change to the source.