fix: correct host CPU and disk utilization metrics

[waninggibbon]

What was the problem/requirement? (What/Why)

Host CPU utilization was frequently logged as 0.0 even while a worker was active.
HostMetricsLogger scheduled each collection with a new threading.Timer, but
non-blocking psutil.cpu_percent() compares against the previous call made from
the same thread. The first call from each timer thread therefore produced an
uninitialized zero sample.

The total-disk-used-percent metric also emitted disk.used / disk.total, which
is a fractional ratio rather than the percentage indicated by the metric name.

What was the solution? (How)

• Replace the timer chain with one long-lived metrics thread and an interruptible
  stop event.
• Prime psutil.cpu_percent() on that thread, wait one collection interval, and
  collect every subsequent sample on the same thread.
• Signal and join the metrics thread during context-manager shutdown.
• Emit psutil.disk_usage(...).percent for total-disk-used-percent.
• Update unit coverage for thread startup and shutdown, CPU priming and repeated
  sampling, and the corrected disk percentage.

What is the impact of this change?

CPU utilization now represents activity over a complete collection interval
instead of repeatedly reporting psutil's uninitialized value. Disk utilization
is reported on the expected 0-100 scale.

The first host metrics event is emitted after one complete collection interval
instead of immediately, avoiding an invalid initial CPU sample.

How was this change tested?

• hatch run test: 3,024 passed, 47 skipped; 84.82% coverage.
• hatch run lint: Ruff lint and formatting passed; Mypy passed for 193 source
  files.
• hatch build: source distribution and wheel built successfully.

Was this change documented?

No documentation change is required. Existing metric names and the log schema
are unchanged.

Is this a breaking change?

No.

---

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

[github-actions]

The priming call psutil.cpu_percent() runs outside any exception handling, unlike the psutil calls inside log_metrics (which are wrapped in try/except). If this call raises (e.g. a transient psutil/OS error), the _run thread dies immediately and no host metrics are ever logged for the lifetime of the context manager — silently, since the exception propagates out of a thread with no handler. Consider wrapping the prime in try/except (log-and-continue), consistent with how log_metrics already tolerates psutil failures.

[waninggibbon]

Addressed in 58fcf78

[leongdl]

wedged seems to be a common Opus 5 favorite word :)

[leongdl]

I would be careful here, 5s is a long time to join, since this is a context enter / exit, does it cost the call stack higher using this context any issues?

[leongdl]

Thanks for this — the CPU-priming diagnosis is a good catch, and the shift to one long-lived thread is the right shape for it. I dug into the __enter__/__exit__ change specifically to see whether the bounded join can propagate anything upstream. Summary: the join itself won't crash anything, and in normal operation it costs nothing — but 5s is the wrong number, and the __enter__ half introduces a new failure path worth closing before merge.

The join is safe, and usually free

Thread.join(timeout=...) never raises on timeout; the code correctly checks is_alive() afterwards and logs instead of assuming success. __exit__ returns None, so it won't accidentally suppress the in-flight exception on the raise paths in Worker.run(). And because _run blocks on self._stop_event.wait(self.interval_s) and __exit__ calls set() first, the wait is woken immediately and the join returns in microseconds. Good.

The full 5s is only ever paid when the thread is mid-log_metrics() and stuck, and there's exactly one thing in there that can block unboundedly: the nvidia-smi subprocess.check_output has no timeout=. That's the scenario the new comment cites — and it's also fixable at the root.

Where 5s does cost something

Windows service stop is the tight one. SvcStop() in win_service.py reports SERVICE_STOP_PENDING once, with no explicit wait hint and no checkpoint loop. pywin32's default wait hint is on the order of 5s, so a 5s metrics join can consume that whole budget before the rest of the unwind (executor join, then _agent_shutdown's update_worker network call) even starts. To be fair this path was already over budget — a single STOP_PENDING with no checkpoints was never going to cover a multi-second shutdown — so the join worsens an existing problem rather than creating one. Caveat: I couldn't verify pywin32's exact default locally, so that number is worth a second pair of eyes.

Spot / ASG shutdown is additive. _monitor_ec2_shutdown returns a grace_time equal to the entire remaining window (2 min for ASG, whatever IMDS reports for Spot), and self._scheduler.shutdown(grace_time=...) runs inside the with. So: scheduler potentially consumes the whole window → up to 5s on the metrics join → _agent_shutdown then tries update_worker to record STOPPED/STOPPING. The 5s eats into a budget already sized to be fully consumed, which can cost the final status update.

