ci: investigate recurring WHP mapped-memory-flush stalls

[ppenna]

Summary

Windows/WHP CI intermittently enters a slow snapshot-generation regime that is isolated to OpenVMM's capture.mapped_memory_flush phase. The condition can persist across both bounded lifecycle measurements and fail an otherwise unrelated pull request.

This recurred in run 35648438246, attempt 1, in the Windows/WHP platform job. An immediate workflow rerun on the same runner succeeded, but its first lifecycle measurement was unstable again before the one allowed remeasurement produced a stable series.

#119 tracks the telemetry and artifact improvements needed to diagnose Windows storage behavior. This issue tracks the recurring infrastructure condition itself, its runner correlation, and its eventual mitigation.

Current incident

• Workflow: CI, run 35648438246, attempt 1
• Event: pull_request for Enforce protected default branch updates #168; the pull request was Ready and remained on head 98960491ee5a4cc576370d895dfa27406c7ba4d7
• Tested merge ref: 36e765615a5886df721eb39f0f8460e38c5400e5
• OpenVMM source: 64054d7a7275c2c6d66c2bbb10f77ec777e11889
• OpenVMM executable SHA-256: af7aded3301b4756ee11d91e062d60264e52ef038392dd04d5a44f9a9fc64853
• Failed job/step: Platform / Windows / WHP / Virtual machine / Run benchmark
• Runner: azure-windows-2, machine VMSSVAOAN000001
• Labels: self-hosted, windows, whp, virtual-machine
• Inputs: 1 vCPU guest, 128 MiB, host CPUs 0-7, host reserve 0, 1 warmup, 10 samples, 40-second marker timeout, guest-exit
• Job interval: 2026-09-21 20:02:54Z - 20:05:25Z
• Classification: current-head failure, not cancellation or pull-request supersession

The guard behaved as designed:

Workflow attempt	Lifecycle measurement	Snapshot p25	Snapshot p50	Result
1	1	778.553 ms	1145.855 ms	Rejected: p50 47.2% above p25
1	2	758.313 ms	1207.128 ms	Rejected: p50 59.2% above p25; job failed
2	1	757.718 ms	1004.276 ms	Rejected: p50 32.5% above p25
2	2	747.362 ms	760.665 ms	Accepted; workflow rerun succeeded

Workflow attempt 2 used the same azure-windows-2 / VMSSVAOAN000001 runner and the same source revisions. Its Windows/WHP job and the overall run completed successfully.

Snapshot-generation samples

Workflow attempt 1, lifecycle measurement 1:

769.860, 750.549, 785.176, 778.553, 1058.199,
1258.866, 1274.070, 1233.511, 1266.400, 1247.438

Workflow attempt 1, lifecycle measurement 2:

748.134, 1221.497, 1266.751, 1266.911, 1249.468,
1239.632, 1192.759, 733.743, 758.313, 764.249

Workflow attempt 2, lifecycle measurement 1:

757.719, 1233.202, 1235.240, 1252.613, 1240.896,
1292.089, 730.264, 770.037, 749.024, 775.352

Workflow attempt 2, lifecycle measurement 2:

773.696, 776.425, 764.066, 764.715, 751.555,
745.271, 767.387, 747.362, 757.264, 735.547

Profile localization

The rejected attempt-1 artifact contained both raw lifecycle profiles. The slow regime tracks capture.mapped_memory_flush almost one-for-one:

• Fast flushes: approximately 0.67-0.72 seconds
• Slow flushes: approximately 1.11-1.21 seconds
• Remaining snapshot-generation time: generally approximately 0.06-0.08 seconds in both regimes

Cold boot and restore did not show the split:

• Lifecycle measurement 1: cold-start p50 444.458 ms; restore p50 121.454 ms
• Lifecycle measurement 2: cold-start p50 434.712 ms; restore p50 112.034 ms
• Guest exits completed without teardown timeouts

