From 9e5ce5324e6b0436341b141efb471941da6076ec Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 21 Oct 2026 11:16:54 -0300 Subject: [PATCH 1/3] microvm tests: flush each scenario's progress line test-microvm announces each scenario with a "Running ..." line on stdout, which Python buffers in blocks when it writes to a pipe, as on the CI runners. The lines therefore reached the job log in bursts. In run 39585909588, the WHP log received the default suite's 41 progress lines in two: 16 when the managed-lifecycle scenario flushed its Cargo command, 2 minutes 24 seconds into the step, and the other 25 when the process exited, 7 minutes 39 seconds later. The log's timestamps could not attribute the suite's 10 minutes to its scenarios. Print each progress line with flush=True, as the benchmarks print theirs, so that it reaches the log when its scenario starts. A test runs every scenario with stubs, each of which requires that stdout has flushed everything printed so far, its own progress line last. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- scripts/nvx_tools/microvm_tests.py | 148 +++++++++++++++++++++-------- scripts/test_microvm_tests.py | 67 +++++++++++++ 2 files changed, 177 insertions(+), 38 deletions(-) diff --git a/scripts/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index 81fc0656a..f3573319a 100644 --- a/scripts/nvx_tools/microvm_tests.py +++ b/scripts/nvx_tools/microvm_tests.py @@ -7556,7 +7556,8 @@ def run(args: argparse.Namespace) -> int: if "guest-boot" in scenarios: print( f"Running {descriptor.distribution} initramfs boot correctness " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_guest_boot( executable, @@ -7571,7 +7572,8 @@ def run(args: argparse.Namespace) -> int: if "guest-identity" in scenarios: print( f"Running {descriptor.distribution} identity correctness " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_guest_identity( executable, @@ -7587,7 +7589,8 @@ def run(args: argparse.Namespace) -> int: for processors in dict.fromkeys(args.processors): print( f"Running microVM console exit correctness ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_console_exit( executable, @@ -7600,7 +7603,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "console-snapshot" in scenarios: - print(f"Running microVM console snapshot correctness on OpenVMM/{args.backend}") + print( + f"Running microVM console snapshot correctness on OpenVMM/{args.backend}", + flush=True, + ) run_console_snapshot( executable, kernel, @@ -7613,7 +7619,8 @@ def run(args: argparse.Namespace) -> int: if "cpu-profile-fallback" in scenarios: print( "Running microVM CPU profile fallback correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", + flush=True, ) run_cpu_profile_fallback( executable, @@ -7627,7 +7634,8 @@ def run(args: argparse.Namespace) -> int: if "endpoint-policy-snapshot" in scenarios: print( "Running microVM endpoint-policy snapshot correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", + flush=True, ) run_endpoint_policy_snapshot( executable, @@ -7641,7 +7649,8 @@ def run(args: argparse.Namespace) -> int: if "filesystem-shares" in scenarios: print( "Running read-write, read-only, and hidden-root microVM shares " - f"through one aggregate on OpenVMM/{args.backend}" + f"through one aggregate on OpenVMM/{args.backend}", + flush=True, ) run_filesystem_shares( executable, @@ -7655,7 +7664,8 @@ def run(args: argparse.Namespace) -> int: if "filesystem-policy" in scenarios: print( "Running microVM share write narrowing and read masking " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_filesystem_policy( executable, @@ -7669,7 +7679,8 @@ def run(args: argparse.Namespace) -> int: if "filesystem-comma-paths" in scenarios: print( "Running public nvx.py shares of host paths with commas " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_filesystem_comma_paths( args.backend, @@ -7680,7 +7691,8 @@ def run(args: argparse.Namespace) -> int: ) if "filesystem-snapshot" in scenarios: print( - f"Running microVM filesystem snapshot correctness on OpenVMM/{args.backend}" + f"Running microVM filesystem snapshot correctness on OpenVMM/{args.backend}", + flush=True, ) run_filesystem_snapshot( executable, @@ -7692,7 +7704,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "lifecycle" in scenarios: - print(f"Running microVM lifecycle correctness on OpenVMM/{args.backend}") + print( + f"Running microVM lifecycle correctness on OpenVMM/{args.backend}", + flush=True, + ) run_lifecycle( executable, kernel, @@ -7704,7 +7719,8 @@ def run(args: argparse.Namespace) -> int: ) if "workload-identity" in scenarios: print( - f"Running microVM workload identity correctness on OpenVMM/{args.backend}" + f"Running microVM workload identity correctness on OpenVMM/{args.backend}", + flush=True, ) run_workload_identity( executable, @@ -7717,16 +7733,22 @@ def run(args: argparse.Namespace) -> int: ) if "managed-exec-config" in scenarios: print( - f"Running public managed execution configuration on OpenVMM/{args.backend}" + f"Running public managed execution configuration on OpenVMM/{args.backend}", + flush=True, ) run_managed_exec_configuration( args.backend, timeout=args.timeout, output_dir=output_dir ) if "sandbox-lifecycle" in scenarios: - print(f"Running public managed sandbox lifecycle on OpenVMM/{args.backend}") + print( + f"Running public managed sandbox lifecycle on OpenVMM/{args.backend}", + flush=True, + ) run_sandbox_lifecycle(args.backend, timeout=args.timeout, output_dir=output_dir) if "managed-lifecycle" in scenarios: - print(f"Running managed microVM lifecycle on OpenVMM/{args.backend}") + print( + f"Running managed microVM lifecycle on OpenVMM/{args.backend}", flush=True + ) run_managed_lifecycle( executable, kernel, @@ -7737,7 +7759,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "structured-outcome" in scenarios: - print(f"Running structured microVM outcomes on OpenVMM/{args.backend}") + print( + f"Running structured microVM outcomes on OpenVMM/{args.backend}", flush=True + ) run_structured_outcome( executable, kernel, @@ -7750,7 +7774,8 @@ def run(args: argparse.Namespace) -> int: if "l3-l4-egress-policy" in scenarios: print( "Running public nvx.py L3/L4 egress policy acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_l3_l4_egress_policy( executable, @@ -7765,7 +7790,8 @@ def run(args: argparse.Namespace) -> int: if "l3-l4-egress-protocols" in scenarios: print( "Running public nvx.py L3/L4 egress protocol acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_l3_l4_egress_protocols( executable, @@ -7780,7 +7806,8 @@ def run(args: argparse.Namespace) -> int: if "l3-l4-egress-port-ranges" in scenarios: print( "Running public nvx.py L3/L4 egress port-range acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_l3_l4_egress_port_ranges( executable, @@ -7795,7 +7822,8 @@ def run(args: argparse.Namespace) -> int: if "ipv6-egress-policy" in scenarios: print( "Running public nvx.py IPv6 egress policy acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_ipv6_egress_policy( executable, @@ -7808,7 +7836,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "host-loopback-policy" in scenarios: - print(f"Running microVM host-loopback policy on OpenVMM/{args.backend}") + print( + f"Running microVM host-loopback policy on OpenVMM/{args.backend}", + flush=True, + ) run_host_loopback_policy( executable, kernel, @@ -7819,7 +7850,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "private-network-ingress" in scenarios: - print(f"Running microVM private-network ingress on OpenVMM/{args.backend}") + print( + f"Running microVM private-network ingress on OpenVMM/{args.backend}", + flush=True, + ) run_private_network_ingress( executable, kernel, @@ -7830,7 +7864,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "denied-filesystem-paths" in scenarios: - print(f"Running microVM denied filesystem paths on OpenVMM/{args.backend}") + print( + f"Running microVM denied filesystem paths on OpenVMM/{args.backend}", + flush=True, + ) run_denied_filesystem_paths( executable, kernel, @@ -7841,7 +7878,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-owner" in scenarios: - print(f"Running microVM filesystem caller ownership on OpenVMM/{args.backend}") + print( + f"Running microVM filesystem caller ownership on OpenVMM/{args.backend}", + flush=True, + ) run_filesystem_owner( executable, kernel, @@ -7852,7 +7892,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "network-snapshot" in scenarios: - print(f"Running microVM network snapshot correctness on OpenVMM/{args.backend}") + print( + f"Running microVM network snapshot correctness on OpenVMM/{args.backend}", + flush=True, + ) run_network_snapshot( executable, kernel, @@ -7868,7 +7911,8 @@ def run(args: argparse.Namespace) -> int: for processors in dict.fromkeys(args.processors): print( f"Running microVM {scenario} correctness ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_smp( executable, @@ -7882,7 +7926,10 @@ def run(args: argparse.Namespace) -> int: counting_lapic=counting_lapic, ) if "sandbox-blocks" in scenarios: - print(f"Running microVM sandbox-block correctness on OpenVMM/{args.backend}") + print( + f"Running microVM sandbox-block correctness on OpenVMM/{args.backend}", + flush=True, + ) run_sandbox_blocks( executable, kernel, @@ -7893,7 +7940,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "sandbox-blocks.log", ) if "scratch-snapshot" in scenarios: - print(f"Running microVM scratch snapshot correctness on OpenVMM/{args.backend}") + print( + f"Running microVM scratch snapshot correctness on OpenVMM/{args.backend}", + flush=True, + ) run_scratch_snapshot( executable, kernel, @@ -7904,7 +7954,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "smp-snapshot" in scenarios: - print(f"Running microVM SMP snapshot correctness on OpenVMM/{args.backend}") + print( + f"Running microVM SMP snapshot correctness on OpenVMM/{args.backend}", + flush=True, + ) run_smp_snapshot( executable, kernel, @@ -7917,7 +7970,8 @@ def run(args: argparse.Namespace) -> int: ) if "restore-processors" in scenarios: print( - f"Running microVM restore-processor correctness on OpenVMM/{args.backend}" + f"Running microVM restore-processor correctness on OpenVMM/{args.backend}", + flush=True, ) run_restore_processors( executable, @@ -7932,7 +7986,8 @@ def run(args: argparse.Namespace) -> int: if "restore-downtime" in scenarios: print( "Running microVM long-downtime restore correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", + flush=True, ) run_restore_downtime( executable, @@ -7944,7 +7999,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-memory" in scenarios: - print(f"Running microVM restore-memory correctness on OpenVMM/{args.backend}") + print( + f"Running microVM restore-memory correctness on OpenVMM/{args.backend}", + flush=True, + ) run_restore_memory( executable, kernel, @@ -7954,7 +8012,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-core" in scenarios: - print(f"Running microVM snapshot-core correctness on OpenVMM/{args.backend}") + print( + f"Running microVM snapshot-core correctness on OpenVMM/{args.backend}", + flush=True, + ) run_snapshot_core( executable, kernel, @@ -7965,7 +8026,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-tiers" in scenarios: - print(f"Running microVM snapshot-tier correctness on OpenVMM/{args.backend}") + print( + f"Running microVM snapshot-tier correctness on OpenVMM/{args.backend}", + flush=True, + ) run_snapshot_tiers( executable, kernel, @@ -7976,7 +8040,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "directional-network-policy" in scenarios: - print(f"Running microVM directional network policy on OpenVMM/{args.backend}") + print( + f"Running microVM directional network policy on OpenVMM/{args.backend}", + flush=True, + ) run_directional_network_policy( executable, kernel, @@ -7990,7 +8057,8 @@ def run(args: argparse.Namespace) -> int: processors = max(args.processors) print( f"Running microVM time ABI conformance ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_time_abi_conformance( executable, @@ -8003,7 +8071,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "time-abi-conformance.log", ) if "virtio-net" in scenarios: - print(f"Running microVM virtio-net correctness on OpenVMM/{args.backend}") + print( + f"Running microVM virtio-net correctness on OpenVMM/{args.backend}", + flush=True, + ) run_virtio_net( executable, kernel, @@ -8016,7 +8087,8 @@ def run(args: argparse.Namespace) -> int: if "command-line-limit" in scenarios: print( "Running a microVM kernel command line at the guest kernel's limit " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + flush=True, ) run_command_line_limit( executable, diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index dbb7a8421..e7ec11ae3 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -109,6 +109,16 @@ def _restore_target(command: list[str]) -> int | None: return int(command[command.index("--restore-processors") + 1]) +def _scenario_runners() -> list[str]: + """Return the names of the microVM test module's run_* functions, among + them every scenario function that its runner calls.""" + return [ + name + for name, value in vars(microvm_tests).items() + if name.startswith("run_") and callable(value) + ] + + # OpenVMM's warning of a cold boot whose --cpu-profile auto falls back to a # host profile (openvmm_core's time_abi host_profile_warning), on stderr. FALLBACK_WARNING = ( @@ -9878,6 +9888,63 @@ def require(path: Path, _description: str) -> Path: self.assertEqual(microvm_tests.run(args), 0) self.assertEqual([call.args[4] for call in run.call_args_list], [1, 2, 4, 8]) + def test_runner_flushes_each_progress_line_before_its_scenario(self): + # CI timestamps each log line when it leaves the process, so every + # scenario's progress line must leave stdout's buffer before the + # scenario starts (#694). + class FlushRecorder(io.StringIO): + flushed = "" + + def flush(self) -> None: + super().flush() + self.flushed = self.getvalue() + + def require(path: Path, _description: str) -> Path: + return path + + stdout = FlushRecorder() + progress: list[str] = [] + + def scenario(*_args: object, **_kwargs: object) -> None: + self.assertEqual(stdout.flushed, stdout.getvalue()) + progress.append(stdout.flushed.splitlines()[-1]) + + scenarios = ( + *microvm_tests.MICROVM_TEST_SCENARIOS, + *microvm_tests.MICROVM_EXPLICIT_SCENARIOS, + ) + with tempfile.TemporaryDirectory() as temporary, ExitStack() as stack: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "kvm", + *(f"--scenario={scenario}" for scenario in scenarios), + "--processors", + "1", + "2", + "--output-dir", + temporary, + ] + ) + stack.enter_context( + patch.object(microvm_tests, "validate_openvmm_test_backend") + ) + stack.enter_context( + patch.object(microvm_tests, "require_file", side_effect=require) + ) + for name in _scenario_runners(): + stack.enter_context( + patch.object(microvm_tests, name, side_effect=scenario) + ) + stack.enter_context(redirect_stdout(stdout)) + self.assertEqual(microvm_tests.run(args), 0) + + # console-exit, smp, and smp-lapic run once per processor count. + self.assertEqual(len(progress), len(scenarios) + 3) + for line in progress: + self.assertRegex(line, r"^Running .+ on OpenVMM/kvm$") + def test_guest_runner_persists_full_output_on_failure(self): class FakeProcess: pid = 123 From dcb7f8e843ddd8856b297f16efc8856117584790 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 21 Oct 2026 11:31:32 -0300 Subject: [PATCH 2/3] microvm tests: record each scenario's duration in a JSON Lines report test-microvm timed nothing finer than the CI step that ran it: in run 39585909588, the default Alpine suite took 603 seconds on WHP and 459 on KVM, with no breakdown by scenario. Sharding the suite by duration (#696) needs each scenario's own time. Write scenario-durations.jsonl into --output-dir. A header names the schema and its version, and the run's start, guest, backend, kernel type, processor counts, selected scenarios, and, in GitHub Actions, the run and job. One record per span of the run follows, appended as soon as the span ends, so that a run that fails, is interrupted, or is killed keeps every span that it completed. The spans follow one another without gaps from the start of the Python process, which Linux reports in /proc/self/stat and Windows through GetProcessTimes: the setup, until the first scenario starts; one span per scenario execution; and the teardown, which sums up the time ABI evidence and records the run's outcome. They therefore add up to the command's time, with the suite's setup apart from the scenarios. Each scenario record names its scenario, guest, backend, kernel type, and the processor counts that it covers, with its start, its duration, and its outcome: passed, failed with the error, or interrupted. The dispatch moves into _run_scenarios, which runs inside the report's with block, and each scenario starts its span by printing its progress line through the report, which still flushes it. The report has a module of its own, microvm_durations.py, whose names a later aggregation can share. Tests drive the report with fake clocks through the spans' contiguity, timestamps, and appends, failures and interruptions in a scenario and in the setup, the replacement of an earlier report, and a report that cannot end without masking the run's error, and check the GitHub identity and the process start on Linux and Windows. Through the runner, they check one record per execution of every scenario with its processor counts, and the records that precede a failed scenario. doc/usage.md describes the format. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/project-structure.md | 1 + doc/usage.md | 41 +++ scripts/nvx_tools/microvm_durations.py | 241 +++++++++++++++ scripts/nvx_tools/microvm_tests.py | 218 +++++++------ scripts/test_microvm_tests.py | 412 +++++++++++++++++++++++++ 5 files changed, 826 insertions(+), 87 deletions(-) create mode 100644 scripts/nvx_tools/microvm_durations.py diff --git a/doc/project-structure.md b/doc/project-structure.md index f22c3914f..d07e656c2 100644 --- a/doc/project-structure.md +++ b/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 diff --git a/doc/usage.md b/doc/usage.md index 7e3e62765..25d8d9675 100644 --- a/doc/usage.md +++ b/doc/usage.md @@ -477,6 +477,47 @@ 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. 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 diff --git a/scripts/nvx_tools/microvm_durations.py b/scripts/nvx_tools/microvm_durations.py new file mode 100644 index 000000000..0d933d777 --- /dev/null +++ b/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") diff --git a/scripts/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index f3573319a..3b04ebbb2 100644 --- a/scripts/nvx_tools/microvm_tests.py +++ b/scripts/nvx_tools/microvm_tests.py @@ -20,7 +20,7 @@ import threading import time import uuid -from collections.abc import Callable, Sequence +from collections.abc import Callable, Collection, Sequence from contextlib import ExitStack, suppress from dataclasses import dataclass from pathlib import Path @@ -65,6 +65,7 @@ ) from .guests import GUEST_NAMES, GuestDescriptor, guest_descriptor from .managed_exec_tests import run_managed_exec_configuration +from .microvm_durations import REPORT_NAME, DurationReport from .nvx_rs import EgressRules, compile_egress_policy from .openvmm_process import OpenvmmProcess, TcpConsole from .sandbox_lifecycle_tests import run_sandbox_lifecycle @@ -409,7 +410,10 @@ def configure_parser(parser: argparse.ArgumentParser) -> None: "--output-dir", type=Path, default=BuildConstants.BUILD_DIR / "test-results" / "microvm", - help="directory for complete per-scenario OpenVMM logs", + help=( + "directory for complete per-scenario OpenVMM logs and the scenario " + "duration report" + ), ) parser.set_defaults(handler=run) @@ -7553,11 +7557,53 @@ def run(args: argparse.Namespace) -> int: + ", ".join(sorted(unsupported)) ) + with DurationReport( + output_dir / REPORT_NAME, + backend=args.backend, + guest=descriptor.name, + kernel="debug" if debug_kernel else "default", + processors=args.processors, + scenarios=scenarios, + ) as report: + _run_scenarios( + report, + args, + scenarios, + descriptor=descriptor, + executable=executable, + kernel=kernel, + initrd=initrd, + output_dir=output_dir, + ) + report.finish() + report_time_abi_evidence( + output_dir, + backend=args.backend, + guest=descriptor.name, + debug_kernel=debug_kernel, + ) + print(f"Wrote microVM correctness logs to {output_dir}") + return 0 + + +def _run_scenarios( + report: DurationReport, + args: argparse.Namespace, + scenarios: Collection[str], + *, + descriptor: GuestDescriptor, + executable: Path, + kernel: Path, + initrd: Path, + output_dir: Path, +) -> None: + """Run the selected scenarios in their fixed order, and time each + execution in `report`.""" if "guest-boot" in scenarios: - print( + report.start( + "guest-boot", f"Running {descriptor.distribution} initramfs boot correctness " f"on OpenVMM/{args.backend}", - flush=True, ) run_guest_boot( executable, @@ -7570,10 +7616,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / f"{descriptor.name}-guest-boot.log", ) if "guest-identity" in scenarios: - print( + report.start( + "guest-identity", f"Running {descriptor.distribution} identity correctness " f"on OpenVMM/{args.backend}", - flush=True, ) run_guest_identity( executable, @@ -7587,10 +7633,11 @@ def run(args: argparse.Namespace) -> int: ) if "console-exit" in scenarios: for processors in dict.fromkeys(args.processors): - print( + report.start( + "console-exit", f"Running microVM console exit correctness ({processors} vCPU) " f"on OpenVMM/{args.backend}", - flush=True, + processors=[processors], ) run_console_exit( executable, @@ -7603,9 +7650,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "console-snapshot" in scenarios: - print( + report.start( + "console-snapshot", f"Running microVM console snapshot correctness on OpenVMM/{args.backend}", - flush=True, ) run_console_snapshot( executable, @@ -7617,10 +7664,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "cpu-profile-fallback" in scenarios: - print( + report.start( + "cpu-profile-fallback", "Running microVM CPU profile fallback correctness on " f"OpenVMM/{args.backend}", - flush=True, ) run_cpu_profile_fallback( executable, @@ -7632,10 +7679,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "endpoint-policy-snapshot" in scenarios: - print( + report.start( + "endpoint-policy-snapshot", "Running microVM endpoint-policy snapshot correctness on " f"OpenVMM/{args.backend}", - flush=True, ) run_endpoint_policy_snapshot( executable, @@ -7647,10 +7694,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-shares" in scenarios: - print( + report.start( + "filesystem-shares", "Running read-write, read-only, and hidden-root microVM shares " f"through one aggregate on OpenVMM/{args.backend}", - flush=True, ) run_filesystem_shares( executable, @@ -7662,10 +7709,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-policy" in scenarios: - print( + report.start( + "filesystem-policy", "Running microVM share write narrowing and read masking " f"on OpenVMM/{args.backend}", - flush=True, ) run_filesystem_policy( executable, @@ -7677,10 +7724,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-comma-paths" in scenarios: - print( + report.start( + "filesystem-comma-paths", "Running public nvx.py shares of host paths with commas " f"on OpenVMM/{args.backend}", - flush=True, ) run_filesystem_comma_paths( args.backend, @@ -7690,9 +7737,9 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "filesystem-snapshot" in scenarios: - print( + report.start( + "filesystem-snapshot", f"Running microVM filesystem snapshot correctness on OpenVMM/{args.backend}", - flush=True, ) run_filesystem_snapshot( executable, @@ -7704,9 +7751,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "lifecycle" in scenarios: - print( + report.start( + "lifecycle", f"Running microVM lifecycle correctness on OpenVMM/{args.backend}", - flush=True, ) run_lifecycle( executable, @@ -7718,9 +7765,9 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "lifecycle.log", ) if "workload-identity" in scenarios: - print( + report.start( + "workload-identity", f"Running microVM workload identity correctness on OpenVMM/{args.backend}", - flush=True, ) run_workload_identity( executable, @@ -7732,22 +7779,23 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "managed-exec-config" in scenarios: - print( + report.start( + "managed-exec-config", f"Running public managed execution configuration on OpenVMM/{args.backend}", - flush=True, ) run_managed_exec_configuration( args.backend, timeout=args.timeout, output_dir=output_dir ) if "sandbox-lifecycle" in scenarios: - print( + report.start( + "sandbox-lifecycle", f"Running public managed sandbox lifecycle on OpenVMM/{args.backend}", - flush=True, ) run_sandbox_lifecycle(args.backend, timeout=args.timeout, output_dir=output_dir) if "managed-lifecycle" in scenarios: - print( - f"Running managed microVM lifecycle on OpenVMM/{args.backend}", flush=True + report.start( + "managed-lifecycle", + f"Running managed microVM lifecycle on OpenVMM/{args.backend}", ) run_managed_lifecycle( executable, @@ -7759,8 +7807,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "structured-outcome" in scenarios: - print( - f"Running structured microVM outcomes on OpenVMM/{args.backend}", flush=True + report.start( + "structured-outcome", + f"Running structured microVM outcomes on OpenVMM/{args.backend}", ) run_structured_outcome( executable, @@ -7772,10 +7821,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "l3-l4-egress-policy" in scenarios: - print( + report.start( + "l3-l4-egress-policy", "Running public nvx.py L3/L4 egress policy acceptance " f"on OpenVMM/{args.backend}", - flush=True, ) run_l3_l4_egress_policy( executable, @@ -7788,10 +7837,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "l3-l4-egress-protocols" in scenarios: - print( + report.start( + "l3-l4-egress-protocols", "Running public nvx.py L3/L4 egress protocol acceptance " f"on OpenVMM/{args.backend}", - flush=True, ) run_l3_l4_egress_protocols( executable, @@ -7804,10 +7853,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "l3-l4-egress-port-ranges" in scenarios: - print( + report.start( + "l3-l4-egress-port-ranges", "Running public nvx.py L3/L4 egress port-range acceptance " f"on OpenVMM/{args.backend}", - flush=True, ) run_l3_l4_egress_port_ranges( executable, @@ -7820,10 +7869,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "ipv6-egress-policy" in scenarios: - print( + report.start( + "ipv6-egress-policy", "Running public nvx.py IPv6 egress policy acceptance " f"on OpenVMM/{args.backend}", - flush=True, ) run_ipv6_egress_policy( executable, @@ -7836,9 +7885,9 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "host-loopback-policy" in scenarios: - print( + report.start( + "host-loopback-policy", f"Running microVM host-loopback policy on OpenVMM/{args.backend}", - flush=True, ) run_host_loopback_policy( executable, @@ -7850,9 +7899,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "private-network-ingress" in scenarios: - print( + report.start( + "private-network-ingress", f"Running microVM private-network ingress on OpenVMM/{args.backend}", - flush=True, ) run_private_network_ingress( executable, @@ -7864,9 +7913,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "denied-filesystem-paths" in scenarios: - print( + report.start( + "denied-filesystem-paths", f"Running microVM denied filesystem paths on OpenVMM/{args.backend}", - flush=True, ) run_denied_filesystem_paths( executable, @@ -7878,9 +7927,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-owner" in scenarios: - print( + report.start( + "filesystem-owner", f"Running microVM filesystem caller ownership on OpenVMM/{args.backend}", - flush=True, ) run_filesystem_owner( executable, @@ -7892,9 +7941,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "network-snapshot" in scenarios: - print( + report.start( + "network-snapshot", f"Running microVM network snapshot correctness on OpenVMM/{args.backend}", - flush=True, ) run_network_snapshot( executable, @@ -7909,10 +7958,11 @@ def run(args: argparse.Namespace) -> int: if scenario not in scenarios: continue for processors in dict.fromkeys(args.processors): - print( + report.start( + scenario, f"Running microVM {scenario} correctness ({processors} vCPU) " f"on OpenVMM/{args.backend}", - flush=True, + processors=[processors], ) run_smp( executable, @@ -7926,9 +7976,9 @@ def run(args: argparse.Namespace) -> int: counting_lapic=counting_lapic, ) if "sandbox-blocks" in scenarios: - print( + report.start( + "sandbox-blocks", f"Running microVM sandbox-block correctness on OpenVMM/{args.backend}", - flush=True, ) run_sandbox_blocks( executable, @@ -7940,9 +7990,9 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "sandbox-blocks.log", ) if "scratch-snapshot" in scenarios: - print( + report.start( + "scratch-snapshot", f"Running microVM scratch snapshot correctness on OpenVMM/{args.backend}", - flush=True, ) run_scratch_snapshot( executable, @@ -7954,9 +8004,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "smp-snapshot" in scenarios: - print( + report.start( + "smp-snapshot", f"Running microVM SMP snapshot correctness on OpenVMM/{args.backend}", - flush=True, + processors=args.processors, ) run_smp_snapshot( executable, @@ -7969,9 +8020,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-processors" in scenarios: - print( + report.start( + "restore-processors", f"Running microVM restore-processor correctness on OpenVMM/{args.backend}", - flush=True, + processors=args.processors, ) run_restore_processors( executable, @@ -7984,10 +8036,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-downtime" in scenarios: - print( + report.start( + "restore-downtime", "Running microVM long-downtime restore correctness on " f"OpenVMM/{args.backend}", - flush=True, ) run_restore_downtime( executable, @@ -7999,9 +8051,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-memory" in scenarios: - print( + report.start( + "restore-memory", f"Running microVM restore-memory correctness on OpenVMM/{args.backend}", - flush=True, ) run_restore_memory( executable, @@ -8012,9 +8064,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-core" in scenarios: - print( + report.start( + "snapshot-core", f"Running microVM snapshot-core correctness on OpenVMM/{args.backend}", - flush=True, ) run_snapshot_core( executable, @@ -8026,9 +8078,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-tiers" in scenarios: - print( + report.start( + "snapshot-tiers", f"Running microVM snapshot-tier correctness on OpenVMM/{args.backend}", - flush=True, ) run_snapshot_tiers( executable, @@ -8040,9 +8092,9 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "directional-network-policy" in scenarios: - print( + report.start( + "directional-network-policy", f"Running microVM directional network policy on OpenVMM/{args.backend}", - flush=True, ) run_directional_network_policy( executable, @@ -8055,10 +8107,11 @@ def run(args: argparse.Namespace) -> int: ) if "time-abi-conformance" in scenarios: processors = max(args.processors) - print( + report.start( + "time-abi-conformance", f"Running microVM time ABI conformance ({processors} vCPU) " f"on OpenVMM/{args.backend}", - flush=True, + processors=[processors], ) run_time_abi_conformance( executable, @@ -8071,9 +8124,9 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "time-abi-conformance.log", ) if "virtio-net" in scenarios: - print( + report.start( + "virtio-net", f"Running microVM virtio-net correctness on OpenVMM/{args.backend}", - flush=True, ) run_virtio_net( executable, @@ -8085,10 +8138,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "virtio-net.log", ) if "command-line-limit" in scenarios: - print( + report.start( + "command-line-limit", "Running a microVM kernel command line at the guest kernel's limit " f"on OpenVMM/{args.backend}", - flush=True, ) run_command_line_limit( executable, @@ -8099,12 +8152,3 @@ def run(args: argparse.Namespace) -> int: timeout=args.timeout, output_dir=output_dir, ) - - report_time_abi_evidence( - output_dir, - backend=args.backend, - guest=descriptor.name, - debug_kernel=debug_kernel, - ) - print(f"Wrote microVM correctness logs to {output_dir}") - return 0 diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index e7ec11ae3..5ffbae90d 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -8,6 +8,7 @@ import inspect import io import ipaddress +import itertools import json import os import queue @@ -22,6 +23,7 @@ import unittest from collections.abc import Callable, Collection from contextlib import ExitStack, nullcontext, redirect_stdout +from datetime import datetime from pathlib import Path from typing import Any, cast from unittest.mock import MagicMock, patch @@ -33,6 +35,7 @@ benchmark, common, managed_exec_tests, + microvm_durations, microvm_tests, nvx_rs, openvmm_process, @@ -43,6 +46,9 @@ BuildConstants, ) +# When this process loaded the tests, on the monotonic clock. +_LOADED = time.monotonic() + def _compile(policy: dict[str, object]) -> nvx_rs.EgressRules: """Compiles an egress policy with nvx-rs, as nvx.py run compiles its @@ -119,6 +125,11 @@ def _scenario_runners() -> list[str]: ] +def _read_report(path: Path) -> list[dict[str, Any]]: + """Return the records of a scenario duration report, in order.""" + return [json.loads(line) for line in path.read_text(encoding="utf-8").splitlines()] + + # OpenVMM's warning of a cold boot whose --cpu-profile auto falls back to a # host profile (openvmm_core's time_abi host_profile_warning), on stderr. FALLBACK_WARNING = ( @@ -9816,6 +9827,11 @@ def require(path: Path, _description: str) -> Path: with self.subTest(scenario=scenario): run.assert_called() self.assertEqual(run.call_args.args[1], build / "vmlinux-debug") + header = _read_report(build / "logs" / microvm_durations.REPORT_NAME)[0] + self.assertEqual( + (header["kernel"], header["scenarios"]), + ("debug", list(microvm_tests.DEBUG_KERNEL_SCENARIOS)), + ) config.write_text("CONFIG_DETECT_HUNG_TASK=y\n", encoding="utf-8") with self.assertRaisesRegex( common.ScriptError, "lacks CONFIG_SOFTLOCKUP_DETECTOR=y" @@ -9945,6 +9961,137 @@ def scenario(*_args: object, **_kwargs: object) -> None: for line in progress: self.assertRegex(line, r"^Running .+ on OpenVMM/kvm$") + def test_runner_reports_every_scenario_execution(self): + def require(path: Path, _description: str) -> Path: + return path + + scenarios = ( + *microvm_tests.MICROVM_TEST_SCENARIOS, + *microvm_tests.MICROVM_EXPLICIT_SCENARIOS, + ) + with tempfile.TemporaryDirectory() as temporary, ExitStack() as stack: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "whp", + *(f"--scenario={scenario}" for scenario in scenarios), + "--processors", + "2", + "1", + "2", + "--output-dir", + temporary, + ] + ) + stack.enter_context( + patch.object(microvm_tests, "validate_openvmm_test_backend") + ) + stack.enter_context( + patch.object(microvm_tests, "require_file", side_effect=require) + ) + for name in _scenario_runners(): + stack.enter_context(patch.object(microvm_tests, name)) + stack.enter_context(redirect_stdout(io.StringIO())) + self.assertEqual(microvm_tests.run(args), 0) + records = _read_report(Path(temporary) / microvm_durations.REPORT_NAME) + + header, setup, *executions, teardown = records + self.assertEqual(header["record"], "run") + self.assertEqual( + (header["guest"], header["backend"], header["kernel"]), + ("alpine", "whp", "default"), + ) + self.assertEqual(header["processors"], [2, 1]) + self.assertEqual(header["scenarios"], list(scenarios)) + self.assertEqual((setup["record"], setup["outcome"]), ("setup", "passed")) + self.assertEqual( + (teardown["record"], teardown["outcome"]), ("teardown", "passed") + ) + # Each execution names the processor counts that it covers, if any. + expected: list[tuple[str, list[int] | None]] = [] + for scenario in scenarios: + if scenario in ("console-exit", "smp", "smp-lapic"): + expected.extend((scenario, [processors]) for processors in (2, 1)) + elif scenario in ("smp-snapshot", "restore-processors"): + expected.append((scenario, [2, 1])) + elif scenario == "time-abi-conformance": + expected.append((scenario, [2])) + else: + expected.append((scenario, None)) + self.assertCountEqual( + [(record["scenario"], record["processors"]) for record in executions], + expected, + ) + for record in executions: + self.assertEqual( + (record["record"], record["guest"], record["backend"]), + ("scenario", "alpine", "whp"), + ) + self.assertEqual( + (record["kernel"], record["outcome"], record["error"]), + ("default", "passed", None), + ) + # The spans follow one another, so they add up to the run's time. + for record, following in itertools.pairwise(records[1:]): + started = datetime.fromisoformat(record["started_at"][:-1]) + ended = datetime.fromisoformat(following["started_at"][:-1]) + self.assertAlmostEqual( + (ended - started).total_seconds(), record["seconds"], delta=0.002 + ) + + def test_runner_report_keeps_the_executions_before_a_failure(self): + def require(path: Path, _description: str) -> Path: + return path + + with tempfile.TemporaryDirectory() as temporary: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "mshv", + "--scenario", + "virtio-net", + "--scenario", + "lifecycle", + "--output-dir", + temporary, + ] + ) + with ( + patch.object(microvm_tests, "validate_openvmm_test_backend"), + patch.object(microvm_tests, "require_file", side_effect=require), + patch.object(microvm_tests, "run_lifecycle"), + patch.object( + microvm_tests, + "run_virtio_net", + side_effect=RuntimeError("no virtio-net marker"), + ), + redirect_stdout(io.StringIO()), + self.assertRaisesRegex(RuntimeError, "no virtio-net marker"), + ): + microvm_tests.run(args) + records = _read_report(Path(temporary) / microvm_durations.REPORT_NAME) + + error = "RuntimeError: no virtio-net marker" + self.assertEqual( + [ + (record["record"], record.get("scenario"), record.get("outcome")) + for record in records + ], + [ + ("run", None, None), + ("setup", None, "passed"), + ("scenario", "lifecycle", "passed"), + ("scenario", "virtio-net", "failed"), + ("teardown", None, "failed"), + ], + ) + self.assertEqual( + [record.get("error") for record in records], + [None, None, None, error, error], + ) + def test_guest_runner_persists_full_output_on_failure(self): class FakeProcess: pid = 123 @@ -9991,5 +10138,270 @@ def close(self) -> None: self.assertEqual(log_path.read_bytes(), b"complete raw output\n") +class DurationReportTests(unittest.TestCase): + # 2027-01-15T08:00:00Z on the wall clock, which the tests' monotonic + # clock reads as 100. + EPOCH = 1_800_000_000.0 + GITHUB = { + "GITHUB_ACTIONS": "true", + "GITHUB_REPOSITORY": "microsoft/nvx", + "GITHUB_WORKFLOW": "CI", + "GITHUB_RUN_ID": "39585909588", + "GITHUB_RUN_ATTEMPT": "2", + "GITHUB_JOB": "test", + "GITHUB_EVENT_NAME": "pull_request", + "GITHUB_REF": "refs/pull/694/merge", + "GITHUB_SHA": "919a774c6" + "0" * 31, + "RUNNER_NAME": "azure-kvm-2", + "RUNNER_OS": "Linux", + } + + def _report( + self, path: Path, readings: list[float] + ) -> microvm_durations.DurationReport: + """Open a report on a run that started at 100 on a clock that + returns `readings`, the first when the report opens.""" + return microvm_durations.DurationReport( + path, + backend="kvm", + guest="alpine", + kernel="debug", + processors=[1, 8, 1], + scenarios=("smp", "lifecycle"), + clock=iter(readings).__next__, + wall_clock=lambda: self.EPOCH + readings[0] - 100, + started=100.0, + ) + + def test_spans_cover_the_run_from_the_process_start_without_gaps(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + written: list[int] = [] + with ( + patch.dict(os.environ, self.GITHUB), + redirect_stdout(io.StringIO()) as stdout, + ): + with self._report(path, [101.5, 102, 105.25, 110, 110.5]) as report: + # Each record is on disk as soon as its span ends. + written.append(len(_read_report(path))) + report.start("smp", "Running smp", processors=[8, 8]) + written.append(len(_read_report(path))) + report.start("lifecycle", "Running lifecycle") + written.append(len(_read_report(path))) + report.finish() + written.append(len(_read_report(path))) + records = _read_report(path) + raw = path.read_bytes() + + self.assertEqual(written, [1, 2, 3, 4]) + self.assertNotIn(b"\r", raw) + self.assertEqual(stdout.getvalue(), "Running smp\nRunning lifecycle\n") + dimensions = {"guest": "alpine", "backend": "kvm", "kernel": "debug"} + passed = {"outcome": "passed", "error": None} + self.assertEqual( + records, + [ + { + "record": "run", + "schema": "nvx-microvm-durations", + "schema_version": 1, + "started_at": "2027-01-15T08:00:00.000Z", + **dimensions, + "processors": [1, 8], + "scenarios": ["smp", "lifecycle"], + "github": { + "repository": "microsoft/nvx", + "workflow": "CI", + "run_id": "39585909588", + "run_attempt": "2", + "job": "test", + "event_name": "pull_request", + "ref": "refs/pull/694/merge", + "sha": self.GITHUB["GITHUB_SHA"], + "runner_name": "azure-kvm-2", + "runner_os": "Linux", + }, + }, + { + "record": "setup", + "started_at": "2027-01-15T08:00:00.000Z", + "seconds": 2.0, + **passed, + }, + { + "record": "scenario", + "scenario": "smp", + **dimensions, + "processors": [8], + "started_at": "2027-01-15T08:00:02.000Z", + "seconds": 3.25, + **passed, + }, + { + "record": "scenario", + "scenario": "lifecycle", + **dimensions, + "processors": None, + "started_at": "2027-01-15T08:00:05.250Z", + "seconds": 4.75, + **passed, + }, + { + "record": "teardown", + "started_at": "2027-01-15T08:00:10.000Z", + "seconds": 0.5, + **passed, + }, + ], + ) + self.assertEqual(sum(record["seconds"] for record in records[1:]), 10.5) + + def test_a_failure_ends_its_scenario_and_the_run(self): + for error, outcome, message in ( + (RuntimeError("no marker\nin the log"), "failed", None), + (TimeoutError(), "failed", "TimeoutError"), + (RuntimeError("x" * 5000), "failed", "RuntimeError: " + "x" * 986), + (KeyboardInterrupt(), "interrupted", None), + ): + with ( + self.subTest(error=type(error).__name__), + tempfile.TemporaryDirectory() as temporary, + ): + path = Path(temporary) / microvm_durations.REPORT_NAME + with ( + redirect_stdout(io.StringIO()), + self.assertRaises(type(error)) as raised, + self._report(path, [101, 102, 103, 104, 105]) as report, + ): + report.start("smp", "Running smp", processors=[1]) + report.start("lifecycle", "Running lifecycle") + raise error + records = _read_report(path) + self.assertIs(raised.exception, error) + if message is None and outcome == "failed": + message = f"RuntimeError: {error}" + self.assertEqual( + [ + (record["record"], record.get("scenario"), record["seconds"]) + for record in records[1:] + ], + [ + ("setup", None, 2), + ("scenario", "smp", 1), + ("scenario", "lifecycle", 1), + ("teardown", None, 1), + ], + ) + self.assertEqual( + [(record["outcome"], record["error"]) for record in records[1:]], + [ + ("passed", None), + ("passed", None), + (outcome, message), + (outcome, message), + ], + ) + self.assertLessEqual( + len(records[-1]["error"] or ""), + microvm_durations.ERROR_CHARACTERS, + ) + + def test_a_failure_before_the_first_scenario_ends_the_setup(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + with ( + self.assertRaisesRegex(ValueError, "no counts"), + self._report(path, [101, 102, 103]), + ): + raise ValueError("no counts") + records = _read_report(path) + self.assertEqual( + [ + (record["record"], record["seconds"], record["outcome"]) + for record in records[1:] + ], + [("setup", 2, "failed"), ("teardown", 1, "failed")], + ) + + def test_a_run_without_scenarios_has_only_setup_and_teardown(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + with self._report(path, [101, 102, 103]) as report: + report.finish() + records = _read_report(path) + self.assertEqual( + [ + (record["record"], record["seconds"], record["outcome"]) + for record in records[1:] + ], + [("setup", 2, "passed"), ("teardown", 1, "passed")], + ) + + def test_a_report_replaces_the_previous_runs_report(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + path.write_text('{"record":"stale"}\n' * 3, encoding="utf-8") + with self._report(path, [101, 102, 103]) as report: + report.finish() + records = _read_report(path) + self.assertEqual( + [record["record"] for record in records], ["run", "setup", "teardown"] + ) + + def test_a_report_that_cannot_end_keeps_the_runs_own_error(self): + with tempfile.TemporaryDirectory() as temporary: + directory = Path(temporary) / "logs" + directory.mkdir() + path = directory / microvm_durations.REPORT_NAME + with ( + redirect_stdout(io.StringIO()), + patch("sys.stderr", new_callable=io.StringIO) as stderr, + self.assertRaisesRegex(RuntimeError, "no marker"), + self._report(path, [101, 102, 103, 104]) as report, + ): + report.start("smp", "Running smp") + shutil.rmtree(directory) + raise RuntimeError("no marker") + self.assertIn(f"warning: could not complete {path}: ", stderr.getvalue()) + # Without an error of the run's own, the report's error stands. + directory.mkdir() + with ( + self.assertRaises(OSError), + self._report(path, [101, 102]), + ): + shutil.rmtree(directory) + + def test_github_identifies_the_job_only_in_github_actions(self): + self.assertIsNone(microvm_durations.github_job({})) + self.assertIsNone( + microvm_durations.github_job({**self.GITHUB, "GITHUB_ACTIONS": "false"}) + ) + self.assertEqual( + microvm_durations.github_job( + {"GITHUB_ACTIONS": "true", "GITHUB_RUN_ID": "39585909588"} + ), + { + name: "39585909588" if name == "run_id" else None + for name, _ in microvm_durations.GITHUB_VARIABLES + }, + ) + + def test_proc_start_follows_any_command_name(self): + # The command name may hold spaces and parentheses; starttime is the + # 22nd field. + fields = ["S", *map(str, range(4, 22)), "4321", *["0"] * 30] + stat = "1234 (nvx) (python 3) " + " ".join(fields) + "\n" + self.assertEqual(microvm_durations.proc_start_seconds(stat, 100), 43.21) + + @unittest.skipUnless(sys.platform in ("linux", "win32"), "needs Linux or Windows") + def test_process_age_counts_from_the_process_start(self): + loaded = time.monotonic() - _LOADED + age = microvm_durations.process_age_seconds() + assert age is not None + # The process started before it loaded the tests, and not long ago. + self.assertGreaterEqual(age, loaded) + self.assertLess(age, 24 * 3600) + + if __name__ == "__main__": unittest.main() From a904264bce16d2c3eefbb8521bc02d91f1dbf792 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Wed, 21 Oct 2026 11:39:44 -0300 Subject: [PATCH 3/3] ci: upload the scenario duration reports of every microVM job The microVM workflow uploaded its test results only when a job failed, so a passing run kept no record of where its time went, and the duration reports that test-microvm now writes would stay behind on the runners. Sharding the default suite by scenario duration (#696) needs them from many runs, passing or not. Add one step to the reusable workflow, which every microVM job runs, the debug-kernel ones too. It uploads the report of each test-microvm step, build/test-results/*/scenario-durations.jsonl, whether the job passes, fails, or is cancelled, as the 30-day artifact nvx-microvm-durations-----, whose name differs for every job and attempt, so that each attempt keeps its own reports. The failure-log upload stays as it was. A test pins the step's condition and path, checks that the path's pattern finds the report of every test-microvm step and that the name differs for each of the six jobs that call the workflow and each attempt, and keeps the failure-log upload to failures. doc/ci.md describes the upload, and doc/usage.md points to it. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .github/workflows/run-nvx-microvm-tests.yml | 12 ++++ doc/ci.md | 7 +- doc/usage.md | 5 +- scripts/test_nvx_tools.py | 77 +++++++++++++++++++++ 4 files changed, 98 insertions(+), 3 deletions(-) diff --git a/.github/workflows/run-nvx-microvm-tests.yml b/.github/workflows/run-nvx-microvm-tests.yml index 7bc311d93..10a8241f1 100644 --- a/.github/workflows/run-nvx-microvm-tests.yml +++ b/.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 diff --git a/doc/ci.md b/doc/ci.md index 45f0102af..988e178ed 100644 --- a/doc/ci.md +++ b/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-----` +artifact, where `` 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 diff --git a/doc/usage.md b/doc/usage.md index 25d8d9675..f0709ec42 100644 --- a/doc/usage.md +++ b/doc/usage.md @@ -482,8 +482,9 @@ and its `build/vmlinux-debug.config`), the selected initramfs, and `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. The report is JSON Lines: one JSON object per line, -whose `record` field names its kind. The first line, `run`, describes the run: +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 | | --- | --- | diff --git a/scripts/test_nvx_tools.py b/scripts/test_nvx_tools.py index 7a553f8c4..79c1e0a89 100644 --- a/scripts/test_nvx_tools.py +++ b/scripts/test_nvx_tools.py @@ -53,6 +53,7 @@ elf, guest_binaries, guests, + microvm_durations, nvx_rs, release, sandbox, @@ -7430,6 +7431,82 @@ def test_ci_runs_the_public_sandbox_acceptance_on_every_backend(self): ) self.assertIn("build/test-results/public-exec-${{ inputs.backend }}", upload) + def test_every_microvm_job_uploads_its_scenario_durations(self): + # Each microVM job, the debug-kernel ones too, keeps the duration + # report of every test-microvm step whether it passes, fails, or is + # cancelled, under a name of its own in each attempt (#694). + workflows = BuildConstants.REPO_ROOT / ".github" / "workflows" + steps = { + step["name"]: step + for step in yaml.safe_load( + (workflows / "run-nvx-microvm-tests.yml").read_text(encoding="utf-8") + )["jobs"]["test"]["steps"] + } + upload = steps["Upload NVX microVM scenario durations"] + self.assertEqual(upload["if"], "always()") + self.assertEqual(upload["uses"], "actions/upload-artifact@v7") + self.assertEqual( + upload["with"]["path"], + f"build/test-results/*/{microvm_durations.REPORT_NAME}", + ) + # The path's pattern finds the report of every test-microvm step. + microvm_runs = [ + step["run"] + for step in steps.values() + if "nvx.py test-microvm" in step.get("run", "") + ] + self.assertTrue(microvm_runs) + for run in microvm_runs: + with self.subTest(run=run): + self.assertEqual( + len(re.findall(r'--output-dir "build/test-results/[^"/*]+"', run)), + 1, + ) + # The failure logs keep their upload, only when a step fails. + self.assertEqual(steps["Upload NVX microVM failure logs"]["if"], "failure()") + + kernel = "${{ inputs.debug-kernel && 'debug' || 'default' }}" + name = upload["with"]["name"] + self.assertEqual( + name, + "nvx-microvm-durations-${{ runner.os }}-${{ inputs.backend }}-" + + kernel + + "-${{ github.run_id }}-${{ github.run_attempt }}", + ) + jobs = { + job_name: job["with"] + for job_name, job in yaml.safe_load( + (workflows / "ci.yml").read_text(encoding="utf-8") + )["jobs"].items() + if job.get("uses") == "./.github/workflows/run-nvx-microvm-tests.yml" + } + self.assertEqual( + set(jobs), + { + *ci.REQUIRED_CI_MICROVM_TEST_JOBS, + *ci.REQUIRED_CI_MICROVM_DEBUG_JOBS, + *ci.REQUIRED_CI_MICROVM_DEBUG_PUSH_JOBS, + }, + ) + artifacts: set[str] = set() + for job_name, inputs in jobs.items(): + system = "Windows" if "windows" in json.loads(inputs["runner"]) else "Linux" + debug = inputs.get("debug-kernel", False) is True + for attempt in (1, 2): + artifact = ( + name.replace("${{ runner.os }}", system) + .replace("${{ inputs.backend }}", inputs["backend"]) + .replace(kernel, "debug" if debug else "default") + .replace("${{ github.run_id }}", "39585909588") + .replace("${{ github.run_attempt }}", str(attempt)) + ) + with self.subTest(job=job_name, attempt=attempt): + self.assertNotIn("${{", artifact) + self.assertNotIn(artifact, artifacts) + artifacts.add(artifact) + self.assertIn("nvx-microvm-durations-Linux-kvm-debug-39585909588-2", artifacts) + self.assertEqual(len(artifacts), 2 * len(jobs)) + @unittest.skipUnless(os.name == "nt", "requires Windows PowerShell") def test_windows_cli_validation_stops_at_each_failed_command(self): action = (