bug pass: whole console lines, a quiet SCI, an honest reserve warning

- schinit, schinitd and vgpud build every message from pieces, one
  write() each, so a job starting on another CPU landed mid-line:
  "schinitd: starting vgpud: os.schos.resolvconfno virtio-gpu on this
  machine". They now collect a line and write it at the newline;
  resolvconf's verbose line is one write with its prefix.
- The ACPI SCI registers IRQ_QUIET. A desktop's SCI never fires, and the
  poller took two seconds of silence for a misrouted line ("irq 9:
  nothing has arrived on it") and called the handler every tick. A line
  is only exempt while every handler on it is quiet.
- The loader claims each segment from where the last one's claim ended,
  so two segments sharing a page no longer ask for it twice. When a
  claim is still refused, it names the memory-map entries in the way.
- Stale divesymlink() declaration gone; the kernel.md struct table
  re-measured (inode, buf and file pools grow from slabs now).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01S1giNvrHTrPMPw7V6x1kQ4

boot/uefi/main.c

@@ -90,6 +90,7 @@ static EFI_BOOT_SERVICES *BS;
 static void mirrors_show(void);   /* see "the other displays", further down */
 static void mirrors_match(EFI_GRAPHICS_OUTPUT_PROTOCOL *primary);
 static void describe_gop(EFI_GRAPHICS_OUTPUT_PROTOCOL *g, const CHAR16 *tag);
+static void explain_range(UINT64 lo, UINT64 hi);
 
 /* Once the splash is up, nothing may write to the console.
  *
@@ -522,6 +523,8 @@ load_elf(EFI_FILE_PROTOCOL *file)
     }
     ui_progress_begin("Loading SchOS", (ui_u32)(total ? total : 1));
 
+    EFI_PHYSICAL_ADDRESS claimed_end = 0;   /* see the AllocatePages below */
+
     for (UINT16 i = 0; i < eh.e_phnum; i++) {
         struct elf64_phdr ph;
         n = sizeof ph;
@@ -537,9 +540,23 @@ load_elf(EFI_FILE_PROTOCOL *file)
         // and this is its memory until it says otherwise; writing to
         // conventional memory it has not handed over is how a loader corrupts
         // the very services it is about to call.
+        //
+        // From the end of what the previous segment claimed, not from this
+        // one's first page. The linker packs segments without page-aligning
+        // them -- .text ending at 0x1dc9fe and .rodata starting at 0x1dca00 --
+        // so two segments routinely share a page, and asking for that page a
+        // second time is refused because it is ours already. That was the
+        // "could not reserve" warning on every boot, about memory that was
+        // reserved all along.
         EFI_PHYSICAL_ADDRESS at  = ph.p_paddr & ~0xfffULL;
-        UINTN pages = (UINTN)((ph.p_paddr + ph.p_memsz - at + 0xfff) / 0x1000);
+        EFI_PHYSICAL_ADDRESS end = (ph.p_paddr + ph.p_memsz + 0xfff) & ~0xfffULL;
-        st = BS->AllocatePages(AllocateAddress, EfiLoaderData, pages, &at);
+        if (at < claimed_end)
+            at = claimed_end;
+        UINTN pages = at < end ? (UINTN)((end - at) / 0x1000) : 0;
+        st = pages ? BS->AllocatePages(AllocateAddress, EfiLoaderData, pages, &at)
+                   : EFI_SUCCESS;
+        if (end > claimed_end)
+            claimed_end = end;
         if (EFI_ERROR(st)) {
             // Already allocated by the firmware for something of its own, or
             // simply not conventional memory. Not fatal on its own -- the
@@ -547,6 +564,7 @@ load_elf(EFI_FILE_PROTOCOL *file)
             // that boots and then corrupts itself starts here.
             print(L"schos: warning: could not reserve "); print_hex(at);
             print(L"\r\n");
+            explain_range(at, end);
         }
 
         if (ph.p_filesz) {
@@ -1044,6 +1062,32 @@ map_read(UINTN *size, UINTN *key, UINTN *dsize, UINT32 *dver)
                             key, dsize, dver);
 }
 
+/* Who owns [lo, hi), when it was not ours to take.
+ *
+ * "could not reserve" alone says where and not why, and the why decides
+ * whether it matters: boot-services memory is the firmware's until
+ * ExitBootServices and harmless to overwrite after it, while runtime services
+ * or ACPI tables under the kernel are a machine that will corrupt itself. So
+ * every descriptor in the range that is not free memory is named. */
+static void
+explain_range(UINT64 lo, UINT64 hi)
+{
+    UINTN size, key, dsize;
+    UINT32 dver;
+
+    if (EFI_ERROR(map_read(&size, &key, &dsize, &dver)) || !dsize)
+        return;
+    for (UINTN off = 0; off + dsize <= size; off += dsize) {
+        EFI_MEMORY_DESCRIPTOR *d = (EFI_MEMORY_DESCRIPTOR *)(mapbuf + off);
+        UINT64 a = d->PhysicalStart, b = a + d->NumberOfPages * 4096;
+        if (b <= lo || a >= hi || d->Type == EfiConventionalMemory)
+            continue;
+        print(L"schos:   type "); print_dec(d->Type);
+        print(L" at "); print_hex(a); print(L".."); print_hex(b);
+        print(L"\r\n");
+    }
+}
+
 static UINT64
 memory_mb(void)
 {

cmd/resolvconf/main.c

@@ -181,9 +181,15 @@ main(int argc, char *argv[])
 
     // Worth one line under -v, because it is the moment names start working
     // and somebody watching a verbose boot may be waiting to know it.
+    // One write(), prefix and all: two would let another job's line land
+    // between them, which a verbose boot on real hardware showed as
+    // "os.schos.keymapnameserver 192.168.1.1".
     if (verbose_boot) {
-        puts_("resolvconf: ");
+        static char line[sizeof("resolvconf: ") + sizeof(buf)];
-        write(1, buf, n);
+        int k = 0;
+        for (const char *p = "resolvconf: "; *p; p++) line[k++] = *p;
+        for (int j = 0; j < n; j++) line[k++] = buf[j];
+        write(1, line, k);
     }
     return 0;
 }

cmd/schinit/main.c

@@ -119,10 +119,34 @@ read_bootmode(void)
     if (n > 0) { b[n] = 0; verbose_boot = (b[0] == 'v'); }
 }
 
