feat(otel): add cold start metrics - #776
Conversation
|
Adding the last two metrics from #433, cc. Jeff Luo (@JeffLuoo), Da Huang (@git286). |
| op.failedPhase = downloadFailedPhase | ||
| if op.failedPhase == "" { | ||
| op.failedPhase = prepFailedPhase | ||
| } |
There was a problem hiding this comment.
failedPhase and the error can come from different goroutines, so the reason gets pinned to the wrong phase.
errgroup.WithContext cancels gctx as soon as either goroutine fails. If the asset/OCI-prep goroutine fails first, the in-flight download aborts with a context error and its defer sets downloadFailedPhase — even though it was only collateral. Here download wins unconditionally, while g.Wait() returned the prep error. The datapoint reads:
ate_snapshot_phase="download", ate_failure_reason="INVALID_CONTAINER_CONFIG"
The error is correct; the phase isn't. On a cold node the download is the long-running one, so it's still in flight almost every time prep fails.
Wait returns the first error verbatim, so identity tells you which goroutine owns it:
var downloadErr, prepErr error
g.Go(func() (err error) {
t := time.Now()
defer func() {
dDownload = time.Since(t)
downloadErr = err
if err != nil {
downloadFailedPhase = ateattr.SnapshotPhaseDownload
}
}()
...
})
g.Go(func() (err error) {
defer func() { prepErr = err }()
...
})
// The cancelled goroutine's error is only gctx fallout; it must not claim the
// phase.
if err := g.Wait(); err != nil {
switch err {
case downloadErr:
op.failedPhase = downloadFailedPhase
case prepErr:
op.failedPhase = prepFailedPhase
}
return nil, err
}errors.Is(err, context.Canceled) won't work as a filter here — CrashIfReason and the GCS wrapping don't reliably preserve it.
There was a problem hiding this comment.
Thanks!
Fixed this and while I testing I found the same bug in the durations, which is also fixed now. Also swapped ate.snapshot.file for the semconv's file.name on atelet.snapshot.size.
420a5d2 to
6ed1e78
Compare
|
Please rebase, thanks |
…uration phase histograms
6ed1e78 to
9ece549
Compare
0dbe152
into
agent-substrate:main
This PR implements the last two metrics from #433.
Right now, we can see that a resume was slow but not where.
ate.actor.lifecycle.operation.durationcovers the whole ateapi operation, andatenet.router.route.durationcovers the edge, but everything between ateapi-atelet-actors is one block that contains fetching the manifest, downloading the snapshot, unpack the OCI image, call to ateom.We have
rpc.server.call.durationthat gives us the atelet restore total time, but template, kind, and scope labels are missing, so today we cannot really pinpoint why/where we have a regressions in latency.In this PR I am adding per-phase histograms, here's an example of what we can know after these changes:
It also fixes a gap #683 opened where a
data_on_goldenresume was labeled identically to a plain one on the lifecycle histogram.Things folks might want to argue with:
rpc.server.call.duration, but that one has no domain labels and gRPC-specifc. We can drop it, but it's an inferior operational UX, so I'd rather have it here.ate.snapshot.scopekey rather than a newate.snapshot.kindvalue fordata_on_golden. A new value would collapse local and external into one bucket, which is the biggest latency difference there is. This does add a label to the already shipped lifecycle histogram.Verified on kind, and all e2e suites pass, and the emitted series cover every kind (golden, latest, local) on both metrics with no unknown values.