From 9d4cdb44fc4acad4a70b4a62536aa936b6b9000f Mon Sep 17 00:00:00 2001 From: Nexoniarz Date: Sat, 12 Sep 2026 21:34:36 +0200 Subject: [PATCH] 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 Claude-Session: https://claude.ai/code/session_01VQ7Qx8E1q1M1bbCq8QLHS2 --- Makefile | 9 +- docs/history/kernel.md | 144 +++++++++++++++++++++ include/defs.h | 3 + include/param.h | 22 ++++ include/posix.h | 5 + kernel/arch/x86_64/lapic.c | 123 +++++++++++++++++- kernel/core/console.c | 17 +++ kernel/core/panic.c | 2 +- kernel/core/time.c | 6 +- kernel/dev/input.c | 4 +- kernel/dev/irq.c | 59 +++++++++ kernel/dev/procfs.c | 12 +- kernel/drivers/gpu/virtio_gpu/virtio_gpu.c | 43 +++++- kernel/sys/sys_fs.c | 34 ++++- kernel/sys/sys_poll.c | 11 +- kernel/sys/sys_proc.c | 12 +- kernel/sys/sys_time.c | 10 +- 17 files changed, 479 insertions(+), 37 deletions(-) diff --git a/Makefile b/Makefile index a0f9a9d..9d8b7c6 100644 --- a/Makefile +++ b/Makefile @@ -141,6 +141,7 @@ ifneq (,$(filter FreeBSD OpenBSD NetBSD DragonFly,$(UNAME_S))) BSDHOST := 1 endif +SMP ?= 2 QEMU = qemu-system-x86_64 # Hardware virtualisation, when the host has it. @@ -610,7 +611,7 @@ schos.iso: $(BUILD)/kernel/kernel $(BUILD)/uefi/BOOTX64.EFI sysroot-install qemu-iso: schos.iso $(QEMU) -serial mon:stdio $(QEMU_DISPLAY) $(QEMU_ACCEL) $(QEMU_NET) \ -cdrom schos.iso -boot d \ - -m 1G -smp 2 -machine pc-i440fx-9.2 + -m 1G -smp $(SMP) -machine pc-i440fx-9.2 # ----------------------------------------------------------------------- # Kernel binary @@ -1033,11 +1034,11 @@ OVMF_DRIVES = -drive if=pflash,format=raw,unit=0,readonly=on,file=$(OVMF_CODE) \ # host has no /dev/kvm rather than to quietly get a slow machine. qemu-kvm: esp $(BUILD)/schfs.img $(OVMF_CODE) $(OVMF_VARS) $(QEMU) -enable-kvm -serial mon:stdio $(QEMU_DISPLAY) $(QEMU_INPUT) $(QEMU_NET) -cpu host \ - $(OVMF_DRIVES) -m 1G -smp 2 -machine pc-i440fx-9.2 + $(OVMF_DRIVES) -m 1G -smp $(SMP) -machine pc-i440fx-9.2 qemu: esp $(BUILD)/schfs.img $(OVMF_CODE) $(OVMF_VARS) $(QEMU) -serial mon:stdio $(QEMU_DISPLAY) $(QEMU_INPUT) $(QEMU_ACCEL) $(QEMU_NET) \ - $(OVMF_DRIVES) -m 1G -smp 2 -machine pc-i440fx-9.2 + $(OVMF_DRIVES) -m 1G -smp $(SMP) -machine pc-i440fx-9.2 # The root filesystem. Built from the staged sysroot; the kernel mounts it as # / in forkret(). @@ -1057,7 +1058,7 @@ $(BUILD)/schfs.img: $(MKSCHFS) $(BUILD)/sysroot.stamp # Once up: cat /proc/schfs qemu-schfs: esp $(BUILD)/schfs.img $(OVMF_CODE) $(OVMF_VARS) $(QEMU) -serial mon:stdio $(QEMU_DISPLAY) $(QEMU_ACCEL) $(QEMU_NET) \ - $(OVMF_DRIVES) -m 1G -smp 2 -machine pc-i440fx-9.2 + $(OVMF_DRIVES) -m 1G -smp $(SMP) -machine pc-i440fx-9.2 # ----------------------------------------------------------------------- # Misc diff --git a/docs/history/kernel.md b/docs/history/kernel.md index 1540288..ac0e112 100644 --- a/docs/history/kernel.md +++ b/docs/history/kernel.md @@ -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. diff --git a/include/defs.h b/include/defs.h index 814e68b..3a1e482 100644 --- a/include/defs.h +++ b/include/defs.h @@ -41,6 +41,9 @@ extern int tty_fg_pgrp; // ICRNL, INLCR, IGNCR, ISTRIP and VMIN. void cons_get_termios(struct termios *); void cons_set_termios(const struct termios *); +void cons_flush_input(void); +extern uint lapic_timer_hz; // measured, kernel/arch/x86_64/lapic.c +extern uint64 tsc_hz; void cprintf(char*, ...); // A log line: the serial port only, never the display. diff --git a/include/param.h b/include/param.h index fbbd75d..a147212 100644 --- a/include/param.h +++ b/include/param.h @@ -1,5 +1,27 @@ #pragma once +// The timer interrupt rate the kernel is built around. Everything that turns +// ticks into a duration divides by this. It used to be the literal 100 written +// out at each site, which made it look like a fact about the hardware; it is +// not. It is a target, and kernel/arch/x86_64/lapic.c calibrates the LAPIC +// timer against the PIT to actually hit it. +#define HZ 100 // timer interrupts per second + +// The tick rate the *user-space ABI* is defined in, which is a different thing +// from HZ and must not follow it. glibc and musl both answer sysconf(_SC_CLK_TCK) +// with a hardcoded 100, so times() and /proc/stat are read as hundredths of a +// second no matter what the kernel's internal rate is. Linux calls this USER_HZ +// and scales at the syscall boundary; so does SchOS, in the two places below. +#define USER_HZ 100 + +// Converting a POSIX timespec/timeval into ticks. These used to appear as the +// bare literals 10000000 and 10000 at each call site, where they looked like +// magic numbers rather than what they are: the length of one tick, expressed +// in the units the caller happens to be using. +#define NSEC_PER_TICK (1000000000 / HZ) +#define USEC_PER_TICK (1000000 / HZ) +#define MSEC_PER_TICK (1000 / HZ) + #define NPROC 128 // maximum number of processes #define KSTACKSIZE 4096 // size of per-process kernel stack (increased for x64) #define KSTACK_CANARY 0xDEADC0DEDEADC0DEULL // sentinel at kstack[0], see kstack_check_canary() diff --git a/include/posix.h b/include/posix.h index 54dfdbf..7a2be39 100644 --- a/include/posix.h +++ b/include/posix.h @@ -113,6 +113,11 @@ struct rlimit { #define TCSETS 0x5402 #define TCSETSW 0x5403 #define TCSETSF 0x5404 +#define TCFLSH 0x540B +// TCFLSH queue selectors. Not a pointer -- these are the argument itself. +#define TCIFLUSH 0 +#define TCOFLUSH 1 +#define TCIOFLUSH 2 #define TIOCGPGRP 0x540F #define TIOCSPGRP 0x5410 #define TIOCGWINSZ 0x5413 diff --git a/kernel/arch/x86_64/lapic.c b/kernel/arch/x86_64/lapic.c index 404bda7..5928fd2 100644 --- a/kernel/arch/x86_64/lapic.c +++ b/kernel/arch/x86_64/lapic.c @@ -49,6 +49,85 @@ lapicw(int index, int value) lapic[ID]; // wait for write to finish, by reading } +// --------------------------------------------------------------------- +// Timer calibration +// --------------------------------------------------------------------- +// The LAPIC timer counts down at the APIC bus frequency, and nothing in the +// architecture tells you what that frequency is. xv6 loaded TICR with +// 10000000 and hoped; its own comment admitted the gap -- "if xv6 cared more +// about precise timekeeping, TICR would be calibrated using an external time +// source." That value yields the intended 100 Hz only if the bus happens to +// run at exactly 1 GHz. +// +// Under KVM it does not, and the error is not subtle. The kernel believed +// ticks arrived 100 times a second while they were arriving roughly 18 times +// a second, so every number derived from ticks was wrong by that same factor, +// in the same direction, everywhere at once: uptime ran slow, `time` reported +// three seconds for twenty, ping's one-second interval stretched to six. It +// read as three unrelated bugs in three unrelated programs. It was this line. +// +// So measure it. The 8254 PIT is exactly the external time source the comment +// asked for: its input clock is fixed at 1193182 Hz by the hardware, it is +// always present, and channel 2 is the one whose gate software can raise and +// whose output software can poll -- a stopwatch that needs no interrupt, which +// matters because this runs before the IDT is ready to take one. +#define PIT_HZ 1193182 // 8254 input clock, fixed by definition +#define PIT_CH2 0x42 +#define PIT_CMD 0x43 +#define PIT_GATE 0x61 // bit 0: ch2 gate, bit 1: speaker, bit 5: ch2 output + +uint lapic_timer_hz; // measured LAPIC timer counts per second +uint64 tsc_hz; // measured TSC cycles per second + +static void +calibrate_timers(void) +{ + // 50 ms: long enough that the port I/O around the measurement is noise, + // short enough that nobody notices it in boot time. The count fits in the + // 16 bits the PIT has (59659), which is the real upper bound here. + const uint us = 50000; + uint count = (uint)(((uint64)PIT_HZ * us) / 1000000); + + // Channel 2, mode 0 (interrupt on terminal count), lobyte then hibyte. + // Gate high so it counts; the speaker bit stays clear so the box is silent. + outb(PIT_GATE, (inb(PIT_GATE) & ~0x02) | 0x01); + outb(PIT_CMD, 0xB0); + outb(PIT_CH2, count & 0xFF); + outb(PIT_CH2, (count >> 8) & 0xFF); + + // A free-running LAPIC counter for the duration: one-shot, masked, started + // at the largest count there is so it cannot wrap inside 50 ms. + lapicw(TDCR, X1); + lapicw(TIMER, MASKED); + lapicw(TICR, 0xFFFFFFFF); + + uint64 tsc0 = rdtsc(); + uint lap0 = lapic[TCCR]; + + while (!(inb(PIT_GATE) & 0x20)) // ch2 output rises at terminal count + ; + + uint lap1 = lapic[TCCR]; + uint64 tsc1 = rdtsc(); + + lapicw(TICR, 0); // stop counting + + // TCCR counts down, so elapsed counts are start minus end. + lapic_timer_hz = (uint)(((uint64)(lap0 - lap1) * 1000000) / us); + tsc_hz = ((tsc1 - tsc0) * 1000000) / us; + + // If the measurement came back implausible -- no LAPIC, a hypervisor that + // stops the counter, a PIT that never raises its output -- fall back to the + // old assumption rather than dividing by zero and taking the machine down. + // Wrong-but-running beats a triple fault, and the printed value says which + // case this is. + if (lapic_timer_hz < HZ * 1000u) { + cprintf("cpu0: lapic calibration implausible (%u Hz), assuming 1 GHz bus\n", + lapic_timer_hz); + lapic_timer_hz = 1000000000u; // the 1 GHz that TICR=10000000 implied + } +} + void lapicinit(void) { @@ -58,13 +137,19 @@ lapicinit(void) // Enable local APIC; set spurious interrupt vector. lapicw(SVR, ENABLE | (T_IRQ0 + IRQ_SPURIOUS)); - // The timer repeatedly counts down at bus frequency - // from lapic[TICR] and then issues an interrupt. - // If xv6 cared more about precise timekeeping, - // TICR would be calibrated using an external time source. + // The timer counts down at the APIC bus frequency and interrupts at zero. + // What that frequency *is*, calibrate_timers() had to go and measure -- + // see the comment above it for why loading a constant here does not work. + if (lapic_timer_hz == 0) { + calibrate_timers(); + cprintf("cpu0: lapic timer %u Hz, tsc %u MHz, tick = %u counts at %d Hz\n", + lapic_timer_hz, (uint)(tsc_hz / 1000000), + lapic_timer_hz / HZ, HZ); + } + lapicw(TDCR, X1); lapicw(TIMER, PERIODIC | (T_IRQ0 + IRQ_TIMER)); - lapicw(TICR, 10000000); + lapicw(TICR, lapic_timer_hz / HZ); // Disable logical interrupt lines. lapicw(LINT0, MASKED); @@ -132,10 +217,36 @@ lapiceoi(void) } // Spin for a given number of microseconds. -// On real hardware would want to tune this dynamically. +// +// This was an empty function body -- xv6's stub, carrying a comment saying +// real hardware would want to tune it dynamically. Nothing ever did, so every +// microdelay() in the tree returned immediately: the xHCI reset sequence, the +// USB hub power-on wait, the UART drain. Those delays are written into the +// specifications because the hardware genuinely needs the time, and a port +// that "works anyway" is one that is racing and winning. +// +// The TSC is the right clock for this: calibrate_timers() measured it in the +// same pass as the LAPIC, and unlike the LAPIC timer it is not already busy +// driving the tick. void microdelay(int us) { + if (us <= 0) + return; + + // Before calibration (early boot, and the AP trampoline) there is no + // measured frequency to work from. Spin on a rough count instead: the + // figure is wrong, but being approximately late is the entire point of the + // call, and being instantly early is what broke it. + if (tsc_hz == 0) { + for (volatile int i = 0; i < us * 100; i++) + ; + return; + } + + uint64 end = rdtsc() + ((uint64)us * tsc_hz) / 1000000; + while (rdtsc() < end) + asm volatile("pause"); } #define CMOS_PORT 0x70 diff --git a/kernel/core/console.c b/kernel/core/console.c index 1f02def..100c48b 100644 --- a/kernel/core/console.c +++ b/kernel/core/console.c @@ -567,6 +567,23 @@ cons_set_termios(const struct termios *in) wakeup(&input.r); } +// Discard everything typed but not yet consumed: completed lines waiting in +// the buffer and the partial line still being edited. TCFLSH (tcflush) is the +// caller, and a line editor issues one whenever it takes the terminal back -- +// after an interrupt, or when a command that read from the tty exits. Without +// it the keys pressed while the last command ran arrive at the next prompt. +// +// A pending EOF goes too: end of input is buffer state like any other, and +// leaving it set would end the *next* read instead of the one it was typed at. +void +cons_flush_input(void) +{ + acquire(&input.lock); + input.e = input.w = input.r; + input.eof = 0; + release(&input.lock); +} + static void echo(int c) { diff --git a/kernel/core/panic.c b/kernel/core/panic.c index 28df9b9..161559c 100644 --- a/kernel/core/panic.c +++ b/kernel/core/panic.c @@ -257,7 +257,7 @@ gather(char *reason, addr_t *pcs, int npcs) { char *p = put_dec(f->value, e, (uint64)ticks); p = put_str(p, e, " ticks (about "); - p = put_dec(p, e, (uint64)ticks / 100); + p = put_dec(p, e, (uint64)ticks / HZ); put_str(p, e, " s)"); } diff --git a/kernel/core/time.c b/kernel/core/time.c index 1839d89..e575ef5 100644 --- a/kernel/core/time.c +++ b/kernel/core/time.c @@ -91,7 +91,7 @@ time_init(void) // Subtract the uptime so far, so boot_epoch is the moment of boot rather than // the moment this function ran. It is only a fraction of a second, but it // keeps boot_epoch meaning exactly what its name says. - uint64 up = ticks / 100; + uint64 up = ticks / HZ; boot_epoch = now > up ? now - up : now; cprintf("time: %d-%d-%d %d:%d:%d UTC from the hardware clock\n", @@ -110,7 +110,7 @@ wallclock(uint64 *sec, uint64 *usec) release(&tickslock); if (sec) - *sec = boot_epoch + xticks / 100; + *sec = boot_epoch + xticks / HZ; if (usec) - *usec = (uint64)(xticks % 100) * 10000; + *usec = (uint64)(xticks % HZ) * (1000000 / HZ); } diff --git a/kernel/dev/input.c b/kernel/dev/input.c index 8c10a62..2b5a0f4 100644 --- a/kernel/dev/input.c +++ b/kernel/dev/input.c @@ -95,8 +95,8 @@ input_report(int dev, int type, int code, int value) d->r++; e = &d->ev[d->w % NEVENT]; - e->time.tv_sec = ticks / 100; - e->time.tv_usec = (ticks % 100) * 10000; + e->time.tv_sec = ticks / HZ; + e->time.tv_usec = (ticks % HZ) * USEC_PER_TICK; e->type = (uint16)type; e->code = (uint16)code; e->value = (int32)value; diff --git a/kernel/dev/irq.c b/kernel/dev/irq.c index 578b834..a5a268a 100644 --- a/kernel/dev/irq.c +++ b/kernel/dev/irq.c @@ -6,6 +6,7 @@ #include "traps.h" #include "spinlock.h" #include "irq.h" +#include "x86.h" struct irq_action { irq_handler_t fn; @@ -134,6 +135,62 @@ irq_unregister(int irq, irq_handler_t fn, void *arg) 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) { @@ -145,6 +202,7 @@ irq_dispatch(int irq) n = line[irq].n; if(n == 0){ line[irq].unhandled++; + storm_check(irq); return; } @@ -154,6 +212,7 @@ irq_dispatch(int irq) line[irq].act[i].count++; line[irq].act[i].fn(line[irq].act[i].arg); } + storm_check(irq); } // --------------------------------------------------------------------------- diff --git a/kernel/dev/procfs.c b/kernel/dev/procfs.c index cf4ac7f..0379480 100644 --- a/kernel/dev/procfs.c +++ b/kernel/dev/procfs.c @@ -130,11 +130,12 @@ gen_meminfo(struct sbuf *sb) static void gen_uptime(struct sbuf *sb) { - uint t = uptime(); // timer ticks, 100 Hz - sb_putu(sb, t / 100); + uint t = uptime(); // timer ticks, HZ of them per second + uint frac = (t % HZ) * 100 / HZ; // hundredths, whatever HZ happens to be + sb_putu(sb, t / HZ); sb_putc(sb, '.'); - sb_putu(sb, (t % 100) / 10); - sb_putu(sb, (t % 100) % 10); + sb_putu(sb, frac / 10); + sb_putu(sb, frac % 10); sb_puts(sb, " 0.00\n"); // idle time: not tracked } @@ -214,7 +215,8 @@ gen_version(struct sbuf *sb) static void gen_stat(struct sbuf *sb) { - uint t = uptime(); + // USER_HZ, like times() -- everything that parses /proc/stat divides by 100. + uint t = (uint)((uint64)uptime() * USER_HZ / HZ); sb_puts(sb, "cpu "); sb_putu(sb, t); sb_puts(sb, " 0 0 0 0 0 0 0 0 0\n"); // Online, for the same reason as cpuinfo: top and friends count the cpuN diff --git a/kernel/drivers/gpu/virtio_gpu/virtio_gpu.c b/kernel/drivers/gpu/virtio_gpu/virtio_gpu.c index 728332f..384e0df 100644 --- a/kernel/drivers/gpu/virtio_gpu/virtio_gpu.c +++ b/kernel/drivers/gpu/virtio_gpu/virtio_gpu.c @@ -14,6 +14,7 @@ #include "types.h" #include "defs.h" +#include "irq.h" #include "param.h" #include "x86.h" #include "spinlock.h" @@ -35,6 +36,9 @@ struct vgpu { volatile uint8 *common; // common configuration structure volatile uint8 *notify; // notification area + // The interrupt status byte. Reading it is what tells the device we have + // noticed, and therefore what makes it drop the PCI interrupt line. + volatile uint8 *isr; uint32 notify_mult; // queue_notify_off multiplier // The queue. Allocated as one contiguous block from the DMA arena, because @@ -396,6 +400,33 @@ const struct display_ops virtio_gpu_display_ops = { // --- probe ----------------------------------------------------------------- +// Acknowledge the device's interrupt. +// +// This driver polls for command completion and wants no notifications at all, +// which is why nothing here reacts to the cause -- but "wants none" and "gets +// none" are different things, and a PCI interrupt line is level-triggered. +// The device raises INTx, the CPU takes the interrupt, the kernel signals EOI, +// and if nobody has cleared the device's interrupt status the line is still +// asserted, so it fires again immediately. Forever. +// +// That is not hypothetical. With no handler registered here at all, this +// device shared IRQ 11 with the e1000 under QEMU and storme at roughly 72,000 +// interrupts a second, eating 83% of CPU0. The visible symptom was nowhere +// near the graphics driver: the timer interrupt was starved, so `ticks` +// advanced at about 14 Hz instead of 100, and every duration in the system -- +// uptime, `time`, sleep, ping's one-second interval -- came out ~7x short. +// See docs/history/kernel.md. +// +// Reading the ISR byte clears it and deasserts the line. That single read is +// the entire handler, and it is not optional. +static void +vgpu_intr(void *arg) +{ + struct vgpu *g = arg; + if (g && g->isr) + (void)*g->isr; +} + static int vgpu_probe(struct pci_dev *d) { @@ -414,6 +445,7 @@ vgpu_probe(struct pci_dev *d) g->common = find_cfg(d, VIRTIO_PCI_CAP_COMMON_CFG, 0); g->notify = find_cfg(d, VIRTIO_PCI_CAP_NOTIFY_CFG, &g->notify_mult); + g->isr = find_cfg(d, VIRTIO_PCI_CAP_ISR_CFG, 0); if (!g->common || !g->notify) { cprintf("virtio-gpu: no modern virtio capabilities; not a 1.0 device\n"); return -1; @@ -465,9 +497,16 @@ vgpu_probe(struct pci_dev *d) return -1; } + // Level-triggered and active low, like every other PCI INTx line -- see + // vgpu_intr for what happens when this registration is missing. + if (g->isr) + irq_register(d->irq, vgpu_intr, g, "virtio-gpu", 1); + else + cprintf("virtio-gpu: no ISR capability; leaving irq %d unclaimed\n", d->irq); + g->ready = 1; - cprintf("virtio-gpu: %dx%d, %d KB framebuffer, queue %d\n", - g->width, g->height, g->fb_bytes / 1024, g->qsize); + cprintf("virtio-gpu: %dx%d, %d KB framebuffer, queue %d, irq %d\n", + g->width, g->height, g->fb_bytes / 1024, g->qsize, d->irq); return 0; } diff --git a/kernel/sys/sys_fs.c b/kernel/sys/sys_fs.c index f97320c..61885e1 100644 --- a/kernel/sys/sys_fs.c +++ b/kernel/sys/sys_fs.c @@ -15,6 +15,7 @@ #include "uaccess.h" #include "errno.h" #include "schfs.h" /* SCHFS_BLKSIZE, SCHFS_NAME_MAX — statfs reports them */ +#include "gfx.h" /* gfx_cols/gfx_rows — TIOCGWINSZ reports them */ // ----------------------------------------------------------------------- // Linux-ABI-compatible struct stat (x86_64 "struct stat" from @@ -1042,10 +1043,41 @@ addr_t sys_ioctl(void) if (request == TIOCGWINSZ) { struct winsize *ws = (struct winsize*)user_ptr(argp, sizeof(*ws)); if (!ws) return -EFAULT; - ws->ws_row = 24; ws->ws_col = 80; ws->ws_xpixel = ws->ws_ypixel = 0; + // The console's real geometry, not a VT100's. + // + // This used to answer 24x80 unconditionally -- the size of a terminal + // SchOS has never drawn. Every program that lays out a screen asks + // this one question first: a line editor to decide where to wrap, `ls` + // to pick a column count, fastfetch to place its logo beside the text. + // At 1024x768 with the 8x16 font the console is 128x48, so all of them + // were formatting for a screen a third the area of the real one, and + // each looked like a separate bug in a separate program. + int cols = gfx_cols(), rows = gfx_rows(); + // Serial-only boot, with no framebuffer attached: 80x24 is then a + // stated default rather than a wrong measurement. + ws->ws_col = cols > 0 ? (uint16)cols : 80; + ws->ws_row = rows > 0 ? (uint16)rows : 24; + ws->ws_xpixel = (uint16)gfx_width(); + ws->ws_ypixel = (uint16)gfx_height(); return 0; } + // The console's size is a property of the framebuffer, so a request to + // change it cannot be honoured -- but it is not an error either: programs + // set it to propagate a size they already learned. Accept and ignore. if (request == TIOCSWINSZ) return 0; + // TCFLSH discards buffered input, output, or both. Unlike every other + // request here the argument is the queue selector *by value*, not a + // pointer -- passing it to user_ptr would fault on a legitimate call. + // + // Output needs no action: the console writes straight to the framebuffer + // and has no queue to drop. Input does, and answering 0 without draining + // it -- which is what the catch-all below did -- is how a keystroke typed + // during a command survives the flush and lands in the next prompt. + if (request == TCFLSH) { + if (argp == TCIFLUSH || argp == TCIOFLUSH) + cons_flush_input(); + return 0; + } // Controlling-terminal foreground process group. // // TIOCGPGRP used to answer with myproc()->pid, which happened to agree with diff --git a/kernel/sys/sys_poll.c b/kernel/sys/sys_poll.c index 22be719..83697ba 100644 --- a/kernel/sys/sys_poll.c +++ b/kernel/sys/sys_poll.c @@ -91,7 +91,10 @@ sys_poll(void) if (nfds > 0 && copy_from_user(fds, ufds, nfds * sizeof(struct pollfd)) < 0) return -EFAULT; - int timeout_ticks = timeout_ms < 0 ? -1 : (timeout_ms + 9) / 10; + // Rounded up: a caller asking for any wait at all must not get zero ticks, + // which poll() below treats as "return immediately". + int timeout_ticks = timeout_ms < 0 ? -1 + : (timeout_ms + MSEC_PER_TICK - 1) / MSEC_PER_TICK; int r = do_poll(fds, nfds, timeout_ticks); if (r >= 0 && nfds > 0 && @@ -123,7 +126,7 @@ sys_ppoll(void) int64 ts[2]; // {tv_sec, tv_nsec} if (copy_from_user(ts, utsp, sizeof(ts)) < 0) return -EFAULT; - timeout_ticks = (int)(ts[0] * 100 + ts[1] / 10000000); + timeout_ticks = (int)(ts[0] * HZ + ts[1] / NSEC_PER_TICK); } int r = do_poll(fds, nfds, timeout_ticks); @@ -178,7 +181,7 @@ sys_select(void) int64 tv[2]; // {tv_sec, tv_usec} if (copy_from_user(tv, utv, sizeof(tv)) < 0) return -EFAULT; - timeout_ticks = (int)(tv[0] * 100 + tv[1] / 10000); + timeout_ticks = (int)(tv[0] * HZ + tv[1] / USEC_PER_TICK); } for (;;) { @@ -252,7 +255,7 @@ sys_pselect6(void) int64 ts[2]; if (copy_from_user(ts, utsp, sizeof(ts)) < 0) return -EFAULT; - timeout_ticks = (int)(ts[0] * 100 + ts[1] / 10000000); + timeout_ticks = (int)(ts[0] * HZ + ts[1] / NSEC_PER_TICK); } for (;;) { diff --git a/kernel/sys/sys_proc.c b/kernel/sys/sys_proc.c index 95be2e7..a3f8493 100644 --- a/kernel/sys/sys_proc.c +++ b/kernel/sys/sys_proc.c @@ -395,8 +395,8 @@ addr_t sys_getrusage(void) acquire(&tickslock); uint xt = ticks; release(&tickslock); - ru->ru_utime.tv_sec = (long)(xt / 100); - ru->ru_utime.tv_usec = (long)((xt % 100) * 10000); + ru->ru_utime.tv_sec = (long)(xt / HZ); + ru->ru_utime.tv_usec = (long)((xt % HZ) * (1000000 / HZ)); return 0; } @@ -411,7 +411,11 @@ addr_t sys_times(void) acquire(&tickslock); uint xt = ticks; release(&tickslock); - return (addr_t)xt; // return clock ticks since boot + // Scaled to USER_HZ, not returned raw. musl answers sysconf(_SC_CLK_TCK) + // with 100 unconditionally, so a shell's `time` builtin divides whatever + // this returns by 100 -- handing it the internal tick count is only right + // while HZ happens to equal 100, and silently wrong the day it does not. + return (addr_t)((uint64)xt * USER_HZ / HZ); } addr_t sys_sysinfo(void) @@ -424,7 +428,7 @@ addr_t sys_sysinfo(void) acquire(&tickslock); uint xt = ticks; release(&tickslock); - si->uptime = (long)(xt / 100); + si->uptime = (long)(xt / HZ); // Real values: PHYSTOP is the top of usable physical memory and the page // allocator knows exactly how much of it is still on the free list. These // used to be the constants 256MB/128MB, invented and always wrong. diff --git a/kernel/sys/sys_time.c b/kernel/sys/sys_time.c index 900a26b..3c9f161 100644 --- a/kernel/sys/sys_time.c +++ b/kernel/sys/sys_time.c @@ -16,7 +16,7 @@ sys_alarm(void) int seconds; if (argint(0, &seconds) < 0) return -1; - myproc()->alarm_ticks = seconds * 100; + myproc()->alarm_ticks = seconds * HZ; return 0; } @@ -48,7 +48,7 @@ sys_nanosleep(void) if (sec > 0) { acquire(&tickslock); uint t0 = ticks; - while (ticks - t0 < (uint)(sec * 100)) { + while (ticks - t0 < (uint)(sec * HZ)) { if (myproc()->killed) { release(&tickslock); return -EINTR; } sleep(&ticks, &tickslock); } @@ -89,8 +89,8 @@ sys_setitimer(void) if (which == 0 && newp) { struct itimerval iv; if (copy_from_user(&iv, newp, sizeof(iv)) == 0) - myproc()->alarm_ticks = (int)(iv.it_value.tv_sec * 100 + - iv.it_value.tv_usec / 10000); + myproc()->alarm_ticks = (int)(iv.it_value.tv_sec * HZ + + iv.it_value.tv_usec / USEC_PER_TICK); } return 0; } @@ -129,7 +129,7 @@ sys_clock_nanosleep(void) if (sec > 0) { acquire(&tickslock); uint t0 = ticks; - while (ticks - t0 < (uint)(sec * 100)) { + while (ticks - t0 < (uint)(sec * HZ)) { if (myproc()->killed) { release(&tickslock); return -EINTR; } sleep(&ticks, &tickslock); }