image-reflector-controller icon indicating copy to clipboard operation
image-reflector-controller copied to clipboard
verified publisher icon fluxcd

Loadtest BadgerGC

Open stealthybox opened this issue 7 months ago • 2 comments

related #757 issue #748

GH Action failing with SIGBUS Try running this yourself:

go test -run '^TestBadgerGCLoad$' github.com/fluxcd/image-reflector-controller/internal/database -v -count 1

This test modifies badger to run with less memory and frequent flushes to record-limited vlog files. The loop starts with around 480,000 image repos and each subsequent loop changes a smaller number of those repos, thus triggering compaction -> discard stats -> GC.

This test on my 14 core apple silicon device causes the GC to also hit its edge-case of 1000 max vlog discards. If you reduce the GC stop deadline, you can also trigger the error case where Badger rejects the GC request and stops the GC run early.

Example log:

=== RUN   TestBadgerGCLoad
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:03.661593" "level"=0 "msg"="INFO: All 0 tables opened in 0s\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:03.670145" "level"=0 "msg"="INFO: Discard stats nextEmptySlot: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:03.670244" "level"=0 "msg"="INFO: Set nextTxnTs to 0"
    badger_gc.go:61: loaded-badger-gc: "ts"="2025-05-23 17:41:03.670414" "level"=0 "msg"="Starting Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:05.409496" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7329837 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:05.442940" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 106307 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:05.455821" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: alpine 5: 120000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:41:23.671816" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:23.671855" "level"=0 "msg"="DEBUG: No file with discard stats"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-05-23 17:41:23.671864" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=0
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:29.328635" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7209369 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:29.362708" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 113680 keys. Skipped 0 keys. Iteration took: 13ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:29.373951" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 99789 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:29.385336" "level"=0 "msg"="DEBUG: [Compactor: 0] Compaction for level: 0 DONE"
    badger_gc_test.go:92: node 5: 120000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:39.098729" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7248920 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:39.144216" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110713 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:39.155614" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 92562 keys. Skipped 0 keys. Iteration took: 10ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:39.171966" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: postgres 5: 120000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:41:43.672032" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:43.672072" "level"=0 "msg"="DEBUG: No file with discard stats"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-05-23 17:41:43.672083" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=0
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:47.110393" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7251023 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:47.143782" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111230 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:47.156281" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111101 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:47.165834" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 84615 keys. Skipped 0 keys. Iteration took: 10ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:47.180054" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: debian 5: 120000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:53.386373" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7237583 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:53.448068" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 113460 keys. Skipped 44718 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:53.460660" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111425 keys. Skipped 651 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:53.467091" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 59403 keys. Skipped 0 keys. Iteration took: 6ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:41:53.482403" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: alpine 4: 105000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:42:03.672703" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:03.786398" "level"=0 "msg"="DEBUG: Discard: 560520 less than threshold: 1212225 for file: 000046.vlog"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-05-23 17:42:03.786427" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=45
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:06.998557" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7222238 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.046858" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111023 keys. Skipped 22180 keys. Iteration took: 15ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.047006" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 79 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.047869" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 113428 keys. Skipped 53714 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.063319" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111305 keys. Skipped 5918 keys. Iteration took: 15ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.071802" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 59554 keys. Skipped 24284 keys. Iteration took: 8ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:07.085121" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: node 4: 105000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:22.416508" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7230268 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:22.457330" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 84616 keys. Skipped 31309 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:22.461079" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 110910 keys. Skipped 36611 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:22.469977" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 59745 keys. Skipped 37310 keys. Iteration took: 9ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:22.487733" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:42:23.786599" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:92: postgres 4: 105000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.420656" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7250269 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.458799" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 84617 keys. Skipped 53307 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.463168" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 111425 keys. Skipped 43656 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.475000" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 110954 keys. Skipped 1513 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.483112" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 59580 keys. Skipped 5001 keys. Iteration took: 8ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:29.498463" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:92: debian 4: 105000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.737885" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7235444 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.797958" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 113220 keys. Skipped 44425 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.816199" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111491 keys. Skipped 46745 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.828802" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110967 keys. Skipped 13764 keys. Iteration took: 13ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.828859" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 129 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:35.844804" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: alpine 3: 90000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.780580" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7174259 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.811542" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 59710 keys. Skipped 2430 keys. Iteration took: 11ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.822223" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 113220 keys. Skipped 44899 keys. Iteration took: 20ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.827226" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.833354" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.834223" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 111512 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.839047" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.841356" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.843621" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.845974" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.847966" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.852141" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 110945 keys. Skipped 58555 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.853025" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.869167" "level"=0 "msg"="DEBUG: [Compactor: 0] Compaction for level: 0 DONE"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.875926" "level"=0 "msg"="DEBUG: 5 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.875946" "level"=0 "msg"="INFO: Processed 5 entries in 1 loops"
    badger_gc_test.go:131: "ts"="2025-05-23 17:42:52.875966" "level"=0 "msg"="INFO: Total entries: 133. Moved: 77"
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-05-23 17:42:55.645123" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc_test.go:92: node 3: 90000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:02.890757" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7160597 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:02.946451" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111194 keys. Skipped 17344 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:02.964938" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111905 keys. Skipped 79576 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:02.968705" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 32173 keys. Skipped 5717 keys. Iteration took: 4ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:02.984902" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: postgres 3: 90000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.777087" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7147849 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.804854" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 32174 keys. Skipped 16457 keys. Iteration took: 5ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.818262" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 110918 keys. Skipped 84136 keys. Iteration took: 19ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.831677" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 111183 keys. Skipped 2701 keys. Iteration took: 13ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.844715" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 111826 keys. Skipped 0 keys. Iteration took: 13ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.844837" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 683 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:11.863020" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:92: debian 3: 90000 repos
    badger_gc_test.go:92: alpine 2: 75000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:43:15.646269" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.075636" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7134433 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.110313" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 111827 keys. Skipped 2467 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.116351" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 113447 keys. Skipped 74347 keys. Iteration took: 21ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.129167" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 110890 keys. Skipped 654 keys. Iteration took: 13ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.144216" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 110593 keys. Skipped 26982 keys. Iteration took: 15ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.144316" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 390 keys. Skipped 38 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.144691" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.147047" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.154028" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.160572" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.184115" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.184127" "level"=0 "msg"="INFO: Processed 9 entries in 1 loops"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:22.184155" "level"=0 "msg"="INFO: Total entries: 133. Moved: 36"
    badger_gc_test.go:92: node 2: 75000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.863388" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7147162 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.887587" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 32858 keys. Skipped 3283 keys. Iteration took: 5ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.898690" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110939 keys. Skipped 48678 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.916758" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111855 keys. Skipped 51603 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.916813" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 15 keys. Skipped 1 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.935689" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.964173" "level"=0 "msg"="INFO: Processed 2 entries in 1 loops"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:35.964206" "level"=0 "msg"="INFO: Total entries: 139. Moved: 2"
    badger_gc_test.go:92: postgres 2: 75000 repos
    badger_gc_test.go:92: debian 2: 75000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.336826" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7149112 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.397212" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111856 keys. Skipped 15560 keys. Iteration took: 15ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.398144" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 113206 keys. Skipped 8098 keys. Iteration took: 15ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.402420" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 32873 keys. Skipped 4590 keys. Iteration took: 5ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.418139" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111117 keys. Skipped 73501 keys. Iteration took: 19ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.429952" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110928 keys. Skipped 1569 keys. Iteration took: 12ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.429993" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 24 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:44.450405" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: alpine 1: 60000 repos
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-05-23 17:43:47.917918" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.484345" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7125967 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.515258" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 111840 keys. Skipped 2473 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.515337" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 41 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.518697" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 113206 keys. Skipped 51225 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.532318" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 111107 keys. Skipped 611 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.549322" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 110593 keys. Skipped 50694 keys. Iteration took: 17ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.549405" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 344 keys. Skipped 34 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:43:59.567957" "level"=0 "msg"="DEBUG: [Compactor: 0] Compaction for level: 0 DONE"
    badger_gc_test.go:92: node 1: 60000 repos
    badger_gc_test.go:92: postgres 1: 60000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.905678" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7156533 size of flushChan: 0\n"
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-05-23 17:44:07.918111" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.949776" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111182 keys. Skipped 34163 keys. Iteration took: 17ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.950684" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111769 keys. Skipped 56705 keys. Iteration took: 18ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.955872" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 32986 keys. Skipped 3296 keys. Iteration took: 5ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.964218" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110607 keys. Skipped 8360 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.964295" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 254 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:07.978682" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:92: debian 1: 60000 repos
    badger_gc_test.go:92: alpine 0: 45000 repos
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.006127" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7134154 size of flushChan: 0\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.046425" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111780 keys. Skipped 2499 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.046523" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 244 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.049926" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 113338 keys. Skipped 44338 keys. Iteration took: 17ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.065483" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 111177 keys. Skipped 24941 keys. Iteration took: 16ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.072033" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.074091" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.076695" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.078682" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.079715" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 110479 keys. Skipped 32935 keys. Iteration took: 14ms"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.085144" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.093865" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.097722" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.100700" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.117832" "level"=0 "msg"="DEBUG: 1 entries written"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.117853" "level"=0 "msg"="INFO: Processed 1 entries in 1 loops"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:22.117865" "level"=0 "msg"="INFO: Total entries: 133. Moved: 64"
    badger_gc_test.go:92: node 0: 45000 repos
    badger_gc_test.go:92: postgres 0: 45000 repos
    badger_gc_test.go:92: debian 0: 45000 repos
    badger_gc_test.go:98: waiting for GC stop
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-05-23 17:44:37.234419" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc.go:70: loaded-badger-gc: "ts"="2025-05-23 17:44:37.234450" "level"=0 "msg"="Stopped Badger GC"
    badger_gc_test.go:103: GC Stopped
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.234853" "level"=0 "msg"="DEBUG: Closing database"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.235042" "level"=0 "msg"="INFO: Lifetime L0 stalled for: 0s\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.235060" "level"=0 "msg"="DEBUG: Flushing memtable"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.235071" "level"=0 "msg"="DEBUG: pushed to flush chan\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.248600" "level"=0 "msg"="DEBUG: Stopping garbage collection of values."
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.425674" "level"=0 "msg"="INFO: \nLevel 0 [ ]: NumTables: 01. Size: 1.8 MiB of 0 B. Score: 1.00->1.18 StaleData: 0 B Target FileSize: 8.0 MiB\nLevel 1 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 2 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 3 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 4 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 5 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 6 [B]: NumTables: 06. Size: 8.5 MiB of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel Done\n"
    badger_gc_test.go:131: "ts"="2025-05-23 17:44:37.425917" "level"=0 "msg"="DEBUG: Waiting for closer"
