feat(memtrack): write ring and pressure stats as JSONL - #546
not-matthias wants to merge 5 commits into
Conversation
…ING_STATS Each ring poller can now report how fast its ring is written and read, sampled from libbpf's mmapped producer/consumer positions (ring__producer_pos, ring__consumer_pos, ring__avail_data_size). This needs no BPF changes and no syscalls: a sample is a few memory loads per poll tick. With CODSPEED_MEMTRACK_RING_STATS=1, every poll thread logs a line per second at debug level and a whole-run summary at info level on shutdown: stacks ring (1s): wrote 818.7 MB/s, read 664.5 MB/s, drain 61398.1 MB/s, peak backlog 159.7 MiB (31.2%), busy 1.1% (max tick 1.02 ms) - wrote: producer position delta over wall time. It counts every reserved byte, including record headers and records the BPF side discards, so it measures ring pressure rather than artifact size. - read: consumer position delta over wall time. - drain: bytes consumed per second of poll-thread busy time, i.e. the read rate the poller can sustain. - peak backlog: largest unconsumed backlog seen at the start of a poll tick. - busy / max tick: share of wall time spent consuming, and the slowest tick. When the variable is unset, the poll loop does one Option check per tick.
Merging this PR will degrade performance by 18.72%
|
| Mode | Benchmark | BASE |
HEAD |
Efficiency | |
|---|---|---|---|---|---|
| ❌ | Memory | encode_events_realistic[1] |
121.1 MB | 151.1 MB | -19.85% |
| ❌ | Memory | encode_events_realistic[4] |
121.1 MB | 151.1 MB | -19.85% |
| ❌ | Memory | encode_events_realistic[2] |
121.1 MB | 151.1 MB | -19.85% |
| ❌ | Memory | encode_events_realistic[8] |
122.4 MB | 150 MB | -18.38% |
| ❌ | Memory | encode_events_realistic[16] |
130.4 MB | 154.4 MB | -15.6% |
Tip
Investigate this regression by commenting @codspeedbot fix this regression on this PR, or directly use the CodSpeed MCP with your agent.
Comparing feat/memtrack-ring-stats (e49142e) with feat/memtrack-pause-worker (4953b6c)
Footnotes
-
4 benchmarks were skipped, so the baseline results were used instead. If they were deleted from the codebase, click here and archive them to remove them from the performance reports. ↩
7d14b24 to
15a41f8
Compare
CODSPEED_MEMTRACK_STATS=<path> records each ring's producer/consumer positions around every poll tick, and each pressure release with the released pids' stop times. Rates, fill levels and pause windows are derived offline by crates/memtrack/scripts/plot_stats.py. Replaces CODSPEED_MEMTRACK_RING_STATS and its periodic log lines.
15a41f8 to
a3e281d
Compare
encode_events takes an on_window callback with the window's input wait, encode and write time plus its msgpack and zstd sizes. MemtrackWriter counts the uncompressed bytes it serializes.
With CODSPEED_MEMTRACK_STATS set, memtrack also writes: - backlog rows every 10 ms: events parsed from the rings vs. taken by the encoder, plus memtrack's own RSS - one resolve row per stack-resolver batch - one encode row per encoder window plot_stats.py adds stage-busy and backlog/RSS panels, encoder in/out throughput, and a log throughput axis.
c071cb3 to
e49142e
Compare
|
Live
|
| run | ring |
backlog |
resolve |
encode |
pressure |
stacks peak fill |
|---|---|---|---|---|---|---|
| x86_64, 1 ms poll | 5508 | 428 | 13 | 2 | 0 | 3.1% |
| x86_64, 2000 ms poll | 72 | 6555 | 2 | 2 | 33 | 75.0% |
| arm64, 1 ms poll | 1564 | 152 | 4 | 2 | 0 | 24.4% |
| arm64, 2000 ms poll | 71 | 6556 | 1 | 2 | 33 | 75.0% |
In the 2000 ms runs, all 33 pressure rows are on stacks and every stopped_at < t. Stop to release takes 1.80–1.85 s on x86_64 and 1.95–1.97 s on arm64. Releases come about 2.00 s apart.
Real workload: 5 shards of a large memory benchmark suite
8 vCPU x86_64 runners, stack capture on, default 1 ms poll.
| shard | stacks written | stacks write avg | stacks poller busy | pressure episodes | paused ms (sum / max) | encoder in → out | memtrack RSS peak |
|---|---|---|---|---|---|---|---|
| 1 | 151 GB | 1141 MB/s | 56.0% | 22 | 8661 / 450 | 139 GB → 2.1 GB (66×) | 6.3 GiB |
| 2 | 348 GB | 1250 MB/s | 57.1% | 44 | 14784 / 488 | 297 GB → 4.6 GB (64×) | 6.3 GiB |
| 3 | 144 GB | 949 MB/s | 58.3% | 12 | 2880 / 554 | 124 GB → 2.2 GB (56×) | 6.7 GiB |
| 4 | 226 GB | 1311 MB/s | 59.6% | 31 | 9717 / 434 | 203 GB → 2.9 GB (69×) | 6.3 GiB |
| 5 | 43 GB | 1413 MB/s | 62.2% | 1 | 375 / 375 | 39 GB → 0.6 GB (65×) | 6.1 GiB |
The fill panel under-reports on this workload. There are 110 pressure episodes, but sampled stacks fill never goes above 1.1%. Every stop falls inside a single stacks poll tick that ran for 0.5–0.7 s (median per shard) and consumed about 75% of the 512 MiB ring. ring__consume() keeps reading until it catches the producer, so each tick ends near empty and the samples at t0/t1 miss the peak in between. cons1 - cons0 per tick, taken against the ring size, shows these episodes; the fill line does not.
The encoder and stack resolver stay below about 11% busy. The stacks poller is busy 56–62% of wall time.
|
Re-run at e49142e, plotted with its
|
| run | ring |
backlog |
resolve |
encode |
pressure |
stacks peak fill |
|---|---|---|---|---|---|---|
| x86_64, 1 ms poll | 5774 | 457 | 14 | 2 | 0 | 4.1% |
| x86_64, 2000 ms poll | 73 | 6559 | 2 | 2 | 33 | 75.0% |
| arm64, 1 ms poll | 1419 | 153 | 5 | 2 | 0 | 17.6% |
| arm64, 2000 ms poll | 71 | 6473 | 1 | 2 | 33 | 75.0% |
In the 2000 ms runs, all 33 pressure rows are on stacks and every stopped_at < t. Stop to release takes 1.87–1.91 s on x86_64 and 1.93–1.97 s on arm64. Releases come about 2.00 s apart.
Real workload: 5 shards of a large memory benchmark suite
8 vCPU x86_64 runners, stack capture on, default 1 ms poll.
| shard | stacks written | stacks write avg | stacks poller busy | pressure episodes | paused ms (sum / max) | encoder in → out | memtrack RSS peak |
|---|---|---|---|---|---|---|---|
| 1 | 151 GB | 898 MB/s | 62.3% | 26 | 8723 / 556 | 139 GB → 2.1 GB (66×) | 6.4 GiB |
| 2 | 348 GB | 1110 MB/s | 65.7% | 50 | 18209 / 480 | 297 GB → 4.6 GB (64×) | 6.4 GiB |
| 3 | 144 GB | 890 MB/s | 61.1% | 25 | 11510 / 609 | 124 GB → 2.2 GB (56×) | 6.6 GiB |
| 4 | 226 GB | 1021 MB/s | 68.2% | 45 | 14498 / 573 | 203 GB → 3.0 GB (69×) | 6.4 GiB |
| 5 | 43 GB | 1098 MB/s | 67.8% | 1 | 45 / 45 | 39 GB → 0.6 GB (65×) | 6.2 GiB |
This confirms the fill-panel gap from the previous run. There are 147 pressure episodes, but sampled stacks fill reaches 10.6% on shard 2 and stays at or below 0.8% on the other shards. Every stop again falls inside a single stacks poll tick that ran for 0.4–1.0 s (median per shard) and consumed about 75% of the 512 MiB ring.
The encoder and stack resolver stay at or below 12% busy. The stacks poller is busy 61–68% of wall time.


















