Skip to content

Split oversized traces into PIPE_BUF-sized chunks instead of dropping them - #167

Open
rlerdorf wants to merge 3 commits into
adsr:masterfrom
rlerdorf:chunked-fout
Open

rlerdorf wants to merge 3 commits into
adsr:masterfrom
rlerdorf:chunked-fout

Conversation

@rlerdorf

Copy link
Copy Markdown
Contributor

Supersedes #157, following the design from our Slack thread: rather than truncating a trace that doesn't fit in -b, assemble the whole trace and emit it as chunks of at most -b bytes, each tagged with a # trace_id = <id>.<k>/<n> record, and glue them back together in stackcollapse-phpspy.pl. Users don't need to think about buffer sizes, -J m, or per-pid files anymore.

The bug

A trace larger than -b is dropped in full: the BUF_FULL from the handler aborts the walk in do_trace(), and STACK_END (hence the write) never runs. Deep stacks are lost preferentially, and the log line says "truncating" while doing the opposite. Measured with a 200-frame recursion at the default -b: 0 traces written on master vs 198 with -b 65536. After this change, 198 at the default.

How it works now

  • event_fout.c assembles the trace in a growable per-handler buffer (realloc, offset-based, hard cap 4 MiB — PHPSPY_MAX_STACK_WALK × the max frame line is ~800 KB, so this is generous). The -f/-F filter runs over the whole assembled trace at STACK_END (previously it only ever saw the first -b bytes — a small behaviour change worth knowing about).
  • The buffer is split at record boundaries into chunks of ≤ -b bytes. Every record ends with the frame delimiter and repl_delim already guarantees no record contains one, so scanning back from the cap is a safe boundary search. Each chunk is written with one writev(2) (payload + marker), which is atomic on a pipe for ≤ PIPE_BUF bytes — same guarantee the single write() relied on.
  • -b now means "max bytes per write" and defaults to PIPE_BUF (<limits.h>), min 128. Values above PIPE_BUF are still allowed with the existing warning (useful with -o file.%d), and the help text no longer refers to a -J m flag that doesn't exist.
  • The trace id is a process-global atomic counter (same pattern as trace_count), so concurrent -P workers never collide. --event-handler-opts m now holds the mutex across all of a trace's chunks, so with it a trace is contiguous in the stream.
  • stackcollapse-phpspy.pl groups frames by id and emits a stack when chunk n-1 arrives; incomplete or out-of-order ids are discarded with a warning rather than emitted as partial stacks. Pre-trace_id capture files still work (legacy depth-0 path). Reader state is bounded: each writer thread has at most one trace in flight. top.c needs no changes — it already skips # lines and tallies per line.

The cases chunking can't fix — a single record longer than a chunk's payload, -1/--single-line mode (the marker joins with \t, so a trace stays one line; chunking is disabled there), or the 4 MiB cap — emit # truncated = 1, drop the rest of that trace (no holes), and STACK_END returns PHPSPY_ERR_BUF_FULL after writing, so the sample still counts toward --limit via PHPSPY_TRACE_COUNTED().

Independent fixes carried over from #157

  • The trace delimiter is now unconditional. On master, when the -d epilogue didn't fit, the delimiter was lost and consecutive traces merged. Measured: -d pt -b 1063 → 198 traces / 0 blank lines on master, 198/198 after. (While here: try_break in phpspy.h is broken — its break binds to the macro's own do/while(0) — and this PR removes its only user. Left the macro alone as out of scope.)
  • A failed vsnprintf re-terminates the buffer so a partial record is never visible to the filter or the write.
  • Truncation is logged once per handler, not once per frame at 99 Hz.

