Skip to content

feat(memtrack): write ring and pressure stats as JSONL - #546

Draft
not-matthias wants to merge 5 commits into
feat/memtrack-pause-workerfrom
feat/memtrack-ring-stats
Draft

not-matthias wants to merge 5 commits into
feat/memtrack-pause-workerfrom
feat/memtrack-ring-stats

Conversation

@not-matthias

@not-matthias not-matthias commented Sep 24, 2026 •

Copy link
Copy Markdown
Member

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 encode rows, runner-shared's encode_events now takes an on_window callback.

All timestamps are CLOCK_MONOTONIC ns. That is the same clock as bpf_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 with uv 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_stopped now stores the stop ktime (__u64) instead of a __u8 marker. This only runs on the stop path.

This replaces CODSPEED_MEMTRACK_RING_STATS and its periodic log lines.

Usage

sudo -E CODSPEED_MEMTRACK_STATS=/tmp/memtrack-stats.jsonl codspeed-memtrack track "<cmd>" --output <dir>
uv run crates/memtrack/scripts/plot_stats.py /tmp/memtrack-stats.jsonl -o stats.png

Example

Charts from alloc_storm_procs 16 50000 with stack capture on (x86_64 GitHub runner). The panels, top to bottom:

  • ring fill %
  • throughput on a log axis: ring write and drain, encoder in and out
  • how busy each stage is: pollers, stack resolver, encoder
  • events in flight and memtrack's RSS
  • the pause swimlane, when there are pressure episodes

2 s poll interval (pressure episodes): the stacks ring fills to 75% and every producer pauses until each drain releases it.

memtrack stats, 2 s poll

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.

memtrack stats, 1 ms poll

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 warnings
  • cargo test --release -p memtrack -p runner-shared --lib
  • Unprivileged checks:
    • With the env var set, the stats file is created before the BPF load fails.
    • An invalid path fails the run with Failed to create memtrack stats file.
  • plot_stats.py on synthetic data, with and without pressure episodes, and on an empty file.
  • Privileged run (docker, alloc_storm_procs 2 20000, stacks on): 507 ring + 3 ring_open rows, plotted fine; 80941 events, no drops. No pressure episodes at this size.
  • Temporary CI job, alloc_storm_procs 16 50000 with stacks on, x86_64 + arm64:
    • 1 ms poll: 1.5k–5k ring rows and no pressure.
    • 2 s poll: 33 pressure rows per job, each with 16 pids and their stop times; the run finishes in 68 s.
    • Every job also wrote backlog, resolve and encode rows.

…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.
@codspeed

codspeed Bot commented Sep 24, 2026 •

Copy link
Copy Markdown

Merging this PR will degrade performance by 18.72%

⚠️ Unknown Walltime execution environment detected

Using the Walltime instrument on standard Hosted Runners will lead to inconsistent data.

For the most accurate results, we recommend using CodSpeed Macro Runners: bare-metal machines fine-tuned for performance measurement consistency.

⚠️ Different runtime environments detected

Some benchmarks with significant performance changes were compared across different runtime environments,
which may affect the accuracy of the results.

Open the report in CodSpeed to investigate

❌ 5 regressed benchmarks
✅ 28 untouched benchmarks
⏩ 4 skipped benchmarks1

Warning

Please fix the performance issues or acknowledge them on CodSpeed.

Performance Changes

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)

Open in CodSpeed

Footnotes

  1. 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. ↩

@not-matthias
not-matthias force-pushed the feat/memtrack-ring-stats branch 2 times, most recently from 7d14b24 to 15a41f8 Compare September 24, 2026 16:38
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.
@not-matthias
not-matthias force-pushed the feat/memtrack-ring-stats branch from 15a41f8 to a3e281d Compare September 24, 2026 16:41
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.
@not-matthias
not-matthias force-pushed the feat/memtrack-ring-stats branch from c071cb3 to e49142e Compare September 24, 2026 16:58
@not-matthias

Copy link
Copy Markdown
Member Author

Live CODSPEED_MEMTRACK_STATS captures on real BPF at dc7d8f1, plotted with crates/memtrack/scripts/plot_stats.py from the same commit.

alloc_storm_procs 16 50000

Record counts (ring_open = 3 in every run):

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.

x86_64, 1 ms poll

storm x86_64 1 ms

x86_64, 2000 ms poll

storm x86_64 2000 ms

arm64, 1 ms poll

storm arm64 1 ms

arm64, 2000 ms poll

storm arm64 2000 ms

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.

shard 2

shards 1, 3, 4, 5

shard 1
shard 3
shard 4
shard 5

@not-matthias

Copy link
Copy Markdown
Member Author

Re-run at e49142e, plotted with its crates/memtrack/scripts/plot_stats.py. Only the plot script changed since dc7d8f1, so this runs the same memtrack code again. The differences from the previous comment are run-to-run variation.

alloc_storm_procs 16 50000

Record counts (ring_open = 3 in every run):

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.

x86_64, 1 ms poll

storm x86_64 1 ms

x86_64, 2000 ms poll

storm x86_64 2000 ms

arm64, 1 ms poll

storm arm64 1 ms

arm64, 2000 ms poll

storm arm64 2000 ms

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.

shard 2

shards 1, 3, 4, 5

shard 1
shard 3
shard 4
shard 5

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant