SchOS/kernel/core/panic.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

556 lines
20 KiB
C

// SPDX-License-Identifier: Apache-2.0
//
// PSOGM — the SchOS crash screen.
//
// The name is a nod to the Amiga's "Guru Meditation", but nothing else about
// this is a nod to 1985. Three things it is built around:
//
// *It does not clear the screen.* Whatever was being displayed stays there,
// dimmed and pushed back, with the report floating over it. A crash screen that
// wipes the display tells you the machine is gone; one that leaves your work
// visible underneath tells you it stopped, which is both truer and much less
// alarming.
//
// *It is not frightening.* No red, no capitals, no "FATAL". A calm sentence, a
// face that is obviously a cartoon, and then the facts. Whoever is reading this
// is already having a bad time.
//
// *It says considerably more than it needs to.* The screen is the only artefact
// of a kernel panic — there is no core dump and no log to go back to — so
// everything cheap to collect is collected: which CPU, which process, how far
// into the boot, where the kernel is loaded, and a call chain. Anything left
// out here is gone.
//
// Everything is also written to the serial console, in the same order. That is
// what tools/bootcheck.ps1 reads, and it is what you get when the crash happens
// before there is a framebuffer at all.
#include "types.h"
#include "defs.h"
#include "gfx.h"
#include "param.h"
#include "memlayout.h"
#include "mmu.h"
#include "x86.h"
#include "proc.h"
#include "spinlock.h"
// Purple, because the name says so, and white on it because nothing else is
// legible at every brightness a monitor might be set to. The palette lives in
// theme.h with everything else; this file used to keep its own copy under the
// same names but with different values, which meant theme.h described a crash
// screen nobody had ever seen.
#include "theme.h"
#include "qr.h"
extern uint ticks;
extern int panicked;
/* ------------------------------------------------------------------ */
/* Small formatting helpers */
/* */
/* cprintf goes to the console, which during a panic is also the screen */
/* being painted over -- so the panel builds its strings itself and */
/* places them with gfx_text_at. */
/* ------------------------------------------------------------------ */
static char *
put_str(char *p, char *end, const char *s)
{
while (*s && p < end - 1)
*p++ = *s++;
*p = '\0';
return p;
}
static char *
put_dec(char *p, char *end, uint64 v)
{
char tmp[24];
int i = 0;
if (v == 0)
tmp[i++] = '0';
while (v && i < (int)sizeof(tmp)) { tmp[i++] = '0' + (v % 10); v /= 10; }
while (i-- && p < end - 1)
*p++ = tmp[i];
*p = '\0';
return p;
}
static char *
put_hex(char *p, char *end, uint64 v, int digits)
{
const char *d = "0123456789abcdef";
if (p < end - 2) { *p++ = '0'; *p++ = 'x'; }
for (int i = digits - 1; i >= 0 && p < end - 1; i--)
*p++ = d[(v >> (i * 4)) & 0xF];
*p = '\0';
return p;
}
/* ------------------------------------------------------------------ */
/* The face */
/* */
/* Guru: a chamfered head with two eyes and a flat mouth. See */
/* docs/branding/ -- it is the system's icon, and the only place it is */
/* allowed to appear is here. */
/* */
/* This replaced ":(", two dots and a parenthesis, whose argument was */
/* that it is "legible as a mood without being a picture of anything, */
/* and does not pretend the machine has feelings about what just */
/* happened." That reasoning was good and is recorded because it is */
/* the thing being traded away: a face is a louder claim than a */
/* punctuation mark, and it has to earn the volume. */
/* */
/* What it buys is identity. ":(" is Microsoft's, recognisably, and a */
/* crash screen is the single screenshot most likely to leave the */
/* machine -- so it is the worst place to be wearing somebody else's */
/* face. The octagon also quotes the chamfered corners of the old */
/* SchOS letterforms, which is the only part of that mark still in use. */
/* */
/* Still drawn from primitives rather than stored as a bitmap, for the */
/* original reason: it scales with the display and costs no space in a */
/* kernel image. Two rectangles and a run of spans -- no allocation, no */
/* locks, nothing that can fail halfway. */
/* ------------------------------------------------------------------ */
/* Geometry, in the 200-unit box docs/branding/guru.svg is drawn in, so the
* two cannot drift apart without somebody editing a number here on purpose.
* The head spans 24..176 of that box; everything is expressed against it. */
#define GURU_BOX_LO 24 /* head's left/top edge in the SVG box */
#define GURU_BOX_SPAN 152 /* head's width and height there */
#define GURU_CHAMFER 34 /* corner cut */
/* SVG coordinate -> pixel offset within a head `h` tall. */
static int
gmap(int v, int h)
{
return (v - GURU_BOX_LO) * h / GURU_BOX_SPAN;
}
static void
draw_guru(int x, int y, int h, uint32 color, uint32 bg)
{
/* The head, as horizontal spans. A scanline fill rather than a polygon
* routine: the shape is convex and its left edge is one subtraction, so
* this is the whole of it. */
for (int py = 0; py < h; py++) {
int sy = GURU_BOX_LO + py * GURU_BOX_SPAN / h; /* back to SVG space */
int inset = 0;
if (sy < GURU_BOX_LO + GURU_CHAMFER)
inset = (GURU_BOX_LO + GURU_CHAMFER) - sy;
else if (sy > GURU_BOX_LO + GURU_BOX_SPAN - GURU_CHAMFER)
inset = sy - (GURU_BOX_LO + GURU_BOX_SPAN - GURU_CHAMFER);
int x0 = gmap(GURU_BOX_LO + inset, h);
int x1 = gmap(GURU_BOX_LO + GURU_BOX_SPAN - inset, h);
if (x1 > x0)
gfx_fill_rect(x + x0, y + py, x1 - x0, 1, color);
}
/* The eyes and the mouth are knocked out of the head rather than drawn on
* top of it, which is what keeps them legible when the head is small: a
* hole in a solid reads at sizes a stroke does not. */
int ey = gmap(82, h), eh = gmap(104, h) - gmap(82, h);
int e1x = gmap(74, h), e2x = gmap(110, h);
int ew = gmap(90, h) - gmap(74, h);
gfx_fill_rect(x + e1x, y + ey, ew, eh, bg);
gfx_fill_rect(x + e2x, y + ey, ew, eh, bg);
int mx = gmap(72, h), mw = gmap(128, h) - gmap(72, h);
int my = gmap(128, h), mh = gmap(139, h) - gmap(128, h);
gfx_fill_rect(x + mx, y + my, mw, mh, bg);
}
/* ------------------------------------------------------------------ */
/* The report */
/* ------------------------------------------------------------------ */
struct field {
const char *label;
char value[72];
};
#define NFIELD 10
static struct field fields[NFIELD];
static int nfields;
static struct field *
field(const char *label)
{
if (nfields >= NFIELD)
return &fields[NFIELD - 1];
struct field *f = &fields[nfields++];
f->label = label;
f->value[0] = '\0';
return f;
}
// Collect everything worth knowing while the machine is still in the state
// that produced the fault. Interrupts are already off and no lock is taken:
// a panic that deadlocks trying to report itself tells you nothing at all.
// A short, shoutable name for the failure, derived from the panic message
// rather than declared at every call site.
//
// Windows stop codes are genuinely useful: they are the thing you search for,
// and they stay the same across builds while the prose around them changes.
// Taking the message up to its first colon (or its first few words) gets that
// for free -- "sysrq: crash requested" becomes SYSRQ, "short filewrite" becomes
// SHORT_FILEWRITE -- with no risk of a call site forgetting to supply one.
static void
stop_code(char *out, int cap, const char *reason)
{
int n = 0;
for (int i = 0; reason[i] && n < cap - 1; i++) {
char c = reason[i];
if (c == ':')
break;
if (c == ' ' || c == '\t') {
if (n == 0 || out[n-1] == '_')
continue;
out[n++] = '_';
continue;
}
if (c >= 'a' && c <= 'z') c = c - 'a' + 'A';
if ((c >= 'A' && c <= 'Z') || (c >= '0' && c <= '9') || c == '_')
out[n++] = c;
}
while (n > 0 && out[n-1] == '_')
n--;
if (n == 0)
{ out[n++] = 'P'; out[n++] = 'A'; out[n++] = 'N'; out[n++] = 'I'; out[n++] = 'C'; }
out[n] = '\0';
}
static void
gather(char *reason, addr_t *pcs, int npcs)
{
char *e;
struct field *f;
nfields = 0;
f = field("Stop code");
stop_code(f->value, sizeof(f->value), reason);
f = field("Reason");
put_str(f->value, f->value + sizeof(f->value), reason);
f = field("CPU");
e = f->value + sizeof(f->value);
put_dec(f->value, e, mycpu() ? (uint64)mycpu()->id : 0);
if (!mycpu())
put_str(f->value, e, "unknown (very early boot)");
f = field("Process");
e = f->value + sizeof(f->value);
if (myproc()) {
char *p = put_str(f->value, e, myproc()->name);
p = put_str(p, e, " pid ");
put_dec(p, e, (uint64)myproc()->pid);
} else {
put_str(f->value, e, "none -- in the kernel, not on anybody's behalf");
}
f = field("Uptime");
e = f->value + sizeof(f->value);
{
char *p = put_dec(f->value, e, (uint64)ticks);
p = put_str(p, e, " ticks (about ");
p = put_dec(p, e, (uint64)ticks / HZ);
put_str(p, e, " s)");
}
// Every address below is a link-time address. Printing where the kernel
// actually sits is what lets addr2line resolve them afterwards, and it is
// the single most useful line here when the trace is all you have.
f = field("Kernel base");
e = f->value + sizeof(f->value);
put_hex(f->value, e, (uint64)KERNBASE, 16);
f = field("Fault PC");
e = f->value + sizeof(f->value);
if (npcs > 0 && pcs[0])
put_hex(f->value, e, (uint64)pcs[0], 16);
else
put_str(f->value, e, "unavailable");
}
/* ------------------------------------------------------------------ */
/* The QR code */
/* */
/* A panic report is only worth what can be carried away from it, and */
/* at this point there is no network, no log to write to, and often no */
/* second machine on the desk. Photographing the screen works but */
/* turns a call chain into something that has to be retyped by hand, */
/* with sixteen hex digits per frame and no way to tell 8 from B. */
/* */
/* A phone camera is a working out-of-band channel that needs no */
/* driver on our side at all. See kernel/core/qr.c. */
/* ------------------------------------------------------------------ */
// Deliberately not a URL. This encodes the report itself, so it goes wherever
// the person holding the phone decides -- and reaches nothing on its own.
//
// Compact because the budget is 134 bytes for the largest symbol this encoder
// builds, and a crash with a deep call chain is exactly when the budget is
// tightest. Two decisions buy most of the room: frames are stored as offsets
// from the kernel base rather than absolute addresses, which halves 16 hex
// digits to 8, and the fields are single letters. The base is included, so
// nothing is lost -- addr2line wants the link-time address and can be given it.
//
// Fields are appended in priority order and the loop simply stops when the
// buffer is full, so a long reason string costs call-chain depth rather than
// producing a report that will not encode.
static int
build_qr_payload(char *buf, int cap, char *reason, addr_t *pcs, int npcs)
{
char *p = buf, *end = buf + cap;
// Magic and format version, so whatever reads this later can tell what it is
// looking at and can change the layout without ambiguity.
p = put_str(p, end, "SXPSOGM1\n");
// The reason, not the stop code: the stop code is derived from the reason by
// stop_code() and carries strictly less, so encoding both would spend bytes
// on something the reader can recompute.
//
// Held back from the end of the buffer so that a long message costs some of
// the call chain but never all of it. A report with a sentence and no
// addresses is much harder to act on than one with addresses and a truncated
// sentence.
{
char *reason_end = end - 34; // three frames and their separators
if (reason_end > p)
p = put_str(p, reason_end, reason);
}
p = put_str(p, end, "\nc");
p = put_dec(p, end, mycpu() ? (uint64)mycpu()->id : 0);
p = put_str(p, end, " p");
p = put_dec(p, end, myproc() ? (uint64)myproc()->pid : 0);
p = put_str(p, end, " t");
p = put_dec(p, end, (uint64)ticks);
if (myproc()) {
p = put_str(p, end, " ");
p = put_str(p, end, myproc()->name);
}
p = put_str(p, end, "\nb");
p = put_hex(p, end, (uint64)KERNBASE, 16);
p = put_str(p, end, "\n");
for (int i = 0; i < npcs && pcs[i]; i++) {
// Nine bytes: eight hex digits and the separator. Stopping here rather than
// letting put_hex truncate matters -- half an address in a crash report is
// worse than one fewer address, because it looks like a real one.
if (end - p < 10)
break;
if (i)
p = put_str(p, end, " ");
// put_hex prefixes "0x", which is 14 wasted bytes across seven frames.
{
const char *d = "0123456789abcdef";
uint64 off = (uint64)pcs[i] - (uint64)KERNBASE;
for (int k = 7; k >= 0; k--)
*p++ = d[(off >> (k * 4)) & 0xF];
*p = '\0';
}
}
return (int)(p - buf);
}
// One static symbol rather than a local: struct qr is about 3.4 KB and the
// panic path runs on whatever stack the fault left behind, which may not have
// that much room. It is only ever touched here, after everything else has
// stopped.
static struct qr panic_qr;
// Returns the width used, so the text column knows what it may not overlap.
static int
draw_qr_panel(int sw, int sh, int ch, char *reason, addr_t *pcs, int npcs)
{
char payload[QR_MAX_BYTES];
int n = build_qr_payload(payload, sizeof(payload), reason, pcs, npcs);
if (n <= 0 || qr_encode(&panic_qr, (unsigned char *)payload, n) != 0)
return 0;
// Four modules of quiet zone, which the standard requires and which decoders
// genuinely need -- without it many will not find the symbol at all.
const int quiet = 4;
int cells = panic_qr.size + 2 * quiet;
// Scale to about a quarter of the display, then clamp. The lower bound is
// what a phone can still resolve from a photograph of a monitor; the upper
// bound stops the thing dominating a screen whose actual job is the text.
int scale = (sw / 4) / cells;
if (scale < 3) scale = 3;
if (scale > 8) scale = 8;
int card = cells * scale;
int x0 = sw - card - sw / 24;
int y0 = sh / 8;
gfx_fill_rect(x0, y0, card, card, PSOGM_CARD);
for (int y = 0; y < panic_qr.size; y++)
for (int x = 0; x < panic_qr.size; x++)
if (panic_qr.mod[y][x])
gfx_fill_rect(x0 + (x + quiet) * scale, y0 + (y + quiet) * scale,
scale, scale, PSOGM_INK);
gfx_text_at(x0, y0 + card + ch, "Scan for a text copy", PSOGM_DIM);
gfx_text_at(x0, y0 + card + ch * 2 + 2, "of this report.", PSOGM_DIM);
return card + sw / 24;
}
// The frame pointers, one per line, as one string per row.
static void
trace_line(char *buf, int cap, int i, addr_t pc)
{
char *e = buf + cap;
char *p = put_str(buf, e, " #");
p = put_dec(p, e, (uint64)i);
p = put_str(p, e, i < 10 ? " " : " ");
put_hex(p, e, (uint64)pc, 16);
}
/* ------------------------------------------------------------------ */
static void
paint(char *reason, addr_t *pcs, int npcs)
{
int sw, sh;
gfx_dims(&sw, &sh);
int ch = gfx_char_h();
int cw = gfx_char_w();
// The whole display, one colour. An earlier version dimmed the previous
// screen and floated a panel over it, which looked good and was wrong: the
// thing is called a Purple Screen, and half a screen of somebody's abandoned
// work behind the report is a distraction at the worst possible moment.
gfx_clear(PSOGM_BG);
// Glyphs are drawn with their background filled, so the console's cream has
// to become the background or every line of text arrives in its own box.
gfx_set_bg(PSOGM_BG);
// The symbol goes first, because it decides how much width the text has. It
// is drawn before anything can fail: if the encoder refuses the payload the
// screen simply has no card and the report is unchanged.
draw_qr_panel(sw, sh, ch, reason, pcs, npcs);
int left = sw / 8;
if (left > 110) left = 110;
int y = sh / 8;
int face_h = 96;
draw_guru(left, y, face_h, PSOGM_FG, PSOGM_BG);
y += face_h + ch * 2;
// Left-aligned, not centred. Centred text reads as a poster; this is a
// report, and a report is read down the left edge.
gfx_text_at(left, y, "SchOS ran into a problem and needs to restart.",
PSOGM_FG);
y += ch + ch / 2;
gfx_text_at(left, y, "Nothing on your disks was touched by this.",
PSOGM_DIM);
// A rule in the boot splash's accent, the same width as the one under the
// wordmark there, tying this screen to the one the machine started with.
//
// Equal space above and below on purpose: at any less it sits close enough to
// the line above to read as an underline of that sentence rather than as a
// divider before the facts.
y += ch * 2;
gfx_fill_rect(left, y, 120, 2, SCH_ACCENT);
y += ch;
// Facts: quiet labels down the left, bright values in a second column.
int vx = left + 14 * cw;
for (int i = 0; i < nfields; i++) {
gfx_text_at(left, y, fields[i].label, PSOGM_DIM);
gfx_text_at(vx, y, fields[i].value, PSOGM_FG);
y += ch + 2;
}
y += ch;
gfx_text_at(left, y, "Call chain", PSOGM_DIM);
y += ch + 2;
for (int i = 0; i < npcs && pcs[i]; i++) {
char line[48];
trace_line(line, sizeof(line), i, pcs[i]);
gfx_text_at(vx - 3 * cw, y, line, PSOGM_FG);
y += ch;
if (y > sh - ch * 5)
break;
}
// Two closing lines, bottom left: what to do with the numbers above, and
// what this screen is called, so it can be searched for by name. Shortened
// from the full command line, which at 62 characters ran under the QR card.
gfx_text_at(left, sh - ch * 3,
"Resolve: addr2line -e kernel <address>", PSOGM_DIM);
gfx_text_at(left, sh - ch * 3 + ch + 4,
"PSOGM -- Purple Screen of Guru Meditation", PSOGM_DIM);
}
// Same report, down the serial line. This is the copy that survives: it is what
// bootcheck reads, and the only one that exists when the framebuffer does not.
static void
report_serial(char *reason, addr_t *pcs, int npcs)
{
cprintf("\n");
cprintf(" :(\n\n");
cprintf(" SchOS ran into a problem and needs to restart.\n");
cprintf(" PSOGM -- Purple Screen of Guru Meditation\n\n");
for (int i = 0; i < nfields; i++) {
// Pad the label out so the values line up, without a printf width
// specifier -- cprintf has no such thing.
int n = 0;
while (fields[i].label[n]) n++;
cprintf(" %s", fields[i].label);
for (int pad = n; pad < 14; pad++)
cprintf(" ");
cprintf("%s\n", fields[i].value);
}
cprintf("\n Call chain\n");
for (int i = 0; i < npcs && pcs[i]; i++)
cprintf(" #%d %p\n", i, pcs[i]);
cprintf("\n Resolve with: addr2line -e build/kernel/kernel <address>\n");
cprintf(" Reason: %s\n", reason);
cprintf(" System halted.\n");
}
__attribute__((noreturn))
void
panic(char *s)
{
addr_t pcs[10];
cli();
// Stop every other path from writing to the console. consputc checks this
// and spins, which is what keeps another CPU from painting over the report
// while it is being drawn.
cons_panic_mode();
for (int i = 0; i < 10; i++)
pcs[i] = 0;
getcallerpcs(&s, pcs);
gather(s, pcs, 10);
report_serial(s, pcs, 10);
if (gfx_ready())
paint(s, pcs, 10);
panicked = 1;
for (;;)
hlt();
}