Conversation
…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
This was referenced Sep 15, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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-bbytes, each tagged with a# trace_id = <id>.<k>/<n>record, and glue them back together instackcollapse-phpspy.pl. Users don't need to think about buffer sizes,-J m, or per-pid files anymore.The bug
A trace larger than
-bis dropped in full: theBUF_FULLfrom the handler aborts the walk indo_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.cassembles 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/-Ffilter runs over the whole assembled trace at STACK_END (previously it only ever saw the first-bbytes — a small behaviour change worth knowing about).-bbytes. Every record ends with the frame delimiter andrepl_delimalready guarantees no record contains one, so scanning back from the cap is a safe boundary search. Each chunk is written with onewritev(2)(payload + marker), which is atomic on a pipe for ≤PIPE_BUFbytes — same guarantee the singlewrite()relied on.-bnow means "max bytes per write" and defaults toPIPE_BUF(<limits.h>), min 128. Values abovePIPE_BUFare still allowed with the existing warning (useful with-o file.%d), and the help text no longer refers to a-J mflag that doesn't exist.trace_count), so concurrent-Pworkers never collide.--event-handler-opts mnow holds the mutex across all of a trace's chunks, so with it a trace is contiguous in the stream.stackcollapse-phpspy.plgroups frames by id and emits a stack when chunkn-1arrives; 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.cneeds 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-linemode (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 returnsPHPSPY_ERR_BUF_FULLafter writing, so the sample still counts toward--limitviaPHPSPY_TRACE_COUNTED().Independent fixes carried over from #157
-depilogue 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_breakinphpspy.his broken — itsbreakbinds to the macro's owndo/while(0)— and this PR removes its only user. Left the macro alone as out of scope.)vsnprintfre-terminates the buffer so a partial record is never visible to the filter or the write.Tests
test_buffer_full.sh(rewritten): deep stack at-b 128keeps 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,--limitstill terminates;-1mode 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.pdo_args_packed_arrayon 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 shellcheckclean; theUSE_ZEND=1build adds no new errors inevent_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_VERSIONbump.🤖 Generated with Claude Code