From 832401d0350e21ac180b1382a26061401c34e4bb Mon Sep 17 00:00:00 2001 From: Babis Chalios Date: Tue, 28 Jul 2026 13:14:43 +0200 Subject: [PATCH] feat(metrics): break down pause-snapshot latency by step MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add two histograms so pause latency can be decomposed into its snapshot sub-steps: - orchestrator.sandbox.snapshot.process_rootfs.duration {fs_only, success} — rootfs export+diff, runs for both pause kinds (threads pauseOpts.filesystemSnapshot into pauseProcessRootfs). - orchestrator.sandbox.snapshot.process_memory.duration {success} — memory export+diff, memory pauses only (fs-only skips it), so no fs_only label. Together with pause.duration (#3425), a filesystem-only pause now decomposes into guest_sync (quiesce) + process_rootfs (rootfs export/diff); memory pauses additionally get process_memory. Pure additive instrumentation; no snapshot logic changed. Co-Authored-By: Claude Opus 4.8 (1M context) Signed-off-by: Babis Chalios --- packages/orchestrator/pkg/sandbox/sandbox.go | 24 ++++++++++++++++++++ packages/shared/pkg/telemetry/meters.go | 6 +++++ 2 files changed, 30 insertions(+) diff --git a/packages/orchestrator/pkg/sandbox/sandbox.go b/packages/orchestrator/pkg/sandbox/sandbox.go index 3ff51305ab..c674ae175e 100644 --- a/packages/orchestrator/pkg/sandbox/sandbox.go +++ b/packages/orchestrator/pkg/sandbox/sandbox.go @@ -52,6 +52,9 @@ var ( envdCollapseChunks = utils.Must(telemetry.GetCounter(meter, telemetry.EnvdCollapseChunks)) guestSyncDurationHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.GuestSyncDurationHistogramName)) + processMemoryDurationHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.SnapshotProcessMemoryDurationName)) + processRootfsDurationHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.SnapshotProcessRootfsDurationName)) + uffdStartupPagesHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.UffdStartupPagesHistogramName)) uffdStartupSourcePagesHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.UffdStartupSourcePagesHistogramName)) uffdStartupBytesHistogram = utils.Must(telemetry.GetHistogram(meter, telemetry.UffdStartupBytesHistogramName)) @@ -1459,6 +1462,7 @@ func (s *Sandbox) Pause( closeHook: s.Close, }, s.config.DefaultCacheDir, + pauseOpts.filesystemSnapshot, ) if err != nil { return nil, fmt.Errorf("error while post processing: %w", err) @@ -1644,6 +1648,14 @@ func pauseProcessMemory( ctx, span := tracer.Start(ctx, "process-memory") defer span.End() + // Duration of the synchronous memory export+diff (memory pauses only; fs-only + // pauses skip this). The async header dedup goroutine below outlives this span. + start := time.Now() + defer func() { + processMemoryDurationHistogram.Record(ctx, time.Since(start).Milliseconds(), + metric.WithAttributes(attribute.Bool("success", e == nil))) + }() + memfileDiffPath := build.GenerateDiffCachePath(cacheDir, buildID.String(), build.Memfile) metaOut := utils.NewSetOnce[*header.DiffMetadata]() // ExportMemory owns memfd and closes it on all paths. @@ -1756,10 +1768,22 @@ func pauseProcessRootfs( originalHeader *header.Header, diffCreator DiffCreator, cacheDir string, + filesystemOnly bool, ) (d build.Diff, h *header.Header, e error) { ctx, span := tracer.Start(ctx, "process-rootfs") defer span.End() + // Duration of the rootfs export+diff, split by fs_only (runs for both pause + // kinds) so the fs-only pause latency can be decomposed into quiesce + rootfs. + start := time.Now() + defer func() { + processRootfsDurationHistogram.Record(ctx, time.Since(start).Milliseconds(), + metric.WithAttributes( + attribute.Bool("fs_only", filesystemOnly), + attribute.Bool("success", e == nil), + )) + }() + rootfsDiffFile, err := build.NewLocalDiffFile(cacheDir, buildId.String(), build.Rootfs) if err != nil { return nil, nil, fmt.Errorf("failed to create rootfs diff: %w", err) diff --git a/packages/shared/pkg/telemetry/meters.go b/packages/shared/pkg/telemetry/meters.go index 24a1664315..736bd69d25 100644 --- a/packages/shared/pkg/telemetry/meters.go +++ b/packages/shared/pkg/telemetry/meters.go @@ -107,6 +107,8 @@ const ( WaitForEnvdDurationHistogramName HistogramType = "orchestrator.sandbox.envd.init.duration" GuestSyncDurationHistogramName HistogramType = "orchestrator.sandbox.guest_sync.duration" PauseDurationHistogramName HistogramType = "orchestrator.sandbox.pause.duration" + SnapshotProcessMemoryDurationName HistogramType = "orchestrator.sandbox.snapshot.process_memory.duration" + SnapshotProcessRootfsDurationName HistogramType = "orchestrator.sandbox.snapshot.process_rootfs.duration" // Pre-pause envd heap collapse round-trip duration (the pause-path cost of // POST /collapse: network plus envd's madvise work), recorded once per pause @@ -453,6 +455,8 @@ var histogramDesc = map[HistogramType]string{ EnvdCollapseDurationHistogramName: "Time taken for the pre-pause envd heap collapse round-trip", GuestSyncDurationHistogramName: "Time taken for the mandatory pre-pause guest sync (filesystem-only pause)", PauseDurationHistogramName: "Time taken to pause a sandbox, labeled by fs_only (filesystem-only vs memory) and success", + SnapshotProcessMemoryDurationName: "Time to export+diff the memory file during a pause snapshot (memory pauses only), labeled by success", + SnapshotProcessRootfsDurationName: "Time to export+diff the rootfs during a pause snapshot, labeled by fs_only and success", PauseResumePrefetchHarvestDurationName: "Time taken for a pause-resume prefetch harvest run (slot-hold cost)", PauseResumePrefetchHarvestPagesName: "Harvested resume-prefetch trace size in 2 MiB blocks, per successful harvest", @@ -504,6 +508,8 @@ var histogramUnits = map[HistogramType]string{ EnvdCollapseDurationHistogramName: "ms", GuestSyncDurationHistogramName: "ms", PauseDurationHistogramName: "ms", + SnapshotProcessMemoryDurationName: "ms", + SnapshotProcessRootfsDurationName: "ms", PauseResumePrefetchHarvestDurationName: "ms", PauseResumePrefetchHarvestPagesName: "{page}", UffdStartupPagesHistogramName: "{page}",