[Pedro Henrique Penna (ppenna)]

Closes #694.
Part of #430.

Summary

test-microvm now flushes each scenario's progress line, and writes scenario-durations.jsonl, a JSON Lines report of how long each scenario execution takes, into its --output-dir, appending each record as soon as its span ends. Every microVM job, the debug-kernel ones included, uploads the reports of its test-microvm steps whether it passes, fails, or is cancelled, so that #696 can shard the default suite by measured duration.

Why

• test-microvm printed its Running ... lines through block-buffered stdout. In the WHP job of reference run 39585909588, the default suite's 41 progress lines reached the log in two bursts: 16 at 2 min 24 s, when managed-lifecycle flushed its Cargo command, and the other 25 when the process exited, 7 min 39 s later. The suite's 603 s on WHP and 459 s on KVM had no finer breakdown.
• The workflow uploaded test results only when a job failed, so passing runs kept no timing at all.
• ci: shard the default microVM suite by scenario duration #696 needs per-scenario durations, keyed by scenario, guest, backend, kernel type, and processor count, from several runs.

Changes

1. microvm tests: flush each scenario's progress line: the 38 Running ... prints of run(), one per scenario, pass flush=True, as the benchmarks' progress lines do.
2. microvm tests: record each scenario's duration in a JSON Lines report:
   • a new module, scripts/nvx_tools/microvm_durations.py, holds DurationReport. run() keeps its setup and opens the report around the dispatch, which moves unchanged into _run_scenarios(); each scenario starts its span with report.start(scenario, progress line, processors=...), which writes the previous span's record and then prints the progress line, flushed;
   • the format, which doc/usage.md documents under "Scenario duration report":
     • a run header: schema nvx-microvm-durations, schema_version 1, started_at, guest, backend, kernel (default or debug), the processors counts, the selected scenarios, and github, the job's repository, workflow, run ID and attempt, job, event, ref, SHA, runner name, and runner OS, or null outside GitHub Actions;
     • then one record per span, which follow one another without gaps and so add up to the command's time: setup, from the Python process's start (/proc/self/stat on Linux, GetProcessTimes on Windows) until the first scenario, one scenario per execution, and teardown, which sums up the time ABI evidence and carries the run's outcome;
     • every span has started_at, seconds, outcome (passed, failed, or interrupted), and error; a scenario record also has scenario, guest, backend, kernel, and processors: the counts that the execution covers, such as [4] for smp on 4 vCPUs, all of them for smp-snapshot and restore-processors, or null for a scenario that takes none;
   • each record is appended, and the file closed, as soon as its span ends, so a failed, interrupted, or killed run keeps every record it completed. A run that fails ends with the failed scenario and a failed teardown; a killed run has no teardown.
