Draft
fix: add shell-level timeout to perf stat capability probes in metadata collection#717
Conversation
Co-authored-by: romirdes <86635949+romirdes@users.noreply.github.com>
Copilot
AI
changed the title
[WIP] Fix indefinite hanging during metadata collection on large VMs
fix: add shell-level timeout to perf stat capability probes in metadata collection
Aug 31, 2026
…arge virtualized instances perf list --json can also stall indefinitely on some hypervisors (e.g. m6i.16xlarge), just like perf stat. The stderr.txt from the failing test showed PerfSpect was stuck at "collecting metadata", and perf list is the remaining unguarded perf command in that stage. Wrap both scriptPerfSupportedEvents and scriptPerfAllSupportedEvents with timeout 30 to bound them consistently with the perf stat probes.
Metrics collection could stall indefinitely during the "collecting metadata" phase. Nothing in the chain bounded it: RunScripts launches the controller script with no timeout, and the controller's `wait` blocks forever on a script that never exits. A single wedged probe therefore hung the whole run. Wrapping the inner command in `timeout` does not fix this. Each script runs under setsid and may fork; `timeout` signals only its direct child, so a wedged grandchild -- e.g. a perf stuck on a PMU access, as seen on some virtualized instance types -- survives and the controller keeps waiting on it. Add a Timeout field to ScriptDefinition and have the controller start a per-script watchdog that signals the script's entire process group (SIGTERM, then SIGKILL after a grace period), which reaps wedged descendants. Apply a 60s budget to the metadata probes, which are all short by construction. Scripts with no timeout keep running unbounded, so indefinite-duration collection is unchanged. Also: - Report each script's exit code and elapsed time, plus a stderr tail on failure, so a hanging probe is identifiable from the log instead of presenting as a silent stall. Timeouts are logged even when continuing on script error, where the controller still exits 0. - Reduce kill_script's post-SIGTERM grace from 60s to 5s. Cleanup is serial and perfspect's signal handler only allows ~20s for the whole controller to exit, so the old budget let one hung script drag shutdown far past that deadline. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
A probe that hangs during metadata collection produced no information at all: the controller waited on it forever, and RunScripts only reads the controller's output once it exits, so nothing was ever reported. The run appeared to stall in "collecting metadata" until ssh gave up 300 seconds later (ServerAliveInterval 30 x ServerAliveCountMax 10) and returned exit code 255 with empty output, which was then reported without the stderr that would have explained it. Signalling harder does not fix this. A process in uninterruptible sleep (state D) -- the expected shape of a wedged PMU access on a virtualized instance -- does not act on any signal, SIGKILL included, until the kernel call it is blocked in returns. So the controller must stop waiting rather than try harder to kill: - Abandon a script that survives SIGKILL: the watchdog leaves a marker, wait_for_script stops waiting on it, and the run completes with that script reported as ABANDONED. Other scripts' results are still returned. - Capture why it could not be stopped: per-process state and wchan for the whole process group, plus the kernel stack of any process in state D, which names the call it is stuck in. Readable because metadata scripts run elevated. - Announce each script as it starts, so a controller that dies before producing results still identifies which scripts were in flight. - Remove the blocking wait from kill_script for the same reason; it would stall shutdown past the ~20s the perfspect signal handler allows. On the Go side: - Bound the controller run when every script is bounded, deriving the deadline from the script budgets (sequential budgets add, concurrent overlap). This guarantees we regain control even if the target wedges or the connection stops delivering. A single unbounded script, such as indefinite-duration collection, leaves the controller unbounded as before. - Include stderr in the returned error. An ssh transport failure and a script failure both surface as a non-zero exit code, and the distinction is not recoverable from the code alone. - Log the controller's own reporting before deciding whether its exit code is fatal, so a diagnosis survives the failure paths. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
A failing run on m6i.16xlarge reported three perf stat probes still alive 61 seconds in, each with its shell in do_wait and no state line for the process it was waiting on. The diagnostics had a hole: they enumerated the script's process group, but 'timeout' places itself and the command it runs into a NEW process group. Metadata probes all run as 'timeout 30 perf stat ...', so the process that actually hung was never inspected, and the kill aimed at the script's group reaped only the wrapping shell -- leaving the wedged probe running, reparented to init, and still holding whatever it was stuck on. That is a plausible reason later probes hung too. Walk descendants by parent pid instead of filtering on process group, and capture the tree before signalling anything, since the first kill orphans it. Signal every process in that tree, including the groups led by descendants, then report whatever is still alive afterwards: surviving SIGKILL is something only a process blocked in the kernel can do, which is the fact still missing from the diagnosis. Also report each process's command line and read its state via ps rather than /proc/<pid>/stat, whose parenthesized comm field can contain spaces and shift the field positions. The same run died with exit code -1: our own deadline killed the controller. The deadline summed the script budgets but not the watchdog's SIGTERM-then-SIGKILL escalation, so a hang -- the one case the deadline exists for -- pushed the run past it. Killing the controller discards everything, because results are printed only after every script finishes, so the run produced no parseable output at all. Add the escalation allowance per phase. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
With a 60s budget, a hung probe holds metadata collection for 60s plus the watchdog escalation, and the controller's deadline lands at 120s -- the same point at which the functional test harness gives up waiting for collection to start and kills perfspect. The diagnosis is produced but never delivered. Drop the budget to 40s, which keeps it above the 'timeout 30' wrapping the perf probes (so a working inner timeout is still attributed to the probe) and brings the controller deadline to 112s, inside that window. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The failing run shows a perf stat probe still alive 61 seconds in, wrapped in 'timeout 30': the inner timeout sent SIGTERM at 30s and the probe ignored it. Plain 'timeout' sends SIGTERM only, so a probe that defers or blocks on that signal runs unbounded. Use --kill-after=5 so SIGKILL follows at 35s, which reaps anything not blocked in the kernel and leaves only the genuinely uninterruptible case to the controller's watchdog. The two 'perf list --json | awk' probes took their exit status from awk, so a perf that timed out reported success with an empty event list -- a silently wrong metadata result rather than a reported failure. Check PIPESTATUS and exit with perf's status instead. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Target-side diagnostics from a failing m6i.16xlarge run show what actually goes wrong, and it is not what the process states suggested it would be: 10570 S timeout 30 perf list --json 10578 R perf list --json 10593 S timeout 30 perf stat -a -e instructions sleep 1 10595 R perf stat -a -e instructions sleep 1 The probes are in state R, spinning, at 10:26 elapsed under a 30-second timeout -- so they are not blocked in the kernel and are perfectly killable. Nobody is killing them. When our deadline fires we kill the local ssh, which does nothing to the target: the controller and every probe below it keep running there. The same leak happens whenever perfspect is killed with SIGKILL, since its signal handler never runs. They accumulate. Each run leaves more spinning perf processes contending for the PMU the next run's probes need, so a machine that passes early tests starts failing later ones, and the failure looks intermittent while actually being cumulative. Kill the controller's whole process tree on the target when we abandon it, and report anything that survives SIGKILL -- that, not merely hanging, is what would indicate an uninterruptible probe. Also do this after the signal handler escalates to SIGKILL, which until now killed the controller and orphaned its probes. The tree walk is now shared between the controller script and this cleanup rather than duplicated. The pid file is validated before its contents reach kill. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
GIT_CLONE_OPTS is a --depth 1 --single-branch clone, which contains only the tip commit of the default branch. Checking out AVX_TURBO_VERSION therefore worked only while the pin happened to be that tip; upstream has since pushed seven commits past it, so the checkout now fails and reports the pinned commit as nonexistent. Nothing in this repository changed to cause it. Fetch the pinned commit by name instead. This keeps the fetch shallow and does not go stale when upstream moves. The version must now be the full 40-character SHA, because the git wire protocol will not resolve an abbreviated one. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
These two tarballs are downloaded by the tools build and kept on disk as a local cache; they were untracked working-tree files that got swept into dc6c9dc by accident. They are not tracked on main and were never meant to be committed. Beyond the 300KB of noise, tools/** is the key for the CI tools-binaries cache, so adding files there forced a cache miss and a full rebuild of the tools from source. Ignore them so this cannot recur. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…t exit The controller writes SCRIPT START and SCRIPT RESULT to stderr so a stalled run can name the script it is stuck in. That reporting was parsed by logControllerDiagnostics only after RunCommandEx returned, which means it was absent from exactly the runs it exists to explain: a controller that hangs does not return, so the log stopped after "running controller script" and never said which of the 40 scripts was in flight. Diagnosing a hang then required the target to still answer ssh, and a target wedged hard enough to hang the controller does not. Add RunCommandExLive, which tees a command's stderr to a caller-supplied writer as it is produced, and use it for the controller with a writer that classifies each line as it arrives. A stall now identifies its script from the local side while it is still stalled. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Streaming the controller's stderr replaced the only caller of logControllerDiagnostics, so it became dead code and staticcheck rejected it (U1000), failing make check_static. Its documentation moves to logControllerDiagnosticLine, which is now the single entry point. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The three "perf stat fixed <event>" metadata probes each ask for numGPCounters+1 copies of one event in a single group, so the group fits only if one copy can land on a fixed counter. That over-subscription is the point of the probe, but combined with -a it ran on every CPU at once. On an m6i.16xlarge guest (64 vCPU, emulated Ice Lake PMU: max_precise=0, no branches cap, no uncore devices) the ref-cycles probe hangs the whole instance: the harness sees it exit 137, meaning it survived its own 'timeout --kill-after=5 30' SIGKILL, and the target drops off the network entirely for minutes. A task that outlives SIGKILL is stuck in the kernel, which points at the per-CPU counter assignment for the deliberately unfittable group rather than at anything in userspace. Scoping to -C 0 keeps the probe's meaning exactly -- counter assignment is per-CPU, so one CPU answers "can this event use a fixed counter?" the same way 64 do -- while cutting the work by the CPU count. getSupportsFixedEvent reads only the exit code, "<not counted>" / "<not supported" and a zero count, so it loses nothing either. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
finalize() killed $pw_pid, but the pipeline is launched as
( processwatch ... | awk ... ) &
so $pw_pid is the subshell wrapping it, not processwatch. Signalling a shell does
not signal its children, and SIGKILL least of all, so this reaped the wrapper and
orphaned processwatch. With duration 0 the script passes no -n count, so
processwatch never exits on its own: a root-owned process holding perf_event fds
kept running on the target indefinitely after perfspect exited.
Collect the descendants before signalling anything, because the first kill orphans
everything below pw_pid and the children can no longer be traced back to it, then
SIGTERM and SIGKILL the whole tree.
This is what the harness's sigint tests check for directly -- they fail a test if
perf or processwatch is still running on the target afterwards -- and processwatch
is used only by telemetry, which matches 'telemetry sigint' failing on every cell
while metrics sigint does not.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
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.
On large virtualized x86 instances (e.g.
m6i.16xlarge), the hypervisor stallsperf_event_openindefinitely rather than returning an error. Since metadata probe scripts run with no timeout (timeout := 0in the controller), PerfSpect hangs forever at "collecting metadata" and never reaches "collecting metrics". Smaller VMs (e.g.c6i.2xl) fail fast with a non-zero exit → expected error; bare-metal works normally.Changes
cmd/metrics/metadata.go: Prefix all 9perf statcapability probeScriptTemplatevalues withtimeout 30:Affected probes:
scriptPerfStatInstructions,scriptPerfStatRefCycles,scriptPerfStatPEBS,scriptPerfStatOCR,scriptPerfStatTMA,scriptPerfStatAMDUncoreProbe,scriptPerfStatFixedInstr,scriptPerfStatFixedCycles,scriptPerfStatFixedRefCycles.Each probe normally completes in ~1 s (it runs
sleep 1as the workload). All probes run concurrently, so the 30 s budget is ~30× the normal wall-clock cost and poses no risk of false failures on loaded instances. On a hung instance,timeoutexits with code 124 (non-zero) → probe treated as unsupported → fast-fail with a clear error instead of an indefinite hang.