From 4d3d32001e3429f28a3c8ab22fa779b3115797b9 Mon Sep 17 00:00:00 2001 From: Drew Nutter Date: Tue, 8 Oct 2024 18:14:39 -0400 Subject: [PATCH 1/5] perf(trace): new Entry to reduce allocations and simplify code --- src/trace/entry.zig | 303 +++++++++++-------------------------------- src/trace/log.zig | 285 ++++++++++++++++------------------------ src/trace/logfmt.zig | 90 ++++++++----- 3 files changed, 240 insertions(+), 438 deletions(-) diff --git a/src/trace/entry.zig b/src/trace/entry.zig index 35fde12ef..954c72927 100644 --- a/src/trace/entry.zig +++ b/src/trace/entry.zig @@ -1,245 +1,90 @@ const std = @import("std"); -const logfmt = @import("logfmt.zig"); -const Level = @import("level.zig").Level; -const Channel = @import("../sync/channel.zig").Channel; +const sig = @import("../sig.zig"); +const trace = @import("lib.zig"); + +const logfmt = trace.logfmt; + +const Level = trace.level.Level; +const ScopedLogger = trace.log.ScopedLogger; +const Channel = sig.sync.Channel; const AtomicBool = std.atomic.Value(bool); -pub const Entry = union(enum) { - channel_print: ChannelPrintEntry, - direct_print: DirectPrintEntry, - noop, +pub fn NewEntry(comptime scope: ?[]const u8) type { + return Entry(struct {}, scope); +} - const Self = @This(); +pub fn Entry(comptime Fields: type, comptime scope: ?[]const u8) type { + return struct { + logger: ScopedLogger(scope), + level: Level, + fields: Fields, - pub fn init(allocator: std.mem.Allocator, channel: *Channel(logfmt.LogMsg), log_level: Level) Self { - return .{ .channel_print = ChannelPrintEntry.init(allocator, channel, log_level) }; - } + const Self = @This(); - pub fn deinit(self: Self) void { - switch (self) { - .noop => {}, - .channel_print => |impl| impl.deinit(), - .direct_print => |impl| impl.deinit(), + pub inline fn init(logger: ScopedLogger(scope), level: Level) Self { + return .{ .logger = logger, .level = level, .fields = .{} }; } - } - pub fn field(self: Self, name: []const u8, value: anytype) Self { - switch (self) { - .noop => { - return self; - }, - .channel_print => |entry| { - var log_entry = entry; - _ = log_entry.field(name, value); - return Entry{ .channel_print = log_entry }; - }, - .direct_print => |entry| { - var log_entry = entry; - _ = log_entry.field(name, value); - return Entry{ .direct_print = log_entry }; - }, + /// Add a field to the log message. + pub inline fn field( + self: Self, + comptime name: [:0]const u8, + value: anytype, + ) Entry(FieldsPlus(name, @TypeOf(value)), scope) { + if (self.logger == .noop) return .{ + .logger = .noop, + .level = undefined, + .fields = undefined, + }; + var new_fields: FieldsPlus(name, @TypeOf(value)) = undefined; + inline for (@typeInfo(Fields).Struct.fields) |existing_field| { + @field(new_fields, existing_field.name) = @field(self.fields, existing_field.name); + } + @field(new_fields, name) = value; + return .{ + .logger = self.logger, + .level = self.level, + .fields = new_fields, + }; } - } - pub fn log(self: Self, comptime msg: []const u8) void { - switch (self) { - .noop => {}, - .channel_print => |impl| { - var logger = impl; - logger.log(msg); - }, - .direct_print => |impl| { - var logger = impl; - logger.log(msg); - }, + /// Log the message using the logger, including all fields that are saved in the entry. + pub inline fn log(self: Self, comptime message: []const u8) void { + self.logger.private_log(self.level, self.fields, message, .{}); } - } - pub fn logf(self: Self, comptime fmt: []const u8, args: anytype) void { - switch (self) { - .noop => {}, - .channel_print => |impl| { - var logger = impl; - logger.logf(fmt, args); - }, - .direct_print => |impl| { - var logger = impl; - logger.logf(fmt, args); - }, + /// Log the message using the logger, including all fields that are saved in the entry. + pub inline fn logf(self: Self, comptime fmt: []const u8, args: anytype) void { + self.logger.private_log(self.level, self.fields, fmt, args); } - } -}; - -pub const ChannelPrintEntry = struct { - allocator: std.mem.Allocator, - scope: ?[]const u8, - log_level: Level, - fields: std.ArrayList(u8), - exit_sig: std.atomic.Value(bool), - channel: *Channel(logfmt.LogMsg), - const Self = @This(); - - pub fn init( - allocator: std.mem.Allocator, - scope: ?[]const u8, - channel: *Channel(logfmt.LogMsg), - log_level: Level, - ) Self { - return .{ - .allocator = allocator, - .scope = scope, - .exit_sig = AtomicBool.init(false), - .log_level = log_level, - .fields = std.ArrayList(u8).init(allocator), - .channel = channel, - }; - } - - pub fn deinit(self: *Self) void { - self.fields.deinit(); - } - - pub fn field(self: *Self, name: []const u8, value: anytype) *Self { - const min_capacity = self.fields.items.len + logfmt.countField(name, value); - self.fields.ensureTotalCapacity(min_capacity) catch return self; - logfmt.fmtField(self.fields.writer(), name, value); - return self; - } - - pub fn log(self: *Self, comptime msg: []const u8) void { - const log_msg = logfmt.LogMsg{ - .level = self.log_level, - .maybe_scope = self.scope, - .maybe_msg = msg, - .maybe_fields = self.fields.toOwnedSlice() catch |err| { - std.debug.print("Processing fields failed with err: {any}", .{err}); - self.deinit(); - return; - }, - .maybe_fmt = null, - }; - - self.channel.send(log_msg) catch |err| { - std.debug.print("Send msg through channel failed with err: {any}", .{err}); - self.deinit(); - return; - }; - } - - pub fn logf(self: *Self, comptime fmt: []const u8, args: anytype) void { - // Get memory for formatting message. - const msg_buf = self.allocBuf(std.fmt.count(fmt, args)) catch |err| { - std.debug.print("allocBuff failed with err: {any}", .{err}); - self.deinit(); - return; - }; - var fmt_message = std.io.fixedBufferStream(msg_buf); - // Format message. - logfmt.fmtMsg(fmt_message.writer(), fmt, args); - - const log_msg = logfmt.LogMsg{ - .level = self.log_level, - .maybe_scope = self.scope, - .maybe_msg = null, - .maybe_fields = self.fields.toOwnedSlice() catch |err| { - std.debug.print("Processing fields failed with err: {any}", .{err}); - self.deinit(); - return; - }, - .maybe_fmt = fmt_message.getWritten(), - }; - - self.channel.send(log_msg) catch |err| { - std.debug.print("Send msg through channel failed with err: {any}", .{err}); - self.deinit(); - return; - }; - } - // Utility function for allocating memory from RecycleFBA for part of the log message. - fn allocBuf(self: *const Self, size: u64) ![]u8 { - const buf = blk: while (true) { - const buf = self.allocator.alloc(u8, size) catch { - std.time.sleep(std.time.ns_per_ms); - if (self.exit_sig.load(.unordered)) { - return error.MemoryBlockedWithExitSignaled; - } - continue; + /// Returns a new struct type based on Fields, just with one more field added. + fn FieldsPlus(comptime field_name: [:0]const u8, comptime FieldType: type) type { + const info = @typeInfo(Fields); + var new_fields: [1 + info.Struct.fields.len]std.builtin.Type.StructField = undefined; + for (info.Struct.fields, 0..) |existing_field, i| { + new_fields[i] = existing_field; + } + const ActualFieldType = switch (@typeInfo(FieldType)) { + .ComptimeFloat => f64, + .ComptimeInt => u64, + else => FieldType, }; - break :blk buf; - }; - errdefer { - self.allocator.free(buf); + new_fields[info.Struct.fields.len] = .{ + .name = field_name, + .type = ActualFieldType, + .default_value = null, + .is_comptime = false, + .alignment = @alignOf(FieldType), + }; + const new_struct = std.builtin.Type.Struct{ + .layout = .auto, + .backing_integer = null, + .fields = &new_fields, + .decls = &.{}, + .is_tuple = false, + }; + return @Type(.{ .Struct = new_struct }); } - return buf; - } -}; - -/// An instance of `Entry` that logs directly to std.debug.print, instead of sending to channel. -pub const DirectPrintEntry = struct { - const builtin = @import("builtin"); - - log_level: Level, - scope: ?[]const u8, - allocator: std.mem.Allocator, - log_msg: std.ArrayList(u8), - - const Self = @This(); - - pub fn init( - allocator: std.mem.Allocator, - scope: ?[]const u8, - log_level: Level, - ) Self { - return .{ - .allocator = allocator, - .scope = scope, - .log_level = log_level, - .log_msg = std.ArrayList(u8).init(allocator), - }; - } - - pub fn deinit(self: *Self) void { - self.log_msg.deinit(); - } - - pub fn field(self: *Self, name: []const u8, value: anytype) *Self { - logfmt.fmtField(self.log_msg.writer(), name, value); - return self; - } - - pub fn log(self: *Self, comptime msg: []const u8) void { - defer self.deinit(); - const log_msg = logfmt.LogMsg{ - .level = self.log_level, - .maybe_scope = self.scope, - .maybe_msg = msg, - .maybe_fields = null, - .maybe_fmt = null, - }; - - const writer = self.log_msg.writer(); - logfmt.writeLog(writer, log_msg) catch @panic("Failed to write log"); - std.debug.print("{s}", .{self.log_msg.items}); - } - - pub fn logf(self: *Self, comptime fmt: []const u8, args: anytype) void { - defer self.deinit(); - // Format message. - var fmt_msg = std.ArrayList(u8).initCapacity(self.allocator, 256) catch @panic("could not initCapacity for message"); - defer fmt_msg.deinit(); - logfmt.fmtMsg(fmt_msg.writer(), fmt, args); - - const log_msg = logfmt.LogMsg{ - .level = self.log_level, - .maybe_scope = self.scope, - .maybe_msg = null, - .maybe_fields = null, - .maybe_fmt = fmt_msg.items, - }; - - const writer = self.log_msg.writer(); - logfmt.writeLog(writer, log_msg) catch @panic("Failed to write log"); - std.debug.print("{s}", .{self.log_msg.items}); - } -}; + }; +} diff --git a/src/trace/log.zig b/src/trace/log.zig index 4136f7a91..fa31bdc9a 100644 --- a/src/trace/log.zig +++ b/src/trace/log.zig @@ -1,16 +1,18 @@ const std = @import("std"); -const Level = @import("level.zig").Level; -const Entry = @import("entry.zig").Entry; -const ChannelPrintEntry = @import("entry.zig").ChannelPrintEntry; -const DirectPrintEntry = @import("entry.zig").DirectPrintEntry; -const logfmt = @import("logfmt.zig"); const sig = @import("../sig.zig"); -// TODO Improve import. -const Channel = @import("../sync/channel.zig").Channel; +const trace = @import("lib.zig"); + +const logfmt = trace.logfmt; + const Allocator = std.mem.Allocator; const AtomicBool = std.atomic.Value(bool); +const Channel = sig.sync.Channel; const RecycleFBA = sig.utils.allocators.RecycleFBA; +const Level = trace.level.Level; +const Entry = trace.entry.Entry; +const NewEntry = trace.entry.NewEntry; + pub const Config = struct { max_level: Level = Level.debug, allocator: std.mem.Allocator, @@ -18,17 +20,8 @@ pub const Config = struct { max_buffer: ?u64 = null, }; -const LogKind = enum { - channel_print, - direct_print, - noop, -}; - -/// A ScopedLogger could either be: -/// - A StandardErrLogger -/// - A TestingLogger pub fn ScopedLogger(comptime scope: ?[]const u8) type { - return union(LogKind) { + return union(enum) { channel_print: *ChannelPrintLogger, direct_print: *DirectPrintLogger, noop: void, @@ -61,52 +54,58 @@ pub fn ScopedLogger(comptime scope: ?[]const u8) type { } } - pub fn err(self: *const Self) Entry { - return switch (self.*) { - .noop => .noop, - inline else => |impl| impl.err(scope), - }; + pub fn err(self: Self) NewEntry(scope) { + return self.entry(.err); } - pub fn warn(self: *const Self) Entry { - return switch (self.*) { - .noop => .noop, - inline else => |impl| impl.warn(scope), - }; + pub fn warn(self: Self) NewEntry(scope) { + return self.entry(.warn); } - pub fn info(self: *const Self) Entry { - return switch (self.*) { - .noop => .noop, - inline else => |impl| impl.info(scope), - }; + pub fn info(self: Self) NewEntry(scope) { + return self.entry(.info); } - pub fn debug(self: *const Self) Entry { - return switch (self.*) { - .noop => .noop, - inline else => |impl| impl.debug(scope), - }; + pub fn debug(self: Self) NewEntry(scope) { + return self.entry(.debug); } - pub fn trace(self: *const Self) Entry { - return switch (self.*) { + pub fn trace(self: Self) NewEntry(scope) { + return self.entry(.trace); + } + + fn entry(self: Self, level: Level) NewEntry(scope) { + const logger = switch (self) { .noop => .noop, - inline else => |impl| impl.trace(scope), + inline else => |impl| if (@intFromEnum(impl.max_level) >= @intFromEnum(level)) + self + else + .noop, }; + return NewEntry(scope).init(logger, level); } pub fn log(self: Self, level: Level, comptime message: []const u8) void { - switch (self) { - .noop => {}, - inline else => |*impl| impl.*.log(scope, level, message), - } + self.private_log(level, .{}, message, .{}); } pub fn logf(self: Self, level: Level, comptime fmt: []const u8, args: anytype) void { + self.private_log(level, .{}, fmt, args); + } + + /// Only intended for use within trace module. + /// + /// Passthrough to the logger implementation + pub fn private_log( + self: Self, + level: Level, + fields: anytype, + comptime fmt: []const u8, + args: anytype, + ) void { switch (self) { .noop => {}, - inline else => |*impl| impl.*.logf(scope, level, fmt, args), + inline else => |impl| impl.log(scope, level, fields, fmt, args), } } }; @@ -122,7 +121,7 @@ pub const ChannelPrintLogger = struct { log_allocator: Allocator, log_allocator_state: *RecycleFBA(.{}), max_buffer: u64, - channel: *Channel(logfmt.LogMsg), + channel: *Channel([]const u8), handle: ?std.Thread, const Self = @This(); @@ -140,7 +139,7 @@ pub const ChannelPrintLogger = struct { .exit = AtomicBool.init(false), .max_level = config.max_level, .handle = null, - .channel = Channel(logfmt.LogMsg).create(config.allocator) catch + .channel = Channel([]const u8).create(config.allocator) catch @panic("could not allocate LogMsg channel"), }; self.handle = try std.Thread.spawn(.{}, run, .{self}); @@ -171,79 +170,55 @@ pub const ChannelPrintLogger = struct { pub fn run(self: *Self) void { while (!self.exit.load(.acquire)) { while (self.channel.receive()) |message| { - { - const writer = std.io.getStdErr().writer(); - std.debug.lockStdErr(); - defer std.debug.unlockStdErr(); - logfmt.writeLog(writer, message) catch {}; - } - if (message.maybe_fields) |fields| { - self.log_allocator.free(fields); - } - if (message.maybe_fmt) |fmt_msg| { - self.log_allocator.free(fmt_msg); - } + const writer = std.io.getStdErr().writer(); + std.debug.lockStdErr(); + defer std.debug.unlockStdErr(); + writer.writeAll(message) catch {}; } } } - pub fn err(self: *Self, comptime maybe_scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.err)) { - return Entry{ .channel_print = ChannelPrintEntry.init(self.log_allocator, maybe_scope, self.channel, Level.err) }; - } - return .noop; - } - - pub fn warn(self: *Self, comptime maybe_scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.warn)) { - return Entry{ .channel_print = ChannelPrintEntry.init(self.log_allocator, maybe_scope, self.channel, Level.warn) }; - } - return .noop; - } - - pub fn info(self: *Self, comptime maybe_scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.info)) { - return Entry{ .channel_print = ChannelPrintEntry.init(self.log_allocator, maybe_scope, self.channel, Level.info) }; - } - return .noop; - } - - pub fn debug(self: *Self, comptime maybe_scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.debug)) { - return Entry{ .channel_print = ChannelPrintEntry.init(self.log_allocator, maybe_scope, self.channel, Level.debug) }; - } - return .noop; - } - - pub fn trace(self: *Self, comptime maybe_scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.trace)) { - return Entry{ .channel_print = ChannelPrintEntry.init(self.log_allocator, maybe_scope, self.channel, Level.trace) }; - } - return .noop; - } + pub fn log( + self: *Self, + comptime scope: ?[]const u8, + level: Level, + fields: anytype, + comptime fmt: []const u8, + args: anytype, + ) void { + if (@intFromEnum(self.max_level) < @intFromEnum(level)) return; + const size = logfmt.countLog(scope, level, fields, fmt, args); + const msg_buf = self.allocBuf(size) catch |err| { + std.debug.print("allocBuff failed with err: {any}", .{err}); + return; + }; + var stream = std.io.fixedBufferStream(msg_buf); + logfmt.writeLog(stream.writer(), scope, level, fields, fmt, args) catch |err| { + std.debug.print("writeLog failed with err: {any}", .{err}); + self.log_allocator.free(msg_buf); + return; + }; + std.debug.assert(size == stream.pos); - pub fn log(self: *Self, comptime scope: ?[]const u8, level: Level, comptime message: []const u8) void { - if (@intFromEnum(self.max_level) >= @intFromEnum(level)) { - switch (level) { - .err => self.err(scope).log(message), - .warn => self.warn(scope).log(message), - .info => self.info(scope).log(message), - .debug => self.debug(scope).log(message), - .trace => self.trace(scope).log(message), - } - } + self.channel.send(msg_buf) catch |err| { + std.debug.print("Send msg through channel failed with err: {any}", .{err}); + self.log_allocator.free(msg_buf); + return; + }; } - pub fn logf(self: *Self, comptime scope: ?[]const u8, level: Level, comptime fmt: []const u8, args: anytype) void { - if (@intFromEnum(self.max_level) >= @intFromEnum(level)) { - switch (level) { - .err => self.err(scope).logf(fmt, args), - .warn => self.warn(scope).logf(fmt, args), - .info => self.info(scope).logf(fmt, args), - .debug => self.debug(scope).logf(fmt, args), - .trace => self.trace(scope).logf(fmt, args), - } + // Utility function for allocating memory from RecycleFBA for part of the log message. + fn allocBuf(self: *const Self, size: u64) ![]u8 { + for (0..100) |_| { + return self.log_allocator.alloc(u8, size) catch { + std.time.sleep(std.time.ns_per_ms); + if (self.exit.load(.unordered)) { + return error.MemoryBlockedWithExitSignaled; + } + continue; + }; } + return error.OutOfMemory; } }; @@ -272,71 +247,31 @@ pub const DirectPrintLogger = struct { return .{ .direct_print = self }; } - pub fn err(self: *Self, comptime scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.err)) { - return Entry{ .direct_print = DirectPrintEntry.init(self.allocator, scope, Level.err) }; - } - return .noop; - } - - pub fn warn(self: *Self, comptime scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.warn)) { - return Entry{ .direct_print = DirectPrintEntry.init(self.allocator, scope, Level.warn) }; - } - return .noop; - } - - pub fn info(self: *Self, comptime scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.info)) { - return Entry{ .direct_print = DirectPrintEntry.init(self.allocator, scope, Level.info) }; - } - return .noop; - } - - pub fn debug(self: *Self, comptime scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.debug)) { - return Entry{ .direct_print = DirectPrintEntry.init(self.allocator, scope, Level.debug) }; - } - return .noop; - } - - pub fn trace(self: *Self, comptime scope: ?[]const u8) Entry { - if (@intFromEnum(self.max_level) >= @intFromEnum(Level.trace)) { - return Entry{ .direct_print = DirectPrintEntry.init(self.allocator, scope, Level.trace) }; - } - return .noop; - } - - pub fn log(self: *Self, comptime scope: ?[]const u8, level: Level, comptime message: []const u8) void { - if (@intFromEnum(self.max_level) >= @intFromEnum(level)) { - switch (level) { - .err => self.err(scope).log(message), - .warn => self.warn(scope).log(message), - .info => self.info(scope).log(message), - .debug => self.debug(scope).log(message), - .trace => self.trace(scope).log(message), - } - } - } - - pub fn logf(self: *Self, comptime scope: ?[]const u8, level: Level, comptime fmt: []const u8, args: anytype) void { - if (@intFromEnum(self.max_level) >= @intFromEnum(level)) { - switch (level) { - .err => self.err(scope).logf(fmt, args), - .warn => self.warn(scope).logf(fmt, args), - .info => self.info(scope).logf(fmt, args), - .debug => self.debug(scope).logf(fmt, args), - .trace => self.trace(scope).logf(fmt, args), - } - } + pub fn log( + self: *Self, + comptime scope: ?[]const u8, + level: Level, + fields: anytype, + comptime fmt: []const u8, + args: anytype, + ) void { + if (@intFromEnum(self.max_level) < @intFromEnum(level)) return; + const writer = std.io.getStdErr().writer(); + std.debug.lockStdErr(); + defer std.debug.unlockStdErr(); + logfmt.writeLog(writer, scope, level, fields, fmt, args) catch {}; } }; +/// change this locally for temporary visibility into tests. +/// normally this should be err since we don't want any output from well-behaved passing tests. +const test_level = Level.err; + test "direct" { const allocator = std.testing.allocator; const std_logger = ChannelPrintLogger.init(.{ .allocator = allocator, - .max_level = Level.err, + .max_level = test_level, .max_buffer = 1 << 30, }) catch @panic("Logger init failed"); defer std_logger.deinit(); @@ -385,7 +320,7 @@ test "trace_ngswitch" { const std_logger = ChannelPrintLogger.init(.{ .allocator = allocator, - .max_level = Level.warn, + .max_level = test_level, .max_buffer = 1 << 30, }) catch @panic("Logger init failed"); defer std_logger.deinit(); @@ -399,7 +334,7 @@ test "trace_ngswitch" { var stuff = Stuff.init(logger); stuff.doStuff(); // Log using the concrete instance also works. - std_logger.info(null).log("Log from main"); + std_logger.log(null, .info, .{}, "Log from main", .{}); } test "reclaim" { @@ -407,7 +342,7 @@ test "reclaim" { var std_logger = ChannelPrintLogger.init(.{ .allocator = allocator, - .max_level = Level.warn, + .max_level = test_level, .max_buffer = 4048, }) catch @panic("Logger init failed"); @@ -429,7 +364,7 @@ test "level" { var std_logger = ChannelPrintLogger.init(.{ .allocator = allocator, - .max_level = Level.err, + .max_level = test_level, .max_buffer = 1 << 30, }) catch @panic("Logger init failed"); @@ -452,7 +387,7 @@ test "level" { logger.info() .field("f_agent", "Firefox") .field("f_version", "2.0") - .field("f_version", "3.0") + .field("f_version_other", "3.0") .log("Logging with logWithFields"); logger.trace() diff --git a/src/trace/logfmt.zig b/src/trace/logfmt.zig index 1b5f2be39..832a42cf8 100644 --- a/src/trace/logfmt.zig +++ b/src/trace/logfmt.zig @@ -3,29 +3,6 @@ const time = @import("../time/time.zig"); const Level = @import("level.zig").Level; const sig = @import("../sig.zig"); -pub const LogMsg = struct { - level: Level, - maybe_scope: ?[]const u8 = null, - maybe_msg: ?[]const u8 = null, - maybe_fields: ?[]const u8 = null, - maybe_fmt: ?[]const u8 = null, -}; - -pub fn fmtMsg(writer: anytype, comptime maybe_fmt: ?[]const u8, args: anytype) void { - if (maybe_fmt) |fmt| { - std.fmt.format(writer, fmt, args) catch @panic("could not format"); - } -} - -pub fn fmtField(writer: anytype, key: []const u8, value: anytype) void { - std.fmt.format(writer, fieldFmtString(@TypeOf(value)), .{ key, value }) catch return; -} - -/// Return the number of bytes needed to write the field. -pub fn countField(key: []const u8, value: anytype) u64 { - return std.fmt.count(fieldFmtString(@TypeOf(value)), .{ key, value }); -} - /// Return the format string for the type when used as a value in a field. fn fieldFmtString(comptime Value: type) []const u8 { return switch (@typeInfo(Value)) { @@ -42,27 +19,72 @@ fn fieldFmtString(comptime Value: type) []const u8 { }; } -pub fn writeLog(writer: anytype, message: LogMsg) !void { - if (message.maybe_scope) |scope| { +/// Formats the entire log message as a string, writing it to the writer. +pub fn writeLog( + writer: anytype, + comptime maybe_scope: ?[]const u8, + level: Level, + fields: anytype, + comptime fmt: []const u8, + args: anytype, +) !void { + if (maybe_scope) |scope| { try std.fmt.format(writer, "[{s}] ", .{scope}); } // format time as ISO8601 - const utc_format = "YYYY-MM-DDTHH:mm:ss"; + const utc_format = "YYYY-MM-DDTHH:mm:ss.SSS"; const now = time.DateTime.now(); try std.fmt.format(writer, "time=", .{}); try now.format(utc_format, .{}, writer); try std.fmt.format(writer, "Z ", .{}); - try std.fmt.format(writer, "level={s} ", .{message.level.asText()}); - if (message.maybe_fields) |kv| { - try std.fmt.format(writer, "{s}", .{kv}); - } + try std.fmt.format(writer, "level={s} ", .{level.asText()}); - if (message.maybe_msg) |msg| { - try std.fmt.format(writer, "{s}\n", .{msg}); + inline for (@typeInfo(@TypeOf(fields)).Struct.fields) |field| { + try std.fmt.format(writer, fieldFmtString(field.type), .{ + field.name, + @field(fields, field.name), + }); } - if (message.maybe_fmt) |fmt| { - try std.fmt.format(writer, "{s}\n", .{fmt}); + + try std.fmt.format(writer, fmt ++ "\n", args); +} + +/// Returns the number of bytes needed to format the log message. +pub fn countLog( + comptime maybe_scope: ?[]const u8, + level: Level, + fields: anytype, + comptime fmt: []const u8, + args: anytype, +) usize { + var count: usize = 30; // timestamp is 30 chars + + if (maybe_scope) |scope| count += std.fmt.count("[{s}] ", .{scope}); + + count += std.fmt.count("level={s} ", .{level.asText()}); + + inline for (@typeInfo(@TypeOf(fields)).Struct.fields) |field| { + count += std.fmt.count(fieldFmtString(field.type), .{ + field.name, + @field(fields, field.name), + }); } + + count += std.fmt.count(fmt ++ "\n", args); + return count; +} + +test "countLog matches writeLog" { + const scope = "test-scope"; + const level = .info; + const fields = .{ .integer = 1, .float = 1.123, .string = "test" }; + const fmt = "here's {} message: {s}"; + const args = .{ 1, "this is a test" }; + const count = countLog(scope, level, fields, fmt, args); + var buf: [1024]u8 = undefined; + var stream = std.io.fixedBufferStream(&buf); + try writeLog(stream.writer(), scope, level, fields, fmt, args); + try std.testing.expectEqual(count, stream.getWritten().len); } From 03ae91ac32ca5a072b3cf1a40572dd837344dd6c Mon Sep 17 00:00:00 2001 From: Drew Nutter Date: Tue, 8 Oct 2024 18:18:11 -0400 Subject: [PATCH 2/5] refactor(trace): remove unused imports --- src/trace/entry.zig | 3 --- src/trace/log.zig | 1 - 2 files changed, 4 deletions(-) diff --git a/src/trace/entry.zig b/src/trace/entry.zig index 954c72927..c23a0fc00 100644 --- a/src/trace/entry.zig +++ b/src/trace/entry.zig @@ -2,11 +2,8 @@ const std = @import("std"); const sig = @import("../sig.zig"); const trace = @import("lib.zig"); -const logfmt = trace.logfmt; - const Level = trace.level.Level; const ScopedLogger = trace.log.ScopedLogger; -const Channel = sig.sync.Channel; const AtomicBool = std.atomic.Value(bool); pub fn NewEntry(comptime scope: ?[]const u8) type { diff --git a/src/trace/log.zig b/src/trace/log.zig index fa31bdc9a..e866ed839 100644 --- a/src/trace/log.zig +++ b/src/trace/log.zig @@ -10,7 +10,6 @@ const Channel = sig.sync.Channel; const RecycleFBA = sig.utils.allocators.RecycleFBA; const Level = trace.level.Level; -const Entry = trace.entry.Entry; const NewEntry = trace.entry.NewEntry; pub const Config = struct { From 80e603c7cc88d00e324a4ed85602df2afcad2cfe Mon Sep 17 00:00:00 2001 From: Drew Nutter Date: Thu, 10 Oct 2024 10:33:44 -0400 Subject: [PATCH 3/5] rafactor(trace): simplify entry field struct definition --- src/trace/entry.zig | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/src/trace/entry.zig b/src/trace/entry.zig index c23a0fc00..995a792e8 100644 --- a/src/trace/entry.zig +++ b/src/trace/entry.zig @@ -58,26 +58,22 @@ pub fn Entry(comptime Fields: type, comptime scope: ?[]const u8) type { /// Returns a new struct type based on Fields, just with one more field added. fn FieldsPlus(comptime field_name: [:0]const u8, comptime FieldType: type) type { const info = @typeInfo(Fields); - var new_fields: [1 + info.Struct.fields.len]std.builtin.Type.StructField = undefined; - for (info.Struct.fields, 0..) |existing_field, i| { - new_fields[i] = existing_field; - } const ActualFieldType = switch (@typeInfo(FieldType)) { .ComptimeFloat => f64, .ComptimeInt => u64, else => FieldType, }; - new_fields[info.Struct.fields.len] = .{ + const new_fields = info.Struct.fields ++ &[_]std.builtin.Type.StructField{.{ .name = field_name, .type = ActualFieldType, .default_value = null, .is_comptime = false, .alignment = @alignOf(FieldType), - }; + }}; const new_struct = std.builtin.Type.Struct{ .layout = .auto, .backing_integer = null, - .fields = &new_fields, + .fields = new_fields, .decls = &.{}, .is_tuple = false, }; From d9dc8e71c73207e9d2d5ea03b3c8878a32be553a Mon Sep 17 00:00:00 2001 From: Drew Nutter Date: Thu, 10 Oct 2024 13:03:11 -0400 Subject: [PATCH 4/5] fix(trace): use monotonic instead of unordered --- src/trace/log.zig | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trace/log.zig b/src/trace/log.zig index e866ed839..b0b6bebf3 100644 --- a/src/trace/log.zig +++ b/src/trace/log.zig @@ -211,7 +211,7 @@ pub const ChannelPrintLogger = struct { for (0..100) |_| { return self.log_allocator.alloc(u8, size) catch { std.time.sleep(std.time.ns_per_ms); - if (self.exit.load(.unordered)) { + if (self.exit.load(.monotonic)) { return error.MemoryBlockedWithExitSignaled; } continue; From f0c6b320cbe51686c31cf5e6ffffadd2325d52d7 Mon Sep 17 00:00:00 2001 From: Drew Nutter Date: Fri, 11 Oct 2024 09:30:01 -0400 Subject: [PATCH 5/5] refactor(trace): uninline Entry functions. remove init by manually inlining the init function's code into the only place it is used --- src/trace/entry.zig | 10 +++------- src/trace/log.zig | 2 +- 2 files changed, 4 insertions(+), 8 deletions(-) diff --git a/src/trace/entry.zig b/src/trace/entry.zig index 995a792e8..c4b00ea92 100644 --- a/src/trace/entry.zig +++ b/src/trace/entry.zig @@ -18,12 +18,8 @@ pub fn Entry(comptime Fields: type, comptime scope: ?[]const u8) type { const Self = @This(); - pub inline fn init(logger: ScopedLogger(scope), level: Level) Self { - return .{ .logger = logger, .level = level, .fields = .{} }; - } - /// Add a field to the log message. - pub inline fn field( + pub fn field( self: Self, comptime name: [:0]const u8, value: anytype, @@ -46,12 +42,12 @@ pub fn Entry(comptime Fields: type, comptime scope: ?[]const u8) type { } /// Log the message using the logger, including all fields that are saved in the entry. - pub inline fn log(self: Self, comptime message: []const u8) void { + pub fn log(self: Self, comptime message: []const u8) void { self.logger.private_log(self.level, self.fields, message, .{}); } /// Log the message using the logger, including all fields that are saved in the entry. - pub inline fn logf(self: Self, comptime fmt: []const u8, args: anytype) void { + pub fn logf(self: Self, comptime fmt: []const u8, args: anytype) void { self.logger.private_log(self.level, self.fields, fmt, args); } diff --git a/src/trace/log.zig b/src/trace/log.zig index b0b6bebf3..44a78e9c5 100644 --- a/src/trace/log.zig +++ b/src/trace/log.zig @@ -81,7 +81,7 @@ pub fn ScopedLogger(comptime scope: ?[]const u8) type { else .noop, }; - return NewEntry(scope).init(logger, level); + return .{ .logger = logger, .level = level, .fields = .{} }; } pub fn log(self: Self, level: Level, comptime message: []const u8) void {