kernel: the clock ran 7x slow because the GPU never acknowledged its interrupt
fastfetch reported 3 seconds of uptime after 15 real ones, `time` claimed
3.12s for a 20-second command, and ping's one-second interval was closer to
six. One cause, not three: `ticks` was advancing at ~14.5 Hz instead of 100.
It was not the timer. virtio-gpu-pci shares IRQ 11 with the e1000 and
registered no interrupt handler at all. PCI INTx is level-triggered, so the
device held the line asserted, the kernel signalled EOI, and it fired again
immediately -- 72,000 interrupts a second, 83% of CPU0, starving the tick.
The e1000's handler read ICR as zero half a million times, correctly
answering "not mine", which is what made it look like a network-free problem.
Reading virtio's ISR byte clears it and drops the line. That is the fix.
irq_dispatch now measures each line's rate against the TSC -- not ticks,
which is the first casualty of a storm -- and names the attached handlers
once above 20000/s. It reproduces the original fault as a single line.
Found along the way, and fixed because they were real:
- lapicinit loaded TICR with xv6's uncalibrated 10000000, whose own comment
admitted it was never measured. calibrate_timers() now measures the LAPIC
and the TSC against the 8254 PIT. (It came back at 999.9 MHz, so this was
not the bug -- but the next machine is not obliged to be 1 GHz.)
- microdelay() was an empty function body. Every microdelay(1000) in the
xHCI reset path and the USB hub power-on sequence returned instantly.
- HZ is a constant in param.h now, not the literal 100 written out at a
dozen ticks-to-seconds conversions. USER_HZ is separate and deliberately
does not follow it: musl answers sysconf(_SC_CLK_TCK) with 100 always, so
times() and /proc/stat scale at the syscall boundary the way Linux does.
- TIOCGWINSZ answered a hardcoded 24x80. gfx_cols()/gfx_rows() have known
the real geometry all along; at 1024x768 the console is 128x48, so every
program that lays out a screen was formatting for the wrong one.
- TCFLSH fell through to the catch-all `return 0`, claiming to discard
input without discarding any.
uptime now advances 5.01 seconds per 5 real seconds. schfs-check passes.
Full investigation, including the two wrong hypotheses and the measurement
flaw that protected them, in docs/history/kernel.md section 13.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VQ7Qx8E1q1M1bbCq8QLHS2
This commit is contained in:
parent
c874811679
commit
9d4cdb44fc
17 changed files with 479 additions and 37 deletions
|
|
@ -760,3 +760,147 @@ Schcom and a client both want the keyboard.
|
|||
to be lying around. It returns `-ENOTDIR` now, and `-ENOENT`/`-EFAULT` on the
|
||||
other two failure paths -- "Not a directory" sends you to the right place,
|
||||
"Operation not permitted" sends you looking at permissions.
|
||||
|
||||
## 13. The clock ran seven times slow, and the graphics card was why
|
||||
|
||||
The report was about time. fastfetch said the machine had been up for 3 seconds
|
||||
after 15 real ones. `time ping 127.0.0.1` claimed `0m03.12s real` for a command
|
||||
that visibly took 20. ping's one-second interval was closer to six. Three
|
||||
programs, three wrong numbers, all wrong by roughly the same factor and all in
|
||||
the same direction -- which is the shape of one shared cause, not three bugs.
|
||||
|
||||
The shared cause was obviously the tick. Everything above is derived from
|
||||
`ticks`, and `ticks` comes from the timer interrupt. So the hunt started at the
|
||||
bottom of that chain, and the first thing it found was real:
|
||||
|
||||
```c
|
||||
// If xv6 cared more about precise timekeeping,
|
||||
// TICR would be calibrated using an external time source.
|
||||
lapicw(TICR, 10000000);
|
||||
```
|
||||
|
||||
That is xv6's own comment, still in the tree, admitting that the LAPIC timer's
|
||||
countdown value was never measured against anything. 10000000 yields the
|
||||
intended 100 Hz only if the APIC bus happens to run at exactly 1 GHz.
|
||||
|
||||
It was a genuine gap and it is now fixed -- `calibrate_timers()` measures the
|
||||
LAPIC and the TSC against the 8254 PIT, which is fixed at 1193182 Hz by the
|
||||
hardware and is exactly the external time source the comment asked for. But it
|
||||
was not the bug. The measurement came back at 999.9 MHz. The bus really was
|
||||
1 GHz, `TICR = 10000000` really was 100 Hz, and the clock was still wrong.
|
||||
|
||||
### What the instruments said
|
||||
|
||||
Every clock agreed with every other clock, which is the confusing part:
|
||||
|
||||
| measured against | TSC | LAPIC timer |
|
||||
|---|---|---|
|
||||
| the PIT | 3792 MHz | 999 MHz |
|
||||
| one CMOS RTC second | 3791 MHz | 999 MHz |
|
||||
|
||||
Three independent clocks, mutually consistent, and 3792 MHz is exactly the
|
||||
5700G's base clock. So the timer was programmed for 10 ms and the registers
|
||||
read back correct at runtime: `TICR=10000314`, `TDCR=11` (divide by one),
|
||||
`LVT=0x20020` (periodic, vector 32). Interrupts nonetheless arrived every 68 ms.
|
||||
|
||||
Two hypotheses died next. Interrupts were not being masked -- the CPU had
|
||||
`IF=1` for 99.98% of the measured window. And it was not the idle `hlt()`:
|
||||
deleting it changed nothing, and neither did dropping to `-smp 1`.
|
||||
|
||||
What broke it open was measuring the gaps between consecutive timer interrupts
|
||||
instead of averaging them:
|
||||
|
||||
```
|
||||
timer gaps us: 2851 137614 2438 136293 3805 136889 3019 138420 6950 137248
|
||||
```
|
||||
|
||||
Bimodal, strictly alternating. Not a slow clock -- a clock being interrupted.
|
||||
In one-shot mode the short gaps sharpened to 10031, 10078, 10064, 10011 µs,
|
||||
which is a perfect 10 ms: the LAPIC was doing its job exactly as programmed,
|
||||
and then something was eating the next 130 ms.
|
||||
|
||||
Timing every trap by vector found it in one boot:
|
||||
|
||||
```
|
||||
trapno 43: 5828 ms total, 510000 entries
|
||||
```
|
||||
|
||||
Vector 43 is `T_IRQ0 + 11`. IRQ 11 was taking **72,000 interrupts a second** and
|
||||
consuming 83% of CPU0.
|
||||
|
||||
### The actual bug
|
||||
|
||||
IRQ 11 was the e1000. Its handler reads ICR, and reading ICR clears it, so the
|
||||
driver looked correct -- and it was. The cause register read back **zero** on
|
||||
essentially every one of those 500,000 interrupts: the e1000 was being handed
|
||||
somebody else's interrupt and correctly answering "not mine".
|
||||
|
||||
The somebody else was `virtio-gpu-pci`, sharing IRQ 11, **with no interrupt
|
||||
handler registered at all**. PCI INTx is level-triggered. The device asserted
|
||||
the line, the kernel signalled EOI, nothing had cleared the device's interrupt
|
||||
status, so the line was still asserted and it fired again immediately. Forever.
|
||||
|
||||
The fix is one read. Reading virtio's ISR byte clears it and drops the line:
|
||||
|
||||
```c
|
||||
static void
|
||||
vgpu_intr(void *arg)
|
||||
{
|
||||
struct vgpu *g = arg;
|
||||
if (g && g->isr)
|
||||
(void)*g->isr;
|
||||
}
|
||||
```
|
||||
|
||||
This driver polls for command completion and wants no notifications. "Wants
|
||||
none" and "gets none" are different things, and only the second one is free.
|
||||
|
||||
Booting without `-device virtio-gpu-pci` had already proved it: 100 ticks in
|
||||
999 ms, and the e1000 taking 2 interrupts instead of half a million. With the
|
||||
handler registered, uptime advances 5.01 seconds per 5 real seconds.
|
||||
|
||||
### What to take from it
|
||||
|
||||
**A shared level-triggered line is only as good as its worst driver.** Every
|
||||
other device on IRQ 11 was correct. One driver that never acknowledged its
|
||||
device was enough to starve the whole machine.
|
||||
|
||||
**The symptom appears where the missing CPU time hurts first, which is nowhere
|
||||
near the fault.** This surfaced as a timekeeping bug, in userspace, in three
|
||||
unrelated programs. It sent the investigation into the timer code, where there
|
||||
was a real defect sitting in plain sight with a comment explaining itself --
|
||||
and fixing that defect changed nothing, because it was not this one. A
|
||||
plausible bug found early is the most expensive thing in a debugging session.
|
||||
|
||||
**Averages hide alternation.** "68 ms per interrupt" suggested a wrong
|
||||
frequency and implied the timer. "10 ms, then 130 ms, repeating" says the timer
|
||||
is fine and something else is stealing the machine. Same data, one of them
|
||||
divided.
|
||||
|
||||
`irq_dispatch` now measures the rate on every line against the TSC -- not
|
||||
against `ticks`, which is the first casualty of a storm -- and says so once:
|
||||
|
||||
```
|
||||
irq 11: 75894 interrupts/second -- a device on this line is not acknowledging it.
|
||||
irq 11: handler 'virtio-gpu' is attached
|
||||
irq 11: handler 'e1000' is attached
|
||||
```
|
||||
|
||||
That is the message this cost an afternoon for. The threshold is 20000/s, which
|
||||
no real device on this machine sustains.
|
||||
|
||||
### Also fixed
|
||||
|
||||
`microdelay()` was an empty function body -- xv6's stub, with a comment saying
|
||||
real hardware would want to tune it. Every `microdelay(1000)` in the xHCI reset
|
||||
path and the USB hub power-on sequence returned instantly. Those waits are in
|
||||
the specifications because the hardware needs the time; a port that "works
|
||||
anyway" is racing and winning. It now spins on the calibrated TSC.
|
||||
|
||||
The tick rate itself stopped being a magic number. `HZ` lives in `param.h`, and
|
||||
the dozen places that wrote `ticks / 100` or `sec * 100` use it. `USER_HZ` is
|
||||
separate and deliberately does not follow it: musl answers
|
||||
`sysconf(_SC_CLK_TCK)` with 100 no matter what, so `times()` and `/proc/stat`
|
||||
are scaled at the syscall boundary the way Linux does it. Before, `sys_times`
|
||||
returned raw ticks -- correct only while `HZ` happened to be 100, and silently
|
||||
wrong the day anyone changed it.
|
||||
|
|
|
|||
Loading…
Reference in a new issue