feat(procusage): profile CPU and memory cost of every run - #207
Merged
ashishkurmi merged 6 commits intoSep 9, 2026
Merged
Conversation
Both dispatch paths now log what a run cost and append one JSON record per run to run-metrics.jsonl (newest 200), so resource trends are visible without reconstructing them from stderr logs. Subprocess CPU is counted on Linux and macOS via getrusage(RUSAGE_CHILDREN) — executor.Run reaps its children, so they are attributed to us. Windows has no equivalent, so its records set children_attributed=false rather than reporting a quietly smaller number. Measured locally, children are ~53% of total run CPU, so that gap is worth flagging rather than hiding. ru_maxrss is kilobytes on Linux and bytes on macOS; the scaling lives in per-OS files with a test each so the 1024x error cannot ship silently. Enterprise runs also record per-phase CPU deltas. There is no memory equivalent: peak RSS is a lifetime high-water mark and cannot be differenced across phase boundaries. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
The line was emitted at debug from a deferred call, which meant it reached neither log we can actually read. Level: installs run at log_level=info, so a debug line is never written to stderr at all and cannot appear in the ExecutionLogs we download. Ordering: execLogsBase64 is snapshotted mid-body, so anything deferred runs after it by construction — and capture.Finalize() is deferred later than the report was, so LIFO restored stderr first anyway. The enterprise path now reports just before the snapshot, with the defer kept as a once-guarded fallback for runs that error out before reaching it. This measures scan and audit work but not the upload, since a payload cannot contain the log of its own upload. Verified on Linux: both lines decode out of execution_logs.output_base64. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
"96% of wall" read as "used 96% of the CPU" when it meant 0.96 of one core — on a 12-core box that is 8% of the machine, a 12x misinterpretation in the alarming direction. CPUPercent is now CPU time over (wall x cores) and cannot exceed 100. The old ratio survives as CoresBusy, named for what it measures. The line reports both, since "1.06 cores busy" and "8.8% of 12 cores" answer different questions. Samples now carry logical_cores: CPU time means nothing without it, and the history is compared across machines with different core counts. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
The size comment was wrong by 4x: a real enterprise record with its 14 phases is ~1.3KB, not the ~300 bytes claimed, so the file tops out near 250KB rather than "well under 100KB". The cap is a record count, so per-record size is the only thing between it and unbounded growth — adding phases or usage fields inflates every record silently. Bound it under test, and assert the temp-and-rename write leaves nothing behind, since a leaked temp per run would grow the directory without bound. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
There was a problem hiding this comment.
Pull request overview
Adds per-run resource usage profiling to Dev Machine Guard so each scan/telemetry execution logs CPU/memory cost at info level and persists a bounded JSONL history (run-metrics.jsonl) for local trend analysis, with enterprise runs also reporting per-phase CPU breakdown.
Changes:
- Introduces
internal/procusageto capture CPU (self + children where supported), peak RSS, and Go runtime memory stats; logs a summary and appends a capped JSONL record per run. - Wires usage reporting into both dispatch paths (
internal/scanandinternal/telemetry), ensuring telemetry emits the usage lines before the execution-log snapshot so they appear inExecutionLogs. - Extends the telemetry phase tracker to record per-phase CPU deltas and adds tests for the new accounting.
Reviewed changes
Copilot reviewed 20 out of 20 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| internal/telemetry/telemetry.go | Adds a once-only resource usage reporter and emits it before the execution-log snapshot for enterprise runs. |
| internal/telemetry/phase_tracker.go | Captures per-phase CPU deltas via procusage.CPUMillis(). |
| internal/telemetry/phase_tracker_test.go | Tests new per-phase CPU accounting and non-negative clamping. |
| internal/scan/scanner.go | Emits per-run resource usage (no phases) for community scans via a deferred report. |
| internal/procusage/procusage.go | Defines the resource sample model and capture/formatting utilities. |
| internal/procusage/procusage_unix.go | Implements Unix getrusage-based collection (self + children). |
| internal/procusage/procusage_windows.go | Implements Windows process CPU/working-set collection (no child attribution). |
| internal/procusage/maxrss_linux.go | Linux-specific ru_maxrss scaling (KB → bytes). |
| internal/procusage/maxrss_linux_test.go | Tests Linux ru_maxrss scaling. |
| internal/procusage/maxrss_darwin.go | macOS-specific ru_maxrss scaling (already bytes). |
| internal/procusage/maxrss_darwin_test.go | Tests macOS ru_maxrss scaling. |
| internal/procusage/maxrss_other.go | Fallback ru_maxrss scaling for other Unix platforms. |
| internal/procusage/report.go | Logs usage/phase summaries and appends the history record. |
| internal/procusage/report_test.go | Verifies info-level emission behavior and history write behavior. |
| internal/procusage/history.go | Implements capped JSONL history append/load with temp-and-rename replacement. |
| internal/procusage/history_test.go | Tests trimming, parsing tolerance, disk footprint bound, and temp cleanup. |
| internal/procusage/procusage_test.go | Tests CPU math helpers and live-hook sanity. |
| internal/paths/paths.go | Adds RunMetricsFile() to locate run-metrics.jsonl in the install dir. |
| CHANGELOG.md | Documents the new per-run profiling behavior and platform caveats. |
| AGENTS.md | Documents the intentional executor.Executor bypass for in-process counters. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
Comment on lines
+156
to
+160
| if err := os.Chmod(tmpPath, 0o600); err != nil { | ||
| return fmt.Errorf("procusage: chmod temp: %w", err) | ||
| } | ||
| return os.Rename(tmpPath, path) | ||
| } |
Member
Author
There was a problem hiding this comment.
Not doing this — the premise is incorrect. Go's os.Rename on Windows does replace an existing destination:
// GOROOT/src/os/file_windows.go
func rename(oldname, newname string) error {
e := windows.Rename(fixLongPath(oldname), fixLongPath(newname))// GOROOT/src/internal/syscall/windows/syscall_windows.go:366
return MoveFileEx(from, to, MOVEFILE_REPLACE_EXISTING)Independent confirmation from this repo: internal/atomicfile/atomicfile.go — the canonical atomic writer, used on Windows for config.json, VS Code settings.json and .npmrc — does a bare os.Rename with no prior Remove. If the claim held, those writes would be broken product-wide on Windows.
The internal/state/state.go:155-158 comment you cited is itself wrong, and internal/progress/filelog/filelog.go carries the same stale claim. It was true for Go's MoveFile-based implementation before Go 1.5 (2015); this module requires Go 1.26.
Adding the Remove would also make things slightly worse, not safer: it opens a window where the file doesn't exist, giving up the atomicity the temp-and-rename exists to provide. And it doesn't fix the one case where MoveFileEx genuinely fails on Windows — destination held open without FILE_SHARE_DELETE — because os.Remove fails there too.
Flagging the two stale comments for a separate cleanup PR rather than widening this one.
Comment on lines
+72
to
+74
| // formatPhaseCPU names the costliest phases, so the debug line points at | ||
| // what to optimise rather than only what the run totalled. | ||
| func formatPhaseCPU(phases []Phase) string { |
Member
Author
There was a problem hiding this comment.
Good catch — fixed. Leftover from when both lines were at debug level.
Two more of the same staleness that weren't flagged, also fixed:
report.go:16—topPhasesLoggedsaid "the debug line names"procusage.go:136—Stringsaid "the one-line debug summary"
And one unrelated inaccuracy in the same file: the ReadMemStats comment claimed it runs "once per run and once per phase boundary". It only runs once per run — phase boundaries call CPUMillis, which deliberately skips it. Corrected with the measured cost.
~1ms per run: 28 phase-boundary getrusage pairs at 3us, one Capture at 65us (ReadMemStats stops the world, so it runs once per run and never in a loop), and one history append at 878us. That is 0.002% of a 54s enterprise run and 0.01% of a 10s community scan. The append dominates and is the only part that scales with the cap, since it rewrites the whole ~250KB file. Benchmarks committed so the next person changing the cap or adding usage fields can see the cost. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
Three comments still said "debug line" from before the level change to info, and the ReadMemStats note claimed it runs per phase boundary. It runs once per run; boundaries call CPUMillis, which skips it. Signed-off-by: Swarit Pandey <swarit@stepsecurity.io>
ashishkurmi
approved these changes
Sep 9, 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.
Logs what each run costs at info level and appends one JSON record per run to
run-metrics.jsonlin the install dir, capped at the newest 200. Both dispatch paths (scan.Run,telemetry.Run) report through one call so records are comparable.cpu_pctis CPU time over (wall × cores), so it is the share of the machine and cannot exceed 100. The raw CPU/wall ratio is reported separately as "cores busy" — as a percentage it read as "used 96% of the CPU" when it meant 0.96 of one core, a 12× misread on a 12-core box.Info, not debug, because installs run at
log_level=info— a debug line never reaches stderr and so is absent from theExecutionLogswe download. The enterprise path also reports before the execution-log snapshot:execLogsBase64is taken mid-body, so anything deferred lands after it by construction. Verified by decodingexecution_logs.output_base64from a--telemetry-outdump — both lines are inside it.Two things worth a reviewer's attention:
getrusage(RUSAGE_CHILDREN)works becauseexecutor.Runreaps its children; Windows has no equivalent, so its records setchildren_attributed: falserather than reporting a quietly smaller number. Closing the gap needs a Job Object — deferred.internal/procusagebypassesexecutor.Executor(AGENTS.md §2.1). These are in-process syscalls against our own PID, so there's no command forexecutor.Mockto intercept; it uses a swappable hook instead. Noted in §2.1.ru_maxrssis kilobytes on Linux and bytes on macOS, so the scaling lives in per-OS files with a test each.