Repository navigation
(atelet): make the restore timing log a joinable per-actor latency record - #1364
Da Huang (git286) merged 3 commits into
Conversation
| {ateattr.SnapshotPhaseTotal, time.Since(tStart)}, | ||
| } | ||
| s.instruments.recordRestore(ctx, op, err, phases...) | ||
| slog.LogAttrs(ctx, slog.LevelInfo, "Restore timing breakdown", |
There was a problem hiding this comment.
Now that the timing log fires on failures too (via the defer), the preexisting collateral cleanup can make it lie.
The prep leg has two phases. If ensureSandboxAssets finishes (say 1.2s) and then the download leg fails, the errgroup cancels prepareOCIBundles mid-flight. isCollateral(err, prepErr) is true, so we zero both dAssets and dBundles, but dAssets was a complete, valid measurement. Since the log drops zero phases and the docs say "absent = never ran", the record now claims sandbox assets never ran when it actually completed, and the histogram drops a valid sample.
There was a problem hiding this comment.
Good catch, this has been a problem even before my PR as well for histograms.
| } | ||
| s.instruments.recordRestore(ctx, op, err, phases...) | ||
| slog.LogAttrs(ctx, slog.LevelInfo, "Restore timing breakdown", | ||
| snapshotLogAttrs(attribution, op, restoreDurationMetric, err, phases)...) |
There was a problem hiding this comment.
Since the log moved into a defer, a panic mid-restore now produces a success shaped record: no return runs during unwinding, so the named err is still nil and ate.failure.reason is omitted. A crashed restore will get logged as a fast success.
There was a problem hiding this comment.
Fixed.
… do not report a panicked restore as a success
agent-substrate#1941) ## Benchamark(atelet, ateom-microvm): log per-actor checkpoint and restore phase breakdowns ### Why `SuspendActor` and `ResumeActor` latency is only attributable down to the `ate.actor.{checkpoint,restore}.duration` histogram phases, and the biggest buckets — `ateom_checkpoint`, `ateom_restore` — are opaque. When a large memory benchmark suspend takes 6 s we want to able to tell where the time is been spent during the suspend. ### What One joinable, developer-facing log record per operation per layer, with the full actor identity (allowed in logs, barred from metric labels), the snapshot scope, and one float-seconds field per phase that ran. **atelet** - `Checkpoint` now writes a `Checkpoint timing breakdown` record, the same way `Restore` has written `Restore timing breakdown` since agent-substrate#1364. Phases: `sandbox_assets`, `ateom_checkpoint`, `persist`, `total`. One slice feeds both the histogram and the record, so they cannot disagree. - Both records carry `error.type` when the operation failed (the gRPC code; context errors map to `DeadlineExceeded` / `Canceled`). The record is written on the way out of a failure too, so its completed phases are kept, and the marker lets a reader exclude a timed-out restore from a latency distribution. This restores what the record lost when the `ateerrors` taxonomy was deleted (agent-substrate#1817), using the `error.type` convention the ateapi instruments already follow. **ateom-microvm** - New `phaselog.go`. `CheckpointWorkload` and `RestoreWorkload` emit records with the same two messages, under `ateom.actor.checkpoint.duration.<phase>` and `ateom.actor.restore.duration.<phase>`, decomposing atelet's `ateom_checkpoint` / `ateom_restore` buckets: - checkpoint: `pause`, `snapshot`, `durable_dir`, `rootfs_upper`, `teardown`, `total` — the three captures run concurrently on the paused guest, so the paused window costs their max, not their sum. - restore: `prep`, `bundles`, `upper_join`, `lowers`, `tap`, `vmm_launch`, `vm_restore`, `resume`, `wakeup_probe`, `total` — sequential; they partition the total. A Data-scope cold boot records `total` only. - These timings already existed as ad-hoc `slog.Duration` fields on the `Actor checkpointed` / `Actor restore phases` lines; those lines are kept. The record adds stable keys, identity, and seconds (the histograms' unit). - The phase names are deliberately private to the binary rather than added to `internal/ateattr`, so they cannot be mistaken for `ate.snapshot.phase` metric values. They are micro-VM specific; ateom-gvisor is unchanged. **docs/observability.md** is updated: the Restore record is no longer the only per-actor latency record, and the ateom records are described. No new instruments, no registry changes, no behavior change. ### Example ```json {"msg":"Checkpoint timing breakdown","ate.actor.uid":"8f2a…","ate.template.name":"glutton", "ate.snapshot.scope":"full", "ateom.actor.checkpoint.duration.pause":0.003, "ateom.actor.checkpoint.duration.snapshot":0.846, "ateom.actor.checkpoint.duration.rootfs_upper":0.022, "ateom.actor.checkpoint.duration.teardown":0.232, "ateom.actor.checkpoint.duration.total":1.081} ``` Joined with atelet's record for the same actor, a run of the glutton workload (1 GiB resident, microVM) attributes a 6.0 s p50 suspend as 75% `persist`, 19% `ateom_checkpoint` (of which the CH `snapshot` is 0.85 s and `teardown` 0.23 s), and a 5.3 s p50 resume as 79% `download`, 18% `ateom_restore` (of which `vm_restore` is 0.73 s). The consumer that produces those tables from pod logs is a separate `benchmarking/analysis` PR. ### Testing - `go test ./cmd/atelet/...` and `./cmd/ateom-microvm/...` pass; new unit tests cover the record shape (seconds, identity keys, zero phases absent, no duplicate keys), the scope mapping, and `error.type` for gRPC, context and plain errors. - `GOOS=linux go vet` clean for both binaries; boilerplate and gofmt clean.
Restore timing breakdown is the only unsampled per-actor latency record we emit, and since traces are head-sampled at 1% on the data plane, and actor identity is not available from metric labels on purpose.
This adds this to logs:
Before:
{"msg":"Restore timing breakdown", "actor":{"type":"*ateapipb.Actor","atespace":"demo","name":"counter-1"}, "download":310000000,"oci_unpack":50000000,"ateom_restore":60000000,"total":420000000}After:
{"msg":"Restore timing breakdown", "ate.atespace":"ate-demo-counter-substrate","ate.actor.name":"join-probe", "ate.actor.uid":"3a5b4e86-1a77-4da7-84c4-c0993d9c83ec", "ate.template.atespace":"ate-demo-counter-substrate","ate.template.name":"counter", "ate.snapshot.scope":"full","ate.snapshot.kind":"golden","ate.sandbox.class":"gvisor", "ate.actor.restore.duration.volume_mount":0.000004583, "ate.actor.restore.duration.manifest_fetch":0.006111636, "ate.actor.restore.duration.sandbox_assets":0.000098958, "ate.actor.restore.duration.download":0.025386544, "ate.actor.restore.duration.oci_unpack":0.000954919, "ate.actor.restore.duration.ateom_restore":0.147448298, "ate.actor.restore.duration.total":0.181189689, "trace_id":"c9d7ea9a5f90a5eb4399bfa0b966d5ac","span_id":"89280ba761137c8e"}The duration keys are the
ate.actor.restore.durationinstrument's name plus anate.snapshot.phasevalue, so a log key and the histogram it mirrors are literally the same identifier in source, which is also why they're seconds.Also adds
ateattr.ActorLogAttrs, the component-log twin ofActorLogLabels, held to the same key set by a test.Verified on kind:
the ateom Actor restoring record for the same actor carries the identical
ate.actor.uidandtrace_id, this was impossible beforeate_actor_restore_duration_seconds_sum{phase="total"} = 0.181189689, matching the log to the nanosecondinduced a download failure by deleting a snapshot object: record sets
ate.failure.reason:FAILED_GET_EXTERNAL_OBJECTand correctly omittedateom_restore; the metric for the same restore shows the same six phasesTests pass
Appropriate changes to documentation are included in the PR