SchOS/kernel/dev/irq.c
Nexoniarz 9d4cdb44fc 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
2026-09-12 21:34:36 +02:00

273 lines
7.8 KiB
C

// Hardware interrupt registration. See include/irq.h for why this exists.
#include "types.h"
#include "defs.h"
#include "param.h"
#include "traps.h"
#include "spinlock.h"
#include "irq.h"
#include "x86.h"
struct irq_action {
irq_handler_t fn;
void *arg;
const char *name;
uint64 count;
};
static struct {
struct irq_action act[NCHAIN];
int n; // handlers installed; only ever grows during boot
int enabled;
int level_low;
uint64 unhandled;
} line[NIRQ];
// Guards registration against itself. The *dispatch* path deliberately does
// not take it: an interrupt handler that blocked on a lock held by whoever
// was registering would deadlock the CPU it fired on. Instead registration
// publishes an entry by writing all of its fields, issuing a barrier, and
// only then incrementing n -- so a concurrent dispatcher either does not see
// the entry at all or sees it complete.
//
// Removal is the harder direction, because compacting the array *does* move
// entries a dispatcher may be walking. irq_unregister therefore masks the
// line first and only re-routes it once the chain has been rewritten: with
// the line masked no new interrupt can arrive, and any handler already
// running holds no reference past its own return.
static struct spinlock irqlock;
void
irq_init(void)
{
initlock(&irqlock, "irq");
}
// IRQ_ERROR and IRQ_SPURIOUS are not IOAPIC pins -- they are local APIC
// vectors that xv6 numbered as though they were, so T_IRQ0+19 and T_IRQ0+31
// are already spoken for. A PCI device routed to pin 19 would deliver on the
// same vector as the LAPIC error interrupt. Refuse it here rather than let it
// be debugged later.
static int
reserved(int irq)
{
return irq == IRQ_ERROR || irq == IRQ_SPURIOUS || irq == IRQ_TIMER;
}
int
irq_register(int irq, irq_handler_t fn, void *arg, const char *name,
int level_low)
{
struct irq_action *a;
if(irq < 0 || irq >= NIRQ || fn == 0)
return -1;
if(reserved(irq)){
cprintf("irq_register: %s wants irq %d, which is reserved\n", name, irq);
return -1;
}
acquire(&irqlock);
if(line[irq].n >= NCHAIN){
release(&irqlock);
cprintf("irq_register: irq %d chain full, %s not attached\n", irq, name);
return -1;
}
// Two devices sharing a line must agree on how it is signalled; they
// physically cannot be wired both ways.
if(line[irq].n > 0 && line[irq].level_low != level_low){
release(&irqlock);
cprintf("irq_register: irq %d shared with conflicting trigger mode "
"(%s)\n", irq, name);
return -1;
}
a = &line[irq].act[line[irq].n];
a->fn = fn;
a->arg = arg;
a->name = name;
a->count = 0;
__sync_synchronize(); // publish the entry before it is reachable
line[irq].n++;
if(!line[irq].enabled){
line[irq].level_low = level_low;
ioapicroute(irq, 0, level_low);
line[irq].enabled = 1;
}
release(&irqlock);
return 0;
}
void
irq_unregister(int irq, irq_handler_t fn, void *arg)
{
int i, j;
if(irq < 0 || irq >= NIRQ)
return;
acquire(&irqlock);
for(i = 0; i < line[irq].n; i++){
if(line[irq].act[i].fn == fn && line[irq].act[i].arg == arg){
// Mask before touching the chain, always -- not only when this is the
// last handler. Compacting the array moves entries that a dispatcher on
// another CPU may be walking, so the line has to be quiet for the
// duration, and then brought back only if anything is left on it.
ioapicmask(irq);
line[irq].enabled = 0;
for(j = i; j + 1 < line[irq].n; j++)
line[irq].act[j] = line[irq].act[j+1];
line[irq].n--;
__sync_synchronize();
if(line[irq].n > 0){
ioapicroute(irq, 0, line[irq].level_low);
line[irq].enabled = 1;
}
break;
}
}
release(&irqlock);
}
// Notice a line that is firing far faster than any real device would, and say
// so once.
//
// A level-triggered PCI interrupt that nobody acknowledges re-fires the instant
// EOI is signalled, so the line runs at whatever rate the CPU can take traps --
// tens of thousands per second. That starves everything else on the machine,
// and it does so silently: the symptom appears wherever the missing CPU time
// hurts first, which is nowhere near the device at fault.
//
// It cost a long afternoon to find one of these. virtio-gpu shared IRQ 11 with
// the e1000 and registered no handler, so the line storm at ~72 kHz and took
// 83% of CPU0. What that looked like from userspace was a clock running seven
// times slow -- uptime, `time`, and ping's interval all wrong together, which
// reads as a timekeeping bug and sends you into the timer code. The timer was
// fine the whole time. This is the message that would have said so.
//
// The rate is measured against the TSC, deliberately: `ticks` is the first
// casualty of a storm, so a storm detector that counted ticks would go quiet
// exactly when it was needed.
#define STORM_SAMPLE 4096 // dispatches between rate checks
#define STORM_HZ 20000 // per second; no real device sustains this
static void
storm_check(int irq)
{
static uint64 sample_tsc[NIRQ];
static uint sample_n[NIRQ];
static uchar reported[NIRQ];
if(reported[irq] || !tsc_hz)
return;
if(++sample_n[irq] < STORM_SAMPLE)
return;
uint64 now = rdtsc(), prev = sample_tsc[irq];
sample_n[irq] = 0;
sample_tsc[irq] = now;
if(!prev)
return; // first sample: no interval to divide by
uint64 elapsed = now - prev;
if(elapsed == 0)
return;
uint64 rate = (uint64)STORM_SAMPLE * tsc_hz / elapsed;
if(rate < STORM_HZ)
return;
reported[irq] = 1;
cprintf("irq %d: %d interrupts/second -- a device on this line is not "
"acknowledging it.\n", irq, (int)rate);
for(int i = 0; i < line[irq].n; i++)
cprintf("irq %d: handler '%s' is attached\n", irq, line[irq].act[i].name);
if(line[irq].n == 0)
cprintf("irq %d: no handler is attached at all\n", irq);
}
void
irq_dispatch(int irq)
{
int i, n;
if(irq < 0 || irq >= NIRQ)
return;
n = line[irq].n;
if(n == 0){
line[irq].unhandled++;
storm_check(irq);
return;
}
// Every handler on a shared line is offered the interrupt; each one is
// responsible for recognising that its device is idle and returning.
for(i = 0; i < n; i++){
line[irq].act[i].count++;
line[irq].act[i].fn(line[irq].act[i].arg);
}
storm_check(irq);
}
// ---------------------------------------------------------------------------
// /proc/interrupts
// ---------------------------------------------------------------------------
static int
emit(char *buf, int cap, int off, const char *s)
{
while(*s && off < cap)
buf[off++] = *s++;
return off;
}
static int
emit_dec(char *buf, int cap, int off, uint64 v, int width)
{
char tmp[24];
int n = 0, i;
if(v == 0)
tmp[n++] = '0';
while(v > 0){
tmp[n++] = '0' + (v % 10);
v /= 10;
}
for(i = n; i < width && off < cap; i++)
buf[off++] = ' ';
while(n > 0 && off < cap)
buf[off++] = tmp[--n];
return off;
}
int
irq_info(char *buf, int cap)
{
int irq, i, off = 0;
for(irq = 0; irq < NIRQ; irq++){
if(line[irq].n == 0 && line[irq].unhandled == 0)
continue;
off = emit_dec(buf, cap, off, irq, 4);
off = emit(buf, cap, off, ": ");
for(i = 0; i < line[irq].n; i++){
off = emit_dec(buf, cap, off, line[irq].act[i].count, 10);
off = emit(buf, cap, off, " ");
off = emit(buf, cap, off,
line[irq].act[i].name ? line[irq].act[i].name : "?");
off = emit(buf, cap, off, i + 1 < line[irq].n ? ", " : "");
}
if(line[irq].n == 0)
off = emit(buf, cap, off, "(unhandled)");
if(line[irq].unhandled)
off = emit(buf, cap, off, " [spurious]");
off = emit(buf, cap, off, line[irq].level_low ? " level\n" : " edge\n");
}
return off;
}