+// Whole lines, in one write() each: the same buffer as schinitd's, for the
+// same reason -- a line written in pieces is a line another process can land
+// in the middle of. See emit() there.
+static char lbuf[512];
+static int  lbn;
+
+static void
+lflush(void)
+{
+    if (lbn)
+        write(1, lbuf, lbn);
+    lbn = 0;
+}
+
+static void
+emit(const char *s, int n)
+{
+    for (int i = 0; i < n; i++) {
+        lbuf[lbn++] = s[i];
+        if (s[i] == '\n' || lbn == (int)sizeof lbuf)
+            lflush();
+    }
+}
+
 static void
 out(const char *s)
 {
-    write(1, (void *)s, slen(s));
+    emit(s, slen(s));
 }
 
 static void
@@ -410,6 +434,7 @@ spawn(struct schinit_spawn *s)
         out("schinit: cannot exec ");
         out(s->program);
         out("\n");
+        lflush();
         exit();
     }
     return pid;

cmd/schinitd/main.c

@@ -83,10 +83,40 @@ ends_with(const char *s, const char *suffix)
     return seq(s + ls - lf, suffix);
 }
 
+// Whole lines, in one write() each.
+//
+// Every message here is assembled from pieces -- a prefix, a job's label, a
+// number -- and each piece used to be its own write(). The console keeps one
+// write() together, but nothing keeps two of them together, so a job starting
+// on another CPU landed in the middle of the line: "schinitd: starting vgpud:
+// os.schos.resolvconfno virtio-gpu on this machine" was this process and
+// vgpud taking turns a word at a time. The pieces now collect here and go out
+// at the newline.
+static char lbuf[512];
+static int  lbn;
+
+static void
+lflush(void)
+{
+    if (lbn)
+        write(1, lbuf, lbn);
+    lbn = 0;
+}
+
+static void
+emit(const char *s, int n)
+{
+    for (int i = 0; i < n; i++) {
+        lbuf[lbn++] = s[i];
+        if (s[i] == '\n' || lbn == (int)sizeof lbuf)
+            lflush();
+    }
+}
+
 static void
 out(const char *s)
 {
-    write(1, (void *)s, slen(s));
+    emit(s, slen(s));
 }
 
 // How the machine was booted, read once.
@@ -139,7 +169,7 @@ static void
 vout(const char *s)
 {
     if (verbose_boot)
-        write(1, (void *)s, slen(s));
+        emit(s, slen(s));
 }
 
 static void
@@ -626,14 +656,17 @@ main(void)
     h.reserved = 0;
     if (write(sock, &h, sizeof(h)) != sizeof(h)) {
         out("schinitd: no channel to pid 1\n");
+        lflush();
         exit();
     }
     if (read(sock, &h, sizeof(h)) != sizeof(h) || h.op != SCHINIT_WELCOME) {
         out("schinitd: pid 1 did not answer\n");
+        lflush();
         exit();
     }
     if (h.proto != SCHINIT_PROTO) {
         out("schinitd: protocol mismatch with pid 1\n");
+        lflush();
         exit();
     }
 
