From f7cd0581d9a52e3d586c5b8567838f3aafb3bac0 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 13:47:16 -0700 Subject: [PATCH 1/5] doctor: gate H4 on the guest's 250 ppm clock correction budget From 2026-10-28 23:00Z to 2026-10-29 15:00Z, H4 failed 9 of the 75 microVM and platform jobs on azure-mshv-1, and with them 8 CI runs, among them a nightly run and three dev pushes (#1008). The runner's TSC kept its rate: its interval rates against CLOCK_MONOTONIC_RAW agreed within 0.005 ppm in every job. What moved is the Hyper-V PTP clock that chronyd follows, whose rate has wandered since about 20:00Z on 2026-10-28, so chronyd's frequency estimate, which H4 gates, read from +2.5 to +189.3 ppm. H4 held that estimate, the host's current clock correction, to 100 ppm, the bound that the time ABI v1 set for the TSC's error alone, to keep the guest's wall-clock discipline, which steers at most 500 ppm, clear of that error plus a restore's rate deviation of up to 250 ppm. No short measurement can tell the TSC's error from the reference's wander, so the bound failed a host whose guests the time ABI can serve. H4's limit is now the guest's budget for the host's correction: Linux's frequency limit of 500 ppm, nvx-rs's FREQUENCY_LIMIT, less the time ABI's restore tolerance of 250 ppm, which a restore's rate deviation can use and which nvx-rs's RATE_DEVIATION_LIMIT and OpenVMM's TSC_TOLERANCE_PPM apply. The doctor derives RATE_TOLERANCE_PPM from the two, and a new unit test reads nvx-rs's constants from its time decoders and OpenVMM's from the gitlink's commit, as the CPU profile tests read OpenVMM's catalog, and checks that the limit is their difference. 250 ppm is also KVM's TSC rate tolerance, which Firecracker applies too. H4 still fails a range that lies wholly above the limit and calls one that straddles it inconclusive; the interval checks, the plausibility check, the parsing of chronyd's report, and the restore tolerance stay as they are. Of the 9 failures, 8 lie wholly within 250 ppm and would have passed. The ninth, +189.1 ppm with a range of 58.5 to 319.8 ppm, straddles it. The H4 tests' cases move to the new limit, and a +150 ppm correction now passes. doc/ci.md's H4 row gives the limit with the rationale that the architecture guide's rewrite dropped, and the wall-clock discipline ties the budget to host qualification. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 2 +- doc/design/3.2-clock-and-time.md | 19 ++-- scripts/nvx_tools/doctor.py | 9 +- scripts/test_time_abi.py | 148 +++++++++++++++++++++++++++---- 4 files changed, 151 insertions(+), 27 deletions(-) diff --git a/doc/ci.md b/doc/ci.md index 976693800..55ae4a404 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -1706,7 +1706,7 @@ microcode and the invariant-TSC flags, may read `unknown`. | H1 | `/dev/kvm` or `/dev/mshv` is readable and writable, and a KVM host has no `/dev/mshv`; on Windows, `WHvGetCapability` reports a hypervisor | | H2 | Vendor, family, model, stepping, microcode, and OS build from `/proc/cpuinfo` or the Windows registry. Then `openvmm --hypervisor --cpu-fingerprint ` writes the host's CPU fingerprint (by default `nvx-cpu-fingerprint-.json` in the probe directory; `--cpu-fingerprint` overrides it), checks it against the pinned profile that `auto` selects from OpenVMM's catalog, the latest revision of the generation's profile, which every backend shares, and prints one `NVX-CPU-PROFILE:` line. The check never falls back to a host profile, so a CPU on which `auto` falls back fails H2. H2 reports the generation and the profile from that line, so a profile that an OpenVMM pin adds qualifies its hosts without an NVX change. H2 requires exit status 0, `status=pass`, the same backend, and a catalog profile of the reported generation, reports the profile and surface digests, and otherwise fails with OpenVMM's code, for example `[E_PROFILE_HOST_UNKNOWN]` on a CPU that no profile serves or `[E_PROFILE_UNSUPPORTED]` naming every unsupported CPUID bit. On MSHV and WHP, OpenVMM checks the entries outside the profile on a probe partition configured from the profile, as a cold boot does. With `--no-openvmm`, H2 maps the host with NVX's copy of the catalog instead: `skylake-sp` (6/85, steppings 0 to 4, `intel.skylake-sp.v1`), `icelake-sp` (6/106, `intel.icelake-sp.v1`), `emeraldrapids` (6/207, `intel.emeraldrapids.v1`), `alderlake` (6/151 and 6/154, `intel.alderlake.v1`), `milan` (AMD 25/1, `amd.milan.v1`), `genoa` (AMD 25/17, `amd.genoa.v2`), or `turin` (AMD 26/2, `amd.turin.v1`). Any other CPU, including Cascade Lake and Cooper Lake, fails with `E_PROFILE_HOST_UNKNOWN`. A unit test keeps the copy, which records the latest revision of each generation's profile, equal to the profiles of the OpenVMM submodule's pinned revision, which it reads from the gitlink's commit, so the NVX CLI jobs validate the CLI after they check out OpenVMM. The host OS's invariant-TSC flags (`constant_tsc nonstop_tsc`, or the CPUID bit on Windows) are recorded as evidence and never fail the check, because they don't decide what a guest observes: Azure WHP hosts show the CPUID bit but cannot offer invariant TSC to partitions, and their guests measure tens of nanoseconds of skew | | H3 | `openvmm --x-time-abi-verify` builds the partition and runs the time ABI preflight without running the guest. Its `NVX-TIME-ABI-VERIFY:` line must report `status=ok` for the backend, plausible declared and native TSC rates, the backend's LAPIC rate, and a `cpu_profile` that is a catalog profile, `..v` of any generation but a host profile's `host`, which rejects the host profile that `auto` falls back to on a CPU that no built-in profile serves, and, when H2 runs too, a revision of the profile H2 names. A failed preflight reports OpenVMM's code, for example `[E_TSC_SYNC_UNSUPPORTED]` | -| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 100 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit, so a range that straddles the limit fails as inconclusive; the rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | +| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit, so a range that straddles the limit fails as inconclusive; the rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | | H5 | Pinned-thread ping-pong rounds over every pair of host CPUs; `max_abs_offset_ns` is at most 1,000, the measurement is conclusive, and no pair stalls | | H6 | A microVM with the largest supported vCPU count up to 8 reports a valid `NVX-TIME-ABI` boot line through `nvx-time status` and runs `nvx-time-probe warp` over every CPU pair five times, with all vCPUs halted for 0.1, 1, 5, and 1 s between the runs, so that a host without an invariant TSC corrects the guest TSC as idle host CPUs wake (#265); then a 1-vCPU microVM runs it once. Every run stays within 1,000 ns. `--ci-schedule` runs CI's schedule instead: two runs 1 s apart | | H7 | `adjtimex` reports no `STA_UNSYNC` and no `TIME_ERROR` on Linux; `w32tm /query /status` names a synchronized source on Windows. When H7 can't read either, its detail starts with `cannot verify host UTC synchronization`: `adjtimex` fails or reports a clock state Linux doesn't define, or `w32tm` fails or prints no English `Source` and `Leap Indicator` lines, as in a Windows display language other than English | diff --git a/doc/design/3.2-clock-and-time.md b/doc/design/3.2-clock-and-time.md index 26d60ef04..ab76b6d4e 100644 --- a/doc/design/3.2-clock-and-time.md +++ b/doc/design/3.2-clock-and-time.md @@ -401,13 +401,18 @@ to three samples per poll. An offset of at least 128 ms is stepped and counted as a discontinuity; a smaller one is slewed with error bounds derived from the offset and its uncertainty, which marks the clock synchronized for applications. The kernel limits the frequency correction to ±500 ppm, of which -the rate tolerance uses at most 250 ppm. A sample whose generation differs -from the recorded one is discarded, because a restore happened and restore -repair resets the discipline. The discipline follows host wall-clock steps -and never powers off the guest. Restore repair and the discipline step the -clock through the kernel, so a workload can observe every step through the -kernel's clock-set notification, such as a `timerfd` armed with -`TFD_TIMER_CANCEL_ON_SET`. +the rate tolerance uses at most 250 ppm. The other 250 ppm is the budget for +the host's own clock correction, which the discipline applies too, because +host UTC follows the host's time service: a host whose TSC runs more than +250 ppm from its declared rate against host UTC does not +[qualify](../ci.md#host-qualification) for the contract, and a larger +correction would leave an offset that grows until the discipline steps it. A +sample whose generation differs from the recorded one is discarded, because a +restore happened and restore repair resets the discipline. The discipline +follows host wall-clock steps and never powers off the guest. Restore repair +and the discipline step the clock through the kernel, so a workload can +observe every step through the kernel's clock-set notification, such as a +`timerfd` armed with `TFD_TIMER_CANCEL_ON_SET`. The [snapshot protocol](5.3-snapshot-protocol.md) and [guest repair](5.5-restore-protocol.md#557-guest-repair) define the snapshot diff --git a/scripts/nvx_tools/doctor.py b/scripts/nvx_tools/doctor.py index 0a55c359a..b3a74af06 100644 --- a/scripts/nvx_tools/doctor.py +++ b/scripts/nvx_tools/doctor.py @@ -75,7 +75,14 @@ # H4's rate stability bounds (doc/ci.md, "Host qualification"). RATE_UNCERTAINTY_PPM = 0.25 RATE_AGREEMENT_PPM = 1.0 -RATE_TOLERANCE_PPM = 100.0 +# H4's limit is the guest's budget for the host's clock correction. The +# guest's wall-clock discipline follows host UTC, so it applies that +# correction on top of a restore's rate deviation, which the time ABI's +# restore tolerance bounds, within Linux's frequency limit +# (doc/design/3.2-clock-and-time.md, "Wall-clock discipline"). +GUEST_FREQUENCY_LIMIT_PPM = 500.0 +RESTORE_TOLERANCE_PPM = 250.0 +RATE_TOLERANCE_PPM = GUEST_FREQUENCY_LIMIT_PPM - RESTORE_TOLERANCE_PPM # chronyd's tracking report, `chronyc -c tracking`, has 14 comma-separated # fields, among them the reference's name (1), the frequency in ppm, positive # when the undisciplined clock runs fast (7), its skew in ppm (9), and the diff --git a/scripts/test_time_abi.py b/scripts/test_time_abi.py index 2cc1ed696..f6749cac6 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -2,6 +2,7 @@ from __future__ import annotations +import ast import contextlib import dataclasses import io @@ -100,6 +101,76 @@ def write_openvmm_profiles( return checkout +# A Rust integer constant, `[pub] const NAME: TYPE = EXPRESSION;`. +RUST_INTEGER_CONSTANT = re.compile( + r"^\s*(?:pub(?:\([^)]*\))?\s+)?const\s+(\w+)\s*:\s*[iu](?:8|16|32|64|128|size)" + r"\s*=\s*([^;]+);", + re.MULTILINE, +) + + +def rust_integer_constants(source: str) -> dict[str, int]: + """Return the integer constants of a Rust source whose values are integer + literals, or sums, differences, products, and left shifts of literals and + of earlier such constants.""" + constants: dict[str, int] = {} + + def evaluate(node: ast.expr) -> int: + if isinstance(node, ast.Constant) and type(node.value) is int: + return node.value + if isinstance(node, ast.Name): + return constants[node.id] + if isinstance(node, ast.BinOp): + left, right = evaluate(node.left), evaluate(node.right) + if isinstance(node.op, ast.Add): + return left + right + if isinstance(node.op, ast.Sub): + return left - right + if isinstance(node.op, ast.Mult): + return left * right + if isinstance(node.op, ast.LShift): + return left << right + raise ValueError(f"unsupported expression {ast.dump(node)}") + + for name, expression in RUST_INTEGER_CONSTANT.findall(source): + try: + constants[name] = evaluate(ast.parse(expression.strip(), mode="eval").body) + except (KeyError, SyntaxError, ValueError): + continue + return constants + + +def pinned_openvmm_file(test: unittest.TestCase, path: str) -> str: + """Return the file at ``path`` in the OpenVMM submodule's pinned revision. + + The file is read from the gitlink's commit, not from the submodule's + working tree, which can hold another revision: a self-hosted CI runner + keeps an earlier job's OpenVMM checkout until the job checks out its own. + Skips ``test`` where the submodule lacks the pinned revision. + """ + root = Path(__file__).resolve().parents[1] + submodule = root / "openvmm" + if not (submodule / ".git").exists(): + test.skipTest("the OpenVMM submodule is not initialized") + + def git(directory: Path, *arguments: str) -> subprocess.CompletedProcess[str]: + return subprocess.run( + ["git", "-C", str(directory), *arguments], + capture_output=True, + encoding="utf-8", + check=False, + ) + + pin = git(root, "rev-parse", ":openvmm").stdout.strip() + if not pin or git(submodule, "cat-file", "-e", f"{pin}^{{commit}}").returncode: + test.skipTest( + f"the OpenVMM submodule lacks its pinned revision {pin or '(unknown)'}" + ) + shown = git(submodule, "show", f"{pin}:{path}") + test.assertEqual(shown.returncode, 0, f"{path} at {pin}: {shown.stderr}") + return shown.stdout + + class FieldParsingTests(unittest.TestCase): def test_parses_plain_and_quoted_fields_with_guest_escapes(self): fields = time_abi.parse_fields( @@ -2401,6 +2472,36 @@ def context_with_files(backend: str = "kvm") -> doctor.DoctorContext: result = doctor.check_openvmm_preflight(context_with_files()) self.assertTrue(result.passed, result.detail) + def test_the_rate_limit_is_the_guests_frequency_budget(self): + # #1008: H4's limit is what the guest's wall-clock discipline leaves + # for the host's clock correction: Linux's frequency limit, to which + # nvx-rs clamps the correction, less a restore's rate deviation, + # which nvx-rs's restore packet decoder bounds by the time ABI's + # restore tolerance, the one that OpenVMM's rate policy applies. + root = Path(__file__).resolve().parents[1] + decoders = rust_integer_constants( + (root / "nvx-rs" / "src" / "guest" / "time" / "decoders.rs").read_text( + encoding="utf-8" + ) + ) + scaled_ppm = decoders["SCALED_PPM"] + self.assertEqual(scaled_ppm, 1 << 16) + self.assertEqual( + decoders["FREQUENCY_LIMIT"], doctor.GUEST_FREQUENCY_LIMIT_PPM * scaled_ppm + ) + self.assertEqual( + decoders["RATE_DEVIATION_LIMIT"], doctor.RESTORE_TOLERANCE_PPM * scaled_ppm + ) + self.assertEqual( + doctor.RATE_TOLERANCE_PPM, + (decoders["FREQUENCY_LIMIT"] - decoders["RATE_DEVIATION_LIMIT"]) + / scaled_ppm, + ) + rate = rust_integer_constants( + pinned_openvmm_file(self, "vmm_core/virt/src/time_abi/rate.rs") + ) + self.assertEqual(rate["TSC_TOLERANCE_PPM"], doctor.RESTORE_TOLERANCE_PPM) + def test_rate_check_applies_the_spec_bounds_to_sleep_separated_samples(self): def records( rates: list[float], @@ -2556,7 +2657,7 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: records([2793437000.0] * 2, interval_s=1.0, bracket=400), "inconclusive: an interval's uncertainty is 0.401 ppm > 0.25 ppm", ), - (records([2794000000.0] * 12), "201.544 ppm from the measured rate"), + (records([2794200000.0] * 12), "273.140 ppm from the measured rate"), (records([100_000_000.0] * 12), "[E_TSC_RATE_IMPLAUSIBLE]"), ): with self.subTest(message=message): @@ -2623,7 +2724,7 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: result = check(context, slewed, chrony="chronyd is not synchronized") self.assertFalse(result.passed) self.assertIn( - "the backend rate is 946.078 ppm from the measured rate (limit 100 ppm)", + "the backend rate is 946.078 ppm from the measured rate (limit 250 ppm)", result.detail, ) self.assertIn( @@ -2641,32 +2742,42 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: True, "79.786 ppm from the", ), + # #1008: the 100 ppm of the time ABI v1 bounded the TSC's error + # alone, which a measurement can't tell from the reference's + # wander; azure-mshv-1 failed at +127.9 ppm, 117.3 to 138.6 ppm + # within chronyd's skew. ( - doctor.ChronyFrequency("PHC0", 90, 15), + doctor.ChronyFrequency("PHC0", 150, 1), + "2300000507", + True, + "149.802 ppm from the", + ), + ( + doctor.ChronyFrequency("PHC0", 240, 15), "2300000507", False, - "the measurement is inconclusive: the backend rate is 89.788 ppm " - "from the measured rate, 74.785 to 104.791 ppm within chronyd's " - "skew of 15.000 ppm, which straddles the limit of 100 ppm", + "the measurement is inconclusive: the backend rate is 239.837 ppm " + "from the measured rate, 224.830 to 254.845 ppm within chronyd's " + "skew of 15.000 ppm, which straddles the limit of 250 ppm", ), ( - doctor.ChronyFrequency("PHC0", 150, 1), + doctor.ChronyFrequency("PHC0", 300, 1), "2300000507", False, - "the backend rate is 149.802 ppm from the measured rate, 148.802 " - "to 150.802 ppm within chronyd's skew of 1.000 ppm (limit 100 ppm)", + "the backend rate is 299.870 ppm from the measured rate, 298.869 " + "to 300.870 ppm within chronyd's skew of 1.000 ppm (limit 250 ppm)", ), # The correction isn't linear in the frequency: the estimate's - # upper bound, 100 ppm from the declared rate, corrects the rate - # by 100.010 ppm, and a range that includes the declared rate + # upper bound, 250 ppm from the declared rate, corrects the rate + # by 250.063 ppm, and a range that includes the declared rate # starts at zero. ( - doctor.ChronyFrequency("PHC0", 0, 100), + doctor.ChronyFrequency("PHC0", 0, 250), "2300000000", False, "the measurement is inconclusive: the backend rate is 0.000 ppm " - "from the measured rate, 0.000 to 100.010 ppm within chronyd's " - "skew of 100.000 ppm, which straddles the limit of 100 ppm", + "from the measured rate, 0.000 to 250.063 ppm within chronyd's " + "skew of 250.000 ppm, which straddles the limit of 250 ppm", ), ): with self.subTest(estimate=estimate): @@ -2676,16 +2787,17 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: self.assertEqual(result.passed, passed, result.detail) self.assertIn(message, result.detail) # The deviation keeps three decimals, so a failure never reads as the - # limit itself: #768's second failure was 100.027 ppm. + # limit itself: #768's second failure was 100.027 ppm, at the 100 ppm + # limit of the time. context = ci_context("mshv") context.facts["native_tsc_hz"] = "2300000507" - result = check(context, records([2300230569.0] * 2, interval_s=1.0)) + result = check(context, records([2300575569.0] * 2, interval_s=1.0)) self.assertFalse(result.passed) self.assertIn( - "the backend rate is 100.027 ppm from the measured rate (limit 100 ppm)", + "the backend rate is 250.027 ppm from the measured rate (limit 250 ppm)", result.detail, ) - self.assertEqual(context.facts["rate_deviation_ppm"], "100.027") + self.assertEqual(context.facts["rate_deviation_ppm"], "250.027") def test_chrony_frequency_reads_a_synchronized_tracking_report(self): report = ( From ce26d2b1ccd6a930bb281d4daeb8caa3bd386725 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 13:53:36 -0700 Subject: [PATCH 2/5] doctor: re-read chronyd's estimate before H4 calls a rate inconclusive H4 bounds chronyd's frequency estimate by chronyd's skew, and calls a rate inconclusive when the rates within that skew straddle the limit. On azure-mshv-1, whose reference clock wanders, chronyd's estimate and skew move within seconds (#1008): in the 15 minutes from 02:51Z on 2026-10-29, the estimate read +19.1, +189.3, +117.1, +51.5, +7.2, and +3.5 ppm, the last with a skew of 0.08 ppm. The job that read +189.3 ppm with a skew of 130.6 ppm straddles even the new 250 ppm limit, at 58.5 to 319.8 ppm, while the runner's next two jobs, which started 50 s and 87 s later, passed conclusively. When chronyd's range straddles the limit, H4 now re-reads the estimate every 2 s for up to 60 s, and uses the first whose range lies wholly within or wholly beyond the limit. Only chronyd's estimate changes, so the samples against CLOCK_MONOTONIC_RAW stand: H4 corrects them by the estimate that it uses, which the measured rate, the rate reference, and the gate all reflect, and the detail names the first estimate as evidence. A chronyc read that fails during the re-reads counts as inconclusive. A range that straddles the limit for the whole minute still fails as inconclusive, and the detail says that no re-read was conclusive. Without H3's rate there is no range, so H4 never re-reads. The re-reads keep the check stateless, and add up to a minute only to a run whose first estimate straddles the limit. The H4 tests run on a fake clock: an estimate that never moves fails as inconclusive after 30 re-reads, one that settles is used, even when it fails, and a run without H3 reads chronyd once. doc/ci.md describes the re-reads and the time that they can add to runner validation. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 5 +- scripts/nvx_tools/doctor.py | 109 +++++++++++++++++++++++++++++------- scripts/test_time_abi.py | 92 +++++++++++++++++++++++++++++- 3 files changed, 180 insertions(+), 26 deletions(-) diff --git a/doc/ci.md b/doc/ci.md index 55ae4a404..b4ae442f3 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -325,7 +325,8 @@ and generation, and the TSC rate stability on its short schedule. The microVM and platform jobs run it after downloading OpenVMM and add OpenVMM's CPU profile check (H2) and preflight (H3), and keep the fingerprint as an artifact when the profile check fails; the other jobs pass `--no-openvmm`. This takes a -few seconds. It reports the CPU generation, the built-in CPU profile that +few seconds, and up to a minute more when H4 re-reads chronyd's frequency +estimate. It reports the CPU generation, the built-in CPU profile that `auto` selects, and the measured TSC rate in the log and the job summary, and fails the job with a stable code when the runner is not qualified, for example `E_PROFILE_HOST_UNKNOWN` on an unknown CPU generation, where `auto` would fall @@ -1706,7 +1707,7 @@ microcode and the invariant-TSC flags, may read `unknown`. | H1 | `/dev/kvm` or `/dev/mshv` is readable and writable, and a KVM host has no `/dev/mshv`; on Windows, `WHvGetCapability` reports a hypervisor | | H2 | Vendor, family, model, stepping, microcode, and OS build from `/proc/cpuinfo` or the Windows registry. Then `openvmm --hypervisor --cpu-fingerprint ` writes the host's CPU fingerprint (by default `nvx-cpu-fingerprint-.json` in the probe directory; `--cpu-fingerprint` overrides it), checks it against the pinned profile that `auto` selects from OpenVMM's catalog, the latest revision of the generation's profile, which every backend shares, and prints one `NVX-CPU-PROFILE:` line. The check never falls back to a host profile, so a CPU on which `auto` falls back fails H2. H2 reports the generation and the profile from that line, so a profile that an OpenVMM pin adds qualifies its hosts without an NVX change. H2 requires exit status 0, `status=pass`, the same backend, and a catalog profile of the reported generation, reports the profile and surface digests, and otherwise fails with OpenVMM's code, for example `[E_PROFILE_HOST_UNKNOWN]` on a CPU that no profile serves or `[E_PROFILE_UNSUPPORTED]` naming every unsupported CPUID bit. On MSHV and WHP, OpenVMM checks the entries outside the profile on a probe partition configured from the profile, as a cold boot does. With `--no-openvmm`, H2 maps the host with NVX's copy of the catalog instead: `skylake-sp` (6/85, steppings 0 to 4, `intel.skylake-sp.v1`), `icelake-sp` (6/106, `intel.icelake-sp.v1`), `emeraldrapids` (6/207, `intel.emeraldrapids.v1`), `alderlake` (6/151 and 6/154, `intel.alderlake.v1`), `milan` (AMD 25/1, `amd.milan.v1`), `genoa` (AMD 25/17, `amd.genoa.v2`), or `turin` (AMD 26/2, `amd.turin.v1`). Any other CPU, including Cascade Lake and Cooper Lake, fails with `E_PROFILE_HOST_UNKNOWN`. A unit test keeps the copy, which records the latest revision of each generation's profile, equal to the profiles of the OpenVMM submodule's pinned revision, which it reads from the gitlink's commit, so the NVX CLI jobs validate the CLI after they check out OpenVMM. The host OS's invariant-TSC flags (`constant_tsc nonstop_tsc`, or the CPUID bit on Windows) are recorded as evidence and never fail the check, because they don't decide what a guest observes: Azure WHP hosts show the CPUID bit but cannot offer invariant TSC to partitions, and their guests measure tens of nanoseconds of skew | | H3 | `openvmm --x-time-abi-verify` builds the partition and runs the time ABI preflight without running the guest. Its `NVX-TIME-ABI-VERIFY:` line must report `status=ok` for the backend, plausible declared and native TSC rates, the backend's LAPIC rate, and a `cpu_profile` that is a catalog profile, `..v` of any generation but a host profile's `host`, which rejects the host profile that `auto` falls back to on a CPU that no built-in profile serves, and, when H2 runs too, a revision of the profile H2 names. A failed preflight reports OpenVMM's code, for example `[E_TSC_SYNC_UNSUPPORTED]` | -| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit, so a range that straddles the limit fails as inconclusive; the rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | +| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | | H5 | Pinned-thread ping-pong rounds over every pair of host CPUs; `max_abs_offset_ns` is at most 1,000, the measurement is conclusive, and no pair stalls | | H6 | A microVM with the largest supported vCPU count up to 8 reports a valid `NVX-TIME-ABI` boot line through `nvx-time status` and runs `nvx-time-probe warp` over every CPU pair five times, with all vCPUs halted for 0.1, 1, 5, and 1 s between the runs, so that a host without an invariant TSC corrects the guest TSC as idle host CPUs wake (#265); then a 1-vCPU microVM runs it once. Every run stays within 1,000 ns. `--ci-schedule` runs CI's schedule instead: two runs 1 s apart | | H7 | `adjtimex` reports no `STA_UNSYNC` and no `TIME_ERROR` on Linux; `w32tm /query /status` names a synchronized source on Windows. When H7 can't read either, its detail starts with `cannot verify host UTC synchronization`: `adjtimex` fails or reports a clock state Linux doesn't define, or `w32tm` fails or prints no English `Source` and `Leap Indicator` lines, as in a Windows display language other than English | diff --git a/scripts/nvx_tools/doctor.py b/scripts/nvx_tools/doctor.py index b3a74af06..95979bcfb 100644 --- a/scripts/nvx_tools/doctor.py +++ b/scripts/nvx_tools/doctor.py @@ -20,6 +20,7 @@ import shutil import subprocess import sys +import time from collections.abc import Callable, Mapping, Sequence from dataclasses import dataclass, field from pathlib import Path @@ -90,6 +91,11 @@ CHRONY_TRACKING_FIELDS = 14 CHRONY_UNSYNCHRONIZED = "Not synchronised" CHRONYC_TIMEOUT_SECONDS = 5.0 +# When chronyd's skew leaves H4's range straddling the limit, H4 re-reads +# chronyd's estimate this often, for at most this long, and uses the first +# estimate whose range is conclusive. +CHRONY_REREAD_INTERVAL_SECONDS = 2.0 +CHRONY_REREAD_SECONDS = 60.0 SKEW_PAIR_DURATION_MS = 5 GUEST_VCPU_COUNTS = (8, 4, 2, 1) GUEST_MEMORY_MIB = 128 @@ -779,6 +785,54 @@ def chrony_frequency() -> ChronyFrequency | str: return ChronyFrequency(fields[1], ppm, skew_ppm) +def reread_chrony_frequency( + conclusive: Callable[[ChronyFrequency], bool], +) -> tuple[ChronyFrequency | None, float]: + """Re-read chronyd's frequency estimate until one is ``conclusive``. + + Reads it every CHRONY_REREAD_INTERVAL_SECONDS for at most + CHRONY_REREAD_SECONDS, and returns the first conclusive estimate, or None, + with the seconds that the re-reads took. + """ + start = time.monotonic() + while ( + time.monotonic() - start + CHRONY_REREAD_INTERVAL_SECONDS + <= CHRONY_REREAD_SECONDS + ): + time.sleep(CHRONY_REREAD_INTERVAL_SECONDS) + estimate = chrony_frequency() + if isinstance(estimate, ChronyFrequency) and conclusive(estimate): + return estimate, time.monotonic() - start + return None, time.monotonic() - start + + +def _deviation_ppm(rate: float, declared_hz: int) -> float: + return (rate - declared_hz) / declared_hz * 1e6 + + +def _corrected_rate(raw_rate: float, ppm: float) -> float: + """Return the rate against true time of a rate against + CLOCK_MONOTONIC_RAW, which a time service estimates runs ``ppm`` fast.""" + # chronyd sets the kernel's frequency to -ppm, so its estimate of true + # time runs at CLOCK_MONOTONIC_RAW's rate times (1 - ppm). + return raw_rate / (1 - ppm / 1e6) + + +def _chrony_deviations( + raw_rate: float, declared_hz: int, chrony: ChronyFrequency +) -> tuple[float, float]: + """Return the nearest and the farthest deviation from ``declared_hz`` of + the rates within chronyd's skew of its estimate.""" + # chronyd's skew bounds the error of its frequency estimate, so the rate + # lies between the rates that the estimate's bounds give. + low, high = ( + _deviation_ppm(_corrected_rate(raw_rate, chrony.ppm + bound), declared_hz) + for bound in (-chrony.skew_ppm, chrony.skew_ppm) + ) + nearest = 0.0 if low <= 0 <= high else min(abs(low), abs(high)) + return nearest, max(abs(low), abs(high)) + + def check_rate(context: DoctorContext) -> CheckResult: clocksource = "" if not host_is_windows(): @@ -833,16 +887,40 @@ def check_rate(context: DoctorContext) -> CheckResult: stable_rate = _window_rate(points, clock_hz) agreement_ppm = (max(rates) - min(rates)) / stable_rate * 1e6 uncertainty_ppm = max(uncertainties_ppm) + declared = context.facts.get("native_tsc_hz") or context.facts.get("tsc_hz") + declared_hz = None if declared is None else int(declared) # Over the window, CLOCK_MONOTONIC also carries the slew with which # chronyd removes its current offset, which reaches hundreds of ppm for # seconds after its reference jumps (#768). chronyd's frequency estimate, # from its whole sample history, says instead how fast # CLOCK_MONOTONIC_RAW runs against the reference. chrony = None if host_is_windows() else chrony_frequency() + reread_problem = reread_evidence = "" + if isinstance(chrony, ChronyFrequency) and declared_hz is not None: + + def conclusive(estimate: ChronyFrequency) -> bool: + nearest, farthest = _chrony_deviations(stable_rate, declared_hz, estimate) + return farthest <= RATE_TOLERANCE_PPM or nearest > RATE_TOLERANCE_PPM + + if not conclusive(chrony): + # The reference's wander moves chronyd's estimate and its skew + # within seconds (#1008). Only the estimate changes, so the + # samples stand while H4 re-reads it. + estimate, seconds = reread_chrony_frequency(conclusive) + if estimate is None: + reread_problem = ( + f", and no re-read of chronyd's estimate in {seconds:.0f} s " + "was conclusive" + ) + else: + reread_evidence = ( + f"; chronyd's first estimate, {chrony.ppm:+.3f} ppm (skew " + f"{chrony.skew_ppm:.3f} ppm), straddled the limit, so H4 " + f"re-read it for {seconds:.0f} s (evidence)" + ) + chrony = estimate if isinstance(chrony, ChronyFrequency): - # chronyd sets the kernel's frequency to -ppm, so its estimate of true - # time runs at CLOCK_MONOTONIC_RAW's rate times (1 - ppm). - measured = stable_rate / (1 - chrony.ppm / 1e6) + measured = _corrected_rate(stable_rate, chrony.ppm) reference = ( f"against {stability_clock['name']} corrected by chronyd's frequency " f"estimate of {chrony.ppm:+.3f} ppm (skew {chrony.skew_ppm:.3f} ppm, " @@ -879,30 +957,18 @@ def check_rate(context: DoctorContext) -> CheckResult: f"the TSC rate is unstable: interval rates differ by " f"{agreement_ppm:.3f} ppm > {RATE_AGREEMENT_PPM} ppm" ) - declared = context.facts.get("native_tsc_hz") or context.facts.get("tsc_hz") - if declared is None: + if declared_hz is None: # validate-runner runs before the OpenVMM binary is available; the # VM jobs run H3 with H4 to compare against the backend's rate. detail += "; not compared with the backend's rate (H3 did not run)" else: - declared_hz = int(declared) - - def deviation(rate: float) -> float: - return (rate - declared_hz) / declared_hz * 1e6 - - deviation_ppm = abs(deviation(measured)) + deviation_ppm = abs(_deviation_ppm(measured, declared_hz)) context.facts["rate_deviation_ppm"] = f"{deviation_ppm:.3f}" detail += f"; {deviation_ppm:.3f} ppm from the backend's {declared} Hz" if isinstance(chrony, ChronyFrequency): - # chronyd's skew bounds the error of its frequency estimate, so the - # rate lies between the rates that the estimate's bounds give, and - # passes only when that whole range lies within the limit. - low, high = ( - deviation(stable_rate / (1 - (chrony.ppm + bound) / 1e6)) - for bound in (-chrony.skew_ppm, chrony.skew_ppm) - ) - nearest = 0.0 if low <= 0 <= high else min(abs(low), abs(high)) - farthest = max(abs(low), abs(high)) + # The rate passes only when the whole range within chronyd's skew + # lies within the limit. + nearest, farthest = _chrony_deviations(stable_rate, declared_hz, chrony) within = ( f", {nearest:.3f} to {farthest:.3f} ppm within chronyd's skew of " f"{chrony.skew_ppm:.3f} ppm" @@ -919,8 +985,9 @@ def deviation(rate: float) -> float: problems.append( f"the measurement is inconclusive: the backend rate is " f"{deviation_ppm:.3f} ppm from the measured rate{within}, which " - f"straddles the limit of {RATE_TOLERANCE_PPM:g} ppm" + f"straddles the limit of {RATE_TOLERANCE_PPM:g} ppm{reread_problem}" ) + detail += reread_evidence if isinstance(chrony, ChronyFrequency): detail += ( f"; {window_rate:.0f} Hz against {rate_clock['name']}, which chronyd " diff --git a/scripts/test_time_abi.py b/scripts/test_time_abi.py index f6749cac6..5ddbd3055 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -16,6 +16,7 @@ import tempfile import threading import unittest +from collections.abc import Sequence from pathlib import Path from typing import cast from unittest.mock import patch @@ -1921,6 +1922,21 @@ def completed(stdout: str, returncode: int = 0, stderr: str = ""): return subprocess.CompletedProcess(["x"], returncode, stdout, stderr) +class FakeClock: + """A monotonic clock that advances only when something sleeps.""" + + def __init__(self) -> None: + self.now = 0.0 + self.sleeps: list[float] = [] + + def monotonic(self) -> float: + return self.now + + def sleep(self, seconds: float) -> None: + self.sleeps.append(seconds) + self.now += seconds + + CPU = { "vendor": "GenuineIntel", "family": "6", @@ -2542,15 +2558,26 @@ def check( probe_records: list[tuple[str, dict[str, str]]], clocksource: str = "tsc", windows: bool = False, - chrony: doctor.ChronyFrequency | str = "chronyc is not installed", + chrony: doctor.ChronyFrequency + | str + | Sequence[doctor.ChronyFrequency | str] = "chronyc is not installed", + clock: FakeClock | None = None, ) -> doctor.CheckResult: + """Run H4; a list of chronyd readings answers its re-reads too.""" + clock = clock or FakeClock() + readings = chrony if isinstance(chrony, list | tuple) else None with ( patch.object(doctor, "run_probe", return_value=probe_records) as run, patch.object(doctor, "host_clocksource", return_value=clocksource), patch.object(doctor, "host_is_windows", return_value=windows), patch.object( - doctor, "chrony_frequency", return_value=chrony + doctor, + "chrony_frequency", + return_value=None if readings else chrony, + side_effect=readings, ) as frequency, + patch.object(doctor.time, "monotonic", clock.monotonic), + patch.object(doctor.time, "sleep", clock.sleep), ): result = doctor.check_rate(context) # Windows reads QueryPerformanceCounter, which no daemon steers. @@ -2783,9 +2810,68 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: with self.subTest(estimate=estimate): context = ci_context("mshv") context.facts["native_tsc_hz"] = declared - result = check(context, steady, chrony=estimate) + clock = FakeClock() + result = check(context, steady, chrony=estimate, clock=clock) self.assertEqual(result.passed, passed, result.detail) self.assertIn(message, result.detail) + # A range that straddles the limit stays inconclusive when + # chronyd's estimate doesn't move for the 60 s of re-reads. + straddles = "straddles" in message + self.assertEqual(clock.sleeps, [2.0] * 30 if straddles else []) + self.assertEqual( + "no re-read of chronyd's estimate in 60 s was conclusive" + in result.detail, + straddles, + ) + # #1008: a range that straddles the limit makes H4 re-read chronyd's + # estimate every 2 s, for up to 60 s, and use the first conclusive + # one. On azure-mshv-1, chronyd's estimate read +189.3 ppm with a skew + # of 130.6 ppm, and +117.1 ppm with a skew of 55.1 ppm 50 s later. + straddling = doctor.ChronyFrequency("PHC0", 189.3, 130.6) + for readings, passed, measured, message in ( + ( + [ + straddling, + straddling, + "chronyc tracking exited 1: 506 Cannot talk to daemon", + doctor.ChronyFrequency("PHC0", 117.1, 55.1), + ], + True, + "2300269362", + "116.893 ppm from the backend's 2300000507 Hz; chronyd's first " + "estimate, +189.300 ppm (skew 130.600 ppm), straddled the limit, " + "so H4 re-read it for 6 s (evidence)", + ), + # The first conclusive estimate decides, even when it fails. + ( + [straddling, doctor.ChronyFrequency("PHC0", 300, 1)], + False, + "2300690207", + "the backend rate is 299.870 ppm from the measured rate, 298.869 " + "to 300.870 ppm within chronyd's skew of 1.000 ppm (limit 250 ppm)", + ), + ): + with self.subTest(readings=readings): + context = ci_context("mshv") + context.facts["native_tsc_hz"] = "2300000507" + clock = FakeClock() + result = check(context, steady, chrony=readings, clock=clock) + self.assertEqual(result.passed, passed, result.detail) + self.assertIn(message, result.detail) + self.assertEqual(clock.sleeps, [2.0] * (len(readings) - 1)) + # Only chronyd's estimate changes, so H4 corrects the same + # samples by the estimate that it uses. + self.assertEqual(context.facts["measured_tsc_hz"], measured) + used = cast(doctor.ChronyFrequency, readings[-1]) + self.assertEqual( + context.facts["rate_reference"], + f"chronyd {used.ppm:+.3f} ppm (skew {used.skew_ppm:.3f} ppm)", + ) + # Without the backend's rate, H4 has no range to re-read for. + clock = FakeClock() + result = check(ci_context("mshv"), steady, chrony=straddling, clock=clock) + self.assertTrue(result.passed, result.detail) + self.assertEqual(clock.sleeps, []) # The deviation keeps three decimals, so a failure never reads as the # limit itself: #768's second failure was 100.027 ppm, at the 100 ppm # limit of the time. From 829eaeebdd7db6116b6ad8631e8a4621dac0fed7 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 13:57:23 -0700 Subject: [PATCH 3/5] doctor: warn when H4's deviation exceeds 100 ppm H4's limit is now the guest's 250 ppm budget for the host's clock correction, so a host whose correction exceeds the time ABI v1's 100 ppm passes. Such a correction comes from a TSC far from its declared rate or from a reference clock that wanders, which no single run can tell apart (#1008), and either deserves a look before it uses up the budget. H4 now passes such a host with a warning that gives the deviation and the share of the guest's budget that it uses, and says that one run can't tell the TSC's error from the reference clock's wander. A deviation that fails or stays inconclusive gets no warning, since its failure says more. CheckResult gains a warning field for a concern that doesn't fail the check. The check's detail leads with it, after "warning:", so that the NVX-DOCTOR line states it; the job summary repeats it below the table; and run_checks prints it as a ::warning:: annotation, escaped as workflow commands require, when it runs in GitHub Actions, so that a CI run shows it on the run's page. Only H4 warns. 7 of the 8 failures of #1008 that now pass lie above 100 ppm and would warn; the other runners read at most about +57 ppm and never would. The H4 tests check the warning's text, that only a passing deviation above 100 ppm warns, and that 100 ppm itself doesn't; a new test follows a warning to the check's line, the summary, and the annotation, which only GitHub Actions gets. doc/ci.md and doc/usage.md describe warnings, and the H4 row the one that H4 gives. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 12 ++++--- doc/usage.md | 3 +- scripts/nvx_tools/doctor.py | 36 +++++++++++++++++++-- scripts/test_time_abi.py | 64 +++++++++++++++++++++++++++++++++++++ 4 files changed, 107 insertions(+), 8 deletions(-) diff --git a/doc/ci.md b/doc/ci.md index b4ae442f3..6686494f9 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -1697,17 +1697,19 @@ profile, rates, and skew metrics to a file such as `$GITHUB_STEP_SUMMARY`. H4 and H6 run on long qualification schedules, which take about three minutes; `--ci-schedule` selects CI's short ones. A failure that matches a time ABI failure code starts its detail with the code in brackets, for example -`[E_PROFILE_HOST_UNKNOWN]`. A check fails, and never passes, when it can't -read a fact it gates on: missing or unrecognized tool output fails it, and an -error in one check fails only that check. Only evidence fields, such as the -microcode and the invariant-TSC flags, may read `unknown`. +`[E_PROFILE_HOST_UNKNOWN]`. A check that passes with a warning starts its +detail with `warning:`, and the summary and, in GitHub Actions, a +`::warning::` annotation repeat the warning. A check fails, and never passes, +when it can't read a fact it gates on: missing or unrecognized tool output +fails it, and an error in one check fails only that check. Only evidence +fields, such as the microcode and the invariant-TSC flags, may read `unknown`. | Check | Implementation | | --- | --- | | H1 | `/dev/kvm` or `/dev/mshv` is readable and writable, and a KVM host has no `/dev/mshv`; on Windows, `WHvGetCapability` reports a hypervisor | | H2 | Vendor, family, model, stepping, microcode, and OS build from `/proc/cpuinfo` or the Windows registry. Then `openvmm --hypervisor --cpu-fingerprint ` writes the host's CPU fingerprint (by default `nvx-cpu-fingerprint-.json` in the probe directory; `--cpu-fingerprint` overrides it), checks it against the pinned profile that `auto` selects from OpenVMM's catalog, the latest revision of the generation's profile, which every backend shares, and prints one `NVX-CPU-PROFILE:` line. The check never falls back to a host profile, so a CPU on which `auto` falls back fails H2. H2 reports the generation and the profile from that line, so a profile that an OpenVMM pin adds qualifies its hosts without an NVX change. H2 requires exit status 0, `status=pass`, the same backend, and a catalog profile of the reported generation, reports the profile and surface digests, and otherwise fails with OpenVMM's code, for example `[E_PROFILE_HOST_UNKNOWN]` on a CPU that no profile serves or `[E_PROFILE_UNSUPPORTED]` naming every unsupported CPUID bit. On MSHV and WHP, OpenVMM checks the entries outside the profile on a probe partition configured from the profile, as a cold boot does. With `--no-openvmm`, H2 maps the host with NVX's copy of the catalog instead: `skylake-sp` (6/85, steppings 0 to 4, `intel.skylake-sp.v1`), `icelake-sp` (6/106, `intel.icelake-sp.v1`), `emeraldrapids` (6/207, `intel.emeraldrapids.v1`), `alderlake` (6/151 and 6/154, `intel.alderlake.v1`), `milan` (AMD 25/1, `amd.milan.v1`), `genoa` (AMD 25/17, `amd.genoa.v2`), or `turin` (AMD 26/2, `amd.turin.v1`). Any other CPU, including Cascade Lake and Cooper Lake, fails with `E_PROFILE_HOST_UNKNOWN`. A unit test keeps the copy, which records the latest revision of each generation's profile, equal to the profiles of the OpenVMM submodule's pinned revision, which it reads from the gitlink's commit, so the NVX CLI jobs validate the CLI after they check out OpenVMM. The host OS's invariant-TSC flags (`constant_tsc nonstop_tsc`, or the CPUID bit on Windows) are recorded as evidence and never fail the check, because they don't decide what a guest observes: Azure WHP hosts show the CPUID bit but cannot offer invariant TSC to partitions, and their guests measure tens of nanoseconds of skew | | H3 | `openvmm --x-time-abi-verify` builds the partition and runs the time ABI preflight without running the guest. Its `NVX-TIME-ABI-VERIFY:` line must report `status=ok` for the backend, plausible declared and native TSC rates, the backend's LAPIC rate, and a `cpu_profile` that is a catalog profile, `..v` of any generation but a host profile's `host`, which rejects the host profile that `auto` falls back to on a CPU that no built-in profile serves, and, when H2 runs too, a revision of the profile H2 names. A failed preflight reports OpenVMM's code, for example `[E_TSC_SYNC_UNSUPPORTED]` | -| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | +| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). Above that old bound, H4 passes with a warning that says how much of the budget the host's correction uses, and that one run can't tell the TSC's error from the reference's wander. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | | H5 | Pinned-thread ping-pong rounds over every pair of host CPUs; `max_abs_offset_ns` is at most 1,000, the measurement is conclusive, and no pair stalls | | H6 | A microVM with the largest supported vCPU count up to 8 reports a valid `NVX-TIME-ABI` boot line through `nvx-time status` and runs `nvx-time-probe warp` over every CPU pair five times, with all vCPUs halted for 0.1, 1, 5, and 1 s between the runs, so that a host without an invariant TSC corrects the guest TSC as idle host CPUs wake (#265); then a 1-vCPU microVM runs it once. Every run stays within 1,000 ns. `--ci-schedule` runs CI's schedule instead: two runs 1 s apart | | H7 | `adjtimex` reports no `STA_UNSYNC` and no `TIME_ERROR` on Linux; `w32tm /query /status` names a synchronized source on Windows. When H7 can't read either, its detail starts with `cannot verify host UTC synchronization`: `adjtimex` fails or reports a clock state Linux doesn't define, or `w32tm` fails or prints no English `Source` and `Leap Indicator` lines, as in a Windows display language other than English | diff --git a/doc/usage.md b/doc/usage.md index c38d4689e..5b593c206 100644 --- a/doc/usage.md +++ b/doc/usage.md @@ -1249,7 +1249,8 @@ python3 scripts/nvx.py doctor Qualifies this host for the [time ABI](design/3.2-clock-and-time.md). It runs the selected checks in order, prints one `NVX-DOCTOR: check= status= detail="..."` line per check, and -exits with status 1 if any check fails. A check fails, and never passes, when +exits with status 1 if any check fails. A check that passes with a warning +starts its detail with `warning:`. A check fails, and never passes, when it can't read a fact it gates on. [CI](ci.md#host-qualification) describes each check and the subset that CI runs. diff --git a/scripts/nvx_tools/doctor.py b/scripts/nvx_tools/doctor.py index 95979bcfb..7c26fc784 100644 --- a/scripts/nvx_tools/doctor.py +++ b/scripts/nvx_tools/doctor.py @@ -84,6 +84,9 @@ GUEST_FREQUENCY_LIMIT_PPM = 500.0 RESTORE_TOLERANCE_PPM = 250.0 RATE_TOLERANCE_PPM = GUEST_FREQUENCY_LIMIT_PPM - RESTORE_TOLERANCE_PPM +# H4 warns above the time ABI v1's limit, which bounded the TSC's error alone: +# one run can't tell that error from the wander of the host's reference clock. +RATE_WARNING_PPM = 100.0 # chronyd's tracking report, `chronyc -c tracking`, has 14 comma-separated # fields, among them the reference's name (1), the frequency in ppm, positive # when the undisciplined clock runs fast (7), its skew in ppm (9), and the @@ -145,6 +148,8 @@ class CheckResult: check: str passed: bool detail: str + # A concern that doesn't fail the check, which the detail also states. + warning: str = "" def line(self) -> str: status = "pass" if self.passed else "fail" @@ -181,6 +186,11 @@ def _escape_markdown(text: str) -> str: return text.replace("|", "\\|").replace("\n", " ") +def _annotation(text: str) -> str: + """Escape text for the message of a GitHub Actions workflow command.""" + return text.replace("%", "%25").replace("\r", "%0D").replace("\n", "%0A") + + def probe_path(directory: Path) -> Path: """Return the cached host probe binary for the current probe source.""" digest = hashlib.sha256(PROBE_SOURCE.read_bytes()).hexdigest()[:16] @@ -945,6 +955,7 @@ def conclusive(estimate: ChronyFrequency) -> bool: f"{uncertainty_ppm:.3f} ppm" ) problems: list[str] = [] + warning = "" if not MIN_TSC_HZ <= measured <= MAX_TSC_HZ: problems.append(f"[E_TSC_RATE_IMPLAUSIBLE] measured {measured:.0f} Hz") if uncertainty_ppm > RATE_UNCERTAINTY_PPM: @@ -987,6 +998,14 @@ def conclusive(estimate: ChronyFrequency) -> bool: f"{deviation_ppm:.3f} ppm from the measured rate{within}, which " f"straddles the limit of {RATE_TOLERANCE_PPM:g} ppm{reread_problem}" ) + elif deviation_ppm > RATE_WARNING_PPM: + warning = ( + f"the backend rate is {deviation_ppm:.3f} ppm from the measured " + f"rate, more than {RATE_WARNING_PPM:g} ppm: the host's clock " + f"correction uses {deviation_ppm / RATE_TOLERANCE_PPM:.0%} of the " + f"guest's {RATE_TOLERANCE_PPM:g} ppm budget, and one run can't " + "tell the TSC's error from the reference clock's wander" + ) detail += reread_evidence if isinstance(chrony, ChronyFrequency): detail += ( @@ -997,9 +1016,11 @@ def conclusive(estimate: ChronyFrequency) -> bool: detail += f"; no chronyd frequency estimate: {chrony} (evidence)" if clocksource: detail += f"; host clocksource {clocksource} (evidence)" + if warning: + detail = f"warning: {warning}; {detail}" if problems: - return CheckResult("H4", False, "; ".join(problems) + f"; {detail}") - return CheckResult("H4", True, detail) + return CheckResult("H4", False, "; ".join(problems) + f"; {detail}", warning) + return CheckResult("H4", True, detail, warning) def check_host_skew(context: DoctorContext) -> CheckResult: @@ -1224,6 +1245,12 @@ def run_checks(context: DoctorContext, checks: Sequence[str]) -> list[CheckResul result = CheckResult(check, False, first) results.append(result) print(result.line(), flush=True) + if result.warning and os.environ.get("GITHUB_ACTIONS") == "true": + print( + f"::warning title=Time ABI host qualification ({context.backend})::" + + _annotation(f"{check} {CHECK_TITLES[check]}: {result.warning}"), + flush=True, + ) return results @@ -1243,6 +1270,11 @@ def summary_markdown( f"{'pass' if result.passed else '**fail**'} | " f"{_escape_markdown(result.detail)} |" ) + for result in results: + if result.warning: + lines.extend( + ("", f"**{result.check} warning:** {_escape_markdown(result.warning)}") + ) reported = ( ("generation", "Generation"), ("cpu", "CPU"), diff --git a/scripts/test_time_abi.py b/scripts/test_time_abi.py index 5ddbd3055..15599b332 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -2814,6 +2814,9 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: result = check(context, steady, chrony=estimate, clock=clock) self.assertEqual(result.passed, passed, result.detail) self.assertIn(message, result.detail) + # Only a deviation that passes above 100 ppm warns. + deviation = float(context.facts["rate_deviation_ppm"]) + self.assertEqual(bool(result.warning), passed and deviation > 100) # A range that straddles the limit stays inconclusive when # chronyd's estimate doesn't move for the 60 s of re-reads. straddles = "straddles" in message @@ -2859,6 +2862,8 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: self.assertEqual(result.passed, passed, result.detail) self.assertIn(message, result.detail) self.assertEqual(clock.sleeps, [2.0] * (len(readings) - 1)) + # The settled +117.1 ppm passes with a warning. + self.assertEqual(bool(result.warning), passed) # Only chronyd's estimate changes, so H4 corrects the same # samples by the estimate that it uses. self.assertEqual(context.facts["measured_tsc_hz"], measured) @@ -2884,6 +2889,30 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: result.detail, ) self.assertEqual(context.facts["rate_deviation_ppm"], "250.027") + self.assertEqual(result.warning, "") + # #1008: above the time ABI v1's 100 ppm, H4 passes with a warning + # that leads its detail and says how much of the guest's budget the + # host's correction uses; 100 ppm itself doesn't warn. + for rate, warning in ( + ( + 2300230569.0, + "the backend rate is 100.027 ppm from the measured rate, more than " + "100 ppm: the host's clock correction uses 40% of the guest's " + "250 ppm budget, and one run can't tell the TSC's error from the " + "reference clock's wander", + ), + (2300230507.0, ""), + ): + with self.subTest(rate=rate): + context = ci_context("mshv") + context.facts["native_tsc_hz"] = "2300000507" + result = check(context, records([rate] * 2, interval_s=1.0)) + self.assertTrue(result.passed, result.detail) + self.assertEqual(result.warning, warning) + self.assertEqual( + result.detail.startswith(f"warning: {warning}; tsc_hz="), + bool(warning), + ) def test_chrony_frequency_reads_a_synchronized_tracking_report(self): report = ( @@ -3286,6 +3315,41 @@ def arithmetic(context: doctor.DoctorContext) -> doctor.CheckResult: ) self.assertIn("check=H5 status=pass", stdout.getvalue()) + def test_warnings_reach_the_line_the_summary_and_ci_annotations(self): + warning = "the host's clock correction uses 60% of the guest's 250 ppm budget" + + def warned(context: doctor.DoctorContext) -> doctor.CheckResult: + del context + return doctor.CheckResult( + "H4", True, f"warning: {warning}; tsc_hz=2300000000", warning + ) + + context = doctor_context(self.root, "mshv") + results: list[doctor.CheckResult] = [] + for actions, annotated in (("true", True), ("", False)): + with self.subTest(actions=actions): + stdout = io.StringIO() + with ( + patch.dict(doctor.CHECKS, {"H4": warned}), + patch.dict(doctor.os.environ, {"GITHUB_ACTIONS": actions}), + contextlib.redirect_stdout(stdout), + ): + results = doctor.run_checks(context, ("H4",)) + lines = stdout.getvalue().splitlines() + # The check passes, and its line states the warning. + self.assertEqual(lines[0], results[0].line()) + self.assertIn('status=pass detail="warning: ', lines[0]) + # In GitHub Actions, an annotation repeats it, escaped. + annotation = ( + "::warning title=Time ABI host qualification (mshv)::H4 host TSC " + "rate stability: the host's clock correction uses 60%25 of the " + "guest's 250 ppm budget" + ) + self.assertEqual(lines[1:], [annotation] if annotated else []) + summary = doctor.summary_markdown("mshv", results, {}) + self.assertIn("(mshv): passed", summary) + self.assertIn(f"\n\n**H4 warning:** {warning}\n", summary) + def test_run_selects_the_cpu_fingerprint_or_runs_without_openvmm(self): seen: list[Path | None] = [] schedules: list[doctor.Schedule] = [] From e2bd728b91ead7879d5971a723d2b3b6a62f11a2 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 14:02:57 -0700 Subject: [PATCH 4/5] doctor: read a kernel PLL's frequency in H4 without chronyd Without chronyd's frequency estimate, H4 measures the TSC against CLOCK_MONOTONIC over its sampling window, which also carries the slews that remove the clock's offset: on azure-mshv-1, a 2 s window read +946.1 ppm while the TSC ran 44 ppm from its declared rate (#768). A host that another time service keeps, such as systemd-timesyncd or ntpd, has no chronyd, but a better estimate (#1008): those services steer the clock through the kernel's PLL, which keeps its frequency estimate in adjtimex's frequency and slews offsets apart from it. When chronyd's estimate is missing and adjtimex reports the clock synchronized with the PLL on (STA_PLL), H4 now corrects the rate against CLOCK_MONOTONIC_RAW by the PLL's frequency, adjtimex's freq plus the frequency that its tick sets, as it corrects it by chronyd's estimate, and keeps the window's rate as evidence. Without STA_PLL the frequency is chronyd's to set, and it carries chronyd's slews: on azure-mshv-1, reads 2 s apart gave +98.5, -33.4, and -14.5 ppm while chronyd's estimate read +33.4 and then +30.7 ppm, so the frequency matches minus chronyd's estimate only between slews. H4 falls back to the window there, as on a clock that adjtimex reports unsynchronized, and the detail says why neither estimate is available. That is what H4 does on prometheus30, whose chronyd takes no commands over UDP (cmdport 0), so chronyc can't read its estimate, while adjtimex reports the PLL off with chronyd's frequency. Windows keeps QueryPerformanceCounter. H4 and H7 now read struct timex through one ctypes structure, as glibc declares it, instead of reading H7's status at a fixed offset of a raw buffer; H7's results and messages don't change. The tick matters: nvx-mshv-test's chronyd held it at 9,999, 100 ppm below nominal. Every Linux host at hand runs chronyd, so none could take the PLL path. On azure-mshv-1, the structure's size, 208 bytes, and its status, frequency, and tick read as expected, and kernel_frequency's unit tests cover the PLL's states. The H4 tests check the correction, its evidence, the unsynchronized fallback, and that H4 reads the PLL only without chronyd's estimate. doc/ci.md describes the PLL's frequency. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 2 +- scripts/nvx_tools/doctor.py | 122 +++++++++++++++++++++++++++++++----- scripts/test_time_abi.py | 91 +++++++++++++++++++++++++-- 3 files changed, 195 insertions(+), 20 deletions(-) diff --git a/doc/ci.md b/doc/ci.md index 6686494f9..e1495f02b 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -1709,7 +1709,7 @@ fields, such as the microcode and the invariant-TSC flags, may read `unknown`. | H1 | `/dev/kvm` or `/dev/mshv` is readable and writable, and a KVM host has no `/dev/mshv`; on Windows, `WHvGetCapability` reports a hypervisor | | H2 | Vendor, family, model, stepping, microcode, and OS build from `/proc/cpuinfo` or the Windows registry. Then `openvmm --hypervisor --cpu-fingerprint ` writes the host's CPU fingerprint (by default `nvx-cpu-fingerprint-.json` in the probe directory; `--cpu-fingerprint` overrides it), checks it against the pinned profile that `auto` selects from OpenVMM's catalog, the latest revision of the generation's profile, which every backend shares, and prints one `NVX-CPU-PROFILE:` line. The check never falls back to a host profile, so a CPU on which `auto` falls back fails H2. H2 reports the generation and the profile from that line, so a profile that an OpenVMM pin adds qualifies its hosts without an NVX change. H2 requires exit status 0, `status=pass`, the same backend, and a catalog profile of the reported generation, reports the profile and surface digests, and otherwise fails with OpenVMM's code, for example `[E_PROFILE_HOST_UNKNOWN]` on a CPU that no profile serves or `[E_PROFILE_UNSUPPORTED]` naming every unsupported CPUID bit. On MSHV and WHP, OpenVMM checks the entries outside the profile on a probe partition configured from the profile, as a cold boot does. With `--no-openvmm`, H2 maps the host with NVX's copy of the catalog instead: `skylake-sp` (6/85, steppings 0 to 4, `intel.skylake-sp.v1`), `icelake-sp` (6/106, `intel.icelake-sp.v1`), `emeraldrapids` (6/207, `intel.emeraldrapids.v1`), `alderlake` (6/151 and 6/154, `intel.alderlake.v1`), `milan` (AMD 25/1, `amd.milan.v1`), `genoa` (AMD 25/17, `amd.genoa.v2`), or `turin` (AMD 26/2, `amd.turin.v1`). Any other CPU, including Cascade Lake and Cooper Lake, fails with `E_PROFILE_HOST_UNKNOWN`. A unit test keeps the copy, which records the latest revision of each generation's profile, equal to the profiles of the OpenVMM submodule's pinned revision, which it reads from the gitlink's commit, so the NVX CLI jobs validate the CLI after they check out OpenVMM. The host OS's invariant-TSC flags (`constant_tsc nonstop_tsc`, or the CPUID bit on Windows) are recorded as evidence and never fail the check, because they don't decide what a guest observes: Azure WHP hosts show the CPUID bit but cannot offer invariant TSC to partitions, and their guests measure tens of nanoseconds of skew | | H3 | `openvmm --x-time-abi-verify` builds the partition and runs the time ABI preflight without running the guest. Its `NVX-TIME-ABI-VERIFY:` line must report `status=ok` for the backend, plausible declared and native TSC rates, the backend's LAPIC rate, and a `cpu_profile` that is a catalog profile, `..v` of any generation but a host profile's `host`, which rejects the host profile that `auto` falls back to on a CPU that no built-in profile serves, and, when H2 runs too, a revision of the profile H2 names. A failed preflight reports OpenVMM's code, for example `[E_TSC_SYNC_UNSUPPORTED]` | -| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). Above that old bound, H4 passes with a warning that says how much of the budget the host's correction uses, and that one run can't tell the TSC's error from the reference's wander. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why chronyd's estimate is missing, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | +| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). Above that old bound, H4 passes with a warning that says how much of the budget the host's correction uses, and that one run can't tell the TSC's error from the reference's wander. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Without chronyd's estimate, on a Linux host whose kernel PLL another time service drives, such as systemd-timesyncd or ntpd, and which `adjtimex` reports synchronized, the rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the PLL's frequency, `adjtimex`'s frequency with its tick's, which the PLL keeps apart from the offsets that it slews; H4 never reads it with chronyd, which keeps the PLL off and slews through that frequency. Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why neither estimate is available, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | | H5 | Pinned-thread ping-pong rounds over every pair of host CPUs; `max_abs_offset_ns` is at most 1,000, the measurement is conclusive, and no pair stalls | | H6 | A microVM with the largest supported vCPU count up to 8 reports a valid `NVX-TIME-ABI` boot line through `nvx-time status` and runs `nvx-time-probe warp` over every CPU pair five times, with all vCPUs halted for 0.1, 1, 5, and 1 s between the runs, so that a host without an invariant TSC corrects the guest TSC as idle host CPUs wake (#265); then a 1-vCPU microVM runs it once. Every run stays within 1,000 ns. `--ci-schedule` runs CI's schedule instead: two runs 1 s apart | | H7 | `adjtimex` reports no `STA_UNSYNC` and no `TIME_ERROR` on Linux; `w32tm /query /status` names a synchronized source on Windows. When H7 can't read either, its detail starts with `cannot verify host UTC synchronization`: `adjtimex` fails or reports a clock state Linux doesn't define, or `w32tm` fails or prints no English `Source` and `Leap Indicator` lines, as in a Windows display language other than English | diff --git a/scripts/nvx_tools/doctor.py b/scripts/nvx_tools/doctor.py index 7c26fc784..d7268a34e 100644 --- a/scripts/nvx_tools/doctor.py +++ b/scripts/nvx_tools/doctor.py @@ -135,7 +135,13 @@ class Schedule: # The registry key of the first processor's identity on Windows. WINDOWS_PROCESSOR_KEY = r"HARDWARE\DESCRIPTION\System\CentralProcessor\0" ADJTIMEX_TIME_ERROR = 5 +ADJTIMEX_STA_PLL = 0x0001 ADJTIMEX_STA_UNSYNC = 0x0040 +# adjtimex's frequency is in ppm scaled by 2^16, and its tick is the +# microseconds that the clock advances per USER_HZ tick, 100 per second, so +# 10,000 leaves the clock's rate alone. +ADJTIMEX_SCALED_PPM = 1 << 16 +ADJTIMEX_NOMINAL_TICK = 10_000 # Every H7 failure to read the host's synchronization state starts with this # phrase; a clock that is not synchronized starts "host UTC is not # synchronized" instead. @@ -816,6 +822,84 @@ def reread_chrony_frequency( return None, time.monotonic() - start +class _Timex(ctypes.Structure): + """Linux's struct timex, as glibc declares it.""" + + _fields_ = [ + ("modes", ctypes.c_uint), + ("offset", ctypes.c_long), + ("freq", ctypes.c_long), + ("maxerror", ctypes.c_long), + ("esterror", ctypes.c_long), + ("status", ctypes.c_int), + ("constant", ctypes.c_long), + ("precision", ctypes.c_long), + ("tolerance", ctypes.c_long), + ("time", ctypes.c_long * 2), # struct timeval + ("tick", ctypes.c_long), + ("ppsfreq", ctypes.c_long), + ("jitter", ctypes.c_long), + ("shift", ctypes.c_int), + ("stabil", ctypes.c_long), + ("jitcnt", ctypes.c_long), + ("calcnt", ctypes.c_long), + ("errcnt", ctypes.c_long), + ("stbcnt", ctypes.c_long), + ("tai", ctypes.c_int), + ("padding", ctypes.c_int * 11), + ] + + +def _adjtimex() -> tuple[int, _Timex]: + """Return adjtimex's clock state and struct timex without changing the + clock, or raise ScriptError naming why adjtimex can't.""" + timex = _Timex() + try: + libc = ctypes.CDLL(None, use_errno=True) + state = int(libc.adjtimex(ctypes.byref(timex))) + except (AttributeError, OSError) as error: + raise ScriptError(f"adjtimex is unavailable: {error}") from error + if state < 0: + raise ScriptError(f"adjtimex failed: {os.strerror(ctypes.get_errno())}") + return state, timex + + +@dataclass(frozen=True) +class KernelFrequency: + """The frequency correction of the kernel's PLL in ppm, positive when it + speeds the clock up: adjtimex's frequency plus its tick's.""" + + ppm: float + + +def kernel_frequency() -> KernelFrequency | str: + """Return a synchronized kernel PLL's frequency correction, or why there is + none. + + A time service such as systemd-timesyncd or ntpd steers the clock through + the kernel's PLL, which keeps its frequency estimate in adjtimex's + frequency and slews offsets apart from it. chronyd keeps the PLL off and + slews through that frequency, which then carries its slews. + """ + try: + state, timex = _adjtimex() + except ScriptError as error: + return str(error) + status = int(timex.status) + if state >= ADJTIMEX_TIME_ERROR or status & ADJTIMEX_STA_UNSYNC: + return ( + f"the kernel clock is not synchronized (adjtimex state={state} " + f"status=0x{status:04x})" + ) + if not status & ADJTIMEX_STA_PLL: + return f"the kernel PLL is off (adjtimex status=0x{status:04x})" + tick = int(timex.tick) + return KernelFrequency( + int(timex.freq) / ADJTIMEX_SCALED_PPM + + (tick - ADJTIMEX_NOMINAL_TICK) * 1e6 / ADJTIMEX_NOMINAL_TICK + ) + + def _deviation_ppm(rate: float, declared_hz: int) -> float: return (rate - declared_hz) / declared_hz * 1e6 @@ -929,6 +1013,9 @@ def conclusive(estimate: ChronyFrequency) -> bool: f"re-read it for {seconds:.0f} s (evidence)" ) chrony = estimate + # Without chronyd's estimate, a kernel PLL that another time service + # drives keeps its own, apart from the offsets that it slews. + kernel = kernel_frequency() if isinstance(chrony, str) else None if isinstance(chrony, ChronyFrequency): measured = _corrected_rate(stable_rate, chrony.ppm) reference = ( @@ -939,6 +1026,15 @@ def conclusive(estimate: ChronyFrequency) -> bool: context.facts["rate_reference"] = ( f"chronyd {chrony.ppm:+.3f} ppm (skew {chrony.skew_ppm:.3f} ppm)" ) + elif isinstance(kernel, KernelFrequency): + # The PLL runs the kernel's clock at CLOCK_MONOTONIC_RAW's rate times + # (1 + ppm), as chronyd's estimate of -ppm would. + measured = _corrected_rate(stable_rate, -kernel.ppm) + reference = ( + f"against {stability_clock['name']} corrected by the kernel PLL's " + f"frequency of {kernel.ppm:+.3f} ppm" + ) + context.facts["rate_reference"] = f"kernel PLL {kernel.ppm:+.3f} ppm" else: measured = window_rate reference = f"against {rate_clock['name']}" @@ -1014,6 +1110,13 @@ def conclusive(estimate: ChronyFrequency) -> bool: ) elif chrony is not None: detail += f"; no chronyd frequency estimate: {chrony} (evidence)" + if isinstance(kernel, KernelFrequency): + detail += ( + f"; {window_rate:.0f} Hz against {rate_clock['name']}, which the " + "kernel PLL also slews (evidence)" + ) + elif kernel is not None: + detail += f"; no kernel PLL frequency: {kernel} (evidence)" if clocksource: detail += f"; host clocksource {clocksource} (evidence)" if warning: @@ -1136,21 +1239,10 @@ def worst(name: str) -> int: def _linux_clock_state() -> tuple[int, int]: """Return adjtimex's clock state and status without changing the clock.""" try: - libc = ctypes.CDLL(None, use_errno=True) - buffer = ctypes.create_string_buffer(256) - state = int(libc.adjtimex(buffer)) - except (AttributeError, OSError) as error: - raise ScriptError( - f"{UTC_UNVERIFIED}: adjtimex is unavailable: {error}" - ) from error - if state < 0: - raise ScriptError( - f"{UTC_UNVERIFIED}: adjtimex failed: {os.strerror(ctypes.get_errno())}" - ) - # struct timex: unsigned modes, then the long offset, freq, maxerror, and - # esterror fields, then the int status. - status = int.from_bytes(buffer.raw[40:44], sys.byteorder) - return state, status + state, timex = _adjtimex() + except ScriptError as error: + raise ScriptError(f"{UTC_UNVERIFIED}: {error}") from error + return state, int(timex.status) def _windows_time_source() -> tuple[bool, str]: diff --git a/scripts/test_time_abi.py b/scripts/test_time_abi.py index 15599b332..c1f9f867e 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -15,6 +15,7 @@ import sys import tempfile import threading +import types import unittest from collections.abc import Sequence from pathlib import Path @@ -1922,6 +1923,10 @@ def completed(stdout: str, returncode: int = 0, stderr: str = ""): return subprocess.CompletedProcess(["x"], returncode, stdout, stderr) +# Why a host whose chronyd keeps the kernel's PLL off has no PLL frequency. +PLL_OFF = "the kernel PLL is off (adjtimex status=0x0000)" + + class FakeClock: """A monotonic clock that advances only when something sleeps.""" @@ -2562,6 +2567,7 @@ def check( | str | Sequence[doctor.ChronyFrequency | str] = "chronyc is not installed", clock: FakeClock | None = None, + kernel: doctor.KernelFrequency | str = PLL_OFF, ) -> doctor.CheckResult: """Run H4; a list of chronyd readings answers its re-reads too.""" clock = clock or FakeClock() @@ -2576,12 +2582,16 @@ def check( return_value=None if readings else chrony, side_effect=readings, ) as frequency, + patch.object(doctor, "kernel_frequency", return_value=kernel) as pll, patch.object(doctor.time, "monotonic", clock.monotonic), patch.object(doctor.time, "sleep", clock.sleep), ): result = doctor.check_rate(context) # Windows reads QueryPerformanceCounter, which no daemon steers. self.assertEqual(frequency.called, not windows) + # H4 reads the kernel's PLL only without chronyd's estimate. + first = readings[0] if readings else chrony + self.assertEqual(pll.called, not windows and isinstance(first, str)) self.assertEqual( run.call_args.args[1:], ( @@ -2623,7 +2633,8 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: self.assertIn("0.013 ppm from the backend's 2793437000 Hz", result.detail) self.assertIn("host clocksource tsc (evidence)", result.detail) self.assertIn( - "no chronyd frequency estimate: chronyc is not installed (evidence)", + "no chronyd frequency estimate: chronyc is not installed (evidence); " + f"no kernel PLL frequency: {PLL_OFF} (evidence)", result.detail, ) self.assertEqual(context.facts["rate_agreement_ppm"], "0.125") @@ -2745,19 +2756,51 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: self.assertEqual( context.facts["rate_reference"], "chronyd +44.300 ppm (skew 4.200 ppm)" ) - # Without chronyd's estimate, the slewed window is all H4 can measure. + # Without chronyd's estimate or a kernel PLL, the slewed window is all + # H4 can measure; a chronyd that isn't synchronized leaves the kernel + # clock unsynchronized too. context = ci_context("mshv") context.facts["native_tsc_hz"] = "2300000507" - result = check(context, slewed, chrony="chronyd is not synchronized") + unsynchronized = ( + "the kernel clock is not synchronized (adjtimex state=5 status=0x0041)" + ) + result = check( + context, + slewed, + chrony="chronyd is not synchronized", + kernel=unsynchronized, + ) self.assertFalse(result.passed) self.assertIn( "the backend rate is 946.078 ppm from the measured rate (limit 250 ppm)", result.detail, ) self.assertIn( - "no chronyd frequency estimate: chronyd is not synchronized (evidence)", + "no chronyd frequency estimate: chronyd is not synchronized (evidence); " + f"no kernel PLL frequency: {unsynchronized} (evidence)", result.detail, ) + # #1008: a kernel PLL that another time service drives, such as + # systemd-timesyncd, keeps its frequency estimate apart from the + # offsets that it slews, so H4 corrects CLOCK_MONOTONIC_RAW by that + # instead of reading the slewed window. + context = ci_context("mshv") + context.facts["native_tsc_hz"] = "2300000507" + result = check(context, slewed, kernel=doctor.KernelFrequency(-44.3)) + self.assertTrue(result.passed, result.detail) + self.assertIn( + "tsc_hz=2300101895 against CLOCK_MONOTONIC_RAW corrected by the kernel " + "PLL's frequency of -44.300 ppm from 3 samples 1 s apart", + result.detail, + ) + self.assertIn("44.082 ppm from the backend's 2300000507 Hz", result.detail) + self.assertIn( + "no chronyd frequency estimate: chronyc is not installed (evidence); " + "2302176486 Hz against CLOCK_MONOTONIC, which the kernel PLL also slews " + "(evidence)", + result.detail, + ) + self.assertEqual(context.facts["rate_reference"], "kernel PLL -44.300 ppm") # chronyd's estimate gates the backend's rate, whatever the window # reads, and its skew bounds the estimate: the rate passes only when # every rate within the skew lies within the limit. @@ -2981,6 +3024,45 @@ def test_chrony_frequency_reads_a_synchronized_tracking_report(self): with patch.object(doctor.shutil, "which", return_value=None): self.assertEqual(doctor.chrony_frequency(), "chronyc is not installed") + def test_kernel_frequency_reads_a_synchronized_kernel_pll(self): + # adjtimex's state and the status, freq, and tick of its struct timex. + def kernel(state: int, status: int, freq: int, tick: int = 10_000): + timex = types.SimpleNamespace(status=status, freq=freq, tick=tick) + return patch.object(doctor, "_adjtimex", return_value=(state, timex)) + + # systemd-timesyncd sets STA_PLL and STA_NANO. The frequency is in ppm + # scaled by 2^16, and each microsecond of tick above 10,000 adds + # 100 ppm, as chronyd's ticks of 9,999 take 100 ppm away. + for tick, ppm in ((10_000, -44.25), (10_001, 55.75), (9_999, -144.25)): + with self.subTest(tick=tick), kernel(0, 0x2001, -2_899_968, tick): + self.assertEqual(doctor.kernel_frequency(), doctor.KernelFrequency(ppm)) + for state, status, reason in ( + # chronyd keeps the PLL off, and slews through the frequency. + (0, 0x0000, "the kernel PLL is off (adjtimex status=0x0000)"), + ( + 5, + 0x2041, + "the kernel clock is not synchronized (adjtimex state=5 status=0x2041)", + ), + ( + 5, + 0x2001, + "the kernel clock is not synchronized (adjtimex state=5 status=0x2001)", + ), + ( + 0, + 0x0041, + "the kernel clock is not synchronized (adjtimex state=0 status=0x0041)", + ), + ): + with self.subTest(state=state, status=status): + with kernel(state, status, -2_899_968): + self.assertEqual(doctor.kernel_frequency(), reason) + with patch.object(doctor.ctypes, "CDLL", side_effect=OSError("no libc")): + self.assertEqual( + doctor.kernel_frequency(), "adjtimex is unavailable: no libc" + ) + def test_rate_check_continues_when_the_clocksource_is_unreadable(self): # #507: the host clocksource is evidence only, so an unreadable # sysfs file must not fail H4; the native probe still runs and the @@ -3031,6 +3113,7 @@ def records(gaps: tuple[int, int]) -> list[tuple[str, dict[str, str]]]: "chrony_frequency", return_value="chronyc is not installed", ), + patch.object(doctor, "kernel_frequency", return_value=PLL_OFF), ): result = doctor.check_rate(context) self.assertTrue(run.called) From c3c46e4b5b746f6dfa71819693db083ec49713d5 Mon Sep 17 00:00:00 2001 From: Pedro Henrique Penna Date: Thu, 29 Oct 2026 14:07:14 -0700 Subject: [PATCH 5/5] doctor: report H4's average correction since boot as evidence No single run of H4 can tell the TSC's error from the wander of the host's reference clock (#1008), but the host's clocks keep a long-run average: CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW both exclude suspend, and after a small offset at boot only the time service's gradual adjustments separate them. CLOCK_MONOTONIC_RAW's rate against CLOCK_MONOTONIC over the uptime is therefore the time service's correction averaged since boot, which needs no saved state. On Linux, H4 now reports that average as evidence: the TSC's rate against CLOCK_MONOTONIC_RAW corrected by it, the average and the hours that it covers, and, when H3 ran, that rate's deviation from the backend's. The job summary lists it. Slews just after boot or a live migration bias it, so H4 doesn't gate on it until runners show how it behaves. Measured read-only on 2026-10-29, after 38 to 42 hours of uptime, the average matched chronyd's current estimate within 2.0 ppm on the five KVM runners and the four steady MSHV runners, whose estimates ranged from -0.3 to +51.8 ppm, and within 0.2 ppm on prometheus32 after 63 days. On azure-mshv-1, whose reference wanders, it read +43.6 ppm over 38.5 hours while chronyd's estimate moved from +33.4 to +30.7 ppm, and +43.4 ppm half an hour later, when chronyd's read +21.3 ppm: close to the runner's long-run rate, which stayed between +34 and +48 ppm over any 6 hours of jobs. nvx-mshv-test, an MSHV test VM, read +43.4 ppm against chronyd's +35.2 ppm. The H4 tests check the evidence with and without H3's rate, and that Windows, which has no CLOCK_MONOTONIC_RAW, skips it; a new test checks the average's arithmetic, and that the host's own clocks give one. doc/ci.md describes it. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- doc/ci.md | 2 +- scripts/nvx_tools/doctor.py | 43 ++++++++++++++++++++++++++++++ scripts/test_time_abi.py | 53 +++++++++++++++++++++++++++++++++++++ 3 files changed, 97 insertions(+), 1 deletion(-) diff --git a/doc/ci.md b/doc/ci.md index e1495f02b..443f1d46e 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -1709,7 +1709,7 @@ fields, such as the microcode and the invariant-TSC flags, may read `unknown`. | H1 | `/dev/kvm` or `/dev/mshv` is readable and writable, and a KVM host has no `/dev/mshv`; on Windows, `WHvGetCapability` reports a hypervisor | | H2 | Vendor, family, model, stepping, microcode, and OS build from `/proc/cpuinfo` or the Windows registry. Then `openvmm --hypervisor --cpu-fingerprint ` writes the host's CPU fingerprint (by default `nvx-cpu-fingerprint-.json` in the probe directory; `--cpu-fingerprint` overrides it), checks it against the pinned profile that `auto` selects from OpenVMM's catalog, the latest revision of the generation's profile, which every backend shares, and prints one `NVX-CPU-PROFILE:` line. The check never falls back to a host profile, so a CPU on which `auto` falls back fails H2. H2 reports the generation and the profile from that line, so a profile that an OpenVMM pin adds qualifies its hosts without an NVX change. H2 requires exit status 0, `status=pass`, the same backend, and a catalog profile of the reported generation, reports the profile and surface digests, and otherwise fails with OpenVMM's code, for example `[E_PROFILE_HOST_UNKNOWN]` on a CPU that no profile serves or `[E_PROFILE_UNSUPPORTED]` naming every unsupported CPUID bit. On MSHV and WHP, OpenVMM checks the entries outside the profile on a probe partition configured from the profile, as a cold boot does. With `--no-openvmm`, H2 maps the host with NVX's copy of the catalog instead: `skylake-sp` (6/85, steppings 0 to 4, `intel.skylake-sp.v1`), `icelake-sp` (6/106, `intel.icelake-sp.v1`), `emeraldrapids` (6/207, `intel.emeraldrapids.v1`), `alderlake` (6/151 and 6/154, `intel.alderlake.v1`), `milan` (AMD 25/1, `amd.milan.v1`), `genoa` (AMD 25/17, `amd.genoa.v2`), or `turin` (AMD 26/2, `amd.turin.v1`). Any other CPU, including Cascade Lake and Cooper Lake, fails with `E_PROFILE_HOST_UNKNOWN`. A unit test keeps the copy, which records the latest revision of each generation's profile, equal to the profiles of the OpenVMM submodule's pinned revision, which it reads from the gitlink's commit, so the NVX CLI jobs validate the CLI after they check out OpenVMM. The host OS's invariant-TSC flags (`constant_tsc nonstop_tsc`, or the CPUID bit on Windows) are recorded as evidence and never fail the check, because they don't decide what a guest observes: Azure WHP hosts show the CPUID bit but cannot offer invariant TSC to partitions, and their guests measure tens of nanoseconds of skew | | H3 | `openvmm --x-time-abi-verify` builds the partition and runs the time ABI preflight without running the guest. Its `NVX-TIME-ABI-VERIFY:` line must report `status=ok` for the backend, plausible declared and native TSC rates, the backend's LAPIC rate, and a `cpu_profile` that is a catalog profile, `..v` of any generation but a host profile's `host`, which rejects the host profile that `auto` falls back to on a CPU that no built-in profile serves, and, when H2 runs too, a revision of the profile H2 names. A failed preflight reports OpenVMM's code, for example `[E_TSC_SYNC_UNSUPPORTED]` | -| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). Above that old bound, H4 passes with a warning that says how much of the budget the host's correction uses, and that one run can't tell the TSC's error from the reference's wander. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Without chronyd's estimate, on a Linux host whose kernel PLL another time service drives, such as systemd-timesyncd or ntpd, and which `adjtimex` reports synchronized, the rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the PLL's frequency, `adjtimex`'s frequency with its tick's, which the PLL keeps apart from the offsets that it slews; H4 never reads it with chronyd, which keeps the PLL off and slews through that frequency. Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why neither estimate is available, or against `QueryPerformanceCounter` on Windows. A Linux host's clocksource is recorded as evidence | +| H4 | Samples of the TSC against the host's monotonic clocks, with sleeps between them so the host's CPUs idle: 13 samples 10 s apart, or 3 samples 1 s apart with `--ci-schedule`. Each sample reads the TSC between two reads of a clock, keeping the tightest of 64 brackets; its uncertainty is half the bracket plus half the clock's resolution. A clock that returns the same value to consecutive reads is coarser than one read, so the probe takes its smallest step as its resolution: Hyper-V's reference TSC page advances the Linux clocks in 100 ns steps although `clock_getres` reports 1 ns. The interval stability is judged against a clock that time synchronization never steers, `CLOCK_MONOTONIC_RAW` on Linux and `QueryPerformanceCounter` on Windows: every interval between consecutive samples must be conclusive within 0.25 ppm, and the interval rates must agree within 1 ppm. chrony's frequency updates move `CLOCK_MONOTONIC`'s rate by up to several ppm between seconds on the Azure runners, which says nothing about the TSC. The rate over the whole window must lie within 250 ppm of the rate H3 reports when H3 runs in the same invocation, and H4 reports their deviation to 0.001 ppm. The limit is the guest's budget for the host's clock correction: the guest's [wall-clock discipline](design/3.2-clock-and-time.md#3210-guest-obligations) follows host UTC, so it applies the host's correction on top of a restore's rate deviation, which the time ABI's restore tolerance bounds at 250 ppm, within Linux's frequency limit of ±500 ppm. Beyond the budget the guest doesn't fail: its offset grows to 128 ms, and the discipline steps its clock and counts a discontinuity. A unit test keeps the limit equal to the difference of nvx-rs's frequency limit and its restore deviation limit, and the latter equal to the restore tolerance of the OpenVMM gitlink's commit. The limit doesn't bound the TSC's error alone, as the time ABI v1's 100 ppm did, because no run can tell that error from the wander of the host's reference clock: on `azure-mshv-1`, chronyd's estimate ranged from +2.5 to +189.3 ppm within a day while the TSC held its rate (#1008). Above that old bound, H4 passes with a warning that says how much of the budget the host's correction uses, and that one run can't tell the TSC's error from the reference's wander. On Linux with a synchronized chronyd, that rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the frequency that chronyd estimates from its whole sample history, as `chronyc -c tracking` reports it, and every rate within chronyd's skew of that estimate must lie within the limit. The reference's wander can move the estimate and its skew within seconds, so when that range straddles the limit, H4 re-reads the estimate every 2 s for up to 60 s and uses the first whose range lies wholly within or wholly beyond the limit, with the same samples, since only the estimate changes; a range that straddles the limit throughout fails as inconclusive. The rate against `CLOCK_MONOTONIC` is evidence only, because it also carries the slew with which chronyd removes its current offset, which reaches hundreds of ppm for seconds after the host's clock jumps (#768). Without chronyd's estimate, on a Linux host whose kernel PLL another time service drives, such as systemd-timesyncd or ntpd, and which `adjtimex` reports synchronized, the rate is the rate against `CLOCK_MONOTONIC_RAW` corrected by the PLL's frequency, `adjtimex`'s frequency with its tick's, which the PLL keeps apart from the offsets that it slews; H4 never reads it with chronyd, which keeps the PLL off and slews through that frequency. Otherwise the rate is measured against `CLOCK_MONOTONIC` on Linux, and the detail says why neither estimate is available, or against `QueryPerformanceCounter` on Windows. On Linux, H4 also reports as evidence the average correction since boot, the rate of `CLOCK_MONOTONIC_RAW` against `CLOCK_MONOTONIC` over the uptime, and the deviation from the backend's rate that it gives: both clocks exclude suspend, and after a small offset at boot only the time service's gradual adjustments separate them, so the average smooths the reference's wander out without saved state, but slews just after boot or a live migration bias it, so H4 doesn't gate on it. A Linux host's clocksource is recorded as evidence | | H5 | Pinned-thread ping-pong rounds over every pair of host CPUs; `max_abs_offset_ns` is at most 1,000, the measurement is conclusive, and no pair stalls | | H6 | A microVM with the largest supported vCPU count up to 8 reports a valid `NVX-TIME-ABI` boot line through `nvx-time status` and runs `nvx-time-probe warp` over every CPU pair five times, with all vCPUs halted for 0.1, 1, 5, and 1 s between the runs, so that a host without an invariant TSC corrects the guest TSC as idle host CPUs wake (#265); then a 1-vCPU microVM runs it once. Every run stays within 1,000 ns. `--ci-schedule` runs CI's schedule instead: two runs 1 s apart | | H7 | `adjtimex` reports no `STA_UNSYNC` and no `TIME_ERROR` on Linux; `w32tm /query /status` names a synchronized source on Windows. When H7 can't read either, its detail starts with `cannot verify host UTC synchronization`: `adjtimex` fails or reports a clock state Linux doesn't define, or `w32tm` fails or prints no English `Source` and `Leap Indicator` lines, as in a Windows display language other than English | diff --git a/scripts/nvx_tools/doctor.py b/scripts/nvx_tools/doctor.py index d7268a34e..fbb9bc94f 100644 --- a/scripts/nvx_tools/doctor.py +++ b/scripts/nvx_tools/doctor.py @@ -900,6 +900,34 @@ def kernel_frequency() -> KernelFrequency | str: ) +@dataclass(frozen=True) +class BootCorrection: + """The time service's frequency correction averaged since boot: how fast + CLOCK_MONOTONIC_RAW ran against CLOCK_MONOTONIC, in ppm, as chronyd's + estimate says how fast it runs now, over ``seconds``.""" + + ppm: float + seconds: float + + +def boot_correction() -> BootCorrection | None: + """Return the time service's frequency correction averaged since boot, or + None where the host has no CLOCK_MONOTONIC_RAW. + + Both clocks exclude suspend, and after a small offset at boot only the + time service's gradual adjustments separate them, so their difference + over the uptime averages the reference's wander out without saved state. + Slews just after boot or a live migration bias it. + """ + if sys.platform == "win32": + return None + raw = time.clock_gettime_ns(time.CLOCK_MONOTONIC_RAW) + monotonic = time.clock_gettime_ns(time.CLOCK_MONOTONIC) + if raw <= 0: + return None + return BootCorrection((raw - monotonic) / raw * 1e6, raw / 1e9) + + def _deviation_ppm(rate: float, declared_hz: int) -> float: return (rate - declared_hz) / declared_hz * 1e6 @@ -1117,6 +1145,20 @@ def conclusive(estimate: ChronyFrequency) -> bool: ) elif kernel is not None: detail += f"; no kernel PLL frequency: {kernel} (evidence)" + boot = None if host_is_windows() else boot_correction() + if boot is not None: + hours = boot.seconds / 3600 + boot_rate = _corrected_rate(stable_rate, boot.ppm) + detail += ( + f"; {boot_rate:.0f} Hz against {stability_clock['name']} corrected by " + f"the average correction since boot, {boot.ppm:+.3f} ppm over " + f"{hours:.1f} h" + ) + if declared_hz is not None: + boot_deviation = abs(_deviation_ppm(boot_rate, declared_hz)) + detail += f", {boot_deviation:.3f} ppm from the backend's rate" + detail += " (evidence)" + context.facts["boot_correction"] = f"{boot.ppm:+.3f} ppm over {hours:.1f} h" if clocksource: detail += f"; host clocksource {clocksource} (evidence)" if warning: @@ -1382,6 +1424,7 @@ def summary_markdown( ("rate_deviation_ppm", "Rate deviation from the backend (ppm)"), ("rate_agreement_ppm", "Interval rate agreement (ppm)"), ("rate_uncertainty_ppm", "Largest interval uncertainty (ppm)"), + ("boot_correction", "Average correction since boot (evidence)"), ("host_skew_ns", "Host skew (ns)"), ("guest_warp_ns", "Guest warp offset (ns)"), ("invariant_tsc", "Host invariant TSC (evidence)"), diff --git a/scripts/test_time_abi.py b/scripts/test_time_abi.py index c1f9f867e..fe35e6530 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -7,6 +7,7 @@ import dataclasses import io import json +import math import queue import re import shutil @@ -15,6 +16,7 @@ import sys import tempfile import threading +import time import types import unittest from collections.abc import Sequence @@ -2568,6 +2570,7 @@ def check( | Sequence[doctor.ChronyFrequency | str] = "chronyc is not installed", clock: FakeClock | None = None, kernel: doctor.KernelFrequency | str = PLL_OFF, + boot: doctor.BootCorrection | None = None, ) -> doctor.CheckResult: """Run H4; a list of chronyd readings answers its re-reads too.""" clock = clock or FakeClock() @@ -2583,12 +2586,14 @@ def check( side_effect=readings, ) as frequency, patch.object(doctor, "kernel_frequency", return_value=kernel) as pll, + patch.object(doctor, "boot_correction", return_value=boot) as average, patch.object(doctor.time, "monotonic", clock.monotonic), patch.object(doctor.time, "sleep", clock.sleep), ): result = doctor.check_rate(context) # Windows reads QueryPerformanceCounter, which no daemon steers. self.assertEqual(frequency.called, not windows) + self.assertEqual(average.called, not windows) # H4 reads the kernel's PLL only without chronyd's estimate. first = readings[0] if readings else chrony self.assertEqual(pll.called, not windows and isinstance(first, str)) @@ -2801,6 +2806,29 @@ def ci_context(backend: str = "kvm") -> doctor.DoctorContext: result.detail, ) self.assertEqual(context.facts["rate_reference"], "kernel PLL -44.300 ppm") + # #1008: the average correction since boot, CLOCK_MONOTONIC_RAW's rate + # against CLOCK_MONOTONIC over the uptime, averages the reference's + # wander out. On azure-mshv-1, it read +43.559 ppm over 38.5 h while + # chronyd's estimate wandered. It is evidence only. + boot = doctor.BootCorrection(43.559, 138_435.1) + average = ( + "2300100190 Hz against CLOCK_MONOTONIC_RAW corrected by the average " + "correction since boot, +43.559 ppm over 38.5 h" + ) + context = ci_context("mshv") + context.facts["native_tsc_hz"] = "2300000507" + wandering = doctor.ChronyFrequency("PHC0", 189.3, 1) + result = check(context, slewed, chrony=wandering, boot=boot) + self.assertTrue(result.passed, result.detail) + self.assertIn("189.115 ppm from the backend's 2300000507 Hz", result.detail) + self.assertIn( + f"; {average}, 43.340 ppm from the backend's rate (evidence)", + result.detail, + ) + self.assertEqual(context.facts["boot_correction"], "+43.559 ppm over 38.5 h") + # Without H3, it has no rate to compare. + result = check(ci_context("mshv"), slewed, chrony=wandering, boot=boot) + self.assertIn(f"; {average} (evidence)", result.detail) # chronyd's estimate gates the backend's rate, whatever the window # reads, and its skew bounds the estimate: the rate passes only when # every rate within the skew lies within the limit. @@ -3063,6 +3091,31 @@ def kernel(state: int, status: int, freq: int, tick: int = 10_000): doctor.kernel_frequency(), "adjtimex is unavailable: no libc" ) + def test_boot_correction_averages_the_clocks_since_boot(self): + if sys.platform == "win32": + # Windows has no CLOCK_MONOTONIC_RAW, and no daemon steers + # QueryPerformanceCounter. + self.assertIsNone(doctor.boot_correction()) + return + # azure-mshv-1, 38.5 h after boot: CLOCK_MONOTONIC trailed + # CLOCK_MONOTONIC_RAW by 6.03 s. + clocks = { + time.CLOCK_MONOTONIC_RAW: 138_435_100_000_000, + time.CLOCK_MONOTONIC: 138_429_069_887_000, + } + with patch.object( + doctor.time, "clock_gettime_ns", side_effect=clocks.__getitem__ + ): + correction = doctor.boot_correction() + assert correction is not None + self.assertAlmostEqual(correction.ppm, 43.559, places=3) + self.assertEqual(correction.seconds, 138_435.1) + # This host's clocks give a finite average over its uptime. + correction = doctor.boot_correction() + assert correction is not None + self.assertTrue(math.isfinite(correction.ppm)) + self.assertGreater(correction.seconds, 0) + def test_rate_check_continues_when_the_clocksource_is_unreadable(self): # #507: the host clocksource is evidence only, so an unreadable # sysfs file must not fail H4; the native probe still runs and the