benchmarking/analysis: aggregate suspend/resume phase breakdown log r…

CONTRIBUTING.md

@@ -31,7 +31,9 @@ The [Quickstart (Development)](README.md#quickstart-development) in the README
 covers bringing up a local cluster with the default (gVisor) runtime. To run
 the microVM runtime locally — which needs `/dev/kvm`, or Lima nested
 virtualization on Apple Silicon — see
-[docs/dev/microvm-local.md](docs/dev/microvm-local.md).
+[docs/dev/microvm-local.md](docs/dev/microvm-local.md). To measure where a
+suspend or resume spends its time on such a cluster, follow
+[docs/dev/suspend-resume-phase-breakdown.md](docs/dev/suspend-resume-phase-breakdown.md).
 
 ## Contribution process
 

benchmarking/README.md

@@ -207,6 +207,16 @@ The Kubernetes API is not required. If it is unreachable, or discovery was
 skipped, the affected fields are written as `null` and the run still
 succeeds. A `null` means the value was not measured. It never means zero.
 
+## Suspend/resume phase breakdown
+
+`SuspendActor` and `ResumeActor` latency can be attributed to the phases
+inside them (object-storage transfer, hypervisor snapshot/restore, rootfs
+assembly, ...) from the structured log records atelet and ateom-microvm
+emit. `analysis/collect_logs.sh` dumps the node logs of a run and
+`analysis/phase_report.py` aggregates them into per-phase percentiles and
+waterfalls of the slowest operations. See
+[analysis/README.md](analysis/README.md).
+
 ## Optional: Prometheus + Grafana
 
 Locust provides graphs, statistics, etc. via the UI. However, you
@@ -241,3 +251,10 @@ repository root:
 ```bash
 python3 -m unittest discover -s benchmarking/locust/unit_tests
 ```
+
+`analysis/test_phase_report.py` covers the phase-log report's parser and
+aggregation:
+
+```bash
+python3 -m unittest discover -s benchmarking/analysis
+```

benchmarking/analysis/README.md

@@ -0,0 +1,114 @@
+# Suspend/resume phase analysis
+
+This directory turns the node side's developer-facing timing logs into the
+percentiles a benchmark run needs, without making the phases metric API. The
+`ate.actor.{restore,checkpoint}.duration` histograms stop at
+`ateom_restore` / `ateom_checkpoint` / `persist` / `download` on purpose:
+phases inside those are implementation details of a runtime, and metrics are
+a contract. The finer breakdown is emitted as structured log records instead,
+and this is the consumer that aggregates them.
+
+Two joinable JSON log records feed it, each written by both layers:
+
+| record (`msg`) | emitter | keys |
+|---|---|---|
+| `Restore timing breakdown` | atelet and ateom-microvm | `ate.actor.restore.duration.<phase>` / `ateom.actor.restore.duration.<phase>` |
+| `Checkpoint timing breakdown` | atelet and ateom-microvm | `ate.actor.checkpoint.duration.<phase>` / `ateom.actor.checkpoint.duration.<phase>` |
+
+Every record carries the full actor identity (`ate.actor.uid`, name,
+atespace, template) and the snapshot scope, which the histograms are barred
+from, so records join per actor and per operation. Durations are float
+seconds, the histograms' unit. A phase that never ran is absent, not zero.
+A failed atelet operation still writes its record, marked with `error.type`
+(the gRPC code); the report excludes those from the percentiles.
+
+## Making a measurement
+
+1. Run a suspend/resume-heavy load (e.g. the `glutton` or `sweperf` user
+   class; see `../README.md`).
+2. Dump the node logs for the run's window while the pods still exist.
+   `automation/orchestrator.py` deletes the workload and ate-system pods right
+   after each test, and does not call this script yet, so run it before that
+   teardown (or against a cluster you manage yourself):
+
+   ```bash
+   ./collect_logs.sh --dest /tmp/run1 --since-time 2026-09-24T18:00:00Z
+   ```
+
+   The script sources `.ate-dev-env.sh` from the repository root when present
+   (set `NO_DEV_ENV` to skip) and honors `KUBECTL_CONTEXT`, like the `hack/`
+   scripts. `--since-time` (or a relative `--since 30m`) should cover the run
+   and nothing before it. `--namespace` (default `ate-system`) selects the
+   atelet pods and `--worker-namespace` (default `benchmark-workloads`) the
+   worker pods; the ateom records land in the worker pod's stdout. `kubectl logs`
+   returns only a container's current log file, so on a long or busy run
+   kubelet's rotation can drop earlier records — collect soon after the run.
+   A container that restarted mid-run is dumped twice (`<pod>.previous.log`).
+
+   On GKE the same records are in Cloud Logging, which keeps them past
+   rotation and teardown; an export is accepted as input directly, instead of
+   the kubectl dumps:
+
+   ```bash
+   gcloud logging read '(jsonPayload.msg="Checkpoint timing breakdown" OR jsonPayload.msg="Restore timing breakdown") AND resource.labels.cluster_name="<cluster>" AND timestamp>="2026-09-24T18:00:00Z"' \
+     --project <project> --format json > /tmp/run1/export.json
+   ```
+
+3. Aggregate, from the kubectl dumps:
+
+   ```bash
+   python3 phase_report.py /tmp/run1/*.log --csv /tmp/run1/report
+   ```
+
+   or from the Cloud Logging export:
+
+   ```bash
+   python3 phase_report.py /tmp/run1/export.json --csv /tmp/run1/report
+   ```
+
+   Use one source per run: the dumps and an export of the same pods hold the
+   same records, and passing both would count each twice.
+
+## Reading the report
+
+**Phase percentiles.** Per layer, operation, sandbox class, snapshot kind,
+scope and phase: count, p50, p90, p95 and max. A `golden` restore downloads
+the golden image and a `latest` one the actor's own, so they are separate
+rows, as are gVisor and micro-VM checkpoints. The atelet rows split a checkpoint between
+`sandbox_assets`, `ateom_checkpoint` and `persist`, and a restore between
+`volume_mount`, `manifest_fetch`, `sandbox_assets`, `download`, `oci_unpack`
+and `ateom_restore`. The ateom rows split the `ateom_*` phase further:
+`prep` / `pause` / `snapshot` / `durable_dir` / `rootfs_upper` / `teardown`
+for a checkpoint, `prep` / `bundles` / `upper_join` / `lowers` / `tap` /
+`vmm_launch` / `vm_restore` / `resume` / `wakeup_probe` for a restore.
+
+Concurrency matters when reading them: the atelet restore phases overlap
+(the download runs alongside the asset fetch and OCI unpack), the three
+ateom checkpoint captures run concurrently on the paused guest (the paused
+window costs their max), and the ateom restore phases are sequential. For
+the two checkpoint layers the report derives an `unattributed` row: the total
+minus what the logged phases account for, counting the concurrent captures
+once. It is the time the instrumentation does not yet name. The ateom
+records carry no snapshot kind of their own; a paired one takes its kind from
+the atelet record, so both layers split into the same rows.
+
+**Waterfalls.** The slowest operations, with the ateom record of the same
+actor nested under the atelet `ateom_*` phase and that phase's gap to the
+ateom total (RPC and queueing between the layers). The ateom record is the
+one written inside that phase's window (for a checkpoint, before `persist`
+began), and each ateom record pairs with at most one operation, so an
+operation whose own record is missing prints without one rather than with
+another cycle's. Failed operations (`error.type` set) are left out of both
+the percentiles and the waterfalls. Tail outliers that blow up in one phase
+every time are systematic; different phases each time are environmental.
+
+`--csv` also writes `phase_percentiles.csv` for run-over-run comparison.
+
+The parser is deliberately tolerant: it scans any line for a JSON object and
+matches on `msg`, so raw `kubectl logs` dumps (even with prefixes) work.
+
+## Tests
+
+```bash
+python3 -m unittest discover -s benchmarking/analysis
+```

