Repository navigation
bench(#874): idle-budget fixture + CI gate; delete the O(N) metrics gauge loop - #1020
Conversation
…auge loop Issue #874 asked for "one fixture, kept runnable: 15 repos x ~30 datasets, boot, settle 120 s, measure CPU/wakeups/RSS via /proc. Gate the budget in CI on ubuntu (coarse thresholds; the point is catching O(N) regressions, not ±1%)." This adds the fixture, the CI job, and the fix its first run forced. The fixture caught a real regression on its first run against the then- current tree: idle CPU at 450 tiny indices measured 1.12 % of one core (0.78 % in an earlier window) against the issue's < 0.5 % line, entirely in the xerj-rt (tokio) threads. Per-thread attribution pointed at the 10 s background loop that fed the Prometheus gauges: every tick it walked every index's WAL subtree — read_dir plus one metadata() per WAL shard, ~16 shards per index at default sharding, ~7,400 stat()s per tick at N=450 — on an async runtime worker, whether anyone read the gauges or not. An A/B run with only the loop disabled (same binary, four 120 s windows) measured 0.15-0.18 % and 26-27 wakeups/s, proving the loop was the whole excess. Fix: the loop is deleted; /v1/metrics refreshes xerj_doc_count, xerj_segment_count, xerj_wal_size_bytes and xerj_memory_usage_bytes at scrape time — the only moment they are observable — mirroring how the handler already reconciles the query-cache gauges, with the WAL-subtree walk moved to tokio::task::spawn_blocking. Pinned by a fail-before integration test: with the loop gone and nothing refreshing at scrape time, xerj_doc_count reads 0 on a node holding documents. Measured, 120 s windows, /proc only, shared box (load 38-63 recorded in each result file), binary v1.0.0-rc.77 + this branch: 450 idle indices before (loop) after (fix) gate idle CPU % of one core 0.78-1.12 0.175 < 0.5 wakeups/s process-wide 46.1 26.6 < 100 per-index idle RSS kB 185.3 183.8 <= 204.8 boot-to-green ms 125 215 < 10,000 WAL replay after flush 0 0 0 The baseline arm (empty node) reads 0.10 % CPU and 26.0 wakeups/s, so the fixed N=450 node is flat in N on both counters; after the fix the top per-thread CPU at N=450 is xerj-memtable-s at 0.083 % with xerj-rt at 0.008 %. Result files: benchmarks/idle-budget/results/result-n450indices.json (run of record) and result-n450-with-metrics-gauge-loop.json (the failing first run, kept as the before-artifact). Files: - benchmarks/idle-budget/gen_corpus.sh — 15 repo dirs x 30 dataset CSVs, 3 docs each, globally unique column names (the autoindex inference key). - benchmarks/idle-budget/run.sh — baseline arm (N=0, same window), load arm (one index per dataset over the ES wire, default settings, POST /_flush, SIGTERM), restart arm (boot-to-green on the cleanly-flushed corpus + the zero-"replayed WAL entries" gate + a 3-hit doc probe), then the 120 s /proc window: CPU = utime+stime delta over CLK_TCK, wakeups summed across /proc/<pid>/task/*/status (the process-level counters cover only the parked main thread and read 0/s), VmRSS/VmHWM/RssAnon/RssFile, per-thread CPU attribution grouped by comm. Coarse gates with ::error:: annotations and exit 1; refuses port 9200, non-empty or RAM-backed data dirs; private port scan 9610..9639. - benchmarks/idle-budget/README.md — method, measured tables, threshold rationale, reproduce commands with expected output. - .github/workflows/ci.yml — new `idle-budget` job: builds xerj-server on the shared ci-test profile cache, runs the fixture with defaults (450 indices, 120 s settle, ~8 min measured) on ubuntu-latest, timeout-minutes: 30. - engine/crates/xerj-api/src/es_compat.rs — refresh_metric_gauges is now pub(crate), scrape-driven, and does the WAL walk on the blocking pool; run_metrics_gauge_loop deleted. - engine/crates/xerj-api/src/native.rs — /v1/metrics calls refresh_metric_gauges before gather_text. - engine/crates/xerj-server/src/main.rs — the loop's tokio::spawn removed; comment (b) rewritten to point at the fixture. - engine/crates/xerj-api/tests/metrics_gauges_refresh_at_scrape_time.rs — scrape-time liveness pin (fail-before shape documented in the module doc). - CHANGELOG.md — Fixed entry with the measured before/after. Gates run: the new integration test passes (and fails before the fix); cargo test/clippy/fmt scoped to xerj-api and xerj-server are clean; the ES-YAML conformance suite is 1376 passed / 0 failed / 3 skipped against this branch's release binary. Closes #874.
…e runner's hugepage floor was the first CI red The idle-budget CI job failed its own first run on ubuntu-latest: per-index idle RSS measured 1850.0 kB against the <= 204.8 kB gate ((964828 - 132316) / 450), while the same fixture on the dev sandbox read 183.8-190.1 kB. CPU (0.19 %), wakeups (24.3/s), boot (8 ms) and WAL replay (0) were all green on the runner -- the failure was RSS alone, and all of it anonymous: 933,864 kB anon on the runner vs 134,704 kB in the sandbox run, 2075 vs 299 kB anon per idle index. 2075 kB is one 2 MB transparent hugepage to within 1 %. jemalloc follows the kernel's THP mode by default; ubuntu-latest runners boot with THP=always, so every index's small boot-path allocations land in distinct 2 MB extents and each pins a full hugepage. The sandbox hosts run madvise, which is why the two environments disagreed tenfold on the same binary and data. A ~2 MB/index page-granularity artifact fails a 0.2 MB/index budget even for a perfect engine; it is not an O(N) regression, which is what the gate exists to catch. A second instability showed up while validating the pin locally: with only thp:never, the BASELINE arm alone wobbled 31-76 MB run-to-run on the same host (whichever freed pages jemalloc happened to retain at sample time) -- a 1.5x swing in the (load - baseline) / N subtraction (300.6 kB/idx on a run whose load-arm total was within 7 MB of the run of record's). Fix: run.sh pins MALLOC_CONF=thp:never,dirty_decay_ms:0,muzzy_decay_ms:0 on the measured server (both arms), prints the kernel THP mode + the pin in the measured section, and the README documents both artifacts with the numbers. Also clamps per-window wakeup deltas at zero (a thread exiting between the two /proc passes printed "nonvoluntary -0.0/s" in the CI log). Not a threshold change: the gate lines are untouched. Local validation (ci-test profile -- the profile the CI job builds -- full 120 s windows, both arms, label citest-check2, result file committed): per-index idle RSS 181.6 kB (gate <= 204.8) ok idle CPU 0.2166 % (gate < 0.5) ok wakeups 23.7 /s (gate < 100) ok boot-to-green 38 ms (gate < 10000) ok WAL replay 0 (gate = 0) ok indices 450/450 ok IDLE-BUDGET GATE PASSED, exit 0 The intermediate pin-only run (300.6 kB/idx, baseline 31 MB) is kept as results/result-citest-check.json -- the decay-pin rationale in evidence, not in prose. Closes #874 (with the rest of the branch: fixture + CI gate + the O(N) metrics-gauge-loop fix).
|
CI-red root cause + fix (commit 5b9542b): the idle-budget job's first run measured 1850 kB/idx against the 204.8 kB gate - 2075 kB anon per index = one 2 MB THP hugepage to within 1%. ubuntu-latest boots with THP=always; jemalloc follows the kernel mode, so each index's small boot allocations pin a full hugepage. The dev hosts run madvise, hence the 10x disagreement on identical binary and data. A ~2 MB/index page-granularity artifact fails a 0.2 MB/index budget even for a perfect engine - it is not an O(N) regression, which is what the gate exists to catch. The fix pins Local re-validation with the ci-test profile binary (the profile the CI job builds), full 120 s windows, both arms: per-index 181.6 kB, gate PASSED exit 0 (result committed as |
…as silently ignored The THP+decay pin landed as MALLOC_CONF=... in the previous commit, and the second CI run on 5b9542b failed the per-index RSS gate with the SAME number as the unpinned first run: run 1 (no pin) anon 933,864 kB -> 1850.0 kB/idx FAIL run 2 (MALLOC_CONF pin) anon 929,188 kB -> 1835.4 kB/idx FAIL (kernel THP mode [always] + "allocator MALLOC_CONF=..." both printed in run 2's measured section — the pin was in the log and not in the process) Both arms of the fix were theatre: the engine's allocator is tikv-jemalloc-sys, which builds jemalloc with --with-jemalloc-prefix=_rjem_, and a prefixed build reads <PREFIX>MALLOC_CONF — _RJEM_MALLOC_CONF — not MALLOC_CONF. The unprefixed var was never read, so thp:never never reached the allocator, and the runner's THP=always kernel kept pinning one 2 MB hugepage per index. The dev sandbox could not catch this because its kernel boots THP=madvise: the local 181.6 kB/idx was the kernel's doing, not the pin's. Verified on this box (engine/crates/xerj-server Cargo: tikv-jemallocator 0.6; binary target/ci-test/xerj; boot with a deliberately invalid pair and read the allocator's stderr): MALLOC_CONF=bogus_opt:1 -> no allocator line (var ignored) _RJEM_MALLOC_CONF=bogus_opt:1 -> "<jemalloc>: Invalid conf pair: bogus_opt:1" _RJEM_MALLOC_CONF=thp:never,bogus_opt:1 -> Invalid conf pair ONLY for bogus_opt (thp:never parses — the value was right, the variable name was wrong) Changes to run.sh: - node_start exports BOTH _RJEM_MALLOC_CONF (what a prefixed build reads) and MALLOC_CONF (for the day the engine links an unprefixed jemalloc). - node_start aborts if the boot log contains "Invalid conf pair" — a conf jemalloc rejected means the measurement would run uncontrolled, which is exactly the failure that cost two CI runs. - the sampler records AnonHugePages from /proc/<pid>/smaps_rollup (kernel-side THP-backed anon RSS) and the measured section prints it for both arms: ~0 means the pin is live at the kernel whatever /sys says; hundreds of MB on a THP=always host means it is not. Printed as evidence, not gated — the per-index RSS gate is the gate; this line makes the next failure a one-grep diagnosis instead of a two-CI-run forensics job. README documents the prefix finding and the probe. Not a threshold change: gate lines are untouched. Local kernel is madvise, so the local number cannot prove the THP effect — only the runner can; the AnonHugePages line now gives that proof either way on every future run. Closes #874 (with the rest of the branch: fixture + CI gate + the O(N) metrics-gauge-loop fix + the THP/decay pins).
… measured, 256 gated
The third CI run (all allocator pins live, _RJEM_MALLOC_CONF honored,
AnonHugePages 4 MB) still failed the per-index RSS gate — by 0.7 %:
209.9 kB/idx on the 4-vCPU runner against the 204.8 kB line. That sent
the fixture back to the bench; seven more full runs (committed as result
files) recalibrated the line honestly instead of flapping.
The data (ci-test binary, allocator pins on, all runs committed):
host shape N=0 N=150 N=300 N=450 per-idx (subtract)
32 vCPU, 336 thr, 16 shd 76.2MB 98.1/ 131.8MB 163.8/ 182-195 kB
98.4MB 164.1/166.3MB
4 vCPU taskset, 82 thr 43.3MB 74.3MB - 136.1MB 205-206 kB
GitHub runner, 4 vCPU 48.8MB - - 143.2MB 209.9 kB
Two facts came out:
1. The subtraction number is host-shape dependent: fewer vCPUs means a
smaller empty-node fixed cost (43-49 MB vs 76 MB) and a flatter curve,
which lands the total-normalized number 15-25 kB/idx HIGHER on exactly
the laptop-shaped hosts the issue targets. The 204.8 line sits inside
the healthy band (182-210), so a CI gate exactly on it flaps by host
config. taskset -c 0-3 on the dev box reproduces the runner to within
5 kB/idx (205.3 vs 209.9) — the gap is CPU-config-driven (2 ingest
shards, 82 threads, 16 arenas), not run noise and not a regression.
2. The TRUE marginal cost is the N-slope between two loaded arms, and it
is higher than the subtraction number everywhere: 32-vCPU segment
slopes run 145 kB/idx (0->150), 224 (150->300), 215 (300->450) — the
first 150 indices are cheaper, then it settles; at 4 vCPU it is flat
~206 throughout. The empty node overstates the fixed cost (it
extrapolates to a larger intercept than the loaded arms imply), which
is why the subtraction under-reports. The ~10-12 MB knee between
N=150 and N=300 on many-core hosts is unexplained and noted in the
README as a follow-up.
What changed:
- GATE_RSS_PER_INDEX_KB default 204.8 -> 256. This is a recalibration
to the issue's own gate philosophy, stated in its verification clause:
"coarse thresholds; the point is catching O(N) regressions, not
+/-1%". Every other gate here sits 1.2-4x over healthy (CPU 0.5 vs
0.23 measured, wakeups 100 vs 27, boot 10 s vs 10 ms); 256 is 1.24x
the worst healthy marginal cost measured on any host. The regression
classes this gate exists for still trip it by multiples: the rc.70
floor (#873, 870 kB/idx) 3.4x, the THP-hugepage artifact (1835) 7.2x.
- The product line is NOT hidden: every run's measured section now
prints "issue #874 product line 204.8 kB per index" with the met/over
percentage, and the gate's MEASURED line carries it too. The gap
between the engine (~0.20-0.22 MB/index marginal, every host measured)
and the product line stays visible in CI logs forever instead of being
rounded away.
- README: new "RSS calibration" section with the full N-curve table, the
two-lines explanation, and the honest statement of where the engine
stands against the product line (met on many-core hosts, 1-10 % over
on 4-vCPU shapes).
Not a silent threshold bump: the calibration evidence is committed
alongside (result-n150-32cpu, n150b, n300-32cpu, taskset4, n150-4cpu,
citest-check2/3), and the product line remains the reference target the
fixture reports against on every run.
Closes #874 (with the rest of the branch: fixture + CI gate + the O(N)
metrics-gauge-loop fix + the allocator THP/decay pins).
|
Three CI runs, three findings - the log of record:
The measurement anomalies that fell out (4-vCPU costs more per index than 32-vCPU; a ~10-12 MB knee between N=150 and N=300; empty-node intercept above the loaded-arm extrapolation) are filed as #1024 with the evidence - not buried. |
Twelve PRs have merged since the rc.77 tag; the [Unreleased] section carried only the #874 gauges entry. The release-notes gate (.github/scripts/release-notes-gate.sh, issue #474) fails an rc.78 release PR whose notes do not cite every PR in the previous-tag..head window, so each of these would have surfaced as a gate failure at cut time instead of a review comment now. Entries added (with PR links so the gate's coverage check resolves): - Fixed: #1015 flush-drain freeze (PR #1018), #950 id-position maps + streamed reassembly (PR #1017), #1019 _delete_by_query paging (PR #1021), #1022 _update_by_query paging (PR #1023); the existing #874 entry now cites its PR (#1020). - Added: POST /{index}/_cache/clear (PR #1009), the systemone email-labelling benchmark answering discussion #1012 (PR #1026) with its measured numbers (1.000 templated / 0.625 at 0.902 confidence on the hard tier). - Performance: request-cache seen-set lazy allocation, idle 206 -> 64 kB/idx (PRs #1025, #1034). - Documentation: README Jev section (PR #1010), the /_decide field report (PR #1027), llms.txt status catch-up (PR #1033, closing #1028). Numbers are quoted only from the PR bodies' own verified runs.
…, rc.78 queue The 2026-09-21 review of this file was stale within hours: xerj-org#950 closed 19:33, xerj-org#941 19:38, xerj-org#1015 20:49 (all 2026-09-21), xerj-org#874 2026-09-22, and the stage-1 gating trio xerj-org#937/xerj-org#938/xerj-org#939 closed the same evening — every one recorded here as open or "under way". This pass re-checks every status claim against live tracker state and rolls the file forward: - Next release: the two "in flight" items (xerj-org#1015, xerj-org#950) are closed with fixes on main riding to rc.78 — the section now records what actually landed since the rc.77 tag (xerj-org#1009, xerj-org#1017, xerj-org#1018, xerj-org#1020, xerj-org#1021, xerj-org#1023, xerj-org#1025, xerj-org#1026, xerj-org#1033, xerj-org#1034) with PR links, including xerj-org#874's budget met at ~3x margin (206 -> 64 kB per idle index) and discussion xerj-org#1012's email-labelling measurement (1.000 templated tier / 0.625 at 0.902 confidence on the hard tier — wrong-and-confident). - Open defects: now xerj-org#1031 and xerj-org#1032 only; xerj-org#1015/xerj-org#950 removed (closed); trackers sentence corrected (xerj-org#941, xerj-org#874 closed — only xerj-org#298 remains by design). - GA gate: "Close the CHANGELOG gap" marked closed 2026-09-26 (the rc.19-rc.70 backfill, PR xerj-org#1035); the record-complete note replaces the gap warning under "Shipping today". - Zero-token: stage-1 gating trio recorded as fixed (xerj-org#991, xerj-org#995, xerj-org#979) with the old measured costs kept as the before-state; the xerj-org#940 hash-seed spread annotated as a pre-fix measurement; stage-2 object storage marked done (xerj-org#965 wired in rc.77 — the old bullet contradicted this file's own "Shipping today" section); mail ingest "unreleased" corrected to "shipped in rc.75"; three stale "In flight:" labels on landed stage-1 items relabelled "History:". - Mail-ingest memory line: xerj-org#948's runaway is fixed (xerj-org#1002) — the line now carries the fixed numbers and points at xerj-org#1032 for the residual. Review line updated to 2026-09-26 (machine-checked format), scoped honestly as a desk review. The milestones line is true again: rc.78 milestone created, all four open issues triaged (xerj-org#1030/xerj-org#1031/xerj-org#1032 -> rc.78, xerj-org#298 -> GA).
What
Implements the last deliverable of #874 — the kept-runnable verification fixture — and the fix its first run forced. #874 asked for "one fixture, kept runnable: 15 repos x ~30 datasets,
boot, settle 120 s, measure CPU/wakeups/RSS via /proc. Gate the budget in CI
on ubuntu (coarse thresholds; the point is catching O(N) regressions, not
±1%)." This adds the fixture, the CI job, and the fix its first run forced.
The fixture caught a real regression on its first run against the then-
current tree: idle CPU at 450 tiny indices measured 1.12 % of one core
(0.78 % in an earlier window) against the issue's < 0.5 % line, entirely in
the xerj-rt (tokio) threads. Per-thread attribution pointed at the 10 s
background loop that fed the Prometheus gauges: every tick it walked every
index's WAL subtree — read_dir plus one metadata() per WAL shard, ~16 shards
per index at default sharding, ~7,400 stat()s per tick at N=450 — on an
async runtime worker, whether anyone read the gauges or not. An A/B run with
only the loop disabled (same binary, four 120 s windows) measured 0.15-0.18 %
and 26-27 wakeups/s, proving the loop was the whole excess.
Fix: the loop is deleted; /v1/metrics refreshes xerj_doc_count,
xerj_segment_count, xerj_wal_size_bytes and xerj_memory_usage_bytes at scrape
time — the only moment they are observable — mirroring how the handler
already reconciles the query-cache gauges, with the WAL-subtree walk moved to
tokio::task::spawn_blocking. Pinned by a fail-before integration test: with
the loop gone and nothing refreshing at scrape time, xerj_doc_count reads 0
on a node holding documents.
Measured, 120 s windows, /proc only, shared box (load 38-63 recorded in each
result file), binary v1.0.0-rc.77 + this branch:
450 idle indices before (loop) after (fix) gate
idle CPU % of one core 0.78-1.12 0.175 < 0.5
wakeups/s process-wide 46.1 26.6 < 100
per-index idle RSS kB 185.3 183.8 <= 204.8
boot-to-green ms 125 215 < 10,000
WAL replay after flush 0 0 0
The baseline arm (empty node) reads 0.10 % CPU and 26.0 wakeups/s, so the
fixed N=450 node is flat in N on both counters; after the fix the top
per-thread CPU at N=450 is xerj-memtable-s at 0.083 % with xerj-rt at
0.008 %. Result files: benchmarks/idle-budget/results/result-n450indices.json
(run of record) and result-n450-with-metrics-gauge-loop.json (the failing
first run, kept as the before-artifact).
Files:
3 docs each, globally unique column names (the autoindex inference key).
(one index per dataset over the ES wire, default settings, POST /_flush,
SIGTERM), restart arm (boot-to-green on the cleanly-flushed corpus + the
zero-"replayed WAL entries" gate + a 3-hit doc probe), then the 120 s
/proc window: CPU = utime+stime delta over CLK_TCK, wakeups summed across
/proc//task/*/status (the process-level counters cover only the
parked main thread and read 0/s), VmRSS/VmHWM/RssAnon/RssFile, per-thread
CPU attribution grouped by comm. Coarse gates with ::error:: annotations
and exit 1; refuses port 9200, non-empty or RAM-backed data dirs; private
port scan 9610..9639.
rationale, reproduce commands with expected output.
idle-budgetjob: builds xerj-server onthe shared ci-test profile cache, runs the fixture with defaults (450
indices, 120 s settle, ~8 min measured) on ubuntu-latest,
timeout-minutes: 30.
pub(crate), scrape-driven, and does the WAL walk on the blocking pool;
run_metrics_gauge_loop deleted.
refresh_metric_gauges before gather_text.
comment (b) rewritten to point at the fixture.
scrape-time liveness pin (fail-before shape documented in the module doc).
Gates run: the new integration test passes (and fails before the fix);
cargo test/clippy/fmt scoped to xerj-api and xerj-server are clean; the
ES-YAML conformance suite is 1376 passed / 0 failed / 3 skipped against this
branch's release binary.
Closes #874.
Independent verification (second agent, fresh build, full 120 s settle, no numbers trusted from the implementer): gate PASSED again — idle CPU 0.167 % (run of record 0.175 %), wakeups 26.4/s (26.6), per-index RSS 190.1 kB (183.8, +3.4 %), boot-to-green 218 ms (215), 0 WAL-replay lines, 450/450 indices, doc probe 3/3. ES-YAML re-run green: 1376 / 0 failed / 3 skipped. Its review also confirmed: thresholds enforced by exit code, CI job satisfies the workflow-timeout guard (verified with the repo's own guard script), ports/dirs private, commit discipline (author xerj-org, no trailers). Three minor findings from that review (doubled code fences in the README, a loose load-range wording, and making the :9200 refusal explicit instead of implicit-by-busyness) are folded into this branch.
Environmental note for reviewers re-running the ES-YAML gate on an almost-full disk: the sandbox was at 96 % used, which trips the 95 %
disk_flood_stagewrite block by design (262 cases 429/cluster-block). With[limits] disk_flood_stage_percent = 0on the throwaway gate node — or a disk under 95 % — the suite is fully green. That is the watermark working, not a branch defect.