Skip to content

Add metrics logging - #32

Merged
DonFreed merged 5 commits into
devfrom
log-metrics
Aug 14, 2026
Merged

Add metrics logging#32
DonFreed merged 5 commits into
devfrom
log-metrics

Conversation

@DonFreed

Copy link
Copy Markdown
Contributor

No description provided.

DonFreed and others added 5 commits August 14, 2026 12:54
Create the log directory only after validation: setup_logging is now
console-only and a new start_run_logs(), called after validate(),
derives and prepares the log directory. A typo'd output path again
fails fast instead of being silently created, a rerun rejected by
validation no longer destroys the previous run's logs, and a log path
colliding with a regular file exits cleanly instead of raising.

Key job-id counters on the sanitized name (sanitize moved to util.py)
so log file paths stay unique even for names that differ only in
unsafe characters.

Make -v/-q/-d independent flags with explicit precedence: -d -v no
longer downgrades DEBUG to INFO, and the new --quiet restores a
warnings-only console. Document the flags and the per-run log
directory in the README.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Spawn pipeline processes with RusagePopen, a subprocess.Popen subclass
whose _try_wait() reaps with os.wait4() and records the child's rusage,
replacing asyncio.create_subprocess_exec (which only provided spawn and
reap here: every stdio stream is already a real FD). Waits move to
async_wait() (Popen.wait in a worker thread), and the executor raises
the loop's default thread pool to 512 lazily-created workers so blocked
waits and proc-sub FIFO opens cannot starve each other. Context.cleanup()
gains a non-blocking poll() sweep so children nobody awaited are still
reaped, as asyncio's watcher used to do. Behavior parity otherwise:
negative returncodes on signal death, SIGPIPE tolerance, and the
signal/kill paths are unchanged. Metrics emission lands separately.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Each reaped process now logs a DEBUG line to run.log with its kernel
resource usage (utime, stime, peak RSS, page faults, block I/O, context
switches), emitted whatever the job's outcome -- signal-killed children
included. Successful jobs extend the "Finished command" INFO line with
the job's summed user/sys CPU and the per-process peak RSS (a sum would
overstate concurrent stages that peak at different times). ru_maxrss is
normalized across platforms (bytes on macOS, KiB elsewhere), and the
DEBUG line renders it without an internal space (maxrss=33.6MiB) so the
key=value line stays space-tokenizable for grep/awk.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
test_simple_command now asserts rusage is recorded at reap, and a new
signal-death test pins the RusagePopen._try_wait override: if a future
CPython changes that private method's shape, the override silently stops
being called and rusage stays None, so the test asserts a SIGTERM'd
child reports both its negative return code and its rusage. New
tests/unit/test_rusage_metrics.py drives a job through LocalExecutor
(the first unit-level file to do so) and checks the per-process "rusage
for" DEBUG record, the aggregated "Finished command" INFO line, and
_maxrss_bytes unit normalization on both platform branches.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Two fixes from a code review of the branch. First, an exception escaping
_drive now tears the children down (_shutdown) before propagating: it
previously unwound into asyncio.run's shutdown, which joins the pool
threads blocked in wait4 on children nobody signalled, hanging the CLI
until the children exited on their own. BaseException, so cancellation
and KeyboardInterrupt are covered; a teardown failure is logged rather
than allowed to mask the original error.

Second, the wait/FIFO-open thread pool size is a keyword parameter
instead of a hidden constant: None on AsyncExecutor (an executor that
spawns nothing leaves the loop's default pool alone) and 512 on
LocalExecutor, beside shutdown_grace_period. async_wait() returns
immediately for an already-reaped child instead of burning a pool
dispatch and a slot.

Also document a known limitation honestly: a reap via poll() -- or
send_signal/kill, which poll internally -- uses the base Popen machinery
and records no rusage. The executor waits every process it reports
metrics for, so those paths only collect processes whose rusage is never
read.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@DonFreed
DonFreed merged commit 1dd30ca into dev Aug 14, 2026
12 checks passed
@DonFreed
DonFreed deleted the log-metrics branch August 14, 2026 23:57
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