From c366ea2dfd92c4d858dfe73ad4ec7ac7da9fb711 Mon Sep 17 00:00:00 2001 From: "K. Lange" Date: Tue, 19 Oct 2021 20:29:01 +0900 Subject: [PATCH] kernel: Initial pass at new debug printf interface --- apps/splash-log.c | 10 ++- base/usr/include/kernel/printf.h | 3 + kernel/arch/x86_64/cmos.c | 25 +++++-- kernel/arch/x86_64/idt.c | 46 ++++++------ kernel/arch/x86_64/main.c | 27 ++++++- kernel/arch/x86_64/smp.c | 2 + kernel/generic.c | 4 + kernel/misc/fbterm.c | 46 ++++++++++-- kernel/vfs/console.c | 124 +++++++++++++++++++++++++++++++ 9 files changed, 249 insertions(+), 38 deletions(-) create mode 100644 kernel/vfs/console.c diff --git a/apps/splash-log.c b/apps/splash-log.c index 6c8a0bec..76c9389e 100644 --- a/apps/splash-log.c +++ b/apps/splash-log.c @@ -59,6 +59,11 @@ static void write_char(int x, int y, int val, uint32_t color) { static unsigned int line_offset = 0; static void fb_update_message(char * c, int line) { + FILE * console = fopen("/dev/console","a"); + fprintf(console, "\r%s\033[K%s", c, line == 0 ? "\n" : ""); + fflush(console); + fclose(console); + #if 0 int x = 20; int y = 20 + line_offset * char_height; if (line == 0) { @@ -73,15 +78,18 @@ static void fb_update_message(char * c, int line) { write_char(x, y, ' ', FG_COLOR); x += char_width; } + #endif } static void fb_clear_screen(void) { + #if 0 line_offset = 0; for (int y = 0; y < height; ++y) { for (int x = 0; x < width; ++x) { set_point(x,y,BG_COLOR); } } + #endif } static void placech(unsigned char c, int x, int y, int attr) { @@ -203,7 +211,7 @@ int main(int argc, char * argv[]) { memcpy(tmp, p->data, p->size); tmp[p->size] = '\0'; update_message(tmp, 0); - update_message("", 1); + //update_message("", 1); free(tmp); } } diff --git a/base/usr/include/kernel/printf.h b/base/usr/include/kernel/printf.h index 832f68b6..dd53432a 100644 --- a/base/usr/include/kernel/printf.h +++ b/base/usr/include/kernel/printf.h @@ -9,3 +9,6 @@ extern size_t (*printf_output)(size_t, uint8_t *); __attribute__((format(__printf__,3,4))) extern int snprintf(char * str, size_t size, const char * format, ...); extern size_t xvasprintf(int (*callback)(void *, char), void * userData, const char * fmt, va_list args); + +__attribute__((format(__printf__,1,2))) +extern int dprintf(const char *fmt, ...); diff --git a/kernel/arch/x86_64/cmos.c b/kernel/arch/x86_64/cmos.c index 847ac427..e96925ff 100644 --- a/kernel/arch/x86_64/cmos.c +++ b/kernel/arch/x86_64/cmos.c @@ -15,6 +15,11 @@ #include #include +uint64_t arch_boot_time = 0; +uint64_t tsc_basis_time = 0; + +unsigned long tsc_mhz = 3500; /* XXX */ + #define from_bcd(val) ((val / 16) * 10 + (val & 0xf)) #define CMOS_ADDRESS 0x70 #define CMOS_DATA 0x71 @@ -126,9 +131,6 @@ uint32_t read_cmos(void) { return time; } -static uint64_t boot_time = 0; -unsigned long tsc_mhz = 3500; /* XXX */ - static inline uint64_t read_tsc(void) { uint32_t lo, hi; asm volatile ( "rdtsc" : "=a"(lo), "=d"(hi) ); @@ -144,7 +146,8 @@ size_t arch_cpu_mhz(void) { } void arch_clock_initialize(void) { - boot_time = read_cmos(); + dprintf("Calibrating system timestamp counter.\n"); + arch_boot_time = read_cmos(); uintptr_t end_lo, end_hi; uint32_t start_lo, start_hi; asm volatile ( @@ -200,11 +203,15 @@ void arch_clock_initialize(void) { uintptr_t start = ((uintptr_t)(start_hi & 0xFFFFffff) << 32) | (start_lo & 0xFFFFffff); tsc_mhz = (end - start) / 10000; if (tsc_mhz == 0) tsc_mhz = 2000; /* uh oh */ + tsc_basis_time = start / tsc_mhz; + + dprintf("TSC timed at %lu MHz. Use tsc_mhz= to override if this is very wrong.\n", tsc_mhz); + dprintf("Boot time is %lus. Initial TSC timestamp was %luus.\n", arch_boot_time, tsc_basis_time); } #define SUBSECONDS_PER_SECOND 1000000 static void update_ticks(uint64_t ticks, uint64_t *timer_ticks, uint64_t *timer_subticks) { - *timer_subticks = ticks; + *timer_subticks = ticks - tsc_basis_time; *timer_ticks = *timer_subticks / SUBSECONDS_PER_SECOND; *timer_subticks = *timer_subticks % SUBSECONDS_PER_SECOND; } @@ -213,7 +220,7 @@ int gettimeofday(struct timeval * t, void *z) { uint64_t tsc = read_tsc(); uint64_t timer_ticks, timer_subticks; update_ticks(tsc / tsc_mhz, &timer_ticks, &timer_subticks); - t->tv_sec = boot_time + timer_ticks; + t->tv_sec = arch_boot_time + timer_ticks; t->tv_usec = timer_subticks; return 0; } @@ -226,6 +233,12 @@ uint64_t now(void) { void relative_time(unsigned long seconds, unsigned long subseconds, unsigned long * out_seconds, unsigned long * out_subseconds) { + if (!arch_boot_time) { + *out_seconds = 0; + *out_subseconds = 0; + return; + } + uint64_t tsc = read_tsc(); uint64_t timer_ticks, timer_subticks; update_ticks(tsc / tsc_mhz, &timer_ticks, &timer_subticks); diff --git a/kernel/arch/x86_64/idt.c b/kernel/arch/x86_64/idt.c index d1904cd9..af9da5bd 100644 --- a/kernel/arch/x86_64/idt.c +++ b/kernel/arch/x86_64/idt.c @@ -114,7 +114,7 @@ void idt_ap_install(void) { static spin_lock_t dump_lock = {0}; static void dump_regs(struct regs * r) { spin_lock(dump_lock); - printf( + dprintf( "Registers at interrupt:\n" " $rip=0x%016lx\n" " $rsi=0x%016lx,$rdi=0x%016lx,$rbp=0x%016lx,$rsp=0x%016lx\n" @@ -218,29 +218,29 @@ static void safe_dump_traceback(struct regs * r) { int max_depth = 20; while (bp && ip && depth < max_depth) { - printf(" 0x%016zx ", ip); + dprintf(" 0x%016zx ", ip); if (ip >= 0xffffffff80000000UL) { char * name = NULL; struct LoadedModule * mod = find_module(ip, &name); if (mod) { - printf(" in module '%s', base address %#zx (offset %#zx)\n", + dprintf("\a in module '%s', base address %#zx (offset %#zx)\n", name, mod->baseAddress, r->rip - mod->baseAddress); } else { - printf(" (unknown)\n"); + dprintf("\a (unknown)\n"); } } else if (ip >= (uintptr_t)&end && ip <= 0x800000000000) { - printf(" in userspace\n"); + dprintf("\a in userspace\n"); } else if (ip <= (uintptr_t)&end) { /* Find symbol match */ char * name; uintptr_t addr = matching_symbol(ip, &name); if (!addr) { - printf(" (no match)\n"); + dprintf("\a (no match)\n"); } else { - printf(" %s+0x%zx\n", name, ip-addr); + dprintf("\a %s+0x%zx\n", name, ip-addr); } } else { - printf(" (unknown)\n"); + dprintf("\a (unknown)\n"); } if (!validate_pointer(bp, sizeof(uintptr_t) * 2)) { break; @@ -266,6 +266,19 @@ static void map_more_stack(uintptr_t fromAddr) { spin_unlock(proc->image.lock); } +extern void arch_fatal_prepare(void); +static void panic(const char * desc, struct regs * r, uintptr_t faulting_address) { + arch_fatal_prepare(); + dprintf("\033[31mPanic!\033[0m %s pid=%d (%s) at %#zx\n", desc, + this_core->current_process ? (int)this_core->current_process->id : 0, + this_core->current_process ? this_core->current_process->name : "kernel", + faulting_address + ); + dump_regs(r); + safe_dump_traceback(r); + arch_fatal(); +} + struct regs * isr_handler(struct regs * r) { this_core->interrupt_registers = r; @@ -278,14 +291,7 @@ struct regs * isr_handler(struct regs * r) { uintptr_t faulting_address; asm volatile("mov %%cr2, %0" : "=r"(faulting_address)); if (!this_core->current_process || r->cs == 0x08) { - printf("Page fault in kernel "); - if (this_core->current_process) { - printf("pid=%d (%s) ", (int)this_core->current_process->id, this_core->current_process->name); - } - printf("at %#zx\n", faulting_address); - safe_dump_traceback(r); - dump_regs(r); - arch_fatal(); + panic("Page fault in kernel", r, faulting_address); } if (faulting_address == 0xFFFFB00F) { /* Thread exit */ @@ -305,13 +311,13 @@ struct regs * isr_handler(struct regs * r) { } case 13: /* GPF */ { if (!this_core->current_process || r->cs == 0x08) { - arch_fatal(); + panic("GPF in kernel", r, 0); } send_signal(this_core->current_process->id, SIGSEGV, 1); break; } case 8: /* Double fault */ { - arch_fatal(); + panic("Double fault", r, 0); break; } case 127: /* syscall */ { @@ -338,10 +344,8 @@ struct regs * isr_handler(struct regs * r) { default: { if (r->int_no < 32) { if (!this_core->current_process || r->cs == 0x08) { - arch_fatal(); + panic("Unexpected interrupt", r, r->int_no); } - printf("int_no %ld in process %d\n", - r->int_no, this_core->current_process->id); send_signal(this_core->current_process->id, SIGILL, 1); } else { for (size_t i = 0; i < IRQ_CHAIN_DEPTH; i++) { diff --git a/kernel/arch/x86_64/main.c b/kernel/arch/x86_64/main.c index 45308fce..66c583ec 100644 --- a/kernel/arch/x86_64/main.c +++ b/kernel/arch/x86_64/main.c @@ -22,6 +22,7 @@ #include #include #include +#include #include #include @@ -32,6 +33,7 @@ extern void arch_clock_initialize(void); extern char end[]; +extern unsigned long tsc_mhz; extern void gdt_install(void); extern void idt_install(void); @@ -46,8 +48,11 @@ extern void pci_remap(void); struct multiboot * mboot_struct = NULL; +static int _serial_debug = 1; #define EARLY_LOG_DEVICE 0x3F8 static size_t _early_log_write(size_t size, uint8_t * buffer) { + if (!_serial_debug) return size; + for (unsigned int i = 0; i < size; ++i) { outportb(EARLY_LOG_DEVICE, buffer[i]); } @@ -178,21 +183,25 @@ void mount_multiboot_ramdisks(struct multiboot * mboot) { uint8_t * data = mmu_map_from_physical(mods[i].mod_start); if (data[0] == 0x1F && data[1] == 0x8B) { /* Yes - decompress it first */ + dprintf("Decompressing initial ramdisk...\n"); uint32_t decompressedSize = *(uint32_t*)mmu_map_from_physical(mods[i].mod_end - sizeof(uint32_t)); size_t pageCount = (((size_t)decompressedSize + 0xFFF) & ~(0xFFF)) >> 12; uintptr_t physicalAddress = mmu_allocate_n_frames(pageCount) << 12; if (physicalAddress == (uintptr_t)-1) { - printf("gzip: failed to allocate pages for decompressed payload, skipping\n"); + dprintf("gzip: failed to allocate pages for decompressed payload, skipping\n"); continue; } gzip_inputPtr = (void*)data; gzip_outputPtr = mmu_map_from_physical(physicalAddress); /* Do the deed */ if (gzip_decompress()) { - printf("gzip: failed to decompress payload, skipping\n"); + dprintf("gzip: failed to decompress payload, skipping\n"); continue; } ramdisk_mount(physicalAddress, decompressedSize); + dprintf("Decompressed %u kB to %u kB, freeing compressed image.\n", + (mods[i].mod_end - mods[i].mod_start) / 1024, + (decompressedSize) / 1024); /* Free the pages from the original mod */ for (size_t j = mods[i].mod_start; j < mods[i].mod_end; j += 0x1000) { mmu_frame_clear(j); @@ -241,6 +250,15 @@ int kmain(struct multiboot * mboot, uint32_t mboot_mag, void* esp) { * as soon as we can call printf(), which is as soon as we get to long mode. */ early_log_initialize(); + dprintf("%s %d.%d.%d-%s \"%s\" %s\n", + __kernel_name, + __kernel_version_major, + __kernel_version_minor, + __kernel_version_lower, + __kernel_version_suffix, + __kernel_version_codename, + __kernel_arch); + /* Initialize GS base */ arch_set_core_base((uintptr_t)&processor_local_data[0]); @@ -269,10 +287,13 @@ int kmain(struct multiboot * mboot, uint32_t mboot_mag, void* esp) { /* Should we override the TSC timing? */ if (args_present("tsc_mhz")) { - extern unsigned long tsc_mhz; tsc_mhz = atoi(args_value("tsc_mhz")); } + if (!args_present("debug")) { + _serial_debug = 0; + } + /* Scheduler is running and we have parsed the kcmdline, initialize video. */ framebuffer_initialize(); fbterm_initialize(); diff --git a/kernel/arch/x86_64/smp.c b/kernel/arch/x86_64/smp.c index 454c9303..7b7b1417 100644 --- a/kernel/arch/x86_64/smp.c +++ b/kernel/arch/x86_64/smp.c @@ -321,6 +321,8 @@ _toomany: /* Wait for AP to signal it is ready before starting next AP */ do { asm volatile ("pause" : : : "memory"); } while (!_ap_startup_flag); } + + dprintf("SMP enabled with %d cores\n", cores); } void arch_wakeup_others(void) { diff --git a/kernel/generic.c b/kernel/generic.c index e8ee2d56..9fd2ec59 100644 --- a/kernel/generic.c +++ b/kernel/generic.c @@ -27,6 +27,7 @@ extern void random_initialize(void); extern int system(const char * path, int argc, const char ** argv, const char ** envin); extern void snd_install(void); extern void net_install(void); +extern void console_initialize(void); void generic_startup(void) { args_parse(arch_get_cmdline()); @@ -36,6 +37,7 @@ void generic_startup(void) { tarfs_register_init(); tmpfs_register_init(); map_vfs_directory("/dev"); + console_initialize(); packetfs_initialize(); zero_initialize(); procfs_initialize(); @@ -65,6 +67,8 @@ int generic_main(void) { boot_app = args_value("init"); } + dprintf("Running %s as init process.\n", boot_app); + const char * argv[] = { boot_app, boot_arg, diff --git a/kernel/misc/fbterm.c b/kernel/misc/fbterm.c index e3ee1d84..6bc6ace1 100644 --- a/kernel/misc/fbterm.c +++ b/kernel/misc/fbterm.c @@ -11,10 +11,6 @@ #include #include -/* Exported cell sizing */ -size_t fbterm_width = 0; -size_t fbterm_height = 0; - /* Whether to scroll or wrap when cursor reaches the bottom. */ static int fbterm_scroll = 0; @@ -40,7 +36,7 @@ static uint32_t bg_color = BG_COLOR; extern uint32_t lfb_resolution_s; -static void set_point(int x, int y, uint32_t value) { +static inline void set_point(int x, int y, uint32_t value) { ((uint32_t*)lfb_vid_memory)[y * (lfb_resolution_s/4) + x] = value; } @@ -60,6 +56,14 @@ static void write_char(int x, int y, int val, uint32_t color) { } } +static void fbterm_init_framebuffer(void) { + for (size_t y = 0; y < lfb_resolution_y; ++y) { + for (size_t x = 0; x < lfb_resolution_x; ++x) { + set_point(x,y,BG_COLOR); + } + } +} + /* We push text in one pixel, which unfortunately means we have slightly less room, * but it also means the text doesn't run right into the left and right edges which * just looks kinda bad. */ @@ -95,6 +99,8 @@ static char term_buf[1024] = {0}; static int term_buf_c = 0; static void invert_at(int x, int y) { + /* Disable cursor for now, as it reads from video memory which is generally slow. */ +#if 0 for (uint8_t i = 0; i < char_height; ++i) { for (uint8_t j = 0; j < char_width; ++j) { uint32_t current = ((uint32_t*)lfb_vid_memory)[(y+i) * lfb_resolution_x + (x+j)]; @@ -105,6 +111,7 @@ static void invert_at(int x, int y) { ((uint32_t*)lfb_vid_memory)[(y+i) * lfb_resolution_x + (x+j)] = current; } } +#endif } static void process_char(char ch) { @@ -240,6 +247,27 @@ size_t fbterm_write(size_t size, uint8_t *buffer) { return size; } +static void draw_square(int x, int y) { + for (size_t _y = 0; _y < 7; ++_y) { + for (size_t _x = 0; _x < 7; ++_x) { + set_point(1 + x * 8 + _x, 1 + y * 8 + _y, + 0xFF00B2FF - (y * 8 + _y) * 0x200); + } + } +} + +static void fbterm_draw_logo(void) { + uint64_t logo_squares = 0x981818181818FFFFUL; + for (size_t y = 0; y < 8; ++y) { + for (size_t x = 0; x < 8; ++x) { + if (logo_squares & (1 << x)) { + draw_square(x,y); + } + } + logo_squares >>= 8; + } +} + void fbterm_initialize(void) { if (!lfb_resolution_x) return; @@ -247,8 +275,12 @@ void fbterm_initialize(void) { fbterm_scroll = 1; } - fbterm_width = (lfb_resolution_x - LEFT_PAD) / char_width; - fbterm_height = (lfb_resolution_y) / char_height; + fbterm_init_framebuffer(); + fbterm_draw_logo(); + y = 66; + previous_writer = printf_output; printf_output = fbterm_write; + + dprintf("fbterm: Generic framebuffer text output enabled.\n"); } diff --git a/kernel/vfs/console.c b/kernel/vfs/console.c new file mode 100644 index 00000000..d9aa9daf --- /dev/null +++ b/kernel/vfs/console.c @@ -0,0 +1,124 @@ +/** + * @file kernel/vfs/console.c + * @brief Device file interface to the kernel console. + * + * @copyright + * This file is part of ToaruOS and is released under the terms + * of the NCSA / University of Illinois License - see LICENSE.md + * Copyright (C) 2021 K. Lange + */ +#include +#include +#include +#include +#include +#include +#include + +static fs_node_t * console_dev = NULL; + +/** Things we use to determine if the clock is ready. */ +extern uint64_t arch_boot_time; + +/** Things we use for framebuffer output. */ +extern uint16_t lfb_resolution_x; +extern size_t (*printf_output)(size_t, uint8_t *); +extern size_t fbterm_write(size_t, uint8_t *); + +static uint8_t tmp_buffer[4096] __attribute__((aligned(4096))); +static uint8_t * buffer_start = tmp_buffer; + +static ssize_t write_console(size_t size, uint8_t *buffer) { + if (lfb_resolution_x) return fbterm_write(size,buffer); + + if (buffer_start + size >= tmp_buffer + sizeof(tmp_buffer)) { + return 0; /* uh oh */ + } + + memcpy(buffer_start, buffer, size); + buffer_start += size; + + return size; +} + +struct dprintf_data { + int prev_was_lf; + int left_width; +}; + +static int cb_printf(void * user, char c) { + struct dprintf_data * data = user; + if (data->prev_was_lf) { + for (int i = 0; i < data->left_width; ++i) write_console(1, (uint8_t*)" "); + data->prev_was_lf = 0; + } + if (c == '\n') data->prev_was_lf = 1; + write_console(1, (uint8_t*)&c); + return 0; +} + +int dprintf(const char * fmt, ...) { + va_list args; + va_start(args, fmt); + + /* Is a viable output ready? */ + if (lfb_resolution_x && buffer_start != tmp_buffer) { + fbterm_write(buffer_start - tmp_buffer, tmp_buffer); + buffer_start = tmp_buffer; + } + + /* Is this a FATAL message? */ + + /* If it's ready now but wasn't ready previously, are there + * things in the queue to dump? */ + + /* Is this a fresh message for this core that we need to assign a timestamp to? */ + + + struct dprintf_data _data = {0,0}; + + if (*fmt == '\a') { + fmt++; + } else { + char timestamp[32]; + unsigned long timer_ticks, timer_subticks; + relative_time(0,0,&timer_ticks,&timer_subticks); + size_t ts_len = snprintf(timestamp, 31, "[%5lu.%06lu] ", timer_ticks, timer_subticks); + _data.left_width = ts_len; + write_console(ts_len, (uint8_t*)timestamp); + } + + int out = xvasprintf(cb_printf, &_data, fmt, args); + va_end(args); + return out; +} + +static ssize_t write_fs_console(fs_node_t * node, off_t offset, size_t size, uint8_t * buffer) { + if (size > 0x1000) return -EINVAL; + size_t size_in = size; + if (size && *buffer == '\r') { + write_console(1,(uint8_t*)"\r"); + buffer++; + size--; + } + if (size) dprintf("%*s", (unsigned int)size, buffer); + return size_in; +} + +static fs_node_t * console_device_create(void) { + fs_node_t * fnode = malloc(sizeof(fs_node_t)); + memset(fnode, 0x00, sizeof(fs_node_t)); + fnode->inode = 0; + strcpy(fnode->name, "console"); + fnode->uid = 0; + fnode->gid = 0; + fnode->mask = 0660; + fnode->flags = FS_CHARDEVICE; + fnode->write = write_fs_console; + return fnode; +} + +void console_initialize(void) { + console_dev = console_device_create(); + vfs_mount("/dev/console", console_dev); +}