benchmarking/analysis/collect_logs.sh

@@ -0,0 +1,107 @@
+#!/usr/bin/env bash
+# Copyright 2026 Google LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+# Dump the node-side logs a benchmark run needs for phase_report.py: every
+# atelet pod (the atelet-side timing breakdowns) and every worker pod
+# (ateom-microvm writes its records to the worker pod's stdout). Point
+# --since-time (RFC 3339) or --since at the run's start so the report covers
+# exactly one run.
+#
+# kubectl logs returns only a container's current log file: once kubelet
+# rotates it under load, earlier records are gone, so collect soon after the
+# run. A container that restarted mid-run is dumped twice, its previous log
+# under <pod>.previous.log. On GKE, Cloud Logging keeps every record past
+# rotation and teardown; phase_report.py reads `gcloud logging read
+# --format json` output directly.
+#
+# Like the other hack scripts, this sources .ate-dev-env.sh from the repo root
+# for the cluster settings unless NO_DEV_ENV is set, and respects
+# KUBECTL_CONTEXT.
+#
+# Usage: collect_logs.sh --dest DIR [--since 30m | --since-time 2026-09-24T18:00:00Z]
+#                        [--namespace ate-system] [--worker-namespace benchmark-workloads]
+
+set -uo pipefail
+
+ROOT="$(git rev-parse --show-toplevel 2>/dev/null || pwd)"
+if [[ -r "${ROOT}/.ate-dev-env.sh" ]] && [[ -z "${NO_DEV_ENV:-}" ]]; then
+  # shellcheck source=/dev/null
+  source "${ROOT}/.ate-dev-env.sh"
+fi
+run_kubectl() { kubectl ${KUBECTL_CONTEXT:+--context=${KUBECTL_CONTEXT}} "$@"; }
+
+DEST=""
+SINCE="1h"
+SINCE_TIME=""
+NAMESPACE="ate-system"
+WORKER_NAMESPACE="benchmark-workloads"
+
+while [[ $# -gt 0 ]]; do
+  case "$1" in
+    --dest) DEST="$2"; shift 2 ;;
+    --since) SINCE="$2"; shift 2 ;;
+    --since-time) SINCE_TIME="$2"; shift 2 ;;
+    --namespace) NAMESPACE="$2"; shift 2 ;;
+    --worker-namespace) WORKER_NAMESPACE="$2"; shift 2 ;;
+    *) echo "unknown flag: $1" >&2; exit 2 ;;
+  esac
+done
+
+if [[ -z "${DEST}" ]]; then
+  echo "usage: $0 --dest DIR [--since 30m | --since-time RFC3339] [--namespace ate-system] [--worker-namespace benchmark-workloads]" >&2
+  exit 2
+fi
+mkdir -p "${DEST}"
+
+if [[ -n "${SINCE_TIME}" ]]; then
+  WINDOW=(--since-time="${SINCE_TIME}")
+else
+  WINDOW=(--since="${SINCE}")
+fi
+
+# One pod that cannot be read (still starting, evicted) must not cost the
+# others, so every kubectl call warns and moves on rather than aborting.
+collect() {
+  local ns="$1" selector="$2"
+  local pods
+  if ! pods=$(run_kubectl get pods -n "${ns}" -l "${selector}" -o name); then
+    echo "warn: could not list pods in ${ns} (${selector}); skipping" >&2
+    return 0
+  fi
+  for pod in ${pods}; do
+    local name="${pod#pod/}"
+    echo "collecting ${ns}/${name} (${WINDOW[*]})"
+    run_kubectl logs -n "${ns}" "${name}" "${WINDOW[@]}" --timestamps=false \
+      > "${DEST}/${ns}-${name}.log" \
+      || { echo "warn: kubectl logs ${ns}/${name} failed; skipping" >&2; rm -f "${DEST}/${ns}-${name}.log"; }
+    # --previous is only valid after a restart; kubectl rejects it otherwise.
+    local restarts
+    restarts=$(run_kubectl get pod -n "${ns}" "${name}" \
+      -o jsonpath='{.status.containerStatuses[0].restartCount}' 2>/dev/null || echo 0)
+    if [[ "${restarts:-0}" -gt 0 ]]; then
+      echo "collecting ${ns}/${name} previous container (${restarts} restarts)"
+      run_kubectl logs -n "${ns}" "${name}" --previous "${WINDOW[@]}" --timestamps=false \
+        > "${DEST}/${ns}-${name}.previous.log" \
+        || { echo "warn: kubectl logs --previous ${ns}/${name} failed; skipping" >&2; rm -f "${DEST}/${ns}-${name}.previous.log"; }
+    fi
+  done
+}
+
+collect "${NAMESPACE}" "app=atelet"
+# Worker pods carry the pool label whatever the pool's name is.
+collect "${WORKER_NAMESPACE}" "ate.dev/worker-pool"
+
+echo "logs in ${DEST}; next:"
+echo "  python3 benchmarking/analysis/phase_report.py ${DEST}/*.log"