Skip to content

Truncate over-budget traces instead of dropping them - #157

Closed
rlerdorf wants to merge 1 commit into
adsr:masterfrom
rlerdorf:pr2-buffer-full
Closed

rlerdorf wants to merge 1 commit into
adsr:masterfrom
rlerdorf:pr2-buffer-full

Conversation

@rlerdorf

Copy link
Copy Markdown
Contributor

A trace larger than -b is discarded in full, while the log line says truncating.

The buffer is per-trace — reset at STACK_BEGIN, written once at STACK_END — so an overflow during a frame returns out of the handler via try, STACK_END never runs, and event_handler_fout_write is never called.

Why it matters

Deep stacks are dropped preferentially, so the profile is biased against exactly the recursive code you opened the profiler to look at. A 60-frame recursion, measured before the change:

-b traces written dropped
4096 (default) 3 143
65536 145 0

98% of samples lost at the default buffer size, and the only hint is a log line whose wording implies partial data was kept. After the change both sizes yield 146 traces, and every sample survives a stackcollapse-phpspy.pl round-trip.

-l was affected too: trace_count was gated on rv == PHPSPY_OK, so on such a target the limit could never be reached and --limit=N ran until the process died.

Approach

The handler absorbs the overflow — emits the frames that fit, appends # truncated = 1, and reports the truncation upward so the sample is still tallied and still counts toward -l.

Details that took some care, and are probably where review is best spent:

  • The epilogue reserve comes out of the existing budget, not on top of it. Growing the buffer past PIPE_BUF would reintroduce interlaced writes in -P mode — the hazard the -b help text already warns about. Buffers under 128 bytes keep the old all-or-nothing behaviour.
  • Once a trace truncates, later records are dropped too. Otherwise a short frame fits after a long one was refused, and the stack comes out with a silent hole in it rather than a clean tail.
  • vsnprintf has already written its truncated copy by the time it reports failure, so the buffer is re-terminated at the cursor — otherwise -f matches against a partial frame that is never written.
  • The trace delimiter is now guaranteed, overwriting the last byte if that is the only way to fit it. This is a pre-existing bug independent of the above: when the -d epilogue overflowed, try_break skipped the delimiter and two traces merged into one in the stream.
  • One log line per handler instead of per frame. At 99 Hz on a deep stack the old one fires for every frame of every sample.

Compatibility

# truncated = 1 is a # comment line, so stackcollapse-phpspy.pl and top.c's parser both already skip it, exactly as they do for # uri = ….

One behaviour change worth calling out explicitly: tests/test_buffer_full.sh currently asserts that an over-budget trace produces nothing at all (not_expected[anything]='^.+$'). That is the behaviour this PR changes, so its second case is rewritten. If you would rather keep the drop as the default and put truncation behind a flag, say so and I will rework it — but I think a silently discarded sample is the wrong default for a sampling profiler.

Testing

make test passes (15/15) under both make and USE_ZEND=1 make against php8.3 and php8.4. tests/test_truncate.sh covers the marker, the delimiter invariant, and that no samples are lost in the round-trip.

Independent of #156 — they touch different code and can merge in either order.

A trace larger than `-b` is discarded in full, while the log line says
"truncating". The buffer is per-trace -- reset at STACK_BEGIN, written once at
STACK_END -- so overflowing it during a frame returns out of the handler,
STACK_END never runs, and the write never happens.

That loses far more than it sounds. A 60-frame recursion at the default
`-b 4096`, measured:

  -b 4096    3 traces written, 143 dropped
  -b 65536   145 traces written, 0 dropped

Deep stacks are dropped preferentially, so the profile is biased against
exactly the recursive code you opened the profiler to look at, and the only
hint is a log line whose wording implies partial data was kept.

The handler now absorbs the overflow: it emits the frames that fit, appends
`# truncated = 1`, and reports the truncation upward so the sample is still
tallied and still counts toward `-l` (which previously could never be reached
on such a target, since the counter was gated on rv == PHPSPY_OK). After the
change both buffer sizes above yield 146 traces, and every sample survives a
stackcollapse-phpspy.pl round-trip.

Some care was needed in the details:

  - The tail room for the epilogue is taken out of the existing budget rather
    than added to it. Growing the buffer past PIPE_BUF would reintroduce
    interlaced writes in `-P` mode, which is the hazard the `-b` help text
    already warns about. Buffers below 128 bytes keep the old behaviour.

  - Once a trace has truncated, later (shorter) records are dropped too;
    otherwise a short frame would fit after a long one was refused and the
    stack would silently come out with a hole in it.

  - vsnprintf has already written its truncated copy by the time it reports
    failure, so the buffer is re-terminated at the cursor -- otherwise `-f`
    would match against a partial frame that is never written.

  - The trace delimiter is now guaranteed, overwriting the last byte if that
    is the only way to fit it. This is a pre-existing bug independent of the
    above: when the `-d` epilogue overflowed, try_break skipped the delimiter
    and two traces merged into one in the stream.

  - The per-frame log line is replaced by one message per handler. At 99 Hz on
    a deep stack the old one fires for every frame of every sample.

