feat(trace): improve trace #249

dadepo · 2024-08-25T19:05:45Z

Key points:

Replace allocation with RecycleFBA.
Add scope
- Be able to switch scope.
Be able to assert log output in tests
Complete implantation (add method for other log levels)
Try out interfaces
- Tried this out but had issues with comptime. Illustrated here https://gist.github.com/dadepo/a0c47dda6fc87aaf737260f1a5961a55
~~Make formatter pluggable~~ For later
~~Make output (writer) pluggable~~ For later

Output currently

zig build test -Dfilter="trace_ng"
test
└─ run test stderr
[trace_ng.log.test.trace_ng: scope switch.Stuff] time=2024-09-03T09:05:32Z level=info doing stuff
[trace_ng.log.test.trace_ng: scope switch.StuffChild] time=2024-09-03T09:05:32Z level=info doing stuff details
time=2024-09-03T09:05:32Z level=info Logging with log
time=2024-09-03T09:05:32Z level=info Logging with logf
time=2024-09-03T09:05:32Z level=info f_agent=Firefox f_version=2.0 Logging with logWithFields
time=2024-09-03T09:05:32Z level=info f_agent=Firefox f_version=120 f_local=en f_stock=nvidia Logging with logfWithFields

src/trace_ng/log.zig

dnut · 2024-08-30T13:01:59Z

src/trace_ng/log.zig

+            }
+            var fmt_message = std.io.fixedBufferStream(buf);
+            const writer = fmt_message.writer();
+


Doesn't passing self.fba_bytes to this function mean that the logger will request an allocation for the entire backing buffer behind the fba? At that point is there any reason to use an allocator instead of passing the entire buffer?

For the formatted message, used std.fmt.count to determine how much allocation to ask from the allocator...https://github.com/Syndica/sig/pull/249/files#diff-a5f543f6d9dfe65e2e547cdf7bd2cd49d8e85d4afccc81a3c51568b0208dfeb7R29

For the k/v fields on the other hand, I have not found how to determine the size. Currently hardcoding it to 512 here https://github.com/Syndica/sig/pull/249/files#diff-a5f543f6d9dfe65e2e547cdf7bd2cd49d8e85d4afccc81a3c51568b0208dfeb7R108

dnut · 2024-08-30T13:03:39Z

src/trace_ng/log.zig

