Skip to content

Commit

Permalink
refactor(trace): reimplement Entry to reduce allocations and simplify…
Browse files Browse the repository at this point in the history
… code (#307)

This changes the `Entry` type so that it directly contains any logger "fields" within the struct as normal struct fields instead of allocating strings repeatedly along the way. This unlocked some simplifications to the code and allows the code to be more organized. It also reduces allocations which theoretically could have a performance benefit.

There are no meaningful changes to the logger api. You still use it in exactly the same way as before. Note that I haven't changed anything outside the `trace` module. While it's true the Entry type is different, the entry type is not intended for use outside the logger, so it's not really an api change in my opinion.

## Explanation of Change
The basic unchanged idea of the logger is that you call some method like `logger.info()` and then you're supposed to directly chain that with other method calls. For normal logging, you would just chain that with a call to `log` or `logf` as in `logger.info().log("hello world")`. If you want to include fields in the log, you would put some calls to `field` in between `info` and `logf`, as in `logger.info().field("src_addr", src_ip).log("message receive")`.

The way this already worked is with the builder pattern. The `info` method returns an item of type `Entry` which is responsible for tracking all the accumulating state. Then when you finish up by calling `Entry.log`, this function is responsible for calling back to the logger to actually log the message.

That describes how it was, and how it still is. So, what have I changed?

Previously `Entry` was a tagged union that kept a bunch of state relevant to the specific logger implementation, with different variants for different logger implementations. The `field` functions perform allocations to construct the field string in the way that this particular logger wants to have a field string look. Then the `log` function implements the approach to logging for this particular logger. So basically, each logger implementation had its implementation fractured across two structs, its logger (e.g. ChannelPrintLogger) and its Entry (e.g. ChannelPrintEntry).

With the new change, Entry has only one responsibility. All it does is store the fields. And it stores them exactly as they were passed, instead of formatting them for the specific logger. Likewise, it's just a struct with a single implementation, instead of being a tagged union representing different implementations. When you call `log`, it just passes the fields directly to the logger. So the loggers now include their own `log` function instead of that logic being defined in various Entry implementations.

To enable the Entry to store the data as is, without needing to format it or produce any allocations, the Entry struct needs to be generic. The entry contains a generic Fields struct that contains whatever fields were added so far. Each time you add a field to the Entry, it returns a new version of Entry that has a fields struct with one more field.

## Reduce Allocations
This reduces allocations to either 0 or 1 allocation per log message.

For the direct print logger, there are zero allocations needed. The fields and the log message are directly formatted by the stderr writer.

For the channel logger, you only need a single allocation. The fields and the log message are written to a single allocated string. That string is sent over the channel, and then written to stderr.

## Code Simplification
Several layers of the code were able to be removed. For example I was able to remove some code from each logger implementation that was redundant with the ScopedLogger interface. I was also able to simplify log formatting because there's no longer a need to bundle up all the parameters into a struct and pass that around before formatting it. The data can be directly formatted to a single string.

The main simplification is that the Entry is just a basic struct containing fields. It doesn't need to do anything more than add fields to a struct. The tradeoff here is that you need to understand comptime code to fully grasp how the entry works under the hood. But the comptime code is fully encapsulated in a single place that doesn't concern itself with any other responsibilities, so that knowledge is not needed unless you're interested making an improvement to that very mechanism.

## Code Clarity & Organization
The code is clearer and more organized because the logger implementations fully encapsulate what it means to log with that logger. You no longer need to fracture a logger implementation halfway between the logger and halfway in some struct that represents an undefined "entry" concept. Previously the entry was just a spillover of the logger and it was unclear why it needs to exist, and just caused confusion until you fully understood the whole logger paradigm. Now it's very clear. The entry holds the fields, and nothing else. The logger implements logging in its entirety.

The code is also clearer now in what it means to "implement a logger". All you need to do is implement a struct with a `log` method conforming to the function signature expected by `ScopedLogger.private_log`. Implement that one method, and you have a fully functional logger.
  • Loading branch information
dnut authored Oct 15, 2024
1 parent 5f49dce commit 4c01fb2
Show file tree
Hide file tree
Showing 3 changed files with 233 additions and 443 deletions.
302 changes: 68 additions & 234 deletions src/trace/entry.zig
Original file line number Diff line number Diff line change
@@ -1,245 +1,79 @@
const std = @import("std");
const logfmt = @import("logfmt.zig");
const Level = @import("level.zig").Level;
const Channel = @import("../sync/channel.zig").Channel;
const AtomicBool = std.atomic.Value(bool);

pub const Entry = union(enum) {
channel_print: ChannelPrintEntry,
direct_print: DirectPrintEntry,
noop,

const Self = @This();

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 sig = @import("../sig.zig");
const trace = @import("lib.zig");

pub fn deinit(self: Self) void {
switch (self) {
.noop => {},
.channel_print => |impl| impl.deinit(),
.direct_print => |impl| impl.deinit(),
}
}
const Level = trace.level.Level;
const ScopedLogger = trace.log.ScopedLogger;
const AtomicBool = std.atomic.Value(bool);

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 };
},
pub fn NewEntry(comptime scope: ?[]const u8) type {
return Entry(struct {}, scope);
}

pub fn Entry(comptime Fields: type, comptime scope: ?[]const u8) type {
return struct {
logger: ScopedLogger(scope),
level: Level,
fields: Fields,

const Self = @This();

/// Add a field to the log message.
pub 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 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 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);
const ActualFieldType = switch (@typeInfo(FieldType)) {
.ComptimeFloat => f64,
.ComptimeInt => u64,
else => FieldType,
};
break :blk buf;
};
errdefer {
self.allocator.free(buf);
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,
.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});
}
};
};
}
Loading

0 comments on commit 4c01fb2

Please sign in to comment.