Profilage par rejeu WAL

Mesurez les performances d'écriture (commit/transaction) d'evitaDB en rejouant un WAL de production sur une instance embarquée avec JMH et async-profiler.

Spar Skills Guide Bot
DeveloppementAvancé
0001/09/2026
Claude Code
#performance-profiling#jmh#async-profiler#evitadb#wal-replay

Recommandé pour


name: wal-replay-profiling description: Measure evitaDB write-path (commit/transaction) performance by replaying a real production catalog's Write-Ahead Log against an embedded instance via the WalReplayBenchmark JMH harness, with async-profiler (alloc/cpu) or JMH -prof gc. Invoke when profiling commit latency, allocation, or GC behavior on the write path, when a production WAL export needs re-measuring, or when a profiling run produced a suspicious/empty/inconsistent result (zero-byte collapsed dump, contended-box numbers, cross-round contradiction). allowed-tools: Read, Edit, Write, Grep, Glob, Bash(mvn *), Bash(rtk *), Bash(java *), Bash(git *), Bash(rg *), Bash(awk *), Bash(ps *), Bash(uptime *), Bash(free *), Bash(kill *), Bash(cd *), Bash(ls *), Bash(du *), Bash(tar *), Bash(diff *), Bash(cp *), Bash(mkdir *), AskUserQuestion

WAL-replay performance profiling

Distilled from the #760 write-path tuning rounds (2026-07-20 → 07-27; see documentation/adr/2026-07-27-write-path-performance-tuning/). The harness (WalReplayBenchmark + WalReplayState, package io.evitadb.performance.walreplay) is dataset-agnostic — it takes the catalog name as a system property, not baked in — so this skill applies to any future production export, not just the original one.

Bundled scripts

All three are in this skill directory and expect ROOT=/www/oss/evita/evitaDB-dev (edit the ROOT= line if the checkout moves). All require CATALOG_NAME=<name> in the environment.

  • run-wal-replay.shdry (plain main(), fast iteration) or jmh (real -prof gc measurement) mode.
  • profile-wal-replay-ap.sh — attaches async-profiler for the replay window only.
  • run-wal-replay-ab.sh — one side of an A/B, given two jars and per-side WAL source copies.

1. Building

rtk mvn clean install -P full -DskipTests

-P full is mandatory — evita_test/evita_performance_tests is not in the default reactor. rtk truncates long build logs and drops the BUILD SUCCESS line — confirm by exit code and target/benchmarks.jar's timestamp, never by grepping the log.

To rebuild only the perf module afterwards (upstream already installed): -o -P full package -pl evita_test/evita_performance_tests -DskipTests.

Gate the jar before spending a measurement on it. Extract the class you changed and assert the change is really there:

unzip -o -q target/benchmarks.jar "io/evitadb/.../Changed.class" -d /tmp/jarcheck
javap -c -p /tmp/jarcheck/io/evitadb/.../Changed.class | grep -c <expected-or-forbidden-symbol>

2. Reproducing the fixture

Requires a fresh catalog export unzipped into two siblings, each containing a <catalogName>/ subfolder: pristine/ (T0 snapshot) and walsource_full/ (WAL slice to replay).

