Skip to content

Report what the sampler is doing: exit summary, zero-capture warning, startup line - #156

Open
rlerdorf wants to merge 1 commit into
adsr:masterfrom
rlerdorf:pr1-diagnostics
Open

rlerdorf wants to merge 1 commit into
adsr:masterfrom
rlerdorf:pr1-diagnostics

Conversation

@rlerdorf

Copy link
Copy Markdown
Contributor

phpspy can sample a process hundreds of times, write an empty file, and never say a word. I hit this profiling a large CLI tool and lost a fair amount of time to it, so this makes the sampler account for what it did.

The problem

A target blocked in a syscall, an attach to the wrong pid of a process that re-execs itself, and a PHP build whose extensions move execution off the VM stack all look identical from outside: phpspy sits there producing nothing. There is currently no signal at all — not while running, not at exit, not in the exit status.

What this adds

$ phpspy -p 318501
phpspy: pid 318501 php 84 executor_globals=0x7f2b1c0e75e0 use_zend=n
phpspy: warning: pid 318501: 0 traces captured in 5s; is the target executing PHP?
        (target blocked in a syscall, wrong pid, or a non-PHP process)
^C
phpspy: 512 samples in 5.17s across 1 pid: 0 written, 512 empty, 0 filtered, 0 errored (0.12 ms/sample)
  • a per-sample tally, reported at exit
  • a one-shot warning when nothing has been captured after -W seconds (default 5, 0 disables)
  • a startup line naming the pid, PHP version and executor_globals address, which makes a wrong-pid attach obvious immediately

Notes for review

The empty bucket is the point. A live target that is not executing PHP returns PHPSPY_OK with depth 0 and emits nothing, so success cannot be inferred from rv alone — do_trace now records the depth it reached. Errors are classified before depth, because a failed read also leaves depth at 0, and reporting a permissions problem as "not executing PHP" would be the same misdiagnosis in a new costume.

No shared writes added to the sampling loop. Counters live in a trace_stats_t that is a main_pid local — already per worker thread in -P mode — and are folded into the totals once per target under a mutex.

Deliberately no overhead percentage. I wanted one, but trace_ns / wall_ns does not include the contention process_vm_readv causes on the target's memory-map lock; on a large, actively-allocating target it reports a few percent where the measured slowdown is nearly 2×. A confidently wrong number seemed worse than none, so the summary reports ms/sample and leaves interpretation to the reader.

Output compatibility. Nothing changes on stdout; all of this goes to stderr, honours -q, and can be suppressed with PHPSPY_NO_SUMMARY=1. top mode sets that on its child, since it counts child stderr lines as errors. The content-free main_pgrep finished gracefully line is replaced by the summary (also updated in the README).

tests/test.sh grows expected_err / not_expected_err / expected_exit_code, since diagnostics go to stderr and there was previously no way to assert on them.

Testing

make test passes (17/17, including three new files) under both make and USE_ZEND=1 make against php8.3 and php8.4.

This is the first of a short series — buffer handling, child-mode exit status, -P robustness and a few features follow, each self-contained. Happy to reshape any of it.

phpspy can sample a process hundreds of times, write an empty file and never
say a word. That happens more often than it sounds: a target blocked in a
syscall, an attach to the wrong pid of a process that re-execs itself, or a
PHP build whose extensions move execution off the VM stack all look identical
from the outside -- a profiler that sits there quietly producing nothing.

Tally every sample and say what happened to it:

  phpspy: pid 318501 php 84 executor_globals=0x7f2b1c0e75e0 use_zend=n
  phpspy: 512 samples in 5.17s across 1 pid: 0 written, 512 empty, 0 filtered, 0 errored (0.12 ms/sample)
  phpspy: warning: pid 318501: 0 traces captured in 5s; is the target executing PHP?
          (target blocked in a syscall, wrong pid, or a non-PHP process)

The "empty" bucket is the point of the exercise. A live target that is not
executing PHP returns PHPSPY_OK with depth 0 and emits nothing, so success
cannot be read from rv alone; do_trace now records the depth it reached.
Errors are classified before depth, because a failed read also leaves the
depth at 0 and reporting a permissions problem as "not executing PHP" is
exactly the misdiagnosis this is meant to prevent.

Counters are a main_pid local -- already per worker thread in -P mode --
folded into the totals once per target, so the sampling loop still touches no
shared memory. -W sets the zero-capture deadline (default 5s, 0 disables); in
-P mode the first worker to trip it speaks and the rest are counted.

Deliberately no estimated target-overhead percentage. phpspy's own trace time
does not include the contention it causes on the target's memory-map lock, so
the figure reads far lower than the slowdown users actually measure, and a
confident wrong number is worse than none.

Everything honours -q, and PHPSPY_NO_SUMMARY suppresses it for wrappers that
treat stderr as failure -- top mode sets that on its child, since it counts
child stderr lines as errors. The content-free "main_pgrep finished
gracefully" line is replaced by the summary, in the code and in the README.

tests/test.sh grows stderr and exit-code assertions, since diagnostics go to
stderr and nothing could assert on them before.
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