Tests

  • test_buffer_full.sh (rewritten): deep stack at -b 128 keeps every frame, has a continuation marker, no truncation; the filter still applies to the whole trace.
  • test_truncate.sh (new): oversized single record → # truncated = 1, one delimiter per trace, --limit still terminates; -1 mode stays one line per trace.
  • test_chunk_interleave.sh (new): two children with disjoint function names traced with -P --threads 2 -b 512, collapsed output must contain both and no stack may mix them; plus a round-trip asserting no sample lost and no stack cut short. 12/12 runs clean.
  • test_stackcollapse.sh (new): hand-interleaved chunk fixtures, legacy input, out-of-order chunk.
  • Full suite: 20/20 on php8.4 and 8.6; the only failures on other versions are ones already failing on master (pdo_args_packed_array on 7.2–8.2, the 7.0 frame-slot varpeek cases fixed in Fix PHP 8.6 sapi_globals offset, PHP 7.0 frame-slot bug, and get real aarch64 struct data #165). make shellcheck clean; the USE_ZEND=1 build adds no new errors in event_fout.c.

Manual check: two 60-deep children under -P -T2 -b 512 → 572 traces in 2860 chunks (up to 5 per trace), 0 mixed stacks, all 572 samples recovered by the Perl script.

No PHPSPY_VERSION bump.

🤖 Generated with Claude Code

rlerdorf and others added 3 commits September 14, 2026 22:18
…dropping them

A trace that does not fit in the -b buffer is not truncated, it is lost.
event_handler_fout_snprintf returns PHPSPY_ERR|PHPSPY_ERR_BUF_FULL, that
escapes the FRAME handler through `try`, should_stop_trace aborts the walk, and
do_trace_end only runs STACK_END when rv == PHPSPY_OK -- so the write never
happens at all, while the log line claims it is "truncating". Because it is
depth that overflows the buffer, the samples that disappear are exactly the
deep stacks, which is the opposite of what a profiler should drop.

At the default -b against a 200-deep recursion, every single sample is lost:

    phpspy --limit=0 --time-limit-ms=2000 -- php -r \
      'function f($n){ if($n) f($n-1); else usleep(3000000); } f(200);' \
      | grep -c '^0 '
    0          # before, default -b
    198        # before, -b 65536
    198        # after,  default -b

Rather than truncate and mark, the whole trace is now assembled in a growable
per-handler buffer and then split at record boundaries into chunks of at most
-b bytes, each written with a single writev(2) and ending in a
`# trace_id = <id>.<k>/<n>` record. -b therefore changes meaning from "output
buffer size" to "max bytes per write", and defaults to PIPE_BUF rather than a
hardcoded 4096: at that size every chunk is still atomic on a pipe, so -P
worker threads can only ever interleave whole chunks, and a reader can put a
trace back together by id. Nobody has to choose a buffer size any more.

Three cases cannot be chunked: a single record longer than a chunk's payload,
-1/--single-line mode (where a trace must stay on one line), and the 4 MiB
assembly cap. Those emit `# truncated = 1` and STACK_END returns
PHPSPY_ERR_BUF_FULL *after* writing, so PHPSPY_TRACE_COUNTED() still counts
the sample toward --limit -- previously a truncated sample counted for
nothing, and `--limit=N` against a deep stack could never terminate.

Also fixed along the way, all in the same code path:

The trace delimiter was skipped when the -d epilogue overflowed, silently
merging two traces into one. With `-d pt` and a -b just large enough for the
frames, every consecutive trace ran together -- 198 traces, 0 blank lines
before this change, 198 and 198 after. (The epilogue's try_break did not
help: `break` binds to the macro's own do/while, so it never left the block.
The block is gone now; the delimiter is written by the chunk writer and no
longer depends on anything having fit.)

A failed vsnprintf left its partial record in the buffer where the -f/-F
filter and the write could see it; the buffer is now re-terminated on every
failure path. And the "Not enough space in buffer" line was printed once per
record, i.e. dozens of times per sample at 99 Hz; it is now one line per
handler for the lifetime of the run.

The filter now matches against the whole assembled trace instead of only its
first -b bytes, which is the behaviour the flag always implied.

-b gains a minimum of 128 so that a chunk always has at least 64 bytes of
payload under the 64 bytes reserved for the marker, the delimiters and the
truncated record. phpspy_trace.c needs no change: PHPSPY_ERR_BUF_FULL is
raised only here, and the handler now absorbs overflow internally, so the walk
always completes and STACK_END always runs.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w
A trace larger than -b is now written as several chunks, and in -P mode chunks
belonging to different traces can be interleaved in the stream. The script
flushed on every depth-0 frame, so an interleaved capture would attribute the
second half of one process's stack to the other's and produce stacks that never
existed.

It now keys on the `# trace_id = <id>.<k>/<n>` record that terminates every
chunk. Frames accumulate into a pending list, a marker moves that list onto its
id's partial stack, and the final chunk (k == n-1) emits the whole thing. This
is sound because each chunk's payload and its marker are written with a single
writev(2) that is atomic on a pipe at the default -b, so the frame lines
immediately preceding a marker always belong to that marker's id no matter how
many threads are writing.

Files captured before this change have no markers, so the old depth-0 flush is
kept and used until the first marker is seen -- which, on chunked input, is
before any depth-0 line other than the first. Once markers are in play, a
leftover pending list or an unterminated id is a partial stack and is dropped
rather than counted as a short one; a chunk that arrives with an unexpected
index discards its id, warns once, and leaves other traces alone.

tests/test.sh exposes its sudo/timeout prefix as `test_cmd_prefix`, because the
harness does not wrap `test_fn` tests itself and test_chunk_interleave.sh has to
attach to live pids.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w
The README showed `# - - - - -` between traces in three examples. phpspy has
never emitted that; the separator is a blank line, so anyone writing a parser
from the README got it wrong. The examples now show what the tool actually
prints, including the `# trace_id` record that terminates every trace.

Adds an "Output format" section, since the record grammar was only discoverable
by running the thing, and it now matters: a reader has to know that a trace can
arrive as several chunks and that in `-P` mode the chunks of different traces
can be interleaved, which is what stackcollapse-phpspy.pl is for. `-b` is
described as "max bytes per write" to match usage().

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w
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