@@ -742,6 +775,7 @@ main(void)
         // pinging -- which it has, because it is no longer talking to us.
         if (pr > 0 && (pf.revents & (POLLHUP | POLLERR | POLLNVAL))) {
             out("schinitd: channel closed; this supervisor has been replaced\n");
+            lflush();
         exit();
         }
 
@@ -752,6 +786,7 @@ main(void)
                 // PID 1 closed the channel. It is the one process that cannot
                 // have gone away, so this means we are being replaced.
                 out("schinitd: channel closed\n");
+                lflush();
         exit();
             }
             if (m.op == SCHINIT_PING) {

cmd/vgpud/main.c

@@ -59,12 +59,42 @@ read_bootmode(void)
     if (n > 0) { b[n] = 0; verbose_boot = (b[0] == 'v'); }
 }
 
+// Whole lines, in one write() each.
+//
+// Every message here is assembled from pieces -- a prefix, a job's label, a
+// number -- and each piece used to be its own write(). The console keeps one
+// write() together, but nothing keeps two of them together, so a job starting
+// on another CPU landed in the middle of the line: "schinitd: starting vgpud:
+// os.schos.resolvconfno virtio-gpu on this machine" was this process and
+// vgpud taking turns a word at a time. The pieces now collect here and go out
+// at the newline.
+static char lbuf[512];
+static int  lbn;
+
+static void
+lflush(void)
+{
+    if (lbn)
+        write(1, lbuf, lbn);
+    lbn = 0;
+}
+
+static void
+emit(const char *s, int n)
+{
+    for (int i = 0; i < n; i++) {
+        lbuf[lbn++] = s[i];
+        if (s[i] == '\n' || lbn == (int)sizeof lbuf)
+            lflush();
+    }
+}
+
 static void
 puts(const char *s)
 {
     int n = 0;
     while (s[n]) n++;
-    write(1, (void *)s, n);
+    emit(s, n);
 }
 
 // Progress, as opposed to news.
@@ -89,10 +119,10 @@ putn(long long v)
 {
     char b[24];
     int i = 0;
-    if (v < 0) { write(1, "-", 1); v = -v; }
+    if (v < 0) { emit("-", 1); v = -v; }
-    if (v == 0) { write(1, "0", 1); return; }
+    if (v == 0) { emit("0", 1); return; }
     while (v > 0) { b[i++] = '0' + (int)(v % 10); v /= 10; }
-    while (i-- > 0) write(1, &b[i], 1);
+    while (i-- > 0) emit(&b[i], 1);
 }
 
 static void
@@ -101,7 +131,7 @@ puthex(unsigned long long v, int digits)
     static const char h[] = "0123456789abcdef";
     char b[17];
     for (int i = digits - 1; i >= 0; i--) { b[i] = h[v & 0xF]; v >>= 4; }
-    write(1, b, digits);
+    emit(b, digits);
 }
 
 static void
@@ -123,6 +153,7 @@ nothing_to_do(const char *why)
     // still an exit the supervisor is told about, which is what stops it being
     // restarted fifteen times in forty-five seconds.
     vputs("vgpud: "); vputs(why); vputs("\n");
+    lflush();
     exit_group(SCHINIT_EXIT_NORESTART);
 }
 

docs/architecture/kernel.md

@@ -184,15 +184,17 @@ partly true:
 
 | | size | table | |
 |---|---|---|---|
-| `struct proc` | 10656 | `NPROC` 128 | larger than a page |
+| `struct proc` | 11744 | `NPROC` 128 | larger than a page; 1 KB of it is FPU state |
-| `struct socket` | 4928 | `NSOCK` 32 | larger than a page |
+| `struct socket` | 4936 | `NSOCK` 128 | larger than a page |
-| `struct buf` | 4272 | `NBUF` 256 | larger than a page |
+| `struct device` | 120 | `NDEVICE` 128 | 15 KB, never hit |
-| `struct inode` | 280 | `NINODE` 200 | a cache, bounded on purpose |
+| `struct buf` | 200 | `NBUF` 256 to start | grows from a slab, data from `kalloc`, up to RAM/32 |
-| `struct device` | 120 | `NDEVICE` 32 | 3.8 KB, never hit |
+| `struct inode` | 296 | none | grows from a slab; `NINODE` 200 is only how many are made up front |
-| `struct file` | 48 | `NFILE` 512 | 24 KB, never hit |
+| `struct file` | 64 | none | grows from a slab; `NFILE` 512 is only the static pool |
 
-The three largest cannot go in a page-backed slab at all. Freeing them needs a
+The two largest cannot go in a page-backed slab at all. Freeing them needs a
 contiguous multi-page allocator, which is a separate thing and is not written.
