microvm tests: record each scenario's duration in a JSON Lines report

.github/workflows/run-nvx-microvm-tests.yml

@@ -1214,3 +1214,15 @@ jobs:
             build/test-results/azurelinux-${{ inputs.backend }}
             build/test-results/aci-edge-sandboxes-${{ inputs.backend }}
           if-no-files-found: warn
+
+      # Each attempt keeps the scenario duration report of every test-microvm
+      # step (doc/usage.md#scenario-duration-report), whether the job passes,
+      # fails, or is cancelled.
+      - name: Upload NVX microVM scenario durations
+        if: always()
+        uses: actions/upload-artifact@v7
+        with:
+          name: nvx-microvm-durations-${{ runner.os }}-${{ inputs.backend }}-${{ inputs.debug-kernel && 'debug' || 'default' }}-${{ github.run_id }}-${{ github.run_attempt }}
+          path: build/test-results/*/scenario-durations.jsonl
+          if-no-files-found: warn
+          retention-days: 30

doc/ci.md

@@ -37,7 +37,12 @@ CLI. Alpine-control-only scenarios remain explicit and are rejected for the
 Ubuntu initramfs. Each job also boots the Azure Linux initramfs through its
 one-vCPU smoke set, under the same time ABI checks; the debug-kernel jobs skip
 it, as they skip the Ubuntu tests. Failure logs from the NVX layer are uploaded
-per backend.
+per backend. Every `nvx-microvm-tests-*` and `nvx-microvm-debug-*` job also
+uploads the [scenario duration report](usage.md#scenario-duration-report) of
+each `test-microvm` step, whether the job passes, fails, or is cancelled, as
+the 30-day `nvx-microvm-durations-<os>-<backend>-<kernel>-<run-id>-<run-attempt>`
+artifact, where `<kernel>` is `default` or `debug`, so that each attempt keeps
+its own.
 Every harness launch, in the tests and the benchmarks, scans the OpenVMM
 console for the guest's [time ABI](design/3.2-clock-and-time.md) output, and the tests
 scan every virtio console they read over TCP the same way, to its end. An

doc/project-structure.md

@@ -137,6 +137,7 @@ nvx/
 |   |   |-- host_telemetry.py    Benchmark host provenance and Windows capture storage telemetry
 |   |   |-- host_time_probe.rs   Host TSC probe that doctor builds and runs
 |   |   |-- managed_exec_tests.py Managed workload environment, directory, and timeout tests
+|   |   |-- microvm_durations.py Scenario duration report of the microVM tests
 |   |   |-- microvm_test_scripts/ Guest workloads for the microVM tests
 |   |   |-- microvm_tests.py     NVX microVM correctness tests
 |   |   |-- nvx_rs.py            Finds, builds, and runs nvx-rs, to which nvx.py delegates

doc/usage.md

@@ -477,6 +477,48 @@ command requires `build/vmlinux` (with `--debug-kernel`, `build/vmlinux-debug`
 and its `build/vmlinux-debug.config`), the selected initramfs, and
 `openvmm/target/release/openvmm[.exe]`.
 
+#### Scenario duration report
+
+`test-microvm` prints each scenario's progress line as the scenario starts,
+so that a log's timestamps follow the scenarios. It also records how long each
+scenario takes in `scenario-durations.jsonl` in `--output-dir`, replacing the
+previous run's report, and [CI](ci.md) uploads the reports of its microVM
+jobs. The report is JSON Lines: one JSON object per line, whose `record` field
+names its kind. The first line, `run`, describes the run:
+
+| Field | Value |
+| --- | --- |
+| `schema`, `schema_version` | `nvx-microvm-durations` and `1`. The version changes only when a reader of the previous version would misread a report, not when a field is added. |
+| `started_at` | When the run and its `setup` started, in UTC, such as `2026-10-21T13:50:00.123Z` |
+| `guest`, `backend` | The `--guest` and the `--backend` |
+| `kernel` | `debug` with `--debug-kernel`, otherwise `default` |
+| `processors` | The `--processors` counts, without repeats |
+| `scenarios` | The selected scenarios |
+| `github` | In GitHub Actions, the job's `repository`, `workflow`, `run_id`, `run_attempt`, `job`, `event_name`, `ref`, `sha`, `runner_name`, and `runner_os`, as strings from the `GITHUB_` and `RUNNER_` variables of those names; otherwise `null` |
+
+Each later line records a span of the run as soon as the span ends, so that a
+run that fails or is interrupted keeps every span that it completed. The spans
+follow one another without gaps, so they add up to the run's time:
+
+- `setup`, from the start of the Python process, or from the report's creation
+  where the OS doesn't report that start, until the first scenario starts;
+- a `scenario` for each scenario execution, until the next one starts.
+  `console-exit`, `smp`, and `smp-lapic` execute once per processor count;
+- `teardown`, which sums up the time ABI evidence and records the run's
+  outcome.
+
+Every span has its `started_at`, its `seconds`, rounded to the millisecond, its
+`outcome`, `passed`, `failed`, or `interrupted`, for example by `SIGINT`, and
+an `error`: for a failure, the exception's type and message, cut to 1,000
+characters, and otherwise `null`. A `scenario` record also has the
+`scenario`, the `guest`, `backend`, and `kernel`, and its `processors`: the
+`--processors` counts that the execution covers, such as `[4]` for `smp` on 4
+vCPUs, the largest count for `time-abi-conformance`, all of them for
+`smp-snapshot` and `restore-processors`, or `null` for a scenario that doesn't
+take them. A failed run ends with the failed scenario's record and the
+`teardown`; a run that is killed keeps every record that it completed and has
+no `teardown`.
+
 ### `doctor`
 
 ```text

scripts/nvx_tools/microvm_durations.py

@@ -0,0 +1,241 @@
+"""The scenario duration report of `nvx.py test-microvm`.
+
+doc/usage.md#scenario-duration-report describes the format.
+"""
+
+from __future__ import annotations
+
+import ctypes
+import json
+import os
+import sys
+import time
+from collections.abc import Callable, Mapping, Sequence
+from datetime import datetime, timezone
+from pathlib import Path
+from types import TracebackType
+from typing import Literal
+
+# The report's name in test-microvm's output directory.
+REPORT_NAME = "scenario-durations.jsonl"
+SCHEMA = "nvx-microvm-durations"
+# Changes only when a reader of the previous version would misread a report;
+# added fields keep it.
+SCHEMA_VERSION = 1
+# The GitHub Actions variables that identify the job that wrote a report,
+# under the names that the report's header gives them.
+GITHUB_VARIABLES = (
+    ("repository", "GITHUB_REPOSITORY"),
+    ("workflow", "GITHUB_WORKFLOW"),
+    ("run_id", "GITHUB_RUN_ID"),
+    ("run_attempt", "GITHUB_RUN_ATTEMPT"),
+    ("job", "GITHUB_JOB"),
+    ("event_name", "GITHUB_EVENT_NAME"),
+    ("ref", "GITHUB_REF"),
+    ("sha", "GITHUB_SHA"),
+    ("runner_name", "RUNNER_NAME"),
+    ("runner_os", "RUNNER_OS"),
+)
+# A record keeps this much of a failure's message; the logs keep all of it.
+ERROR_CHARACTERS = 1000
+# Seconds from the FILETIME epoch, 1601-01-01, to the Unix epoch.
+FILETIME_UNIX_EPOCH_SECONDS = 11_644_473_600
+
+
+def proc_start_seconds(stat: str, ticks_per_second: int) -> float:
+    """Return when a Linux process started, in seconds after boot, from its
+    /proc/PID/stat."""
+    # The fields after the command name, which may hold spaces and
+    # parentheses, start with the 3rd; starttime is the 22nd.
+    return int(stat.rpartition(")")[2].split()[19]) / ticks_per_second
+
+
+def process_age_seconds() -> float | None:
+    """Return how long ago this process started, or None if the OS doesn't
+    tell."""
+    try:
+        if sys.platform == "linux":
+            started = proc_start_seconds(
+                Path("/proc/self/stat").read_text(encoding="utf-8", errors="replace"),
+                os.sysconf("SC_CLK_TCK"),
+            )
+            return time.clock_gettime(time.CLOCK_BOOTTIME) - started
+        if sys.platform == "win32":
+            kernel32 = ctypes.WinDLL("kernel32", use_last_error=True)
+            kernel32.GetCurrentProcess.restype = ctypes.c_void_p
+            filetime = ctypes.POINTER(ctypes.c_uint64)
+            kernel32.GetProcessTimes.argtypes = (
+                ctypes.c_void_p,
+                filetime,
+                filetime,
+                filetime,
+                filetime,
+            )
+            kernel32.GetProcessTimes.restype = ctypes.c_int
+            created, exited, kernel, user = (ctypes.c_uint64() for _ in range(4))
+            if not kernel32.GetProcessTimes(
+                kernel32.GetCurrentProcess(),
+                ctypes.byref(created),
+                ctypes.byref(exited),
+                ctypes.byref(kernel),
+                ctypes.byref(user),
+            ):
+                raise ctypes.WinError(ctypes.get_last_error())
+            # FILETIME counts 100 ns intervals.
+            return time.time() - (
+                created.value / 10_000_000 - FILETIME_UNIX_EPOCH_SECONDS
+            )
+    except (OSError, ValueError, IndexError):
+        pass
+    return None
+
+
+def github_job(environment: Mapping[str, str]) -> dict[str, str | None] | None:
+    """Return the GitHub Actions job that an environment describes, or None
+    outside GitHub Actions."""
+    if environment.get("GITHUB_ACTIONS") != "true":
+        return None
+    return {name: environment.get(variable) for name, variable in GITHUB_VARIABLES}
+
+
+def _outcome(error: BaseException | None) -> str:
+    if error is None:
+        return "passed"
+    return "interrupted" if isinstance(error, KeyboardInterrupt) else "failed"
+
+
+def _error(error: BaseException | None) -> str | None:
+    if error is None or isinstance(error, KeyboardInterrupt):
+        return None
+    message = str(error)
+    name = type(error).__name__
+    return (f"{name}: {message}" if message else name)[:ERROR_CHARACTERS]
+
+
+class DurationReport:
+    """The scenario duration report of one test-microvm run.
+
+    The report is JSON Lines. A header comes first, and then one record for
+    each span of the run, which the report appends as soon as the span ends,
+    so that a run that fails or is interrupted keeps every span that it
+    completed. The spans follow one another without gaps from the start of
+    the process: the setup, one span for each scenario execution, which ends
+    when the next one starts, and the teardown, which finish() starts and
+    which ends with the with block, with the run's outcome.
+    """
+
+    def __init__(
+        self,
+        path: Path,
+        *,
+        backend: str,
+        guest: str,
+        kernel: str,
+        processors: Sequence[int],
+        scenarios: Sequence[str],
+        clock: Callable[[], float] = time.monotonic,
+        wall_clock: Callable[[], float] = time.time,
+        started: float | None = None,
+    ) -> None:
+        """Write the header of a report on a run that started at `started`
+        on `clock`, by default when this process started."""
+        self.path = path
+        self._clock = clock
+        now = clock()
+        # Every timestamp is a reading of `clock` plus this one offset, so
+        # that each span starts exactly where the previous one ended.
+        self._offset = wall_clock() - now
+        if started is None:
+            started = now - max(0.0, process_age_seconds() or 0.0)
+        self._dimensions = {"guest": guest, "backend": backend, "kernel": kernel}
+        self._span: dict[str, object] = {"record": "setup"}
+        self._span_started = started
+        self._write(
+            {
+                "record": "run",
+                "schema": SCHEMA,
+                "schema_version": SCHEMA_VERSION,
+                "started_at": self._timestamp(started),
+                **self._dimensions,
+                "processors": [*dict.fromkeys(processors)],
+                "scenarios": list(scenarios),
+                "github": github_job(os.environ),
+            },
+            mode="w",
+        )
+
+    def start(
+        self,
+        scenario: str,
+        message: str,
+        *,
+        processors: Sequence[int] | None = None,
+    ) -> None:
+        """End the open span, print `message` at once, and time `scenario`,
+        which runs on `processors` if it takes processor counts."""
+        ended = self._end_span(None)
+        self._span = {
+            "record": "scenario",
+            "scenario": scenario,
+            **self._dimensions,
+            "processors": None if processors is None else [*dict.fromkeys(processors)],
+        }
+        self._write(ended)
+        print(message, flush=True)
+
+    def finish(self) -> None:
+        """End the last scenario, or the setup if none ran, and start the
+        teardown."""
+        ended = self._end_span(None)
+        self._span = {"record": "teardown"}
+        self._write(ended)
+
+    def __enter__(self) -> DurationReport:
+        return self
+
+    def __exit__(
+        self,
+        kind: type[BaseException] | None,
+        error: BaseException | None,
+        traceback: TracebackType | None,
+    ) -> None:
+        """End the open span, and then the teardown, with the run's outcome."""
+        try:
+            if self._span["record"] != "teardown":
+                # The span that raised `error`, or the last scenario if
+                # finish() was not called.
+                ended = self._end_span(error)
+                self._span = {"record": "teardown"}
+                self._write(ended)
+            self._write(self._end_span(error))
+        except OSError as failure:
+            if error is None:
+                raise
+            # Keep the run's own error; the report then lacks its end.
+            print(
+                f"warning: could not complete {self.path}: {failure}",
+                file=sys.stderr,
+                flush=True,
+            )
+
+    def _end_span(self, error: BaseException | None) -> dict[str, object]:
+        now = self._clock()
+        record = {
+            **self._span,
+            "started_at": self._timestamp(self._span_started),
+            "seconds": round(now - self._span_started, 3),
+            "outcome": _outcome(error),
+            "error": _error(error),
+        }
+        self._span_started = now
+        return record
+
+    def _timestamp(self, value: float) -> str:
+        moment = datetime.fromtimestamp(self._offset + value, timezone.utc)
+        return moment.isoformat(timespec="milliseconds").replace("+00:00", "Z")
+
+    def _write(
+        self, record: Mapping[str, object], mode: Literal["a", "w"] = "a"
+    ) -> None:
+        with self.path.open(mode, encoding="utf-8", newline="\n") as stream:
+            stream.write(json.dumps(record, separators=(",", ":")) + "\n")