diff --git a/system/kernel/log.zig b/system/kernel/log.zig index e939859..ce1d418 100644 --- a/system/kernel/log.zig +++ b/system/kernel/log.zig @@ -139,26 +139,45 @@ fn appendLocked(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, byte fn render(pid: u32, name: []const u8, level: abi.KlogLevel, line: []const u8, line_complete: bool) void { if (sink_count == 0) return; if (line.len == 0 and !line_complete) return; + // Compose the whole rendered piece first and emit it in ONE sink call per + // sink: fewer, larger UART writes, and no partial-line window should any + // path ever reach a sink without the log lock. + var buffer: [render_buffer_size]u8 = undefined; + var used: usize = 0; if (!at_line_start and open_line_pid != pid) { - fanOut("\n"); + buffer[used] = '\n'; + used += 1; at_line_start = true; } if (at_line_start and level != .raw) { - fanOut(name); - fanOut(": "); - switch (level) { - .err => fanOut("error: "), - .warn => fanOut("warning: "), - .debug => fanOut("debug: "), - .info, .raw => {}, - } + used += place(buffer[used..], name); + used += place(buffer[used..], ": "); + used += place(buffer[used..], switch (level) { + .err => "error: ", + .warn => "warning: ", + .debug => "debug: ", + .info, .raw => "", + }); } - fanOut(line); - if (line_complete) fanOut("\n"); + used += place(buffer[used..], line); + if (line_complete and used < buffer.len) { + buffer[used] = '\n'; + used += 1; + } + fanOut(buffer[0..used]); at_line_start = line_complete; open_line_pid = pid; } +/// newline + name + ": warning: " + a full payload line + newline. +const render_buffer_size = 1 + abi.maximum_process_name + 11 + abi.klog_maximum_message + 1; + +fn place(destination: []u8, bytes: []const u8) usize { + const n = @min(destination.len, bytes.len); + @memcpy(destination[0..n], bytes[0..n]); + return n; +} + fn fanOut(bytes: []const u8) void { for (sinks[0..sink_count]) |sink| sink(bytes); } diff --git a/system/kernel/tests.zig b/system/kernel/tests.zig index b4f6111..0cf6db1 100644 --- a/system/kernel/tests.zig +++ b/system/kernel/tests.zig @@ -26,11 +26,13 @@ const irq = @import("irq.zig"); const sync = @import("sync.zig"); const process = @import("process.zig"); const initial_ramdisk = @import("initial-ramdisk"); +const kernel_log = @import("log.zig"); -/// Formatted write straight to serial, independent of the framebuffer console. +/// Formatted test-marker write. Goes through the kernel log (not straight to +/// serial): the log lock is what keeps marker lines from interleaving with +/// concurrent user-process records on other cores. fn log(comptime fmt: []const u8, args: anytype) void { - var buffer: [128]u8 = undefined; - architecture.serialWrite(std.fmt.bufPrint(&buffer, fmt, args) catch return); + kernel_log.print(fmt, args); } var passed: u32 = 0; @@ -2171,7 +2173,7 @@ fn vfsClientDeathTest(boot_information: *const BootInformation) void { check("the exit notification arrived", badge == abi.notify_badge_bit | abi.notify_exit_bit | client); // The VFS heard the same published event; its release line is the proof. - const released = "vfs: released 1 handle(s) for dead client"; + const released = "released 1 handle(s) for dead client"; scheduler.setPriority(1); deadline = architecture.millis() + 10000; while (architecture.millis() < deadline) {