+The buffer header shrank to 200 bytes when its 4 KB of data moved out to a page
+of its own, which is what let the cache grow at all.
 
 ## Processes
 

include/core/defs.h

@@ -164,7 +164,6 @@ unsigned int    BKDRHash(char * str);
 uint            tree_expand(struct inode *ip, uint off);
 void            tree_search(struct inode* dp, char* name, uint* poff, struct dirent* de,uint add);
 void            build_dir_tree(struct inode* dp,uint64 pinum);
-struct inode*   divesymlink(struct inode *);
 // A socket node for AF_UNIX bind(2), and unlink by path for the failure that
 // follows it. See the notes on each in kernel/sys/sys_fs.c.
 struct inode*   create_sock(char *path);

include/core/irq.h

@@ -51,6 +51,13 @@ typedef void (*irq_handler_t)(void *arg);
 #define IRQ_LEVEL_HIGH  2
 #define IRQ_EDGE_LOW    3
 #define IRQ_IS_LEVEL(m) ((m) == IRQ_LEVEL_LOW || (m) == IRQ_LEVEL_HIGH)
+// OR'd into the mode by a handler whose line is *meant* to be silent: the
+// ACPI SCI fires for a power button or a lid, and on a desktop that is never.
+// Without it the poller below took two seconds of silence as a misrouted line
+// and called the handler every tick for the rest of the boot. A line is only
+// exempt while every handler on it says so -- a PCI device sharing the SCI's
+// pin still gets polled.
+#define IRQ_QUIET       0x10
 int  irq_register(int irq, irq_handler_t fn, void *arg, const char *name,
                   int level_low);
 void irq_unregister(int irq, irq_handler_t fn, void *arg);

kernel/acpi/host.c

@@ -501,7 +501,7 @@ uacpi_kernel_install_interrupt_handler(uacpi_u32 irq,
   s->fn = fn;
   s->ctx = ctx;
   s->irq = gsi;
-  if (irq_register(gsi, sci_trampoline, s, "acpi", mode) < 0) {
+  if (irq_register(gsi, sci_trampoline, s, "acpi", mode | IRQ_QUIET) < 0) {
     uacpi_kernel_free(s);
     return UACPI_STATUS_INTERNAL_ERROR;
   }

kernel/dev/irq.c

@@ -13,6 +13,7 @@ struct irq_action {
   void         *arg;
   const char   *name;
   uint64        count;
+  int           quiet;          // registered IRQ_QUIET
 };
 
 static struct {
@@ -22,6 +23,7 @@ static struct {
   int  level_low;
   int  msi;             // an MSI vector, not an IOAPIC pin: nothing to route
   int  polled;          // handlers run from irq_poll_thread as well
+  int  nquiet;          // handlers registered IRQ_QUIET
   uint64 delivered;     // real interrupts, not polls
   uint64 since;         // ticks when the first handler was attached
   uint64 unhandled;
@@ -65,7 +67,9 @@ irq_register(int irq, irq_handler_t fn, void *arg, const char *name,
              int level_low)
 {
   struct irq_action *a;
+  int quiet = (level_low & IRQ_QUIET) != 0;
 
+  level_low &= ~IRQ_QUIET;
   if(irq < 0 || irq >= NIRQ || fn == 0)
     return -1;
   if(reserved(irq)){
@@ -95,8 +99,10 @@ irq_register(int irq, irq_handler_t fn, void *arg, const char *name,
   a->arg   = arg;
   a->name  = name;
   a->count = 0;
+  a->quiet = quiet;
   __sync_synchronize();         // publish the entry before it is reachable
   line[irq].n++;
+  line[irq].nquiet += quiet;
   if(line[irq].n == 1)
     line[irq].since = ticks;
 
@@ -133,6 +139,7 @@ irq_unregister(int irq, irq_handler_t fn, void *arg)
         ioapicmask(irq);
       line[irq].enabled = 0;
 
+      line[irq].nquiet -= line[irq].act[i].quiet;
       for(j = i; j + 1 < line[irq].n; j++)
         line[irq].act[j] = line[irq].act[j+1];
       line[irq].n--;
@@ -423,6 +430,9 @@ irq_poll_thread(void)
     for(int irq = 0; irq < NIRQ_IOAPIC; irq++){
       if(line[irq].n == 0 || line[irq].msi || reserved(irq))
         continue;
+      // Silent by design, and only its own handlers on it.
+      if(line[irq].nquiet == line[irq].n && !line[irq].polled)
+        continue;
       int poll = line[irq].polled ||
                  (IRQ_IS_LEVEL(line[irq].level_low) && line[irq].delivered == 0 &&
                   now - line[irq].since > POLL_AFTER);