Key system properties (full list in WalReplayState's own JavaDoc):

| property | meaning | |---|---| | evita.replay.catalogName | required — the catalog name; both directories must contain a matching subfolder | | evita.replay.pristineDataDir | T0 snapshot, copied into the work dir on setup | | evita.replay.walSourceDir | WAL slice(s) to replay, comma-separated, consumed left to right | | evita.replay.workDir | scratch; the fixture wipes and repopulates it itself | | evita.replay.maxTransactions | transaction cap — the JMH path does not set this, pass it explicitly | | evita.replay.holdOpenSeconds | keeps the JVM alive after the result block so an attached profiler can dump | | evita.replay.waitForVisibility | block on trunk incorporation per commit — measures the true empty-pipeline floor | | evita.replay.perTxCsv | one CSV row per transaction (mutation count + every stage latency) |

Pin -Xmx24g -Xms8g on every run; heap size drives the collation cache's heap-derived default.

The WAL source is not mutated by a run — three independent sources stayed byte-identical to their origin after full 300-tx replays, so the fixture copies into its work dir. Still worth a diff -rq before a run costing real wall-clock time, since the driver only checks the directory exists.

3. What each instrument can and cannot answer

| question | instrument | notes | |---|---|---| | did allocation change? | JMH -prof gcgc.alloc.rate.norm | primary metric; also compare gc.count/gc.timeunit-free, no conversion needed | | where does allocation come from? | async-profiler alloc | valid even on a loaded box (§5) | | where does CPU go? | async-profiler cpu | needs a quiet box | | wall / latency | JMH single shot | ±2.0 % noise band on identical builds — make no claim inside it |

Single-shot JMH means one sample, no variance estimate. gc.alloc.rate.norm is steadier but not deterministic — a few percent of drift is normal. wall profiling mode (not JMH wall time) is useless on this harness: it samples ~160 parked threads, flattening every share to ~0.6%, and the thread doing most of the allocation resolves to unresolved libc frames. Use cpu.

4. Reading a collapsed profile

  • Frames use / package separators (structure/Attributes.<init>), not . — a .-pattern silently matches nothing.
  • Line format is stack<space>count; thread names contain spaces, so take $NF as the count.
  • In an alloc profile the leaf is the allocated type. Attribute a site by the deepest io/evitadb/ frame; attribute what was allocated by the leaf — doing both separates removable machinery from irreducible cost.
  • In a cpu profile the leaf is a method, so trim trailing whitespace when a site can also be the leaf, or it splits into two rows and halves its apparent share.
  • Samples are byte-weighted in alloc mode — a leaf's share is its share of bytes, not events.
  • mawk (the default awk here) has no asorti — emit KIND<TAB>count<TAB>name and rank with sort -rn, not an awk-side sort.

5. Four ways a run silently lies

  1. The profiler dump races JVM exit. The harness tears down within seconds of printing its result block — too fast for a fresh profiler stop JVM to connect. Fixed via evita.replay.holdOpenSeconds (both bundled profile scripts already set it and check for a non-empty dump); if writing a new driver, do the same or the profiler leaves a zero-byte .collapsed while every exit code still says success.
  2. mvn clean deletes target/profiling. Copy collapsed files out of target/ immediately after a run that matters.
  3. The box is not quiet. Check with uptime and ps -eo pcpu,args --sort=-pcpu before measuring. A foreign JVM from another session/worktree eating cores is the usual culprit — process alive, work dead, invisible to a liveness check. Allocation shares are usable from a loaded box; wall time and CPU shares are not — empirically: 231 s vs 145 s wall (loaded vs quiet, −59%) but 375,600 vs 366,349 allocation samples (−2.5%). Alloc-profiling overhead on a quiet box is only ~2.6%; a profiled run far slower than that means a loaded box, not the profiler.
  4. Cross-run comparison without controls. When total allocation falls, every surviving site's percentage inflates and looks like a regression. Find 3-4 sites no change touched and check their absolute sample counts match before trusting a percentage comparison.

6. Interpretation rules that cost rounds to learn

  • Size a finding before ranking it. A profile share is not a realizable saving — TLAB-sampled profiles rank candidates well and predict magnitude poorly.
  • GC cost tracks what SURVIVES, not allocation volume. Cutting a third of allocation can buy a fraction of that off GC if what was deleted was short-lived young-gen garbage. GC's share of CPU can even rise while its absolute cost falls, if the application side shrinks faster.
  • Structure sharing moves latency; deleting an allocation site moves bytes. Lead with visible-latency median for the former, gc.alloc.rate.norm for the latter.
  • Estimating a lazy-allocation residual: check how often the guard actually passes — a reserved "still allocated in the common case" residual can be wrong by an order of magnitude if the common case is actually the empty one.
  • Pre-register the acceptance metric — and which metric will NOT move. A metric that shouldn't move but reads as a miss if you didn't say so in advance (e.g. a fix that only affects big transactions won't move the small-tx floor).
  • An Enum.ordinal-style leaf in a hot loop is usually the inlined loop body, not the accessor. Prove the frame is real (e.g. by removing the memoization and re-measuring) before optimizing it.

7. JMH pitfalls specific to this harness

  • A JMH run whose @Setup throws still exits 0 with an empty result table. Assert the result JSON has rows before believing a run.
  • evitaDB treats every storage subdirectory as a catalog, and each boot leaves a UUID-scratch directory behind — a second fork in the same JMH run aborts with Catalog <uuid> has invalid format. Sweep those directories between runs; use one JVM per benchmark for suites that fork.
  • Never hardcode a JDK path — JAVA_BIN/JAVA_HOME env vars, falling back to a default, is what the bundled scripts do; a hardcoded /usr/lib/jvm/... path breaks on any machine using sdkman.

8. Server-side diagnostic runs (boot/replay forensics, not JMH)

For investigating a specific corruption/crash against a real snapshot rather than measuring throughput: launch evita-server.jar with JDWP (-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:8005), -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints, and a diagnostic logback raising io.evitadb.core.transaction / io.evitadb.core.catalog.Catalog to DEBUG while pinning com.linecorp.armeria/io.netty to ERROR and io.micrometer to OFF. Useful knobs: cache.enabled=false, server.trafficRecording.enabled=false, server.closeSessionsAfterSecondsOfInactivity=0.

Point storage.storageDirectory at a scratch copy, never at the live ../data. Opening a real catalog with branch code can trigger a one-way format migration, and a T0 baseline must stay intact if it is also the source for a WAL replay.

Skills similaires