Skip to content

Test: don't assert an absolute defrag hit count during AOF loading - #56

Open
madolson wants to merge 1 commit into
unstablefrom
ai/issue-40
Open

madolson wants to merge 1 commit into
unstablefrom
ai/issue-40

Conversation

@madolson

Copy link
Copy Markdown
Owner

Active defrag - AOF loading asserts active_defrag_hits > 80000 right after debug loadaof, but that count is bounded by how long the replay takes in wall-clock time: defrag only runs from whileBlockedCron, which returns early unless a millisecond has elapsed (src/server.c:1822), and its duty cycle is computed as a percentage of the elapsed wait (src/defrag.c:1071). The replay duration is set by key-load-delay -25, a 1-in-25 sampled usleep(1) per replayed command (src/aof.c:1705, src/debug.c:2619), so the threshold really measures how expensive usleep(1) is on the runner. Making that sleep 16x rarer (key-load-delay -400) drops the count to 33k-70k and fails 5 out of 5 loops locally on an unmodified build. This asserts the property the comment above it already describes, that defrag ran and relocated allocations during loading, and drops the absolute count.

Details

Reproduction

Emulating a runner where usleep(1) is cheap. Locally on x86-64, active_defrag_hits scales with the replay wall time:

key-load-delay active_defrag_hits total_active_defrag_time (ms) result
-25 (as committed) 133929 311 pass
-100 127296 144 pass
-400 30906 - 49089 20 - 33 fail, 5/5
0 (no sleep) 974 - 1115 0 fail, 3/3

validate_latency 500 on the line above passes in every one of those runs, so nothing else in the test is disturbed.

Applied as a scratch patch to make the knob settable:

-                r config set key-load-delay -25 ;# sleep on average 1/25 usec
+                r config set key-load-delay [expr {[info exists ::env(REPRO40_KLD)] ? $::env(REPRO40_KLD) : -25}]
REPRO40_KLD=-400 ./runtest --single unit/memefficiency \
  --only "Active Defrag main dictionary: standalone" \
  --only "Active defrag - AOF loading" --loops 5

Before, 5 of 5 loops fail:

REPRO40 hits=48101 misses=6937 keyhits=25424 time=35
[err]: Active defrag - AOF loading in tests/unit/memefficiency.tcl
Expected [s active_defrag_hits] > 80000 (context: type eval line 30 cmd {assert {[s active_defrag_hits] > 80000}} proc ::test)
REPRO40 hits=41279 misses=4815 keyhits=21752 time=31
[err]: Active defrag - AOF loading in tests/unit/memefficiency.tcl
REPRO40 hits=32928 misses=3167 keyhits=17216 time=20
[err]: Active defrag - AOF loading in tests/unit/memefficiency.tcl
REPRO40 hits=63989 misses=11671 keyhits=34439 time=42
[err]: Active defrag - AOF loading in tests/unit/memefficiency.tcl
REPRO40 hits=70320 misses=14776 keyhits=38070 time=49
[err]: Active defrag - AOF loading in tests/unit/memefficiency.tcl

After, same knob, 5 of 5 loops pass:

REPRO40 hits=43364 misses=5485 keyhits=22773 time=30
[ok]: Active defrag - AOF loading (515 ms)
REPRO40 hits=37740 misses=3889 keyhits=19656 time=25
[ok]: Active defrag - AOF loading (510 ms)
REPRO40 hits=30906 misses=2840 keyhits=16014 time=20
[ok]: Active defrag - AOF loading (506 ms)
REPRO40 hits=48277 misses=6681 keyhits=25725 time=33
[ok]: Active defrag - AOF loading (519 ms)
REPRO40 hits=49089 misses=7140 keyhits=26112 time=33
[ok]: Active defrag - AOF loading (522 ms)
\o/ All tests passed without errors!

The puts and the key-load-delay knob are scratch instrumentation and are not in this PR.

Why not raise or lower the threshold

1c5572fed (#2402) already ratcheted this once, from > 100000 down to > 80000, with the message "During AOF loading, we only hit 95k items rather than 100k in one defrag test". Any absolute number picked from an observed value is a number about one machine. There is no floor that both survives a fast runner and means anything: the observed range here spans 974 to 133929 hits on a single unchanged binary, purely as a function of the replay duration.

Why the failures are 32-bit only

Each hit is one relocation gated by the jemalloc hint, and a pointer with no hint increments misses, not hits (allocatorShouldDefrag, src/defrag.c:169). Which pointers jemalloc offers depends on slab utilization, and slab packing for these 250-byte objects differs on a 32-bit build, which lands 32-bit runners closer to the threshold to begin with.

What is still asserted

config resetstat on tests/unit/memefficiency.tcl:292 zeroes total_active_defrag_time (src/server.c:2854) along with the hit counters, and activedefrag no closes the window on the line after debug loadaof, so all three values still cover only the debug loadaof window. A regression where defrag never starts while blocked, or starts and relocates nothing, still fails. Held at the extreme: even with key-load-delay 0, where total_active_defrag_time rounds to 0 ms, active_defrag_hits was ~1000, so the check has real margin against a "defrag never ran" regression.

This was generated by AI but verified, with love, by a human.

The hit count is bounded by the wall-clock duration of the AOF replay, so
the threshold measures runner speed rather than correctness. Assert that
defrag ran and relocated allocations during loading instead.

Fixes valkey-io/valkey#3954

Signed-off-by: Madelyn Olson <matolson@amazon.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant