Skip to content

(atelet): make the restore timing log a joinable per-actor latency record - #1364

Merged
Da Huang (git286) merged 3 commits into
agent-substrate:mainfrom
krisztianfekete:feat/restore-timing-log
Sep 1, 2026
Merged

Da Huang (git286) merged 3 commits into
agent-substrate:mainfrom
krisztianfekete:feat/restore-timing-log

Conversation

@krisztianfekete

@krisztianfekete Krisztian F (krisztianfekete) commented Sep 1, 2026 •

Copy link
Copy Markdown
Collaborator

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.duration instrument's name plus an ate.snapshot.phase value, 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 of ActorLogLabels, 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.uid and trace_id, this was impossible before

  • ate_actor_restore_duration_seconds_sum{phase="total"} = 0.181189689, matching the log to the nanosecond

  • induced a download failure by deleting a snapshot object: record sets ate.failure.reason: FAILED_GET_EXTERNAL_OBJECT and correctly omitted ateom_restore; the metric for the same restore shows the same six phases

  • Tests pass

  • Appropriate changes to documentation are included in the PR

@krisztianfekete
Krisztian F (krisztianfekete) marked this pull request as ready for review September 1, 2026 16:44
@krisztianfekete Krisztian F (krisztianfekete) changed the title atelet: make the restore timing log a joinable per-actor latency record (atelet): make the restore timing log a joinable per-actor latency record Sep 1, 2026
Comment thread cmd/atelet/main.go
{ateattr.SnapshotPhaseTotal, time.Since(tStart)},
}
s.instruments.recordRestore(ctx, op, err, phases...)
slog.LogAttrs(ctx, slog.LevelInfo, "Restore timing breakdown",

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, this has been a problem even before my PR as well for histograms.

Comment thread cmd/atelet/main.go Outdated
}
s.instruments.recordRestore(ctx, op, err, phases...)
slog.LogAttrs(ctx, slog.LevelInfo, "Restore timing breakdown",
snapshotLogAttrs(attribution, op, restoreDurationMetric, err, phases)...)

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed.

… do not report a panicked restore as a success
@git286
Da Huang (git286) merged commit 85d404a into agent-substrate:main Sep 1, 2026
9 checks passed
@krisztianfekete
Krisztian F (krisztianfekete) deleted the feat/restore-timing-log branch September 1, 2026 20:20
pull Bot pushed a commit to RolfLobo/substrate that referenced this pull request Sep 30, 2026
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.
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.

2 participants