This localizes the failure to host-side mapped-RAM flushing rather than guest boot, snapshot restore, or a general OpenVMM lifecycle failure.

The failed job uploaded artifact 10661007084, but the workflow rerun reused the run-scoped artifact name with overwrite: true. The failed artifact now returns 404 and has been replaced by artifact 10662446972, which contains the rerun's rejected and accepted lifecycle measurements. Job logs retain the failed sample values, but not the raw failed profiles. Workflow-attempt-scoped artifact retention remains an observability gap related to #119.

Recurrence

I scanned every CI run and every workflow attempt since the snapshot stability guard landed: 215 run IDs and 152 completed, assigned Windows/WHP platform jobs. Ten job attempts (6.6%) contained a validator-detected instability. One additional earlier series was missed by the original p50/p25-only detector and failed the historical performance gate instead.

Runner	Completed WHP jobs	Detected incidents	Rate
azure-windows-1	19	1	5.3%
azure-windows-2	28	6	21.4%
azure-windows-3	71	3	4.2%
azure-windows-4	18	0	0%
azure-windows-5	14	0	0%
azure-windows-vmssvaoan000004	2	0	0%

The old-detector miss also ran on azure-windows-3, so the behavior is not exclusive to one runner. However, the observed rate on azure-windows-2 is materially higher and should be investigated.

Known occurrences

Run/job	Runner	Evidence and outcome
35180745983 attempt 1	azure-windows-3	p50 61.4% above p25; failed before bounded remeasurement existed. Workflow attempt 2 succeeded.
35382585623	azure-windows-2	p50 33.7% above p25; failed before bounded remeasurement existed. Led to #117.
35393916034	azure-windows-3	Two fast and eight slow samples; old validator missed the split and the performance gate failed. Led to #118.
35397304565	azure-windows-3	p50 34.3% above p25; internal remeasurement succeeded.
35404802205	azure-windows-2	p50 48.0% above p25; internal remeasurement succeeded.
35416685879	azure-windows-2	p50 37.1% above p25; internal remeasurement succeeded. The job later failed for unrelated release provenance.
35562857677	azure-windows-1	Both measurements rejected: 29.0% internal gap, then p50 60.4% above p25. Led to #159.
35605532024	azure-windows-3	55.9% internal gap; internal remeasurement succeeded.
35612178865 attempt 1	azure-windows-2	Both measurements rejected: p50 31.2%, then 61.2%, above p25. Workflow attempt 2 succeeded on azure-windows-4.
35648438246 attempt 1	azure-windows-2	Both measurements rejected: p50 47.2%, then 59.2%, above p25.
35648438246 attempt 2	azure-windows-2	First measurement rejected at 32.5% above p25; second measurement stable and accepted.

Of the validator-detected incidents:

• Two predated bounded remeasurement and failed on the first unstable result.
• Five recovered on the one allowed internal remeasurement. One of those jobs later failed for an unrelated reason.
• Three produced two consecutive unstable measurements and directly failed the benchmark job.

Root-cause hypothesis

This is a recurring transient infrastructure condition in which mapped RAM flushes take approximately 0.4-0.5 seconds longer. Candidate triggers include managed-disk throttling, host writeback pressure, antivirus/scanning activity, or unrelated storage contention. The external trigger is not yet proven.

The evidence does not currently support an NVX or OpenVMM source regression:

• It occurs across unrelated heads and multiple runners.
• The same exact source and artifacts can fail and then pass without modification.
• In the current run, the same runner moved between slow and fast regimes within minutes.
• The slow samples are localized to mapped_memory_flush; other lifecycle phases remain stable.

The stability thresholds and single bounded remeasurement are working as intended. This issue should not be addressed by loosening the guard, adding unbounded retries, or publishing rejected data.

Related work