Adds an opt-in stats file for memtrack's ring pipeline. With
CODSPEED_MEMTRACK_STATS=<path>set, memtrack writes JSON lines to that path:ring_open: the ring name and its size, written once per poller.ring: producer and consumer positions before and after each poll tick. Ticks where nothing moved are not written.pressure: written on each pressure release, with the drained ring, the release time, and every released pid with the time it was stopped.backlog: written every 10 ms. It has the number of events parsed from the rings, the number taken by the encoder, and memtrack's own RSS. Sent minus received is everything in flight between the rings and the encoder: poll batches, the resolver queue, and the unbounded channel.resolve: one row per stack-resolver batch, with the batch size and its start and end times.encode: one row per encoder window, with the time spent waiting for input, encoding, and writing, plus its msgpack and zstd sizes.To support
encoderows,runner-shared'sencode_eventsnow takes anon_windowcallback.All timestamps are
CLOCK_MONOTONICns. That is the same clock asbpf_ktime_get_ns()and the artifact's event timestamps, so the stats line up with the captured events. Only raw counters are recorded.crates/memtrack/scripts/plot_stats.py(run it withuv run) derives fill %, write/drain MB/s, pause episodes and a per-pid pause swimlane, and prints a per-ring summary.To record the stop time,
pressure_stoppednow stores the stop ktime (__u64) instead of a__u8marker. This only runs on the stop path.This replaces
CODSPEED_MEMTRACK_RING_STATSand its periodic log lines.Usage
Example
Charts from
alloc_storm_procs 16 50000with stack capture on (x86_64 GitHub runner). The panels, top to bottom:2 s poll interval (pressure episodes): the stacks ring fills to 75% and every producer pauses until each drain releases it.
1 ms poll interval (default): nothing comes close to the watermark. Events in flight climb to about 400k while the encoder is busy with its first window, then drop back.
The "drain (while busy)" lines divide bytes by poll-thread busy time, not wall time. They show how much headroom the poller has, not how much data is read.
Testing
cargo clippy --release -p memtrack --all-targets -- -D warningscargo test --release -p memtrack -p runner-shared --libFailed to create memtrack stats file.plot_stats.pyon synthetic data, with and without pressure episodes, and on an empty file.alloc_storm_procs 2 20000, stacks on): 507ring+ 3ring_openrows, plotted fine; 80941 events, no drops. No pressure episodes at this size.alloc_storm_procs 16 50000with stacks on, x86_64 + arm64:ringrows and no pressure.pressurerows per job, each with 16 pids and their stop times; the run finishes in 68 s.backlog,resolveandencoderows.