--- PASS: TestBadgerGCLoad (214.86s)
PASS
ok  	github.com/fluxcd/image-reflector-controller/internal/database	215.172s

stealthybox avatar May 23 '25 07:05 stealthybox

A release candidate for this garbage-collection logic is cut:

  • ghcr.io/fluxcd/image-reflector-controller:rc-c4913021
  • docker.io/fluxcd/image-reflector-controller:rc-c4913021

Updated CRD's: kustomize build https://github.com/fluxcd/image-reflector-controller//config/crd/

stealthybox avatar May 24 '25 06:05 stealthybox

Rebased on badger v4 + test passes locally

=== RUN   TestBadgerGCLoad
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:17.723669" "level"=0 "msg"="INFO: All 0 tables opened in 0s\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:17.733238" "level"=0 "msg"="INFO: Discard stats nextEmptySlot: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:17.733326" "level"=0 "msg"="INFO: Set nextTxnTs to 0"
    badger_gc.go:61: loaded-badger-gc: "ts"="2025-09-05 13:30:17.733636" "level"=0 "msg"="Starting Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:19.685479" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7332081 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:19.725668" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 106307 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:19.740837" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:93: alpine 5: 120000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:30:37.733749" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:37.733811" "level"=0 "msg"="DEBUG: No file with discard stats"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-09-05 13:30:37.733819" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=0
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:51.053776" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7211481 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:51.101245" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 114257 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:51.111745" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 99212 keys. Skipped 0 keys. Iteration took: 10ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:51.126827" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:30:57.734059" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:30:57.734111" "level"=0 "msg"="DEBUG: No file with discard stats"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-09-05 13:30:57.734120" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=0
    badger_gc_test.go:93: node 5: 120000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:03.119805" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7248816 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:03.149292" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 102036 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:03.160019" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 100662 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:03.176838" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: postgres 5: 120000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:13.015802" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7245391 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:13.048952" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 102968 keys. Skipped 0 keys. Iteration took: 10ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:13.060789" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 102747 keys. Skipped 0 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:13.072320" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 100654 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:13.086190" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:31:17.734335" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:17.734406" "level"=0 "msg"="DEBUG: No file with discard stats"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-09-05 13:31:17.734418" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=0
    badger_gc_test.go:93: debian 5: 120000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:21.000470" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7237487 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:21.054604" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 114184 keys. Skipped 44789 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:21.066233" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103550 keys. Skipped 580 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:21.071874" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 58869 keys. Skipped 0 keys. Iteration took: 6ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:21.084563" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: alpine 4: 105000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:31:37.734646" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.003660" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7220926 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.045547" "level"=0 "msg"="DEBUG: Discard: 577368 less than threshold: 1248661 for file: 000046.vlog"
    badger_gc.go:85: loaded-badger-gc: "ts"="2025-09-05 13:31:38.045579" "level"=1 "msg"="Ran Badger GC" "discarded_vlogs"=45
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.054104" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 102747 keys. Skipped 29864 keys. Iteration took: 15ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.055011" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 114282 keys. Skipped 54483 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.068113" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103452 keys. Skipped 5149 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.075852" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 58869 keys. Skipped 16600 keys. Iteration took: 8ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:38.093956" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: node 4: 105000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:57.694705" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7230784 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:57.727050" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 101729 keys. Skipped 22048 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:57.744184" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 106334 keys. Skipped 77765 keys. Iteration took: 17ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:57.750642" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 54207 keys. Skipped 5417 keys. Iteration took: 6ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:31:57.765366" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:31:58.045673" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:93: postgres 4: 105000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.797388" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7249913 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.849955" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 54207 keys. Skipped 48790 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.855393" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103693 keys. Skipped 42969 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.866584" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101723 keys. Skipped 2200 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.879684" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 106099 keys. Skipped 9518 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:06.896112" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: debian 4: 105000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.659981" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7234304 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.703983" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 113991 keys. Skipped 44502 keys. Iteration took: 15ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.719420" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103616 keys. Skipped 40275 keys. Iteration took: 15ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.732271" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101840 keys. Skipped 20157 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.732355" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 251 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:14.749283" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: alpine 3: 90000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.180855" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7173251 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.213425" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 106350 keys. Skipped 4054 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.219449" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 113925 keys. Skipped 44899 keys. Iteration took: 17ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.228376" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.230314" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 103713 keys. Skipped 0 keys. Iteration took: 11ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.230525" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.241845" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.247296" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 101743 keys. Skipped 56925 keys. Iteration took: 17ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.247338" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 66 keys. Skipped 6 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.247931" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.250316" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.252668" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.258510" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.265483" "level"=0 "msg"="DEBUG: [Compactor: 0] Compaction for level: 0 DONE"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.267110" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.283181" "level"=0 "msg"="DEBUG: 1 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.283197" "level"=0 "msg"="INFO: Processed 1 entries in 1 loops"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:35.283233" "level"=0 "msg"="INFO: Total entries: 128. Moved: 73"
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-09-05 13:32:35.744469" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc_test.go:93: node 3: 90000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.047266" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7160071 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.098055" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 54207 keys. Skipped 27753 keys. Iteration took: 9ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.101209" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101742 keys. Skipped 2452 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.117733" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 106295 keys. Skipped 72308 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.117802" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 122 keys. Skipped 122 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:48.139856" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: postgres 3: 90000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:32:55.744637" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.519881" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7149273 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.546398" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 54329 keys. Skipped 16455 keys. Iteration took: 7ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.556852" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103992 keys. Skipped 77915 keys. Iteration took: 18ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.573396" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101966 keys. Skipped 8924 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.586919" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 105792 keys. Skipped 0 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:32:59.604784" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: debian 3: 90000 repos
    badger_gc_test.go:93: alpine 2: 75000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.528276" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7134241 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.564713" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 105792 keys. Skipped 4010 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.568703" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 114289 keys. Skipped 74431 keys. Iteration took: 20ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.579070" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 104057 keys. Skipped 570 keys. Iteration took: 10ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.592430" "level"=0 "msg"="DEBUG: [2] LOG Compact. Added 101537 keys. Skipped 25477 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:11.611270" "level"=0 "msg"="DEBUG: [Compactor: 2] Compaction for level: 0 DONE"
    badger_gc_test.go:93: node 2: 75000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.230720" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7146697 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.264145" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 101788 keys. Skipped 37790 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.281593" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 106331 keys. Skipped 57347 keys. Iteration took: 17ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.289476" "level"=0 "msg"="DEBUG: [0] LOG Compact. Added 53539 keys. Skipped 8411 keys. Iteration took: 8ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.305151" "level"=0 "msg"="DEBUG: [Compactor: 0] Compaction for level: 0 DONE"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.337344" "level"=0 "msg"="DEBUG: 7 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.337359" "level"=0 "msg"="INFO: Processed 7 entries in 1 loops"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:29.337403" "level"=0 "msg"="INFO: Total entries: 134. Moved: 7"
    badger_gc_test.go:93: postgres 2: 75000 repos
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-09-05 13:33:33.910651" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc_test.go:93: debian 2: 75000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:39.996768" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7151146 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.051857" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 106434 keys. Skipped 0 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.054573" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 113841 keys. Skipped 8124 keys. Iteration took: 15ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.060271" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 53436 keys. Skipped 20129 keys. Iteration took: 8ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.072371" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103898 keys. Skipped 72836 keys. Iteration took: 18ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.083970" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101822 keys. Skipped 2232 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.084105" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 573 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:40.099441" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:93: alpine 1: 60000 repos
    badger_gc.go:80: loaded-badger-gc: "ts"="2025-09-05 13:33:53.911769" "level"=1 "msg"="Running Badger GC"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.743397" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7129460 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.778093" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 106391 keys. Skipped 4042 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.779074" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 616 keys. Skipped 0 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.783177" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 113939 keys. Skipped 51272 keys. Iteration took: 18ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.796864" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 103976 keys. Skipped 545 keys. Iteration took: 14ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.811283" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 101646 keys. Skipped 49178 keys. Iteration took: 14ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:33:58.828911" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:93: node 1: 60000 repos
    badger_gc_test.go:93: postgres 1: 60000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.559435" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7158711 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.597735" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 54052 keys. Skipped 14053 keys. Iteration took: 8ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.605483" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 103976 keys. Skipped 33536 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.611139" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.614141" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.617435" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.618060" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 101642 keys. Skipped 8987 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.620815" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.630819" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.634161" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 106198 keys. Skipped 45751 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.634246" "level"=0 "msg"="DEBUG: [3] LOG Compact. Added 197 keys. Skipped 197 keys. Iteration took: 0s"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.636010" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.644505" "level"=0 "msg"="DEBUG: 73 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.649414" "level"=0 "msg"="DEBUG: [Compactor: 3] Compaction for level: 0 DONE"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.661329" "level"=0 "msg"="DEBUG: 10 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.661338" "level"=0 "msg"="INFO: Processed 10 entries in 1 loops"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:08.661374" "level"=0 "msg"="INFO: Total entries: 976. Moved: 521"
    badger_gc_test.go:93: debian 1: 60000 repos
    badger_gc_test.go:93: alpine 0: 45000 repos
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.239907" "level"=0 "msg"="DEBUG: Flushing memtable, mt.size=7146052 size of flushChan: 0\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.279630" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 106198 keys. Skipped 4043 keys. Iteration took: 13ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.284396" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 114129 keys. Skipped 44416 keys. Iteration took: 18ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.287089" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 54249 keys. Skipped 521 keys. Iteration took: 7ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.300713" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 103950 keys. Skipped 24844 keys. Iteration took: 16ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.312886" "level"=0 "msg"="DEBUG: [1] LOG Compact. Added 101478 keys. Skipped 31093 keys. Iteration took: 12ms"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.318875" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.326329" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.332886" "level"=0 "msg"="DEBUG: [Compactor: 1] Compaction for level: 0 DONE"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.359182" "level"=0 "msg"="DEBUG: 9 entries written"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.359203" "level"=0 "msg"="INFO: Processed 9 entries in 1 loops"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:25.359242" "level"=0 "msg"="INFO: Total entries: 128. Moved: 27"
    badger_gc_test.go:93: node 0: 45000 repos
    badger_gc.go:93: loaded-badger-gc: "ts"="2025-09-05 13:34:29.506981" "msg"="Warning: Badger GC ran for maximum discards" "error"=null "discarded_vlogs"=1000
    badger_gc_test.go:93: postgres 0: 45000 repos
    badger_gc_test.go:93: debian 0: 45000 repos
    badger_gc_test.go:99: waiting for GC stop
    badger_gc.go:70: loaded-badger-gc: "ts"="2025-09-05 13:34:36.484356" "level"=0 "msg"="Stopped Badger GC"
    badger_gc_test.go:104: GC Stopped
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.484846" "level"=0 "msg"="DEBUG: Closing database"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.485065" "level"=0 "msg"="INFO: Lifetime L0 stalled for: 0s\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.485088" "level"=0 "msg"="DEBUG: Flushing memtable"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.485098" "level"=0 "msg"="DEBUG: pushed to flush chan\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.500632" "level"=0 "msg"="DEBUG: Stopping garbage collection of values."
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.699308" "level"=0 "msg"="INFO: \nLevel 0 [ ]: NumTables: 01. Size: 1.9 MiB of 0 B. Score: 1.00->1.12 StaleData: 0 B Target FileSize: 8.0 MiB\nLevel 1 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 2 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 3 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 4 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 5 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 6 [B]: NumTables: 05. Size: 8.9 MiB of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel Done\n"
    badger_gc_test.go:132: "ts"="2025-09-05 13:34:36.699575" "level"=0 "msg"="DEBUG: Waiting for closer"
--- PASS: TestBadgerGCLoad (259.99s)
PASS
ok  	github.com/fluxcd/image-reflector-controller/internal/database	260.314s

stealthybox avatar Sep 10 '25 06:09 stealthybox