• Reject unstable samples when measuring snapshot generation #60 introduced the snapshot-generation stability guard.
• ci: remeasure unstable Windows lifecycle benchmarks #117 added one bounded Windows remeasurement after run 35382585623.
• ci: detect minority snapshot performance regimes #118 added minority-regime detection after run 35393916034.
• Fix Windows CI failure reporting and retain benchmark attempts #159 preserved internal benchmark attempts and fixed Windows failure propagation after run 35562857677.
• ci: improve Windows benchmark provenance and storage diagnostics #119 tracks runner/storage provenance and bounded storage telemetry.

Investigation and mitigation

• Use the telemetry planned in ci: improve Windows benchmark provenance and storage diagnostics #119 to correlate mapped_memory_flush with disk latency, queue depth, throughput, writeback, throttling, and scanning activity.
• Inspect Azure host and managed-disk metrics for the timestamps above, especially azure-windows-2 / VMSSVAOAN000001.
• Determine why azure-windows-2 shows a 21.4% detected incidence rate versus 0-5.3% on the other established runners.
• Decide whether the affected instance should be drained/reimaged while diagnosis continues.
• If storage configuration is causal, apply one consistent disk SKU, caching policy, and scratch-data placement across the Windows runner pool.
• Preserve benchmark artifacts per workflow attempt so a manual rerun cannot delete the failed raw profiles.
• Keep the current stability guard and one bounded remeasurement unchanged while collecting evidence.
• Define and complete a post-mitigation observation window that covers every Windows runner and demonstrates that consecutive-instability job failures no longer recur.

Acceptance criteria

• The external trigger for the slow mapped_memory_flush regime is identified with runner telemetry.
• A runner-pool or host remediation is applied and documented.
• Failed and successful workflow attempts retain enough provenance and raw profile data for comparison.
• Rejected lifecycle series cannot enter performance history.
• A representative post-fix observation window completes without two consecutive unstable lifecycle measurements.

[ppenna]

Reopened: post-mitigation recurrence on 2026-09-22

The Windows/WHP lifecycle instability recurred after #171 integrated the bounded mapped-file flush concurrency change from nanvix/openvmm#89. That change was explicitly a candidate mitigation, not proof that the Azure-runner condition had been eliminated. This issue should remain open while the external trigger and representative post-mitigation behavior are unresolved.

New failing run

• Workflow: CI run 35771477786, workflow attempt 1, push to dev.
• Exact NVX head: 58fc6421db6dc1f7430babd8dda2309d7161f3c9.
• OpenVMM gitlink: b9603efc025867a64a66db625fe6275f82a3753a, which includes mitigation commit 7a2b217471e2fbf977e9eec260b80f80051ee821.
• Failed job: 106903399733, Platform / Windows / WHP / Virtual machine.
• First causal failing step: Run benchmark -> Run Windows acceptance test.
• Runner: azure-windows-3; platform windows-whp-virtual-machine.
• Inputs: 1 vCPU, 128 MiB, host CPUs 0-7, host reserve 0, one warmup, ten retained samples, 40-second timeout, guest-exit, snapshot profiling enabled.
• Classification: genuine failed acceptance check, not cancellation or PR-head supersession. The required-status failure was secondary.

Workflow attempt	Lifecycle measurement	Runner	Evidence
1	1	azure-windows-3	Samples split 2/8 between 1038.376 ms and 1589.209 ms: 53.0% gap, above the unchanged 25% limit.
1	2	azure-windows-3	Samples split 7/3 between 1058.808 ms and 1407.693 ms: 33.0% gap; the job failed after the one permitted remeasurement.
2	1	azure-windows-5	Accepted at the same NVX head; job 106912594297 and the workflow succeeded.

The second rejected sample list, preserved in the job log, is:

1407.693, 1721.982, 1619.932, 1021.735, 1052.441,
851.316, 1058.808, 1033.541, 1038.010, 977.973

Local reproduction with exact CI artifacts