tests/test_buffer_full.sh asserted the old behaviour -- that an over-budget
trace produces nothing at all -- so its second case is rewritten.
tests/test_truncate.sh covers the marker, the delimiter invariant and the
round-trip.
@rlerdorf

Copy link
Copy Markdown
Contributor Author

Replaced by #167

@rlerdorf rlerdorf closed this Sep 15, 2026
adsr added a commit that referenced this pull request Oct 7, 2026
Supersedes #167, which in turn superseded #157.

Currently phpspy drops traces that are larger than `-b`, which
defaults to `PIPE_BUF` (4096 bytes). The idea is to avoid interleaved
traces in `-P` mode. The problem is that traces are often larger than
4k in production, so we often bump `-b` and eat the cost of
potentially corrupt traces.

The fix is to split large traces into smaller chunks. As long as each
thread outputs each chunk under `PIPE_BUF` bytes, then readers like
`stackcollapse-phpspy.pl` can reassemble the chunks back into the
full trace.

Differences compared to #167:

* Writes happen in a single pass. #167 did one pass to count chunks
  and another pass to write each chunk as `k/n`. Here we include a
  sentinel with each chunk that indicates "incomplete" (`~`) or
  "complete" (`!`).

* There's no fixed reserve for `trace_id` records. It's calculated
  dynamically.

* Traces under `-b` are unchanged -- no `trace_id` metadata.

* No partial records. If a single frame record exceeds `-b`, drop it
  and emit a `# truncated = 1` metadata record. We could make it a
  flag to emit partial records.

* `-1` mode is not a special case. #167 disabled chunking in `-1`
  mode.

* The `-o` fd is `open`-d then `dup`-d by other threads under a
  mutex. This avoids interleaving/corruption in `-P -o ...` mode.
  Adds a comment TODO the same for `-O` and `-E`. Could be a separate
  commit.

* Delimiter stripping uses `memchr` -- more efficient than the
  existing byte loop. Could be a separate commit.
adsr added a commit that referenced this pull request Oct 8, 2026
Supersedes #167, which in turn superseded #157.

Currently phpspy drops traces that are larger than `-b`, which
defaults to `PIPE_BUF` (4096 bytes). The idea is to avoid interleaved
traces in `-P` mode. The problem is that traces are often larger than
4k in production, so we often bump `-b` and eat the cost of
potentially corrupt traces.

The fix is to split large traces into smaller chunks. As long as each
thread outputs each chunk under `PIPE_BUF` bytes, then readers like
`stackcollapse-phpspy.pl` can reassemble the chunks back into the
full trace.

Differences compared to #167:

* Writes happen in a single pass. #167 did one pass to count chunks
  and another pass to write each chunk as `k/n`. Here we include a
  sentinel with each chunk that indicates "incomplete" (`~`) or
  "complete" (`!`).

* There's no fixed reserve for `trace_id` records. It's calculated
  dynamically.

* Traces under `-b` are unchanged -- no `trace_id` metadata.

* No partial records. If a single record exceeds `-b`, drop it and
  end the trace with a `# truncated = 1` chunk by itself.

* `-1` mode is not a special case. #167 disabled chunking in `-1`
  mode.

* The `-o` fd is `open`-d then `dup`-d by other threads under a
  mutex. This avoids interleaving/corruption in `-P -o ...` mode.
  Adds a comment TODO the same for `-O` and `-E`. Could be a separate
  commit.

* Delimiter stripping uses `memchr` -- more efficient than the
  existing byte loop. Could be a separate commit.
adsr added a commit that referenced this pull request Oct 15, 2026
Supersedes #167, which in turn superseded #157.

Currently phpspy drops traces that are larger than `-b`, which
defaults to `PIPE_BUF` (4096 bytes). The idea is to avoid interleaved
traces in `-P` mode. The problem is that traces are often larger than
4k in production, so we often bump `-b` and eat the cost of
potentially corrupt traces.

The fix is to split large traces into smaller chunks. As long as each
thread outputs each chunk under `PIPE_BUF` bytes, then readers like
`stackcollapse-phpspy.pl` can reassemble the chunks back into the
full trace.

Differences compared to #167:

* Writes happen in a single pass. #167 did one pass to count chunks
  and another pass to write each chunk as `k/n`. Here we include a
  sentinel with each chunk that indicates "incomplete" (`~`) or
  "complete" (`!`).

* There's no fixed reserve for `trace_id` records. It's calculated
  dynamically.

* Traces under `-b` are unchanged -- no `trace_id` metadata.

* No partial records. If a single record exceeds `-b`, drop it and
  end the trace with a `# truncated = 1` chunk by itself.

* `-1` mode is not a special case. #167 disabled chunking in `-1`
  mode.

* The `-o` fd is `open`-d then `dup`-d by other threads under a
  mutex. This avoids interleaving/corruption in `-P -o ...` mode.
  Adds a comment TODO the same for `-O` and `-E`. Could be a separate
  commit.

* Delimiter stripping uses `memchr` -- more efficient than the
  existing byte loop. Could be a separate commit.
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