systemd is fine. The unit generated by install.sh sets no TimeoutStopSec, so it inherits DefaultTimeoutStopSec (typically 90s). 5s against 90s is comfortable.

One ordering note: in Worker.run() the managers are entered as (self._executor, AwsCredentialsRefresher(...), host_metrics_logger), so they exit in reverse and the metrics join runs first — ahead of self._executor.__exit__(). The 5s is strictly serial added latency on every shutdown path, not something overlapping work that was going to happen anyway.

The unremarked risk is in __enter__, not __exit__

Previously __enter__ called log_metrics(), which swallows everything internally — it could not fail. Now it calls Thread.start(), which raises RuntimeError if the OS can't create a thread (resource exhaustion / hitting a thread limit — plausible on a loaded render host running many session subprocesses). That propagates out of __enter__, out of the with in Worker.run(), up to entrypoint, where the generic handler calls sys.exit(1). So an optional best-effort observability feature can now take down the whole agent, where before it would at worst have logged nothing.

This is the inverse of the bot's earlier finding: that one caught the unprotected psutil prime inside _run (nicely fixed in 58fcf78 via _prime_metrics), but the unprotected start() in __enter__ is still there and has a much larger blast radius.

Suggested changes, in priority order

1. Wrap __enter__'s thread creation in try/except and degrade to "no metrics" rather than killing the agent. This is the only real crash path.
2. Add timeout= to the nvidia-smi check_output. This bounds the one unbounded blocker and fixes the root cause the join is compensating for.
3. Drop JOIN_TIMEOUT_S to ~1s, or skip the join entirely. The thread is a daemon and _stop_event.set() already wakes it immediately, so there's no correctness reason to wait 5s; a bounded join is really just tidiness, and tidiness shouldn't cost 5s on the Spot path.

I've left these as inline comments at the three spots too. Nothing here is a blocker on the core fix — the metric corrections themselves look right.

[leongdl]

Suggestion 1 of 3 (highest priority): this is a new crash path for the whole agent.

Before this PR, __enter__ called log_metrics(), which try/excepts everything internally — it could not fail. Now it calls Thread.start(), which raises RuntimeError when the OS can't create a thread (resource exhaustion, hitting a thread/process limit — plausible on a loaded render host running many session subprocesses).

That RuntimeError propagates out of __enter__ → out of the with (...) in Worker.run() → up to entrypoint, where the generic except Exception handler calls sys.exit(1). So a failure in an optional, best-effort observability feature now takes down the Worker Agent, where previously it would at worst have logged nothing.

This is the mirror image of the earlier bot finding: that one caught the unprotected psutil prime inside _run (fixed nicely in 58fcf78 via _prime_metrics), but the unprotected start() here is still open and has a much bigger blast radius.

Suggest degrading to "no metrics" instead of failing:

def __enter__(self) -> HostMetricsLogger:
    self._stop_event.clear()
    thread = Thread(target=self._run, name="HostMetricsLogger", daemon=True)
    try:
        thread.start()
    except RuntimeError as e:
        module_logger.warning(
            f"Failed to start the host metrics thread. Host metrics will not be logged. Error: {e}"
        )
    else:
        self._thread = thread
    return self

Assigning self._thread only on success also keeps __exit__ correct for free — it already guards on if self._thread, so it becomes a no-op rather than joining a thread that never started.

[waninggibbon]

Thanks for the suggested fix, applied in latest commit

[leongdl]

Please add the 3 changes, especially the nvidia-smi timeout one.

[leongdl]

Suggestion 2 of 3: this is the unbounded blocker that the new 5s join is compensating for.

This check_output has no timeout=, so it can block indefinitely. A wedged nvidia-smi is a real failure mode on unhealthy GPU drivers, where the process can sit in uninterruptible sleep — and it's exactly the "unresponsive nvidia-smi" case cited in the new __exit__ comment.

This line is outside the diff, so it's pre-existing rather than something this PR introduced. But it's worth fixing here, because it's the root cause: it's the only thing inside log_metrics() that can keep the metrics thread from noticing _stop_event promptly, and therefore the only reason the bounded join can ever run out its clock. Bounding the collection makes the join's timeout nearly unreachable in practice.

output = subprocess.check_output(
    ["nvidia-smi", f"--query-gpu={query_str}", "--format=csv,noheader,nounits"],
    stderr=subprocess.PIPE,
    universal_newlines=True,
    timeout=...,  # a few seconds, comfortably under interval_s
)