Ran locally on a Windows 11 Enterprise / WHP virtual-machine host, build 26200, Python 3.12.10, NTFS, at the exact failing NVX and OpenVMM revisions. This matches the backend and host type but is not the same Azure runner.

Downloaded the executable and guest artifacts from the failing workflow run and verified their provenance and SHA-256 values:

Artifact	SHA-256
OpenVMM executable	ac551eb2666c786ae226f8ce5c43aea00385f97c220b0a24fa53a51409c261aa
Kernel	e0d211989898e5b7f153203919417fec5e9294fa39129f826d3e9d145e6107cf
Alpine initramfs	3c6699735e32a42488b0f9416e5072cc3808a24b02ac383dd9326b9308f22808

After source verification and a reduced one-warmup/one-sample smoke run, executed the original acceptance parameters:

python scripts\nvx.py verify
python scripts\nvx.py benchmark `
  --suite e2e --backend whp --platform windows-whp-virtual-machine `
  --processors 1 --warmups 1 --runs 10 --timeout 40 `
  --skip-build --teardown-mode guest-exit --snapshot-profile `
  --cpus 0-7 --host-cpu-reserve 0 `
  --output data\runs\whp-35771477786-repro.json
python scripts\nvx.py performance validate-openvmm `
  --platform windows-whp-virtual-machine `
  --input data\runs\whp-35771477786-repro.json

Both local ten-sample runs passed the unchanged validator:

• First run: snapshot-generation p50 283.370 ms, range 225.947-305.514 ms. capture.mapped_memory_flush dominated at approximately 176-256 ms.
• Second run: snapshot-generation p50 298.724 ms, range 222.281-314.362 ms.
• Replaying the original CI sample list deterministically reproduces the identical 7/3, 33.0% gap rejection.

These are diagnostic observations, not cross-host performance comparisons or evidence of a timing improvement: no OpenVMM or benchmark timing code was changed between the local runs. The Azure stall itself was not reproduced locally, and no deterministic guest/VMM failure was established.

Confirmed evidence-loss defect

Workflow attempt 2 overwrote attempt 1's benchmark artifact because its name included the workflow run ID but not github.run_attempt, and overwrite: true was enabled. The rejected sample values survive in logs, but the original raw phase profiles can no longer be inspected.

Consequently, attributing this particular recurrence to capture.mapped_memory_flush is consistent with the established incident pattern, but remains an inference rather than direct inspection of this run's failed profiles. Azure disk throttling, writeback pressure, scanning, and other contention remain hypotheses, not established causes.

The historical check covered 30 recent currently-failed CI runs (2026-09-19 through 2026-09-22) and 28 Windows/WHP platform logs, plus directly referenced workflows that had succeeded after reruns. It reconfirmed the matching failures in 35562857677, 35612178865, and 35648438246, including unchanged-source recovery on the same runner. This bounded check is not a replacement for the complete incidence survey in the issue description.

Scoped diagnostic-retention fix

Draft PR #195, commit 218a803d3ad851537fc4ffea5cbe6ebfb7520f49, addresses the demonstrated artifact-retention gap also tracked by #119:

• Preserve immutable benchmark-diagnostics-<platform>-<run-id>-attempt-<run-attempt> artifacts, including failed attempts, with one-day retention.
• Upload diagnostics before replacing the existing run-scoped canonical artifact.
• Keep the canonical names unchanged so failed-jobs-only reruns can reuse successful platform results from earlier workflow attempts.
• Leave stability thresholds, bounded remeasurement, workloads, performance history, runner configuration, and OpenVMM source/pins unchanged.

The retention regression failed before the change and passed afterward. All 18 CI configuration tests were rerun before the commit; the complete 370-test Windows CLI validation and applicable Python quality checks also passed. The PR records the platform-specific validation limits and remains Draft.

This is an observability fix, not a resolution of the timing condition. Next steps remain preserving and correlating future failed profiles with runner/storage telemetry, establishing the external trigger, and observing representative behavior across the runner pool after a targeted mitigation. No threshold relaxation or additional retry is justified by the available evidence.

[ppenna]

New post-mitigation recurrence: run 35805840174

The Windows/WHP lifecycle instability recurred on the dev push produced by #196. Both bounded lifecycle measurements were rejected, and the raw artifact confirms that the split is again isolated almost entirely to capture.mapped_memory_flush.

Incident

• Workflow: CI run 35805840174, workflow attempt 1, push to dev.
• Exact NVX head: b04081a8ac152609888ca759f14294c7af73b7bf.
• OpenVMM gitlink: 1f94c06cbd42daefd2b4ac09135237afb261e638.
• Failed job: 107008875004, Platform / Windows / WHP / Virtual machine.
• First causal failing step: Run benchmark; the required-status failure was secondary.
• Runner: azure-windows-3; platform windows-whp-virtual-machine.
• Job interval: 2026-09-23 01:32:27Z - 01:35:41Z.
• Raw artifact: benchmark-windows-whp-virtual-machine-35805840174, artifact 10728420550, currently retained through 2026-09-24 01:35:33Z.

Workflow attempt	Lifecycle measurement	Snapshot split	Gap	Outcome
1	1	5/5 between 1061.002 ms and 1565.606 ms	47.6%	Rejected; one bounded remeasurement started
1	2	6/4 between 1073.379 ms and 1627.027 ms	51.6%	Rejected; job failed

Both exceed the unchanged 25% cluster-gap limit.

Raw snapshot and mapped-memory-flush samples

Lifecycle measurement 1, snapshot generation:

1056.990, 1059.972, 1049.124, 1028.674, 1722.794,
1565.606, 1617.771, 1743.662, 1726.707, 1061.002

Lifecycle measurement 1, capture.mapped_memory_flush:

998.467, 995.074, 981.940, 969.813, 1657.708,
1500.322, 1547.662, 1677.964, 1663.248, 1001.330

Lifecycle measurement 2, snapshot generation:

1738.666, 1731.792, 1627.027, 1739.080, 966.341,
1073.379, 972.637, 1066.488, 1063.071, 1046.675

Lifecycle measurement 2, capture.mapped_memory_flush:

1678.332, 1671.653, 1565.961, 1679.537, 902.899,
1009.687, 913.802, 1003.862, 1002.066, 977.308

The mapped-memory-flush samples track the complete snapshot-generation split nearly one-for-one: approximately 0.90-1.01 seconds in the fast regime and 1.50-1.68 seconds in the slow regime. This is the same phase localization already documented in this issue.

Source-change assessment

The preceding successful dev run, 35802625855, accepted its first Windows/WHP lifecycle measurement on azure-windows-4. Its mapped-memory-flush samples ranged from 807.346 ms to 1017.265 ms without a second cluster.

The intervening OpenVMM change from 9073d248af94e1527ad7fd5994f16dbb524de8a2 to 1f94c06cbd42daefd2b4ac09135237afb261e638 is confined to MSHV cancellation handling, its tests/documentation, and dependency metadata. It does not modify the WHP mapped-memory-flush implementation, benchmark thresholds, or retry behavior. This recurrence is therefore consistent with the existing transient runner/storage condition; it does not establish a regression from #196.

Rerun and diagnostics status

Workflow attempt 2 was requested at 2026-09-23 03:06:31Z but was cancelled at 03:06:48Z before any jobs were created. The newer dev push from merged #195 triggered run 35812918243 and superseded the rerun, so there is no unchanged-head recovery result for b04081a8.

#195 is now merged, so subsequent workflow attempts should retain immutable attempt-scoped diagnostic artifacts. It improves evidence retention but does not change the underlying timing condition, thresholds, or bounded retry policy.

Classification: another genuine post-mitigation recurrence matching #169. The external trigger remains unresolved; no threshold relaxation or extra retry is justified by this evidence.