Skip to content

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

Draft
not-matthias wants to merge 36 commits into
mainfrom
feat/memtrack-ring-stats
Draft

not-matthias wants to merge 36 commits into
mainfrom
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.

Copy the caller's user stack in chunks at allocator entry and fold an
FNV-1a digest over it in the kernel. The digest rides on the allocation
event as stack_hash; the copied bytes, a DWARF-numbered register
snapshot and a frame-pointer walk are emitted once per distinct digest
on a dedicated ring buffer, so unwinding and symbolication can happen
offline.

Capture stays off until userspace sets the rodata toggle, so allocator
probes are unchanged by default.

Refs COD-3222
Add the userspace half of allocation stack capture: env-driven
configuration, stack-definition ring parsing, loss counters, per-pid
module mapping tracking, a folding recorder that deduplicates
definitions and counts occurrences, and the report it produces.

Nothing constructs these yet; the tracker wiring follows.

Refs COD-3222
Wire the capture rodata and map sizing into skeleton load, poll the
stack-definition ring alongside the event ring, and expose the loss
counters and frame-pointer chains. The attach worker snapshots module
mappings while it holds a process stopped, which is the only point they
are guaranteed readable.

Guard the lifecycle: finishing with a live session would block forever
on the recorder, and a second spawn would leave the capture rings
undrained, so both now fail with a descriptive error.

With capture disabled the ring buffer and frame-pointer map shrink to
the allocator minimum rather than reserving tens of MiB.

Refs COD-3222
Add a fixture with two non-inlinable malloc call paths and privileged
tests over it: distinct call paths get distinct identities with module
mappings for the binary and libc, repeated calls deduplicate, and the
default-off path still reports allocations.

Two cases guard failure modes the default budget cannot reach. The
maximum copy budget is the only configuration that exercises the
verifier's instruction limit, since the frozen rodata makes the copy
and hash loops scale with the configured size. Shrinking the
frame-pointer map to one slot proves exhaustion costs only the fallback
chain, never an allocation event.

Refs COD-3222
The symbol, unwind-data and debug-info extraction is not perf-specific: it
turns a set of mapped ELF modules into the deduplicated keyed artifacts a
profile references, whatever discovered the mappings. Memory mode needs the
same pipeline, so it moves out of wall_time/profiler/perf into
executor/shared/module_artifacts.
Memory mode needs the same per-pid module references walltime writes, so the
five artifact fields move into a flattened `ModuleArtifacts` shared by both
formats; walltime's JSON is unchanged, asserted against output captured from
the flat struct.

Flattening buffers those fields through serde's `Content`, which unlike
serde_json's direct deserializer cannot parse a string JSON key into a pid, so
pid-keyed maps get an explicit key-parsing helper.
Allocation stacks are raw addresses, so resolving them off-box needs the
module geometry perf gets from PERF_RECORD_MMAP2. No single hook provides it:
security_mmap_file has the file but runs before the VMA exists, and
perf_event_mmap has the addresses but cannot resolve a path. So an LSM program
caches the path once per inode and a perf_event_mmap fentry emits inode-keyed
address records, joined in userspace while the maps are still live.

Path resolution is only reachable from an LSM program at all, and only above
5.11 (bpf_d_path on the sleepable hook) or 6.12 (the bpf_path_d_path kfunc),
with the bpf LSM active. MappingSupport probes both, and when neither holds
stack capture is turned off rather than shipping stacks nothing can attribute.
Memory mode now turns the mappings memtrack recorded into the same keyed
unwind_data/symbols.map files walltime writes, plus a memtrack.metadata
referencing them per pid, so allocation stacks can be unwound off-box.

Each mapping's inode is rechecked against the path before its ELF is read: BPF
cannot produce a build id, so the recorded (dev, ino) is what proves the file
on disk is still the one that was mapped rather than a rebuilt binary whose
eh_frame would be bound to the wrong addresses.
Replace the BPF LSM path cache and mapping ring with inherited per-CPU PERF_RECORD_MMAP2 collectors. Store executable mappings as a terminal suffix in the main memtrack stream so existing timeline consumers remain compatible, then extract and order them in the runner before generating module artifacts.
Every frame's output buffer started empty and doubled its way to the
compressed size, which for a 64k event frame is 8 realloc-and-copy steps
over roughly 8 MB. Not measurable in wall clock at current frame sizes;
it removes the copy traffic.
The memory instrument reports allocation counts and bytes per benchmark,
which is what the encode path is bound by. It runs on a hosted runner
like simulation does; the runner grants memtrack its capabilities during
setup.
glibc exports cfree at the same file offset as free, so attaching both instrumented one function twice: every free() produced two Free events and two stack captures. Track (library, offset) pairs and skip symbols already covered by an alias.
…tation

mimalloc lowers memtrack's own memory usage, fragmentation and allocation
overhead compared to glibc's allocator. As a side effect, it also doesn't
route through the exported malloc/free/calloc/realloc symbols, so it skips
the allocator uprobes (attached system-wide with pid -1) that would
otherwise fire for memtrack's own bookkeeping allocations.

