diff --git a/src/kern/log.zig b/src/kern/log.zig index 45f68f7..f15f1e8 100644 --- a/src/kern/log.zig +++ b/src/kern/log.zig @@ -1,33 +1,52 @@ const std = @import("std"); const b = @import("base"); +const rtl = @import("rtl"); const pl = b.pl; const ke = b.ke; +const ki = ke.private; -pub var debug_lock = ke.SpinLock.init(); +var console_lock = ke.SpinLock.init(); +var console_list: rtl.List = .{ .head = .{ .next = &console_list.head, .prev = &console_list.head } }; -pub fn print(bytes: []const u8) void { - for (bytes) |c| { - pl.debug_write(c); - } +/// Represents a console device. +/// This is used as an output device. +pub const Console = struct { + last_seq: u64, + write: WriteFn, + link: rtl.List.Entry, + pub const WriteFn = *const fn (self: *Console, data: []const u8) void; +}; + +/// Register a console. +pub fn register_console(console: *Console) void { + const ipl = console_lock.acquire(); + console_list.insert_tail(&console.link); + console_lock.release(ipl); + + flush(); } -const LogWriter = struct { +const ConsoleWriter = struct { interface: std.Io.Writer, + console: *Console, - pub fn init() LogWriter { + pub fn init(console: *Console) ConsoleWriter { return .{ .interface = .{ .vtable = &.{ .drain = drain }, .buffer = &.{}, .end = 0, }, + .console = console, }; } - fn drain(_: *std.Io.Writer, data: []const []const u8, _: usize) std.Io.Writer.Error!usize { + fn drain(w: *std.Io.Writer, data: []const []const u8, _: usize) std.Io.Writer.Error!usize { + const self: *ConsoleWriter = @fieldParentPtr("interface", w); + var total_written: usize = 0; for (data) |slice| { - print(slice); + self.console.write(self.console, slice); total_written += slice.len; } @@ -35,6 +54,34 @@ const LogWriter = struct { } }; +var ringbuffer = ki.log_ring.RingBuffer(14, 5).init(); + +fn flush() void { + var buf: [512]u8 = undefined; + + // Note: we trylock here because if the lock is already held, that means + // someone else is already flushing the logs. + if (console_lock.try_acquire()) |ipl| { + var it = console_list.iterator(); + + while (it.next()) : (it.advance()) { + const console: *Console = @fieldParentPtr("link", it.get()); + var writer = ConsoleWriter.init(console); + + while (true) { + const info = ringbuffer.read(console.last_seq, &buf) catch break; + + writer.interface.print("[{:>5}.{:06}] ", .{ info.timestamp / std.time.ns_per_s, info.timestamp / std.time.ns_per_us }) catch break; + console.write(console, buf[0..info.length]); + + console.last_seq = info.sequence + 1; + } + } + + console_lock.release(ipl); + } +} + pub fn log( comptime level: std.log.Level, comptime scope: @EnumLiteral(), @@ -44,14 +91,17 @@ pub fn log( _ = level; _ = scope; - const ipl = debug_lock.acquire(); + var discarder: std.Io.Writer.Discarding = .init(&.{}); + discarder.writer.print(fmt ++ "\n", args) catch return; - var writer = LogWriter.init(); + var res = ringbuffer.reserve(discarder.fullCount()) catch return; - writer.interface.print( - fmt ++ "\r\n", - args, - ) catch unreachable; + res.info.timestamp = ke.timecounter.read_time_nano(); + res.info.length = @truncate(discarder.fullCount()); - debug_lock.release(ipl); + res.buf = std.fmt.bufPrint(res.buf, fmt ++ "\n", args) catch return; + + ringbuffer.publish(res); + + flush(); } diff --git a/src/kern/log_ring.zig b/src/kern/log_ring.zig new file mode 100644 index 0000000..0d2f306 --- /dev/null +++ b/src/kern/log_ring.zig @@ -0,0 +1,566 @@ +const std = @import("std"); +const base = @import("base"); +const rtl = @import("rtl"); +const ke = base.ke; +const ki = ke.private; + +const BlkPos = struct { + begin: usize, + end: usize, +}; + +const DescState = enum(u2) { + Reserved = 0, + Published = 1, + Free = 2, + Miss = 3, +}; + +const usize_bits = @bitSizeOf(usize); +// Id is a monotonically increasing counter. `id & desc_mask` maps to the physical array index. +const Id = std.meta.Int(.unsigned, usize_bits - 2); +const IdSigned = std.meta.Int(.signed, usize_bits - 2); + +const State = packed struct(usize) { + id: Id, + state: DescState, +}; + +const Desc = struct { + state: std.atomic.Value(State), + blk_pos: BlkPos, +}; + +pub const Info = struct { + sequence: u64, + timestamp: u64, + length: u16, +}; + +const Entry = struct { + id: usize, + data: *[]u8, + data_size: u16, +}; + +const DataBlock = struct { + id: Id, + data: [0]u8, +}; + +pub const Reservation = struct { + irq_state: bool, + id: Id, + info: *Info, + buf: []u8, +}; + +pub const ReserveError = error{ NoSpace, ReservationFailed, ZeroSize }; +pub const ReadError = error{NotYetAvailable}; + +// Logical positions are always aligned to `@sizeOf(usize)` (even numbers). +// Thus, 1 (an odd number) is guaranteed to never collide with a real data block position. +const lpos_no_data = 1; + +pub fn RingBuffer(data_size_bits: usize, avg_msg_bits: usize) type { + return struct { + const data_size = 1 << data_size_bits; + const desc_bits = data_size_bits - avg_msg_bits; + const desc_count = 1 << desc_bits; + const desc_mask = desc_count - 1; + const data_mask = data_size - 1; + + descs: [desc_count]Desc, + infos: [desc_count]Info, + data: [data_size]u8, + + /// ID of the newest descriptor. + head_id: std.atomic.Value(usize), + /// ID of the oldest descriptor. + tail_id: std.atomic.Value(usize), + + /// Logical position of the next (not yet existing) data block. + head_lpos: std.atomic.Value(usize), + + /// Beginning of the oldest data block. + tail_lpos: std.atomic.Value(usize), + + const Self = @This(); + + // Returns the exact Id of the descriptor that occupied this physical slot one loop ago. + fn prev_wrap(id: Id) Id { + return id -% desc_count; + } + + fn get_desc_state(id: Id, expected: State) DescState { + if (id != expected.id) { + return .Miss; + } + + return expected.state; + } + + fn to_block_size(size: usize) usize { + var sz = size; + sz += @sizeOf(DataBlock); + sz = std.mem.alignForward(usize, sz, @sizeOf(usize)); + return sz; + } + + fn to_desc(self: *Self, id: Id) *Desc { + return &self.descs[id & desc_mask]; + } + + fn to_info(self: *Self, id: Id) *Info { + return &self.infos[id & desc_mask]; + } + + fn to_block(self: *Self, lpos: usize) *DataBlock { + return @ptrCast(@alignCast(&self.data[lpos & data_mask])); + } + + fn check_size(size: usize) bool { + // If the size is larger than half of the data buffer, it can never fit in the ring buffer. + return size <= data_size / 2; + } + + fn need_more_space(lpos_current: usize, lpos_next: usize) bool { + // Unsigned wrapping arithmetic safely calculates distance between positions + // across overflow, checking if it exceeds the ring's physical capacity. + return lpos_next -% lpos_current -% 1 < data_size; + } + + const ReadDescResult = struct { + state: DescState, + seq: u64 = 0, + desc: Desc = undefined, + }; + + fn read_desc(self: *Self, id: Id) ReadDescResult { + const desc = self.to_desc(id); + const info = self.to_info(id); + var state_var = desc.state.load(.acquire); + const state = get_desc_state(id, state_var); + + var result: ReadDescResult = .{ .state = state }; + + if (state == .Miss or state == .Reserved) { + result.desc.state.store(state_var, .monotonic); + return result; + } + + // Copy descriptor position and state block. + // Ordering is not critical for the payload copy itself. + result.desc.blk_pos = desc.blk_pos; + result.desc.state.store(state_var, .monotonic); + + result.seq = info.sequence; + + // Ensure the copy is finished before the state load. + rtl.barrier.rmb(); + + state_var = desc.state.load(.acquire); + result.state = get_desc_state(id, state_var); + result.desc.state.store(state_var, .monotonic); + + return result; + } + + fn read_desc_finalized(self: *Self, id: Id, seq: u64, desc_out: *Desc) !void { + const res = self.read_desc(id); + desc_out.* = res.desc; + + if (res.state == .Miss or res.state == .Reserved or (res.seq != seq)) { + return error.Invalid; + } + + if (res.state == .Free or (desc_out.blk_pos.begin == lpos_no_data)) + return error.DataLost; + } + + fn free_desc(self: *Self, id: Id) void { + var desc = self.to_desc(id); + const expected_state: State = .{ .state = .Published, .id = id }; + const new_state: State = .{ .state = .Free, .id = id }; + + _ = desc.state.cmpxchgStrong(expected_state, new_state, .release, .monotonic); + } + + fn free_data(self: *Self, begin: usize, end: usize) ?usize { + var desc: Desc = undefined; + var cur_begin = begin; + + while (need_more_space(cur_begin, end)) { + const blk = self.to_block(cur_begin); + + // Loading the ID here is purposely racey because we check if the descriptor is valid anyway. + const id: Id = @truncate(@atomicLoad(usize, @as(*usize, @ptrCast(&blk.id)), .monotonic)); + const res = self.read_desc(id); + desc = res.desc; + + switch (res.state) { + .Miss, .Reserved => { + // The block is still in use, we can't free it yet. + return null; + }, + .Published => { + if (desc.blk_pos.begin != cur_begin) { + // The descriptor does not point back to the data block, we must've lost a race. + return null; + } + self.free_desc(id); + }, + .Free => { + if (desc.blk_pos.begin != cur_begin) { + // The descriptor does not point back to the data block, we must've lost a race. + return null; + } + }, + } + + // The block can be freed, move to the next one. + cur_begin = desc.blk_pos.end; + } + + return cur_begin; + } + + fn data_advance_tail(self: *Self, new_tail_lpos: usize) !void { + if (new_tail_lpos & 1 != 0) { + // No data. + return; + } + + var cur_tail = self.tail_lpos.load(.monotonic); + + // Loop until the tail is at or beyond the new tail position. + while (need_more_space(cur_tail, new_tail_lpos)) { + // Invalidate all data blocks before the new tail position. + if (self.free_data(cur_tail, new_tail_lpos)) |new_tail| { + // Successfully freed some blocks, try advancing the tail. + if (self.tail_lpos.cmpxchgWeak(cur_tail, new_tail, .release, .monotonic)) |real_cur_tail| { + cur_tail = real_cur_tail; + std.atomic.spinLoopHint(); + } else { + break; + } + } else { + // Failed to free the data, which means we either lost a race or the descriptor is still in use. + // Reload the tail position to try again. + const new_tail = self.tail_lpos.load(.acquire); + if (new_tail == cur_tail) { + return error.ReservationFailed; + } + + // Another CPU pushed the tail, try again. + cur_tail = new_tail; + std.atomic.spinLoopHint(); + continue; + } + } + } + + // Try advancing the tail. + fn advance_tail(self: *Self, tail_id: Id) !void { + const res = self.read_desc(tail_id); + const tail_desc = res.desc; + + switch (res.state) { + .Published => { + // Free the descriptor. + self.free_desc(tail_id); + }, + .Reserved => { + // The descriptor is still reserved, we can't do anything but fail the reservation. + return error.ReservationFailed; + }, + .Miss => { + if (tail_desc.state.load(.monotonic).id == prev_wrap(tail_id)) { + // This must mean that the descriptor is currently getting reserved by another writer. + return error.ReservationFailed; + } + + // Someone else has already advanced the tail, we are good. + return; + }, + .Free => { + // The descriptor is already free, we can just advance the tail. + }, + } + + // Invalidate data blocks + try self.data_advance_tail(tail_desc.blk_pos.end); + + // Read the next descriptor after tail_id, because the tail must always be in a finalized or free state. + const next_res = self.read_desc(tail_id +% 1); + + if (next_res.state == .Published or next_res.state == .Free) { + // Advance the tail to the next descriptor. + // release: push all previous state changes before the tail update, guaranteeing the new tail is visible after all evictions. + _ = self.tail_id.cmpxchgStrong(@as(usize, tail_id), @as(usize, tail_id +% 1), .release, .monotonic); + } else { + // The next descriptor is not in the desired state. + // One possibility is that the tail was pushed by another CPU, in which case we are good. + const tail_id_cur = self.tail_id.load(.acquire); + if (tail_id_cur != tail_id) { + // Another CPU pushed the tail, we are good. + return; + } + return error.ReservationFailed; + } + } + + // Reserve a new descriptor and make space for it if needed. + fn reserve_desc(self: *Self) !Id { + var head_id: Id = @truncate(self.head_id.load(.acquire)); + var new_id: Id = undefined; + var prev_id: Id = undefined; + + while (true) { + new_id = head_id +% 1; + prev_id = prev_wrap(new_id); + + // Ordering: acquire pairs with release in advance_tail, + // guaranteeing we see the tail after any previous evictions. + const tail_id = self.tail_id.load(.acquire); + + if (prev_id == tail_id) { + // Wrapped back to the tail, need to make space by advancing it. + try self.advance_tail(prev_id); + } + + // Ordering: acq_rel to claim head and publish, acquire on failure to retry. + if (self.head_id.cmpxchgWeak(head_id, new_id, .acq_rel, .acquire)) |val| { + head_id = @truncate(val); + std.atomic.spinLoopHint(); + } else { + break; + } + } + + const desc = self.to_desc(new_id); + + // Ordering: monotonic is safe here because acq_rel on head_id published our claim. + const prev_state = desc.state.load(.monotonic); + const raw: usize = @bitCast(prev_state); + + if (raw != 0 and get_desc_state(prev_id, prev_state) != .Free) { + return error.ReservationFailed; + } + + // Ordering: release ensures all setup is published before making the descriptor reserved. + if (desc.state.cmpxchgStrong(prev_state, .{ .state = .Reserved, .id = new_id }, .release, .monotonic) != null) { + return error.ReservationFailed; + } + + return new_id; + } + + // Check if a block crosses the buffer boundary. + // `lpos` encodes a "generation" in its upper bits to track wrapping. + fn data_wraps(begin: usize, end: usize) bool { + return (begin >> data_size_bits) != ((end -% 1) >> data_size_bits); + } + + fn get_next_lpos(lpos: usize, size: usize) usize { + const begin_lpos = lpos; + const next_lpos = lpos +% size; + + // We never physically split a payload across the ring boundary. + // If it would cross the boundary, we advance the `lpos` to the next generation boundary + // so the data can sit contiguously at physical offset 0. + if (data_wraps(begin_lpos, next_lpos)) { + return ((next_lpos >> data_size_bits) << data_size_bits) + size; + } + + return next_lpos; + } + + fn alloc_data(self: *Self, size: usize, id: Id, out_position: *BlkPos) ReserveError![]u8 { + const blk_size = to_block_size(size); + var head_lpos = self.head_lpos.load(.monotonic); + var new_head_lpos = head_lpos; + + if (size == 0) { + out_position.begin = lpos_no_data; + out_position.end = lpos_no_data; + return error.ZeroSize; + } + + while (true) { + new_head_lpos = get_next_lpos(head_lpos, blk_size); + + // Make room if needed, try advancing the tail until we have enough space. + self.data_advance_tail(new_head_lpos -% data_size) catch |e| { + out_position.begin = lpos_no_data; + out_position.end = lpos_no_data; + return e; + }; + + // Try to claim the new head position. + if (self.head_lpos.cmpxchgWeak(head_lpos, new_head_lpos, .acq_rel, .acquire)) |real_head_lpos| { + head_lpos = real_head_lpos; + std.atomic.spinLoopHint(); + } else { + break; + } + } + + var blk = self.to_block(head_lpos); + blk.id = id; + + if (data_wraps(head_lpos, new_head_lpos)) { + // Wrapping blocks store their data at the beginning + blk = self.to_block(0); + blk.id = id; + } + + out_position.begin = head_lpos; + out_position.end = new_head_lpos; + + return @as([*]u8, @ptrCast(&blk.data))[0..size]; + } + + fn read_internal(self: *Self, seq: u64, buf: ?[]u8) !Info { + const rdesc = self.to_desc(@truncate(seq)); + const info = self.to_info(@truncate(seq)); + var desc: Desc = undefined; + + const id = rdesc.state.load(.monotonic).id; + + try self.read_desc_finalized(id, seq, &desc); + + const result_info = info.*; + + if (buf) |b| { + if (desc.blk_pos.begin == lpos_no_data) { + return error.DataLost; + } + + var blk = self.to_block(desc.blk_pos.begin); + if (data_wraps(desc.blk_pos.begin, desc.blk_pos.end)) { + blk = self.to_block(0); + } + + const data_ptr: [*]u8 = @ptrCast(&blk.data); + const len = @min(b.len, result_info.length); + @memcpy(b[0..len], data_ptr[0..len]); + } + + try self.read_desc_finalized(id, seq, &desc); + return result_info; + } + + /// Initialize and return a new ring buffer instance. + pub fn init() Self { + const dummy_id: Id = 0 -% @as(Id, desc_count + 1); + const blk0: usize = -%@as(usize, data_size); + + var self: Self = std.mem.zeroes(Self); + + self.descs[desc_count - 1].state.store(.{ .state = .Free, .id = dummy_id }, .monotonic); + self.descs[desc_count - 1].blk_pos = .{ .begin = lpos_no_data, .end = lpos_no_data }; + + self.head_id.store(dummy_id, .monotonic); + self.tail_id.store(dummy_id, .monotonic); + + self.infos[0].sequence = -%(@as(u64, desc_count)); + + self.head_lpos.store(blk0, .monotonic); + self.tail_lpos.store(blk0, .monotonic); + + return self; + } + + /// Reserve space for a record and return a reservation. + pub fn reserve(self: *Self, size: usize) ReserveError!Reservation { + if (!check_size(size)) { + return error.NoSpace; + } + + var reservation: Reservation = undefined; + + reservation.irq_state = ki.impl.disable_interrupts(); + + const id = try self.reserve_desc(); + + const desc = self.to_desc(id); + var info = self.to_info(id); + const seq = info.sequence; + + reservation.id = id; + + if (seq == 0 and (id & desc_mask) != 0) { + // Bootstrap sequence number for initial descriptors. + info.sequence = @as(u64, id & desc_mask); + } else { + // Advance sequence by ring size for subsequent iterations. + info.sequence = seq +% desc_count; + } + + reservation.buf = self.alloc_data(size, id, &desc.blk_pos) catch |e| { + // On failure, publish the descriptor as-is to clean up the reservation. + self.publish(reservation); + return e; + }; + + reservation.info = info; + + return reservation; + } + + /// Publish a previously reserved record. + pub fn publish(self: *Self, res: Reservation) void { + const desc = self.to_desc(res.id); + + _ = desc.state.cmpxchgStrong(.{ .state = .Reserved, .id = res.id }, .{ .state = .Published, .id = res.id }, .release, .monotonic); + + // Restore IRQ state after publishing the new entry. + ki.impl.restore_interrupts(res.irq_state); + } + + /// Return the first readable sequence currently retained by the ring. + pub fn first_seq(self: *Self) u64 { + var seq: u64 = undefined; + + while (true) { + const id: Id = @truncate(self.tail_id.load(.acquire)); + const res = self.read_desc(id); + seq = res.seq; + + if (res.state == .Published or res.state == .Free) break; + std.atomic.spinLoopHint(); + } + + return seq; + } + + /// Read a record at `seq` into `buf`. + pub fn read(self: *Self, seq: u64, buf: ?[]u8) ReadError!Info { + var cur_seq = seq; + + while (true) { + return self.read_internal(cur_seq, buf) catch |err| switch (err) { + error.Invalid => { + const first = self.first_seq(); + if (cur_seq < first) { + // Behind the tail, catch up and try again. + cur_seq = first; + continue; + } + return error.NotYetAvailable; + }, + error.DataLost => { + // Record at cur_seq was overwritten, skip forward. + const first = self.first_seq(); + if (cur_seq < first) + cur_seq = first + else + cur_seq += 1; + continue; + }, + }; + } + } + }; +} diff --git a/src/kern/panic.zig b/src/kern/panic.zig index 00a8120..6cfa23b 100644 --- a/src/kern/panic.zig +++ b/src/kern/panic.zig @@ -5,15 +5,8 @@ const ki = ke.private; /// Panics! pub fn panic(comptime fmt: []const u8, args: anytype) noreturn { - ki.log.debug_lock.acquire_no_ipl(); + // FIXME: this is probably broken. + std.log.err("KERNEL PANIC: " ++ fmt, args); - var buf: [1024]u8 = undefined; - - const str = std.fmt.bufPrint(&buf, fmt, args) catch unreachable; - - ki.log.print("Panic!\n"); - ki.log.print(str); - - ki.log.debug_lock.release_no_ipl(); while (true) {} } diff --git a/src/kern/private.zig b/src/kern/private.zig index d6a89e9..704fc68 100644 --- a/src/kern/private.zig +++ b/src/kern/private.zig @@ -29,3 +29,4 @@ pub const timecounter = @import("timecounter.zig"); pub const sched = @import("sched.zig"); pub const wait = @import("wait.zig"); pub const timer = @import("timer.zig"); +pub const log_ring = @import("log_ring.zig"); diff --git a/src/kern/root.zig b/src/kern/root.zig index fb710c3..d45ec16 100644 --- a/src/kern/root.zig +++ b/src/kern/root.zig @@ -14,7 +14,6 @@ pub const TimeCounter = p.timecounter.TimeCounter; pub const Timer = p.timer.Timer; // === Exported Interfaces === -pub const log = p.log.log; pub const panic = p.panic.panic; pub const ipl = struct { @@ -52,6 +51,13 @@ pub const wait = struct { pub const wait_any = p.wait.wait_any; }; +pub const log = struct { + pub const register_console = p.log.register_console; + pub const log = p.log.log; +}; + +pub const Console = p.log.Console; + pub const Cpu = p.cpu.Cpu; pub const CpuLocal = p.cpu.CpuLocal; pub const CpuMask = p.cpu.CpuMask; diff --git a/src/platform/um/impl.zig b/src/platform/um/impl.zig index 764ec70..90933ea 100644 --- a/src/platform/um/impl.zig +++ b/src/platform/um/impl.zig @@ -39,8 +39,8 @@ pub threadlocal var my_cpu: *ke.Cpu = undefined; pub fn devices_init() void {} -pub fn debug_write(char: u8) void { - std.debug.print("{c}", .{char}); +fn debug_write(_: *ke.Console, buf: []const u8) void { + _ = linux.write(1, buf.ptr, @intCast(buf.len)); } pub const arm_timer = timer.arm_timer; @@ -60,6 +60,12 @@ const bootstrap_offsets = [1]usize{0}; pub var cpu_offsets: []usize = undefined; +var early_console: ke.Console = .{ + .write = debug_write, + .last_seq = 0, + .link = undefined, +}; + pub fn early_init() linksection(b.init) void { // Ensure we can use per-cpu data. cpu_offsets = @constCast(&bootstrap_offsets); @@ -100,6 +106,8 @@ pub fn early_init() linksection(b.init) void { b.kernel_heap_base = heap_base; std.log.info("um: kernel heap lives at {X}", .{heap_base}); + + ke.log.register_console(&early_console); } fn sigusr1_handler(_: posix.SIG, _: *const posix.siginfo_t, _: ?*anyopaque) callconv(.c) void { diff --git a/src/root.zig b/src/root.zig index ed0bb6e..150ff8b 100644 --- a/src/root.zig +++ b/src/root.zig @@ -38,5 +38,5 @@ pub fn tib(comptime N: u32) usize { } pub const std_options = std.Options{ - .logFn = ke.log, + .logFn = ke.log.log, };