+                std.time.sleep(std.time.ns_per_ms * 5);
+                const messages = self.channel.drain() orelse {
+                    // channel is closed
+                    return;


You can use std.fmt.count to determine the number of bytes you need to allocate.

Used here https://github.com/Syndica/sig/pull/249/files#diff-a5f543f6d9dfe65e2e547cdf7bd2cd49d8e85d4afccc81a3c51568b0208dfeb7R29

dnut · 2024-08-30T13:14:50Z

src/trace_ng/log.zig

+            comptime maybe_fmt: ?[]const u8,
+            args: anytype,
+        ) logfmt.LogMsg {
+            // obtain a memory to write to


Ideally you should also realloc the buffer to a smaller size.

When you call free in the other thread, it's going to pass in a len that is smaller than the actual size of the allocation. For the RecycleFBA it does not actually make a difference. But with other allocators it may cause a problem. The GPA will complain about this.

test "invalid free" { const x = try std.testing.allocator.alloc(u8, 100); std.testing.allocator.free(x[0..50]); }

dadepo · 2024-09-09T13:45:38Z

src/trace_ng/log.zig

+        pub fn deinit(self: *Self) void {
+            self.channel.close();
+            if (self.handle) |*handle| {
+                std.time.sleep(std.time.ns_per_ms * 5);


Not 100% sure if this is the best way to fix this, but the issue I found was that in the test case where the scope of the logger was switched (ie essentially having two loggers...the one used by the parent struct and the child struct) it often happens that the log from the child does not make it to the std err before the process dies. It seems the handle.join() sometimes does not work...but if I introduce a std.debug.print (or the sleep above) it consistently shows up.

the scope of the logger was switched (ie essentially having two loggers

This wouldn't be an issue if you use only a single instance of the underlying logger.

dadepo · 2024-09-09T16:15:28Z

src/trace_ng/log.zig

+    defer logger.deinit();
+
+    var stuff = Stuff.init(&logger);
+    defer stuff.deinit();


One consequence of the design of having the logger as a state in the struct, is that any struct that makes use of the standard error logger would need to have a deinit method (in other to be able to free deinit the allocator/channel). Not sure if it's a pro or con, although it does feel like extra responsibility to have to call the deinit method? But then again this is a common practice in Zig, so maybe not that bad?

I think the typical usage pattern would be that you initialize StdErrLogger somewhere near the main function of your application. You defer deinit in that scope only. Then you convert it to a Logger, which contains a pointer to StdErrLogger. The logger gets passed around everywhere by value, but it never needs to be deinited because it's just a pointer to the logger owned by main, which will be deinited when main returns.

For scoped logger, does this not bring back the possibility for error where a scoped logger is passed and used in a different scope than was intended?

I felt having the logger be part of the state of the struct, ie

const Foo = struct { logger: ScopedLogger(Foo Scope) self.logger.info(..) }

Would ensure that logging from Foo would always be scoped to Foo Scope.

And I am not sure that can be accomplished with the approach you described.

Scope is not a part of the state. It's an immutable part of the type. Copying the logger to another place and using a new scope in that place is not going to make any changes to the scope of the original logger. The original logger will continue using the scope as specified in its type.

dnut · 2024-09-10T02:16:11Z

src/trace_ng/log.zig

+        channel: *Channel(logfmt.LogMsg),
+        handle: ?std.Thread,
+
+        pub fn init(config: Config) !*Self {


Is there a particular reason why this this returns a pointer to self? It could just return Self instead of *Self, which would simplify the function. Then the calling scope has the choice of how to allocate it. Currently it's forced into allocating the logger with the same allocator that's used for log messages, which may not always be a desirable constraint.

Is there a particular reason why this this returns a pointer to self?

If the union holds pointers, ie

pub fn ScopedLogger(comptime scope: ?[]const u8) type { return union(LogKind) { ... standard: *StandardErrLogger(scope), testing: *TestingLogger(scope), ... }

And ScopedLogger.init(...) needs to be able to create one of the union variants, then it needs to return a a pointer to self.

With the suggestion here #249 (comment) might be possible to remove them.

Yeah, I see your reasoning now. I think I saw this function before I noticed ScopedLogger.init.

But actually, even if you keep ScopedLogger.init, you could still have this return Self. ScopedLogger.init could allocate the pointer, and set it to the value returned by this function.

dnut · 2024-09-10T02:22:53Z

src/trace_ng/log.zig

+        pub fn unscoped(self: Self) Logger {
+            return .{
+                .allocator = self.allocator,
+                .recycle_fba = self.log_allocator_state,
+                .max_buffer = self.max_buffer,
+                .max_level = self.max_level,
+                .exit_sig = self.exit_sig,
+                .channel = self.channel,
+                .handle = self.handle,
+            };
+        }
+
+        pub fn withScope(self: Self, comptime new_scope: anytype) ScoppedLogger(new_scope) {
+            return .{
+                .allocator = self.allocator,
+                .recycle_fba = self.log_allocator_state,
+                .max_buffer = self.max_buffer,
+                .max_level = self.max_level,
+                .exit_sig = self.exit_sig,
+                .channel = self.channel,
+                .handle = self.handle,
+            };
+        }


These functions would fail to compile if they were actually used. ScoppedLogger is a union that holds only a pointer to the logger implementation.

For these to work it just needs to create the union from the pointer to self. Also I might change the function names to clarify that it's returning a different type. This is consistent with the interface pattern used in zig std.

Suggested change

pub fn unscoped(self: Self) Logger {

return .{

.allocator = self.allocator,

.recycle_fba = self.log_allocator_state,

.max_buffer = self.max_buffer,

.max_level = self.max_level,

.exit_sig = self.exit_sig,

.channel = self.channel,

.handle = self.handle,

};

}

pub fn withScope(self: Self, comptime new_scope: anytype) ScoppedLogger(new_scope) {

return .{

.allocator = self.allocator,

.recycle_fba = self.log_allocator_state,

.max_buffer = self.max_buffer,

.max_level = self.max_level,

.exit_sig = self.exit_sig,

.channel = self.channel,

.handle = self.handle,

};

}

pub fn logger(self: *Self) Logger {

return .{ .standard = self };

}

pub fn scopedLogger(self: Self, comptime new_scope: anytype) ScoppedLogger(new_scope) {

return .{ .standard = self };

}

dnut · 2024-09-10T02:27:54Z

src/trace_ng/log.zig

+/// A ScopedLogger could either be:
+/// - A StandardErrLogger
+/// - A TestingLogger
+pub fn ScoppedLogger(comptime scope: ?[]const u8) type {


Suggested change

pub fn ScoppedLogger(comptime scope: ?[]const u8) type {

pub fn ScopedLogger(comptime scope: ?[]const u8) type {

dnut · 2024-09-10T02:38:05Z

src/trace_ng/log.zig

+        pub fn init(config: Config) !Self {
+            switch (config.kind) {
+                .standard => {
+                    return .{ .standard = try StandardErrLogger(scope).init(.{
+                        .allocator = config.allocator,
+                        .max_level = config.max_level,
+                        .max_buffer = config.max_buffer,
+                    }) };
+                },
+                .testing, .noop => {
+                    return .{ .testing = TestingLogger(scope).init(.{
+                        .allocator = config.allocator,
+                        .max_level = config.max_level,
+                        .max_buffer = config.max_buffer,
+                    }) };
+                },
+            }
+        }
+
+        pub fn deinit(self: *const Self) void {
+            switch (self.*) {
+                .standard => |*logger| {
+                    logger.*.deinit();
+                },
+                .testing => |*logger| {
+                    logger.*.deinit();
+                },
+                .noop => {},
+            }
+        }
+


Do we need these functions? The caller could instead initialize whatever logger implementation they want, and convert it to the interface.

const std_logger = StdErrLogger.init(...); const logger = std_logger.logger();

This approach is more flexible because it doesn't couple all the logger init functions together to have a unified set of dependencies.

The idea behind the current approach is to have the caller call one init function (specifying the kind of logger they want) and they good to go ie:

const std_logger = Logger.init(.{.. .kind = LogKind.standard,})

Your approach would be two calls, but it might indeed be more flexible since it removes the init from the interface. I'll play around with it and see.

One reason I mentioned this approach is because in zig this is the typical pattern used by interfaces like Allocator, Random, Reader, Writer, etc. It's also common in other languages like rust and java to initialize a concrete type before casting it as the trait or interface.

I have also seen an approach like yours before, where you init the interface directly. This is basically the factory pattern. But the main difference is that the factory pattern usually doesn't give the caller direct choice over which type is going to be used for the implementation. In my experience, I've seen the factory pattern used to abstract away the logic that chooses which implementation to use. This allows the caller to just say "give me any logger", and the factory method has some special knowledge to make the correct decision about what logger to provide.

dnut · 2024-09-10T02:41:51Z

src/trace_ng/log.zig

+        pub fn unscoped(self: *const Self) !Logger {
+            switch (self.*) {
+                .standard => |logger| {
+                    return Logger.init(.{
+                        .allocator = logger.*.allocator,
+                        .max_buffer = logger.*.max_buffer,
+                        .kind = LogKind.standard,
+                    });
+                },
+                .testing => |logger| {
+                    return Logger.init(.{
+                        .allocator = logger.*.allocator,
+                        .kind = LogKind.testing,
+                    });
+                },
+                .noop => {
+                    @panic("Cannot scope noop");
+                },
+            }
+        }
+
+        pub fn withScope(self: *const Self, comptime new_scope: []const u8) !ScoppedLogger(new_scope) {
+            switch (self.*) {
+                .standard => |*logger| {
+                    return ScoppedLogger(new_scope).init(.{
+                        .allocator = logger.*.allocator,
+                        .max_buffer = logger.*.max_buffer,
+                        .kind = LogKind.standard,
+                    }) catch @panic("message: []const u8");
+                },
+                .testing => |*logger| {
+                    return ScoppedLogger(new_scope).init(.{
+                        .allocator = logger.*.allocator,
+                        .kind = LogKind.testing,
+                    }) catch @panic("message: []const u8");
+                },
+                .noop => {
+                    @panic("Cannot scope noop");
+                },
+            }
+        }
+


Why not just use the existing logger instead of creating a new one? Also what's wrong with scoping noop?

Why not just use the existing logger instead of creating a new one?

That is due to the pattern of passing in a logger, and allowing the struct use that to create a new one that is scoped.

const StuffChild = struct { const StuffChild = @This(); logger: ScopedLogger(@typeName(StuffChild)), // <- Scoped logger needed by struct pub fn init(logger: *const Logger) StuffChild { // ↓ New scoped logger created ↓ return .{ .logger = logger.withScope(@typeName(StuffChild)) catch { @panic("Init logger failed"); } }; }

Also if this is not done this way, ie, if the struct uses existing one, won't there be the risk of changing the scope externally?

Also what's wrong with scoping noop?

Nothing. It could technically be scoped, just did not pay much attention to it yet and defaulted to panic. But can update.

The instance of the underlying logger implementation can remain the same while changing the scope.

pub fn unscoped(self: Self) Logger { return switch (self) { .standard => |logger| .{ .standard = logger }, .testing => |logger| .{ .testing = logger }, .noop => .noop, }; } pub fn withScope(self: Self, comptime new_scope: []const u8) !ScoppedLogger(new_scope) { return switch (self) { .standard => |logger| .{ .standard = logger }, .testing => |logger| .{ .testing = logger }, .noop => .noop, }; }

dnut · 2024-09-10T02:43:47Z

src/trace_ng/log.zig

+pub const Logger = ScoppedLogger(null);
+
+/// An instance of `ScopedLogger` that logs to the standard err.
+pub fn StandardErrLogger(comptime scope: ?[]const u8) type {


You could make scope a parameter for the log functions instead of being a parameter for the logger implementation types. The logger interface would still need it, but the implementations of the interface do not need it.

Personally I feel that it simplifies the code because this can be defined as a normal struct instead of a generic struct. It cleans up an unnecessary layer of abstraction

Not sure if/how that would work since the implementation contains logic that refers to the scope. For example:

pub fn log(self: *Self, level: Level, message: []const u8) void { if (@intFromEnum(level) > @intFromEnum(self.max_level)) { // noop return; } const maybe_scope = if (scope) |s| s else null; // <---- The scope needed here const log_msg = logfmt.LogMsg{ .level = level, .maybe_scope = maybe_scope, .maybe_msg = message, .maybe_fields = null, .maybe_fmt = null, }; self.channel.send(log_msg) catch |err| { std.debug.print("Send msg through channel failed with err: {any}", .{err}); return; }; }

Unless the method on the implementation be modified to take scope like this

pub fn log(self: *Self, comptime scope: ?[]const u8, level: Level, message: []const u8) void

and then modify the interface to supply the scope when calling the implementation.

Done in 460cf27

dnut · 2024-09-10T13:35:01Z

src/trace_ng/log.zig

+                if (message.maybe_fields) |fields| {
+                    self.log_allocator.free(fields);
+                }
+                if (message.maybe_fmt) |fmt_msg| {
+                    self.log_allocator.free(fmt_msg);
+                }


These frees occur while holding the stderr lock. But you don't actually need to hold the lock to execute this. To reduce contention, you could ensure the lock is only held while actually calling writeLog.

dnut · 2024-09-10T13:35:27Z

src/trace_ng/log.zig

+            };
+            defer self.channel.allocator.free(messages);
+            for (messages) |message| {
+                const writer = std.io.getStdErr().writer();


I'm not sure if it makes any difference, but you could also create this outside the loop. It might improve performance. Is there an advantage of creating it inside the loop?

I think same comment here #249 (comment) applies here too

I can see an advantage of acquiring the lock within the loop, but I think this is different. What's the advantage of instantiating the writer inside the loop?

Actually misread the comment to be referring to the lock acquisition.

What's the advantage of instantiating the writer inside the loop?

I don't think there is any. Removed in 45c4535

dnut · 2024-09-10T13:37:17Z

src/trace_ng/log.zig

+            defer self.channel.allocator.free(messages);
+            for (messages) |message| {
+                const writer = std.io.getStdErr().writer();
+                std.debug.lockStdErr();


This acquires and releases the lock once for every log message. Another approach could acquire the lock once, log all messages, then release the lock.

I'm not sure what's best. Here's the tradeoff that I'm imagining...

Acquiring the lock only once for all messages means other threads are blocked for more time before they can access stderr. This could delay other important messages from being seen.

Acquiring the lock separately for each message uses more computation because it needs to execute atomic operations on every loop iteration.

For that tradeoff, I think the best answer depends on how many threads are writing to stderr, and how responsive you need them to be. If there are multiple threads writing to stderr, and there is likely to be a large number of messages in here that will take a long time to process, then it might be best to acquire the lock separately for each message. But if this is the only thread that you expect to write to stderr, or if you know that message batches will typically be small, then it might be optimal to only acquire the lock once for the entire loop. What do you think?

I think the base case is to acquire the lock for each message written. This is what the std lib log does (alongside using buffered writer), and also debug.print. And given that we are offloading the writing out of the log message off to another thread, hopefully the computation needed to acquire/release the std err does not easily affect other working threads.

Also giving that the stderr is a shared resource, i'll err on the side of not holding on to it too much. Even though the likelihood of that happening is low in this case, if there is a bug in the logger, where the loop runs for more time than needed, there is the possibility of hogging unto the shared resource for more than needed.

So maybe acquire the lock for each message (as it is currently) but if in practice, this proves to have a noticeable performance impact, then it can be revisited?

0xNineteen

lgtm - we'll want this fully integrated (production ready) before we merge this to main - to make reviewing easier (like you mentioned previously), could you create another PR which branches off this PR which integrates the new logger?

once integration is reviewed and approved well merge both into main

dadepo · 2024-10-03T16:12:54Z

Since the API has been updated in #277 I'll close this one and have that target main intead.

dadepo added 3 commits August 25, 2024 22:41

Exploring new tracing

8afbc2f

Committed files

2330ef6

How polymorphism via a vtable might look

6558f7a

0xNineteen mentioned this pull request Aug 26, 2024

feat(trace): scoped logging #230

Closed

Added multiple methods

5c233e7

0xNineteen changed the title ~~feat(trace) Improve trace~~ feat(trace): improve trace Aug 27, 2024

Run log through channel

e163930

0xNineteen assigned dadepo Aug 28, 2024

dadepo added 8 commits August 29, 2024 12:14

Switch to RecycleFBA

7176238

Run logWithFields through channel

73c9148

Moved all methods

fdd78f8

Fix garbled text

c0e98ba

Remove chaining implementation

211ad58

Use allocated memory to also construct key value

8a1091e

Some renaming

da350df

Seitching scope

bde034c

dnut reviewed Aug 30, 2024

View reviewed changes

src/trace_ng/log.zig Outdated Show resolved Hide resolved

dnut reviewed Aug 30, 2024

View reviewed changes

dadepo added 10 commits August 30, 2024 22:23

Partial fix of leak

10a883e

Fix leak

7085987

Add level guard

1825d74

Remove todo

e31caf5

Added static dispatch polymorphism

d5ad7a1

Rename variable

852c407

Allocate based on size of fmt message

4a7c0f1

Pass log message as a reference

74ef498

Added test logger that tests formats of log message

1dec7e2

Move struct used for testing inside testing block

49aa9a4

dadepo added 13 commits September 6, 2024 00:21

Add methods

26f97ba

Fix warnfWithFields

dd1e13b

Estimate field size and not hardcode to 512

06d3257

Fmt

7c233b8

Removed unused line

81d38a6

Test logger does not need the max_buffer

0be2b8a

Removed last @ptrCast and some minor clean ups

2c6d054

Implementation out of the union

792e8bb

Removed unintended diff

33a9877

Hack to ensure child logs show up in std err

eeb08bd

Ensure the test logger is only used in tests

615f5c2

Remove panic from unscoped and scope

fa0d2bf

Do not ignore errors but fallback to std.debug.print

890133f

dadepo commented Sep 9, 2024

View reviewed changes

dnut reviewed Sep 10, 2024

View reviewed changes

dadepo added 3 commits September 10, 2024 14:40

Typo

990c827

Fixed hidden broken compilation

0a52225

Have implementation as struct instead of type functions

460cf27

dnut reviewed Sep 10, 2024

View reviewed changes

dadepo added 6 commits September 10, 2024 22:16

Limit the scope of holding the lock on std err

3c23009

Remove the sleep

822c6c3

Switched to pattern of concrete instance turning itself to interface

610ec6a

Moved the write out of the loop

45c4535

Typo

7d576d4

Update scope switch test

5d929f1

0xNineteen reviewed Sep 23, 2024

View reviewed changes

dadepo mentioned this pull request Sep 28, 2024

improve(trace): incorporate the new logger #277

Merged

5 tasks

dadepo closed this Oct 3, 2024

	pub fn ScoppedLogger(comptime scope: ?[]const u8) type {
	pub fn ScopedLogger(comptime scope: ?[]const u8) type {

feat(trace): improve trace #249

feat(trace): improve trace #249

Conversation

dadepo commented Aug 25, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dnut Aug 30, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dnut Sep 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dadepo Sep 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dadepo Sep 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dadepo Sep 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dadepo Sep 10, 2024 • edited Loading

Choose a reason for hiding this comment

0xNineteen left a comment

Choose a reason for hiding this comment

dadepo commented Oct 3, 2024

dadepo commented Aug 25, 2024 •

edited

Loading

dnut Aug 30, 2024 •

edited

Loading

dnut Sep 10, 2024 •

edited

Loading

dadepo Sep 10, 2024 •

edited

Loading

dadepo Sep 10, 2024 •

edited

Loading

dadepo Sep 10, 2024 •

edited

Loading

dadepo Sep 10, 2024 •

edited

Loading