[GH-ISSUE #64] pexpert: i386 local APIC timer calibration can be off by a large factor (one 10 ms sample), skewing every guest time interval #57

New issue

Closed

opened 2026-11-03 22:03:24 -07:00 by gitea-mirror · 1 comment

gitea-mirror commented

2026-11-03 22:03:24 -07:00

Owner

Originally created by @raynorpat on GitHub (Oct 19, 2026).
Original GitHub issue: https://github.com/RhapsodiOS/RhapsodiOS/issues/64

Symptom

On i386, when pexpert switches the system clock to the local APIC timer, the calibration sometimes comes out wrong by a large factor. Every guest-time interval is then wrong by that factor: the clock, sleep, timeouts, and the stress suite's watchdog.

Seen under QEMU TCG on a loaded host. Two guests booted at the same time from the same image and kernels:

Guest	COM2 at boot	Clock vs host
A	`pexpert: local APIC timer is the clock, 104817 counts per tick (160 MHz bus / 16)`	3.4x fast
B	`... 1247564 counts per tick (1984 MHz bus / 16)`	0.5x slow
both, after reboot	`621777` / `624164` counts per tick (~992 MHz bus / 16)	correct

On guest A the stress suite's 600 s watchdog fired after about 175 real seconds. That turned a normal mmap trunc run into a FAIL reason=timeout secs=600, which first looked like a kernel hang.

Cause (as far as known)

src/drivers-i386/bus/drvPExpert/i386/clock.c:

lapic_ticks_in() (:28-49) measures one 10 ms window (CALIBRATE_US).
It counts LAPIC timer ticks against IOGetTimestamp() and scales the result to the window.
lapic_clock_enable() (:51-) takes that single sample as per_10ms and multiplies it by 100.

There is no repeat, no sanity check, and no agreement test between samples. If the vCPU is descheduled, or the reference timestamp misbehaves inside that one 10 ms window, the error carries straight into count_per_tick. The errors seen are close to whole multiples (about 6x and 0.5x of the true rate), which suggests a missed or doubled wrap of the 8254-based reference rather than random jitter.

Expected

Calibration should be robust:

take several samples (and/or a longer window);
reject outliers and require agreement;
fall back to the 8254 if they can't be made to agree.

Optionally, cross-check the result against the RTC over a longer interval.

Reproduce

Boot several -snapshot QEMU guests of vm/work/rhap-i386-bootstrapped-v2.img at once on a busy host (TCG) and read the pexpert: local APIC timer is the clock, N counts per tick line on COM2. Correct is about 624000 at 992 MHz / 16. Compare date in the guest against the host over a minute.

Found by the stress suite (the soak mmap trunc "hang", investigated in vm/work/soak-trunc/). Related: #46 (early timers).

Originally created by @raynorpat on GitHub (Oct 19, 2026). Original GitHub issue: https://github.com/RhapsodiOS/RhapsodiOS/issues/64 ## Symptom On i386, when pexpert switches the system clock to the local APIC timer, the calibration sometimes comes out wrong by a large factor. Every guest-time interval is then wrong by that factor: the clock, `sleep`, timeouts, and the stress suite's watchdog. Seen under QEMU TCG on a loaded host. Two guests booted at the same time from the same image and kernels: | Guest | COM2 at boot | Clock vs host | |---|---|---| | A | `pexpert: local APIC timer is the clock, 104817 counts per tick (160 MHz bus / 16)` | **3.4x fast** | | B | `... 1247564 counts per tick (1984 MHz bus / 16)` | **0.5x slow** | | both, after reboot | `621777` / `624164` counts per tick (~992 MHz bus / 16) | correct | On guest A the stress suite's 600 s watchdog fired after about 175 real seconds. That turned a normal `mmap trunc` run into a `FAIL reason=timeout secs=600`, which first looked like a kernel hang. ## Cause (as far as known) `src/drivers-i386/bus/drvPExpert/i386/clock.c`: - `lapic_ticks_in()` (:28-49) measures one 10 ms window (`CALIBRATE_US`). - It counts LAPIC timer ticks against `IOGetTimestamp()` and scales the result to the window. - `lapic_clock_enable()` (:51-) takes that single sample as `per_10ms` and multiplies it by 100. There is no repeat, no sanity check, and no agreement test between samples. If the vCPU is descheduled, or the reference timestamp misbehaves inside that one 10 ms window, the error carries straight into `count_per_tick`. The errors seen are close to whole multiples (about 6x and 0.5x of the true rate), which suggests a missed or doubled wrap of the 8254-based reference rather than random jitter. ## Expected Calibration should be robust: - take several samples (and/or a longer window); - reject outliers and require agreement; - fall back to the 8254 if they can't be made to agree. Optionally, cross-check the result against the RTC over a longer interval. ## Reproduce Boot several `-snapshot` QEMU guests of `vm/work/rhap-i386-bootstrapped-v2.img` at once on a busy host (TCG) and read the `pexpert: local APIC timer is the clock, N counts per tick` line on COM2. Correct is about 624000 at 992 MHz / 16. Compare `date` in the guest against the host over a minute. Found by the stress suite (the soak `mmap trunc` "hang", investigated in `vm/work/soak-trunc/`). Related: #46 (early timers).

gitea-mirror closed this issue

2026-11-03 22:03:26 -07:00

gitea-mirror commented

2026-11-03 22:03:27 -07:00

Author

Owner

@raynorpat commented on GitHub (Oct 20, 2026):

Fixed by dd7f4ebcb (pexpert: calibrate the local APIC timer against 8254 counter 2, median of five bracketed samples), merged into ffs-perf in a104feaaa.

Mechanism. The old lapic_ticks_in timed one 10 ms window with IOGetTimestamp, which is IRQ 0's tick count plus counter 0's fraction (kernel-7/machdep/i386/machine_clock.c ~450-490).

Slow (2x/3x): when the vCPU is held off across two counter-0 reloads, the edges merge into one interrupt and a whole tick is lost. The "hold still" clamp then freezes the timestamp, so the 10 ms window really spans 20 or 30 ms.
Fast: a tick interrupt landing just after the start read makes the timestamp jump, so the window closes early.
Evidence: a raw-count probe caught a bad first sample, the one the stock code uses: timestamp 10.03 ms, but 1246331 LAPIC counts (19.9 ms). A hold-off probe produced 2x, 3x and fast readings on demand.

Fix.

The reference is now 8254 counter 2, one-shot and gated through port 0x61 with the speaker off. It needs no interrupt, so the lost/gained-tick mechanism is gone.
Each counter read is bracketed by two LAPIC reads. A sample held off inside a pair, or one where counter 2 ran out, is refused.
Five clean samples are taken; the median is used if the middle three agree within 1%. Up to three sets are tried, then it falls back to the 8254 with a console line.
tests/lapic_calibration_test.py now simulates stalls; it passes, and 4 checks fail when the guards are removed.

Concurrent boots, 6 guests at a time on a loaded host, stock and fixed side by side:

	boots	counts per tick
stock	60	2 bad: 17155 (36x fast), 67909 (9x fast); others 616706-623674
fixed	57	625020-625064 every time, no fallbacks

Guest date against the host over 60 s: within ±1 s on all 6 fixed guests. misc timer and vm clock pass.

Left open: the kernel's own timestamp (the 8254 clock path) still loses ticks when the CPU is held off. That is outside pexpert and only matters when the LAPIC clock isn't in use.

@raynorpat commented on GitHub (Oct 20, 2026): Fixed by dd7f4ebcb (pexpert: calibrate the local APIC timer against 8254 counter 2, median of five bracketed samples), merged into ffs-perf in a104feaaa. **Mechanism.** The old `lapic_ticks_in` timed one 10 ms window with `IOGetTimestamp`, which is IRQ 0's tick count plus counter 0's fraction (`kernel-7/machdep/i386/machine_clock.c` ~450-490). - **Slow (2x/3x):** when the vCPU is held off across two counter-0 reloads, the edges merge into one interrupt and a whole tick is lost. The "hold still" clamp then freezes the timestamp, so the 10 ms window really spans 20 or 30 ms. - **Fast:** a tick interrupt landing just after the start read makes the timestamp jump, so the window closes early. - **Evidence:** a raw-count probe caught a bad first sample, the one the stock code uses: timestamp 10.03 ms, but 1246331 LAPIC counts (19.9 ms). A hold-off probe produced 2x, 3x and fast readings on demand. **Fix.** - The reference is now 8254 counter 2, one-shot and gated through port 0x61 with the speaker off. It needs no interrupt, so the lost/gained-tick mechanism is gone. - Each counter read is bracketed by two LAPIC reads. A sample held off inside a pair, or one where counter 2 ran out, is refused. - Five clean samples are taken; the median is used if the middle three agree within 1%. Up to three sets are tried, then it falls back to the 8254 with a console line. - `tests/lapic_calibration_test.py` now simulates stalls; it passes, and 4 checks fail when the guards are removed. **Concurrent boots, 6 guests at a time on a loaded host, stock and fixed side by side:** | | boots | counts per tick | |---|---|---| | stock | 60 | 2 bad: 17155 (36x fast), 67909 (9x fast); others 616706-623674 | | fixed | 57 | 625020-625064 every time, no fallbacks | Guest `date` against the host over 60 s: within ±1 s on all 6 fixed guests. `misc timer` and `vm clock` pass. **Left open:** the kernel's own timestamp (the 8254 clock path) still loses ticks when the CPU is held off. That is outside pexpert and only matters when the LAPIC clock isn't in use.