3. ci: upload the scenario duration reports of every microVM job: one if: always() step at the end of run-nvx-microvm-tests.yml, which all six microVM jobs run, uploads build/test-results/*/scenario-durations.jsonl as nvx-microvm-durations-<os>-<backend>-<kernel>-<run-id>-<run-attempt>, kept 30 days. The failure-log upload is unchanged.

A report looks like this, cut to a few lines:

{"record":"run","schema":"nvx-microvm-durations","schema_version":1,"started_at":"2026-10-21T14:21:02.007Z","guest":"alpine","backend":"whp","kernel":"default","processors":[1,2,4,8],"scenarios":["console-exit","...","workload-identity"],"github":{"repository":"microsoft/nvx","workflow":"CI","run_id":"...","run_attempt":"1","job":"test","event_name":"pull_request","ref":"refs/pull/.../merge","sha":"...","runner_name":"azure-windows-6","runner_os":"Windows"}}
{"record":"setup","started_at":"2026-10-21T14:21:02.007Z","seconds":0.812,"outcome":"passed","error":null}
{"record":"scenario","scenario":"guest-boot","guest":"alpine","backend":"whp","kernel":"default","processors":null,"started_at":"2026-10-21T14:21:02.819Z","seconds":3.215,"outcome":"passed","error":null}
{"record":"scenario","scenario":"console-exit","guest":"alpine","backend":"whp","kernel":"default","processors":[1],"started_at":"2026-10-21T14:21:06.034Z","seconds":5.902,"outcome":"passed","error":null}
{"record":"teardown","started_at":"2026-10-21T14:31:41.951Z","seconds":0.204,"outcome":"passed","error":null}

Decisions

• Setup and execution. The issue asks for setup and execution durations. Each scenario function interleaves its host preparation, such as images, shares, and policies, with its guest runs, and no two scenarios share preparation, so a scenario's span is its whole cost: what a shard pays to run it. Splitting it would mean restructuring all 39 scenarios. The suite-level setup, the interpreter's start, imports, and artifact checks before the first scenario, and the teardown after the last are spans of their own, so the scenario records plus the setup and teardown account for the command's time.
• Schema stability for ci: shard the default microVM suite by scenario duration #696. Entries carry their own dimensions, so they aggregate without joining the header; the header carries the run's identity and start. schema_version changes only when a reader of version 1 would misread a report.

Interactions with other pull requests

• openvmm: refuse kernel command lines that the guest kernel would truncate #661 (merged) added the command-line-limit scenario to the default suite. This branch is rebased onto it: the first commit flushes its progress line, and in the second it starts its own span, so the report records it like every other scenario. The runner tests enumerate MICROVM_TEST_SCENARIOS, so they cover it, and they fail if it isn't recorded.
• ci: run the guest and sandbox steps beside the default microVM suite #706 (ci: run the guest smoke and sandbox steps in a job beside the default microVM suite #695, open) splits each backend's microVM job in two through a guests-and-sandboxes input. Both jobs would then run this upload step under the same artifact name, and the second upload would fail. Whichever of the two merges second must add ${{ inputs.guests-and-sandboxes && '-guests' || '' }} to the artifact name, as ci: run the guest and sandbox steps beside the default microVM suite #706 does for its failure logs, and extend test_every_microvm_job_uploads_its_scenario_durations to the new jobs.
• nvx-rs: add the VMM supervisor with a spawn allowlist, stop, and reattach #656, nvx-rs: hold the guest port permission for one transaction at a time #662, nvx-rs: parse legacy egress rules with the MXC form's helpers #682, ci: key the guest images and VMM tests on the guest binaries' sources #710, ci: link the Windows OpenVMM test builds with /Brepro for sccache #714, and ci: run the Linux OpenVMM unit tests on a GitHub-hosted runner #717 (merged) don't interact with this change. The rebase resolved only openvmm: refuse kernel command lines that the guest kernel would truncate #661's conflict in microvm_tests.py, and nvx-rs: hold the guest port permission for one transaction at a time #662, which merged after it, merges cleanly.
• ci: shard the default microVM suite by scenario duration #696 (blocked on ci: record each microVM scenario's duration in a machine-readable report #694) will read these reports; their schema is version 1.

Tests

• scripts/test_microvm_tests.py:
  • every scenario, stubbed, finds its progress line flushed and nothing else left in stdout's buffer;
  • through the runner: one record per execution of every scenario with its processor counts, contiguous spans, the header's selection, the debug kernel's kernel, and the records kept before a failed scenario;
  • DurationReport with fake clocks: exact spans, timestamps, and sums, each record on disk as soon as its span ends, LF line ends, failures (also with an empty or a 5,000-character message), interruptions, a failure before the first scenario, a run without scenarios, replacement of an earlier report, and a report that cannot be completed without masking the run's own error;
  • the GitHub identity, the /proc/PID/stat parser with a command name that holds spaces and parentheses, and the process age on Linux and Windows.
• scripts/test_nvx_tools.py: the upload step's condition and path, that its pattern finds the report of every test-microvm step, that its name differs for each of the six jobs that call the workflow and each attempt, and that the failure-log upload still runs only on failure.
• Seeded regressions fail the tests: a missing flush, a misnamed scenario, a dropped processor count, a failure-only upload, a name without the attempt, and a nested output directory.

Validation

• Windows, Python 3.14, on this branch rebased onto f2b4a11ef:
  • test_nvx_tools (490 tests) passes;
  • test_microvm_tests (222 tests) passes, apart from test_host_loopback_allow_script_checks_publication_and_traffic, whose Git for Windows sh runs exceeded their 10-second timeout while other jobs loaded the host; it passes on its own, and this PR doesn't touch it. The module also passes at each of the first two commits, with the same exception;
  • test_performance, test_guest_binaries, test_development_release, test_host_telemetry, test_time_abi, test_tool_versions, test_markdown_links, test_adversarial, and test_hosts pass, as do compileall and every --help check of validate-nvx;
  • test_setup_azure, which runs the Linux setup scripts, fails on this host on dev too, and this PR doesn't touch it;
  • ruff check, ruff format --check, pyright for Linux and Windows, check_markdown_links.py, and git diff --check pass.
• WSL Ubuntu, Python 3.14: the new and changed test_microvm_tests tests pass, including the process age from /proc/self/stat.
• actionlint 1.7.7 (release binary, checksum verified): run-nvx-microvm-tests.yml and ci.yml are clean; the only finding across the workflows is the existing unknown runner label in adversarial.yml.
• CI, run 39666359892 on a904264bc: every check passes; the MSHV and WHP debug-kernel jobs, both OpenVMM suites, the release, and performance persistence skip, as pull requests and these inputs expect. The KVM, MSHV, and WHP microVM jobs and the KVM debug-kernel job each uploaded a report for every test-microvm step, 14 in all, whose spans account for each step's time within 0.04 s on Linux and 0.48 s on Windows, where Windows PowerShell starts before Python and exits after it. Each default-suite report records 42 executions, command-line-limit among them. Run 39619765285 on f12c2cf57, before the rebase, gave the same results. #694 has the per-step accounting and the per-scenario durations of both runs.
• Trial merge with dev at c6ea9e27d, after nvx-rs: hold the guest port permission for one transaction at a time #662 changed run_snapshot_core: git merge-tree reports no conflict, and test_microvm_tests (223 tests) passes on the merged tree.

Expected effect

• Each scenario's progress line reaches the CI log when the scenario starts.
• Every microVM job uploads a small report per test-microvm step, with per-scenario durations for ci: shard the default microVM suite by scenario duration #696 to aggregate across runs.
• No scenario, guest, backend, kernel type, or processor count changes; the report adds about one file write per scenario.

Post-merge verification

• The MSHV and WHP debug-kernel jobs, which pull requests skip, upload their reports on the first dev push.

[Copilot]

🟢 Approval recommended

No blocking issues were identified in reporting, scenario integration, tests, or artifact collection.

No open issues 🎉

What changed in this PR

Adds per-scenario timing reports to NVX microVM tests, providing data for future duration-balanced CI sharding.

Changes:

• Flushes progress lines and incrementally records timing, outcomes, and run metadata.
• Uploads reports from every microVM job regardless of outcome.
• Documents the report format and adds reporting and workflow tests.

File	Description
scripts/​test_nvx_tools.py	Tests report uploads and artifact naming.
scripts/​test_microvm_tests.py	Tests timing, progress flushing, and failure handling.
scripts/​nvx_tools/​microvm_tests.py	Integrates reporting into scenario execution.
scripts/​nvx_tools/​microvm_durations.py	Implements incremental JSON Lines timing reports.
doc/​usage.md	Documents report fields and lifecycle.
doc/​project-structure.md	Lists the new reporting module.
doc/​ci.md	Documents timing artifact collection.
.github/​workflows/​run-nvx-microvm-tests.yml	Uploads reports regardless of job outcome.

_{Review effort: Balanced}

[Copilot]

🟢 Approval recommended

The reporting changes preserve scenario execution, have focused regression coverage, and leave no unresolved blocking findings.

No open issues 🎉

_{Review effort: Balanced}