One thing to check if you take this: subprocess.TimeoutExpired is not a subclass of CalledProcessError, so it would fall through to the existing except Exception catch-all below. That does the right thing (debug log, then _host_has_no_gpu = True), but note the _host_has_no_gpu latch means a single transient timeout permanently disables GPU metrics for the process lifetime. A dedicated except subprocess.TimeoutExpired that logs and returns without setting the latch is probably what you want, so a one-off hang doesn't cost you GPU metrics forever.

[waninggibbon]

I went ahead with a 5 second time out, skipped the _host_has_no_gpu latch, and added a dedicated timeout expired handler.

Agree that a transient hang causing us to drop a sample is preferable here. Thanks for the suggestion!

[leongdl]

Suggestion 3 of 3: 5s is a long time to spend on a metrics thread during shutdown.

To be clear about what's not wrong here: the join is correctly written. join(timeout=...) never raises, the is_alive() check afterwards logs rather than assuming success, and __exit__ returning None means it won't suppress the in-flight exception on the raise paths in Worker.run(). And because _run blocks on _stop_event.wait(self.interval_s) and __exit__ sets the event first, the normal case returns in microseconds. This value is only ever paid when the thread is stuck mid-collection.

The concern is what it costs when that does happen, given where __exit__ sits in the shutdown sequence:

• Windows service stop. SvcStop() reports SERVICE_STOP_PENDING once, with no explicit wait hint and no checkpoint loop. pywin32's default hint is on the order of 5s, so this join alone can consume the whole SCM budget before the executor join and _agent_shutdown's update_worker call even start. That path was already over budget pre-PR, so this worsens rather than creates the problem — and I couldn't verify pywin32's exact default, so worth a second look.
• Spot / ASG. _monitor_ec2_shutdown returns a grace_time covering the entire remaining window, and _scheduler.shutdown(grace_time=...) runs inside the with. The scheduler can consume that whole window, then this join adds up to 5s, and only then does _agent_shutdown try to record STOPPED/STOPPING. That can cost the final status update.
• systemd is fine — the generated unit sets no TimeoutStopSec, so it inherits the ~90s default.

Worth noting the ordering too: in Worker.run() the managers are entered as (self._executor, AwsCredentialsRefresher(...), host_metrics_logger), so they exit in reverse and this join runs first, ahead of self._executor.__exit__(). It's strictly serial added latency on every shutdown path.

Given the thread is a daemon and _stop_event.set() already wakes it immediately, there's no correctness reason to wait 5s — a bounded join here is really just tidiness, and tidiness shouldn't cost 5s on the Spot path. I'd suggest JOIN_TIMEOUT_S = 1.0 (or dropping the join entirely and relying on the daemon flag). If suggestion 2 lands and nvidia-smi gets a timeout=, the collection itself becomes bounded and this timeout gets even harder to reach.

Minor, while you're in here: the comment just below uses "wedged" and then "unresponsive" two words later — worth settling on "unresponsive" or "hung" for both.

[waninggibbon]

Yeah good callout, I went ahead and dropped the timeout to just 1 second. The fix you suggested in (2) should make the timeout harder to reach at all. I think this leaves us a place where the existing pywin32 issue isn't addressed but also isn't exacerbated. Let me know what you think here.

I also dropped "wedged" in favor of unresponsive.

[github-actions]

Startup no longer logs an immediate metrics line. Previously __enter__ called log_metrics() synchronously, so a first sample was emitted at t=0 and then every interval_s. Now _run primes baselines and then blocks on self._stop_event.wait(self.interval_s) before the first log_metrics(), so the first line appears only after a full interval (default 60s).

Two consequences worth confirming are intended:

• A Worker that lives less than one interval will now log no host metrics at all, whereas before it logged at least one line on startup.
• Observability of a freshly started Worker is delayed by up to interval_s.

If the goal was only to get accurate (non-zeroed) rates on the first sample, that is already achieved by _prime_metrics(); you could still emit an immediate priming sample or shorten the first wait to preserve the previous startup-visibility behavior.

[github-actions]

total-disk-used-percent changes scale/units for existing consumers. The old code emitted round(disk.used / disk.total, 1) — a 0.0–1.0 fraction (e.g. 0.2 for a 25%-full disk), while the new code emits round(disk.used / disk.total * 100, 1) — a 0–100 percentage (e.g. 25.0).

This is the correct value (the old one was never a real percent), but it is a ~100× change to a metric a public product emits. Any existing CloudWatch alarm, dashboard, or log-based metric keyed on total-disk-used-percent will silently misbehave after this ships: a threshold like > 0.8 will now fire almost always, and a > 80 threshold that never fired before will start working. Worth calling out in the changelog / release notes so operators can re-tune anything built on the previous (fractional) values.