feat(memtrack): write ring and pressure stats as JSONL - #546
not-matthias wants to merge 36 commits into
Conversation
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.
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.
9cc4405 to
7c135cc
Compare


















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.