atelet: emit per-actor usage events from the stats sweep

[Tim Bai (baizhenyu)]

Part of #896 (Phase 1 of #550): the events channel — per-actor usage samples as structured log events. With this, both halves of #174's cardinality split exist: template-level metrics in the TSDB (#961), and everything carrying actor/atespace identity here, in the log store.

The events

One JSON record per executing actor per sweep on atelet's stdout, riding the poller's existing probe — no extra RPC load, and one knob governs both channels (--actor-stats-poll-interval 0 disables the subsystem). Idle workers emit nothing: an idle fleet is silent by design.

Records use the same label vocabulary as actorlog's lifecycle events (ateattr.ActorLogLabels, including the GCE logging.googleapis.com/labels spelling) — so one Cloud Logging filter on labels."ate.actor.uid" returns an actor's container logs, lifecycle transitions, and usage samples interleaved. Identity comes solely from each sample's echo, per the stats RPCs' attribution contract. Measurements ride as payload fields (kind, class, source, the four numbers, observed_at_unix_nano); the kind field (today always periodic) lets future kinds join without reshaping the record.

Events also carry the ate.workerpool.namespace/name pair the metric labels already carry, resolved by the sweep's own pod list, so a pool-level metric spike can pivot to the actors behind it — pool membership lives on the worker pod and is unrecoverable from logs once the pod is gone, so it must be stamped at emission. An unresolved pod emits without the pair, following the metric channel's rule.

Scope

