diff --git a/doc/ci.md b/doc/ci.md index 976693800..443f1d46e 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 @@ -1696,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 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). 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/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/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 0a55c359a..fbb9bc94f 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 @@ -75,7 +76,17 @@ # 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 +# 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 @@ -83,6 +94,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 @@ -119,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. @@ -132,6 +154,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" @@ -168,6 +192,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] @@ -772,6 +801,160 @@ 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 + + +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 + ) + + +@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 + + +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(): @@ -826,16 +1009,43 @@ 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 + # 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): - # 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, " @@ -844,6 +1054,15 @@ def check_rate(context: DoctorContext) -> CheckResult: 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']}" @@ -860,6 +1079,7 @@ def check_rate(context: DoctorContext) -> CheckResult: 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: @@ -872,30 +1092,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" @@ -912,8 +1120,17 @@ 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}" + ) + 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 += ( f"; {window_rate:.0f} Hz against {rate_clock['name']}, which chronyd " @@ -921,11 +1138,34 @@ def deviation(rate: float) -> float: ) 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)" + 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: + 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: @@ -1041,21 +1281,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]: @@ -1150,6 +1379,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 @@ -1169,6 +1404,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"), @@ -1184,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 2cc1ed696..fe35e6530 100644 --- a/scripts/test_time_abi.py +++ b/scripts/test_time_abi.py @@ -2,10 +2,12 @@ from __future__ import annotations +import ast import contextlib import dataclasses import io import json +import math import queue import re import shutil @@ -14,7 +16,10 @@ import sys import tempfile import threading +import time +import types import unittest +from collections.abc import Sequence from pathlib import Path from typing import cast from unittest.mock import patch @@ -100,6 +105,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( @@ -1850,6 +1925,25 @@ 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.""" + + 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", @@ -2401,6 +2495,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], @@ -2441,19 +2565,38 @@ 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, + 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() + 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, "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)) self.assertEqual( run.call_args.args[1:], ( @@ -2495,7 +2638,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") @@ -2556,7 +2700,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): @@ -2617,19 +2761,74 @@ 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 100 ppm)", + "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); " + 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: chronyd is not synchronized (evidence)", + "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") + # #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. @@ -2641,51 +2840,150 @@ 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", 150, 1), + "2300000507", + True, + "149.802 ppm from the", + ), ( - doctor.ChronyFrequency("PHC0", 90, 15), + 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): 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) + # 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 + 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)) + # 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) + 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. + # 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") + 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 = ( @@ -2754,6 +3052,70 @@ 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_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 @@ -2804,6 +3166,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) @@ -3088,6 +3451,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] = []