Pulled in via the ebpf feature, which the binary already requires.
Each stack record needs its frame-pointer chain looked up in the
stack_traces map, which is a syscall per record. Doing that inside the
ring-buffer parse callback made the poll thread pay it, so a burst of
stacks could push it behind the producer and records were dropped.

ResolvingPoller wraps a RingBufferPoller with a dedicated resolver
thread: the poll thread only parses (event, stackid) and hands it over an
internal channel, and the resolver does the map lookup and forwards the
completed event. Drop order keeps the existing shutdown contract, the
ring is dropped first so its poll thread joins and closes the internal
sender, which lets the resolver drain what it already has before its
join returns.
…y map

A single-entry ARRAY map lookup is not actually checked at runtime: for a
constant in-range key the verifier strips PTR_MAYBE_NULL and drops the
`if (!enabled)` branch as dead code, while the inlined lookup still re-reads
the key from the BPF stack. Uprobe programs run under migrate_disable() only,
so a program preempting one on the same CPU shares its per-CPU private stack
and can clobber that key slot, turning the lookup into an unchecked NULL
deref.

A global has no key to clobber. This supersedes 97d269c, whose fail-closed
branch the verifier removes anyway.

The two toggles became byte-identical apart from the written value, so they
now delegate to a shared `set_tracking`.
Closing the last reference to a uprobe link fd waits for an RCU-tasks-trace
grace period, and hangs indefinitely when the kernel is wedged. Doing that
work in this process makes teardown unbounded no matter how many threads
share the wait, which is what 705245d tried to solve.

Fork holder children over disjoint fd chunks instead: they own the terminal
close, so this process only drops duplicate references. Holders that do not
exit within a shared 30s deadline are abandoned for init to reap, bounding
teardown even when the grace period never completes.
Share one poll interval across the event, stack and attach pollers and
lower it from 10ms to 1ms so bursts drain before the rings fill.
A full allocation-stack ring loses stack records the same way a full
event ring loses events, so a run that overflowed it must fail the same
incompleteness check.
The FNV lanes lived on the BPF stack. Large kprobe-family programs may
spill that to per-CPU storage, which a nested uprobe on the same CPU can
overwrite mid-capture, corrupting the hash. Accumulate the lanes in the
not-yet-submitted ring record instead, which is private to this
reservation.
After every event or stack submission, BPF checks the ring's fill level.
Once it is 75% full, the writing tracked process is recorded in
`pressure_stopped` and gets SIGSTOP, so processes that don't write keep
running.

The event and stack pollers resume every recorded process once a poll
leaves their ring empty, and resume everything still recorded on
shutdown. A tracked process that writes to a nearly full ring after the
pollers are gone stays stopped.

A process can be stopped both for ring pressure and for an allocator
attach request, and SIGSTOP is not counted. The exec-mapping watcher
therefore records its stops in `attach_stopped`. Each side deletes its
own entry before checking the other's, so the process resumes only once
both are done with it.

`RingBufferPoller::drain` no longer acknowledges a consume that stopped at
an uncommitted reservation, and `wait_all_stopped` treats exited threads
as stopped.

The event and stack poll interval is configurable through the
`poll_interval_ms` tracker option (env `CODSPEED_MEMTRACK_POLL_INTERVAL_MS`,
default 1ms), which lets the event ring cross its watermark on demand. The
attach poller keeps its fixed interval.
Add `alloc_storm` (threads) and `alloc_storm_procs` (forked processes)
fixtures and pressure tests that run them with a 10s poll interval and
assert that no events are dropped. The multi-process test checks that
every writing process is stopped and resumed on its own.
On glibc >= 2.42 the per-thread tcache is initialized lazily. A thread's
first small free() whose tcache is still inactive goes through
tcache_free_init(), which tail-calls __libc_free() again, so the free
uprobe fires twice for one call. Whether a thread reaches that path
depends on arena assignment, i.e. scheduling, so the Free count of the
same workload varies between runs.

for_each_variant compared raw Free counts between the Legacy and Token
runs, which made test_thread_dlopen flaky on ubuntu-26.04-arm
(glibc 2.43). GLIBC_TUNABLES (tcache_count=0, tcache_max=0) does not
avoid the re-entry.

event_profile now replays events in timestamp order and counts a Free
only when it releases an allocation still live in that run, which drops
the duplicate hit as well as frees of memory allocated before tracking.
The stop maps kept a process's entry after it exited, so a later release
could send SIGCONT to an unrelated process that reused the pid.

The exit handler now deletes a process from `pressure_stopped` and
`attach_stopped`, and a release resumes a process only if it removed its
own entry. The exec-mapping watcher stops a process only once it is
recorded, like the pressure check, so every stop has an entry to release.
Both maps move to a shared header so the exit handler can reach them.
…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

@not-matthias
not-matthias force-pushed the feat/memtrack-pause-worker branch 5 times, most recently from 9cc4405 to 7c135cc Compare September 28, 2026 10:09
Base automatically changed from feat/memtrack-pause-worker to main September 28, 2026 10:35
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