Earlier revisions also took first/final lifecycle samples from the Run/Restore/Checkpoint handlers. Per the review discussion on suspend/resume latency, those are descoped from this PR: it now touches no lifecycle path at all. The bracket design (including taking the final sample inside ateom's CheckpointWorkload and echoing it in the response) moves to a follow-up under #896.

Isolation

The poller dials its own short-lived connection per probe (dialAteomStats) and never touches the lifecycle RPCs' cached clients — after review on #961 the isolation is structural.

Validated live on ate-dev

Periodic events read back from Cloud Logging via labels."ate.actor.name", one per executing actor per minute, with ate.actor.uid confirmed promoted into LogEntry.labels (filterable) — the claim only production could prove.

Consumer note: aggregate freely in the log store, but a log-based metric built over these events must label only by the bounded set (template, class, source, pool) — promoting actor identity into a metric label would reintroduce exactly the cardinality #174 keeps out of the TSDB.

Part of #896. Part of #550.

[Jeff Luo (JeffLuoo)]

Could you update docs/observability.md in the logging section to include instructions for using the new per-actor usage events?

[Tim Bai (baizhenyu)]

docs/observability.md

We can update doc in a separate PR after implementation is finalized and submitted. Otherwise, we will need to maintain sync of implementation and doc which is not very efficient.

[Da Huang (git286)]

Actor Suspend -> Resume latency (sub-second) is one of the most important performance SLO the project is trying to achieve. Right now the sampleFirst sit in the critical path synchronously and could impact the latency in the unhappy case (I see the timeout is 10 seconds for worst case).

I think we should make the sampling async to reduce the impact on the critical path latency.

[Tim Bai (baizhenyu)]

Right now the sampleFirst sit in the critical path synchronously

Done in 91e3fff: sampleFirst now samples from its own goroutine on a context.WithoutCancel context — the Run/Restore handlers return immediately, so the resume SLO pays nothing for telemetry, fast path or worst case. The sampler's own 10s timeout still bounds the detached read.

sampleFinal deliberately stays synchronous: its ordering against CheckpointWorkload is the feature (sampling after the dispatch would race the epoch's own end), and the suspend path carries no sub-second SLO. Both doc comments now state this asymmetry, and the tests cover the async emission and that the detached context still carries a deadline.

[Da Huang (git286)]

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

(Given the first sampling logic has become async so suspend -> running latency won't be affected)

[Benjamin Elder (BenTheElder)]

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

Yikes, 10s in the hot path is way outside of our targets, what other options did we consider?

[Tim Bai (baizhenyu)]

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

Yikes, 10s in the hot path is way outside of our targets, what other options did we consider?

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

[Benjamin Elder (BenTheElder)]

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

So in theory we want say, 100ms, but realistically we are something at least XXXms for gVisor operations, and slower for uVM at the moment. Slowing that down in any way is going the wrong direction as we're already pretty far from the desired latency.

Can we just sample while it's online and not sample during snapshot etc.

[Tim Bai (baizhenyu)]

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

So in theory we want say, 100ms, but realistically we are something at least XXXms for gVisor operations, and slower for uVM at the moment. Slowing that down in any way is going the wrong direction as we're already pretty far from the desired latency.

Can we just sample while it's online and not sample during snapshot etc.

The periodic resource event emission during normal operation has already been implemented in this PR. However, the final resource utilization event is very important before actor suspend. This event contains the metric of total CPU usage of current actor session. The periodic resource event is unable to provide this information accurately.

Alternatively, we can make this operation async (best effort) so that it does not block the hot path. WDYT?

[Da Huang (git286)]

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.

Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.

Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.

WDYT about overlap + short grace in this PR, piggyback as follow-up?

[Tim Bai (baizhenyu)]

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.

Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.

Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.

WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

[Da Huang (git286)]

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.
Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.
Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.
WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

One thing that hasn't come up in this thread: the latency question aside, there's a correctness bug in the current ordering that the ateom approach would fix for free. Right now we emit the final sample before calling CheckpointWorkload. If the checkpoint fails transiently, the workload keeps running and the control plane retries so we emit a second final for the same session. Anyone summing finals now double counts almost the whole session, and the events carry no epoch/attempt id to dedup on.

If ateom takes the sample as part of CheckpointWorkload and returns it in the response, this problem can't happen: we only emit when the checkpoint actually succeeded, so it's always exactly one final per session. Same trick would work for Terminate, which currently emits no final at all.

So I'd frame the follow-up as a correctness fix, not a latency optimization. On the latency concern: the read is cheap on gVisor, and ateom can overlap it with its own pre-destructive prep, same as what we're doing here. So it doesn't have to add anything to the critical path.

[Tim Bai (baizhenyu)]

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.
Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.
Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.
WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

One thing that hasn't come up in this thread: the latency question aside, there's a correctness bug in the current ordering that the ateom approach would fix for free. Right now we emit the final sample before calling CheckpointWorkload. If the checkpoint fails transiently, the workload keeps running and the control plane retries so we emit a second final for the same session. Anyone summing finals now double counts almost the whole session, and the events carry no epoch/attempt id to dedup on.

If ateom takes the sample as part of CheckpointWorkload and returns it in the response, this problem can't happen: we only emit when the checkpoint actually succeeded, so it's always exactly one final per session. Same trick would work for Terminate, which currently emits no final at all.

So I'd frame the follow-up as a correctness fix, not a latency optimization. On the latency concern: the read is cheap on gVisor, and ateom can overlap it with its own pre-destructive prep, same as what we're doing here. So it doesn't have to add anything to the critical path.

Updated in the latest commits — the final sample now follows the overlap shape proposed above, tightened one step further:

• beginFinalSample starts the read at the top of the Checkpoint handler, so it runs concurrently with the handler's own prep (sandbox record, asset ensure, dial, spec build) and is done long before it's needed.
• joinBeforeCheckpoint runs immediately before dispatching CheckpointWorkload: it waits at most 50ms, and a read still in flight is cancelled, not left racing the teardown. By dispatch time the sample is deterministically complete or abandoned — never pending.
• emitAfterSuccess publishes only once the ateom confirms the checkpoint. This also fixes an ordering bug in the previous revision: a transiently failed, retried checkpoint would have emitted a duplicate final per attempt, double-counting the session for anyone summing finals. Now every session gets exactly one final, from the attempt that succeeded.

Net latency: zero added in the happy case; worst case 50ms, paid only when the stats path is already broken. The read timeout (500ms) bounds only a background goroutine, never the handler.

On the ateom-side follow-up: with emit-on-success in atelet, the duplicate-final correctness issue is fixed here, so what the proto change would still buy is exact-at-freeze accuracy (the current design undercounts by the CPU burned between read and freeze — prep-length on a session-length measurement) and dropping the 50ms grace. The Terminate gap doesn't need it either: the same begin/join/emit pattern fits the Terminate handler as a small follow-up.

Update doc in a follow up PR

[Tim Bai (baizhenyu)]

Updated the PR, removed the lifecycle event and only keep periodic ones.

[Da Huang (git286)]

One robustness concern: emit writes to stdout synchronously inside the sweep's errgroup, and a write to a full pipe blocks forever, since there's no timeout on stdout writes. So if the log consumer stalls (disk full, log rotation stuck), one stuck write wedges g.Wait(), the tick loop stops, and the metrics freeze too. They'll keep re-serving the last snapshot with no error. Before this PR the sweep never wrote to stdout, so log-pipe health and metric health were independent; this couples them, and it bites exactly during disk incidents when you'd be looking at these dashboards.

Suggestion: make the emitter non-blocking. A small bounded channel drained by one writer goroutine, dropping and counting when full, would do it. Dropping is safe here since these are cumulative samples: the next healthy tick repairs the gap. Losing events when stdout is dead is unavoidable anyway; losing the metrics with them isn't.

[Da Huang (git286)]

pool != (workerPoolRef{}) treats a half populated ref (namespace set, name empty) as resolved and emits an empty-string ate.workerpool.name label, contradicting the doc comment's 'omits the label pair rather than emitting empty strings'.