diff --git a/include/defs.h b/include/defs.h index fee92b9..6967f26 100644 --- a/include/defs.h +++ b/include/defs.h @@ -49,6 +49,9 @@ extern uint vt_chord_base; struct vt *vt_for_minor(int minor); extern uint lapic_timer_hz; // measured, kernel/arch/x86_64/lapic.c extern uint64 tsc_hz; +extern uint64 boot_tsc; +void monotonic(uint64 *sec, uint64 *usec); +int proc_write_schinit(int user_src, uint64 src, uint n); void cprintf(char*, ...); // A log line: the serial port only, never the display. diff --git a/kernel/arch/x86_64/lapic.c b/kernel/arch/x86_64/lapic.c index 5928fd2..7017be8 100644 --- a/kernel/arch/x86_64/lapic.c +++ b/kernel/arch/x86_64/lapic.c @@ -78,6 +78,7 @@ lapicw(int index, int value) uint lapic_timer_hz; // measured LAPIC timer counts per second uint64 tsc_hz; // measured TSC cycles per second +uint64 boot_tsc; // the TSC when calibration finished static void calibrate_timers(void) @@ -116,6 +117,11 @@ calibrate_timers(void) lapic_timer_hz = (uint)(((uint64)(lap0 - lap1) * 1000000) / us); tsc_hz = ((tsc1 - tsc0) * 1000000) / us; + // Where the clock starts. Everything the system reports as elapsed time is + // measured from here, against the TSC, rather than by counting timer + // interrupts -- see kernel/core/time.c. + boot_tsc = tsc1; + // 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. diff --git a/kernel/core/time.c b/kernel/core/time.c index e575ef5..654d5bc 100644 --- a/kernel/core/time.c +++ b/kernel/core/time.c @@ -19,6 +19,7 @@ #include "types.h" #include "defs.h" +#include "x86.h" #include "date.h" #include "param.h" #include "spinlock.h" @@ -91,26 +92,72 @@ 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 / HZ; + uint64 up, dummy; + monotonic(&up, &dummy); boot_epoch = now > up ? now - up : now; cprintf("time: %d-%d-%d %d:%d:%d UTC from the hardware clock\n", (int)year, r.month, r.day, r.hour, r.minute, r.second); } +// How long the machine has been running, from the TSC. +// +// **Not from `ticks`.** This is the important line in this file. +// +// `ticks` counts timer interrupts, and a timer interrupt that arrives while +// interrupts are disabled is not delayed, it is *lost* -- the LAPIC in periodic +// mode holds one pending interrupt and drops the rest. So anything the kernel +// does with interrupts off for longer than 10 ms makes the clock run slow, and +// it never catches up. A long console write, a framebuffer scroll on a display +// that is expensive to draw to, a driver spinning on a register: all of them +// silently steal time from every program that asks what time it is. +// +// That has now happened twice. The first was an interrupt storm taking 83% of +// the CPU (docs/history/kernel.md ยง13) and the clock ran seven times slow; the +// second was heavy console output, and it presented the same way. Both times +// the tick was the messenger. +// +// The TSC cannot be starved. It is a counter in the silicon that advances at a +// fixed rate whether or not this kernel is paying attention, and it is already +// measured against the PIT at boot. Reading it is one instruction and no lock. +// +// `ticks` is still what the scheduler preempts on and what sleep() counts, +// which is the right job for it: losing a tick there means a slightly longer +// sleep, not a wrong answer about what time it is. +void +monotonic(uint64 *sec, uint64 *usec) +{ + // Before calibration there is no TSC frequency to divide by. Fall back to + // the tick count, which is what this used to do always. + if (tsc_hz == 0) { + uint xticks; + acquire(&tickslock); + xticks = ticks; + release(&tickslock); + if (sec) *sec = xticks / HZ; + if (usec) *usec = (uint64)(xticks % HZ) * (1000000 / HZ); + return; + } + + uint64 d = rdtsc() - boot_tsc; + uint64 s = d / tsc_hz; + // The remainder first, then scale. `d * 1000000` would overflow 64 bits + // after about 80 minutes at 3.8 GHz; the remainder is always below tsc_hz, + // so this cannot. + uint64 rem = d - s * tsc_hz; + + if (sec) *sec = s; + if (usec) *usec = (rem * 1000000) / tsc_hz; +} + // Seconds and microseconds since the epoch. One place, so gettimeofday, // clock_gettime and anything added later cannot disagree about what time it is. void wallclock(uint64 *sec, uint64 *usec) { - uint xticks; + uint64 s, us; - acquire(&tickslock); - xticks = ticks; - release(&tickslock); - - if (sec) - *sec = boot_epoch + xticks / HZ; - if (usec) - *usec = (uint64)(xticks % HZ) * (1000000 / HZ); + monotonic(&s, &us); + if (sec) *sec = boot_epoch + s; + if (usec) *usec = us; } diff --git a/kernel/dev/irq.c b/kernel/dev/irq.c index a5a268a..78aa994 100644 --- a/kernel/dev/irq.c +++ b/kernel/dev/irq.c @@ -269,5 +269,34 @@ irq_info(char *buf, int cap) off = emit(buf, cap, off, " [spurious]"); off = emit(buf, cap, off, line[irq].level_low ? " level\n" : " edge\n"); } + + // How many timer interrupts were lost. + // + // The clock does not depend on this any more -- kernel/core/time.c reads the + // TSC -- but that makes lost ticks *invisible* rather than harmless, and + // they are not harmless: the scheduler preempts on them, and a machine + // dropping them is a machine spending too long with interrupts disabled. + // + // Twice now that has been diagnosed from the outside, by noticing a clock + // running slow, which is a terrible way to find out. This is the number to + // look at instead: expected is elapsed time times HZ, and the gap is how + // many the machine did not take. + { + uint64 sec, usec; + monotonic(&sec, &usec); + uint64 expect = sec * HZ + (usec * HZ) / 1000000; + uint64 got = ticks; + off = emit(buf, cap, off, "\ntimer: "); + off = emit_dec(buf, cap, off, got, 0); + off = emit(buf, cap, off, " ticks taken, "); + off = emit_dec(buf, cap, off, expect, 0); + off = emit(buf, cap, off, " expected"); + if (expect > got + HZ) { + off = emit(buf, cap, off, " -- LOSING "); + off = emit_dec(buf, cap, off, expect - got, 0); + off = emit(buf, cap, off, ", interrupts are off too long somewhere"); + } + off = emit(buf, cap, off, "\n"); + } return off; } diff --git a/kernel/dev/procfs.c b/kernel/dev/procfs.c index 0379480..6d56069 100644 --- a/kernel/dev/procfs.c +++ b/kernel/dev/procfs.c @@ -127,15 +127,22 @@ gen_meminfo(struct sbuf *sb) sb_kv(sb, "SwapFree: ", 0, "kB"); } + +void gen_schinit(struct sbuf *sb); /* defined at the end of this file */ + static void gen_uptime(struct sbuf *sb) { - 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); + // From the TSC, not from the tick count -- see monotonic() in + // kernel/core/time.c. A tick lost while interrupts were disabled is lost + // forever, so anything derived from ticks runs slow under load and never + // catches up. This is the number people check when they suspect that. + uint64 sec, usec; + monotonic(&sec, &usec); + sb_putu(sb, (uint)sec); sb_putc(sb, '.'); - sb_putu(sb, frac / 10); - sb_putu(sb, frac % 10); + sb_putu(sb, (uint)(usec / 100000)); + sb_putu(sb, (uint)((usec / 10000) % 10)); sb_puts(sb, " 0.00\n"); // idle time: not tracked } @@ -425,6 +432,7 @@ proc_gen_global(int id, char *buf, int cap) case PROC_PCI: sb.len = pci_info(buf, PROC_BUFSZ); break; // Likewise irq.c: it owns the table, so it renders it. case PROC_INTERRUPTS: sb.len = irq_info(buf, PROC_BUFSZ); break; + case 16: gen_schinit(&sb); break; // And likewise net.c, which is the only file here allowed to include lwIP's // headers -- reaching into the stack from this one would put them on every // kernel file's include path. @@ -520,3 +528,56 @@ procwrite(struct inode *ip, uint64 off, char *src, int n) return -1; return proc_write_sysrq(0, (uint64)src, (uint)n); } + +// --------------------------------------------------------------------------- +// /proc/schinit -- the job table +// --------------------------------------------------------------------------- +// +// docs/plan/init.md part 2. PID 1 writes this whenever the table changes and +// anyone may read it; a supervisor that has just been restarted reads it back +// and knows what is running without having started any of it. +// +// The kernel holds the text and does not interpret it. That is deliberate: a +// procfs generator runs in the kernel, and walking PID 1's memory to answer a +// read would put this file's format into the kernel, where it would then have +// to be kept in step with a userspace program. Instead the kernel is a +// pinboard -- PID 1 knows the format and knows when it changed. +// +// procfs rather than a file on disk for four reasons: it survives a read-only +// root, it survives a full disk, it costs no I/O, and it is already the +// pattern this kernel uses for exactly this kind of question. + +#define SCHINIT_TABLE_MAX 2048 + +static char schinit_table[SCHINIT_TABLE_MAX]; +static int schinit_table_len; + +int +proc_write_schinit(int user_src, uint64 src, uint n) +{ + if (n > SCHINIT_TABLE_MAX) + n = SCHINIT_TABLE_MAX; + + // A write replaces the table rather than appending to it. There is one + // writer and it always sends the whole thing, so append would only be a way + // to accumulate stale rows. + if (user_src) { + if (copy_from_user(schinit_table, src, n) < 0) + return -EFAULT; + } else { + memmove(schinit_table, (char *)src, n); + } + schinit_table_len = (int)n; + return (int)n; +} + +void +gen_schinit(struct sbuf *sb) +{ + if (schinit_table_len == 0) { + sb_puts(sb, "generation 0\nsupervisor 0\n"); + return; + } + for (int i = 0; i < schinit_table_len; i++) + sb_putc(sb, schinit_table[i]); +} diff --git a/kernel/fs/procfs.c b/kernel/fs/procfs.c index 5152448..4abf500 100644 --- a/kernel/fs/procfs.c +++ b/kernel/fs/procfs.c @@ -87,6 +87,7 @@ static const struct global_file globals[] = { { "filesystems", 8 }, { "schfs", 9 }, { "sysrq", 10 }, + { "schinit", 16 }, { "pci", 11 }, { "interrupts", 12 }, { "devices", 13 }, @@ -253,11 +254,13 @@ procfs_iload(struct inode *ip) ip->valid = 1; ip->nlink = 1; ip->major = ip->minor = 0; - // Read-only, with one exception: /proc/sysrq is the deliberate write target - // (`echo c > /proc/sysrq` to crash on purpose). Marking everything 2 made - // filewrite() refuse it with "permission denied", which the USB suite - // caught immediately -- three of its checks drive the disk through sysrq. - ip->rwmode = (INO_IS_GLOBAL(ino) && (ino & 0xFF) == 10) ? 3 : 2; + // Read-only, with two exceptions: /proc/sysrq is the deliberate write target + // (`echo c > /proc/sysrq` to crash on purpose), and /proc/schinit is where + // PID 1 publishes its job table. Marking everything 2 made filewrite() + // refuse with "permission denied", which the USB suite caught immediately -- + // three of its checks drive the disk through sysrq. + ip->rwmode = (INO_IS_GLOBAL(ino) && + ((ino & 0xFF) == 10 || (ino & 0xFF) == 16)) ? 3 : 2; ip->showmode = 1; ip->atime = ip->mtime = ip->ctime = 0; @@ -331,6 +334,12 @@ procfs_write(struct inode *ip, int user_src, uint64 src, uint64 off, uint n) // generators. Everything else is read-only, and says so. if (INO_IS_GLOBAL(ip->inum) && (ip->inum & 0xFF) == 10) return proc_write_sysrq(user_src, src, n); + // /proc/schinit is the job table, and PID 1 is the one that knows it. The + // kernel holds the text rather than generating it: walking another + // process's memory to answer a read is not something a procfs generator + // should be doing, and PID 1 already knows when the table changed. + if (INO_IS_GLOBAL(ip->inum) && (ip->inum & 0xFF) == 16) + return proc_write_schinit(user_src, src, n); (void)off; return -EROFS; } diff --git a/kernel/sys/sys_proc.c b/kernel/sys/sys_proc.c index a3f8493..dc20e21 100644 --- a/kernel/sys/sys_proc.c +++ b/kernel/sys/sys_proc.c @@ -392,11 +392,10 @@ addr_t sys_getrusage(void) argint(0, &who); if (argptr(1, (char**)&ru, sizeof(*ru)) < 0) return -1; memset(ru, 0, sizeof(*ru)); - acquire(&tickslock); - uint xt = ticks; - release(&tickslock); - ru->ru_utime.tv_sec = (long)(xt / HZ); - ru->ru_utime.tv_usec = (long)((xt % HZ) * (1000000 / HZ)); + uint64 rsec, rusec; + monotonic(&rsec, &rusec); + ru->ru_utime.tv_sec = (long)rsec; + ru->ru_utime.tv_usec = (long)rusec; return 0; } @@ -408,14 +407,15 @@ addr_t sys_times(void) struct tms *t = (struct tms*)user_ptr(bufaddr, sizeof(*t)); if (t) memset(t, 0, sizeof(*t)); } - acquire(&tickslock); - uint xt = ticks; - release(&tickslock); - // 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); + // USER_HZ units, measured from the TSC. + // + // musl answers sysconf(_SC_CLK_TCK) with 100 unconditionally, so a shell's + // `time` builtin divides whatever this returns by 100. Deriving it from + // the tick count made `time` under-report whenever ticks were being lost + // -- which is how a 20-second command came to print 3.12s. + uint64 tsec, tusec; + monotonic(&tsec, &tusec); + return (addr_t)(tsec * USER_HZ + (tusec * USER_HZ) / 1000000); } addr_t sys_sysinfo(void) @@ -425,10 +425,10 @@ addr_t sys_sysinfo(void) struct sysinfo *si = (struct sysinfo*)user_ptr(bufaddr, sizeof(*si)); if (!si) return -EFAULT; memset(si, 0, sizeof(*si)); - acquire(&tickslock); - uint xt = ticks; - release(&tickslock); - si->uptime = (long)(xt / HZ); + // TSC, like everything else that reports elapsed time. + uint64 upsec, upusec; + monotonic(&upsec, &upusec); + si->uptime = (long)upsec; // 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.