Comptime-checking log level & calling a function

std.log.debug produces no code if logging level is below .debug, which is great, but what if I have a lot of calls to std.log.debug in one place, enough to warrant gathering them in a separate function?

I would have to call this function only if log level is .debug, but would that check be comptime (good) or runtime (bad)?

In other words, am I reducing my performance when log_level != .debug by having this if?

if (std.options.log_level == .debug)
    myDebugLoggerFn(some_data);

In the same vein, if I want to std.log.debug an array of something in a loop (so that I can control where line breaks are, etc.), and put that loop in a if (std.options.log_level == .debug), would that mean no code is emitted / no code runs when log_level != .debug?

Also, I hope Zig doesn’t emit machine code for functions that are not called (e.g. because log_level is not .debug)… does it?

Easy way to test: set the debug level to something other than .debug and add a @compileError inside the if statement. If you hit it, then the if statement has survived compilation, if you don’t, then it was elided at comptime.

My prediction is that it you will not hit the compile error because std.options.log_level is comptime known (given how it’s already used at comptime).

Lastly, I do think that all the calls to std.log.debug themselves get elided if they result to calls to empty functions (which is what they should be when log_level is not debug). I guess this is an optimization that might not kick in if you make a debug build (with log_level not set to debug), so you might want to look at some compiler explorer output to verify this.

But if you’re making an optimized release, then you most definitely shouldn’t worry about this.

3 Likes

This is a good advice indeed.
Here’s my test code:

const std = @import("std");

pub fn main() void
{
    var ham = [_]u8 { 0x00, 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, 0x09, 0x0A, 0x0B, 0x0C, 0x0D, 0x0E, 0x0F };
    for (&ham) |*b| // Some processing
        b.* += 0x40;

    // Must run in .debug log level only, the idea being that in release mode this should procude no opcodes
    if (std.options.log_level == .debug)
    {
        debugLogHam(&ham);
        @compileError("if (std.options.log_level == .debug) is compiled!");
    }
}

fn debugLogHam(ham: []const u8) void
{
    for (ham) |b|
        std.log.debug("{x:0>2}, {c}", .{ b, b });
    @compileError("debugLogHam is compiled!");
}

It compiles and runs in release modes, but generates two compiler errors in debug mode, just as expected:

$ zig run log_comptime.zig
log_comptime.zig:13:9: error: if (std.options.log_level == .debug) is compiled!
        @compileError("if (std.options.log_level == .debug) is compiled!");
        ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
referenced by:
    callMain: /home/archie/apps/zig/lib/std/start.zig:575:17
    initEventLoopAndCallMain: /home/archie/apps/zig/lib/std/start.zig:519:34
    remaining reference traces hidden; use '-freference-trace' to see all reference traces
log_comptime.zig:21:5: error: debugLogHam is compiled!
    @compileError("debugLogHam is compiled!");
    ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

perfect, then unless you have particular worries about performance in debug builds (in which case you might want to do more investigation), you can just leave the debug logging calls where they are and be confident that they won’t cause any overhead in release mode

1 Like

I have noticed one thing, however - when running tests, log_level seems to be .debug, but std.log.debug doesn’t work.

Here’s a modification of the code above, demonstrating this:

const std = @import("std");

// @compileError shows whether parts of the code are compiled or skipped.
// Try building this code in Debug mode (should fail) and in Release modes (should compile).

pub fn main() void
{
    var ham = [_]u8 { 0x00, 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, 0x09, 0x0A, 0x0B, 0x0C, 0x0D, 0x0E, 0x0F };
    for (&ham) |*b| // Some processing
        b.* += 0x40;

    // Must run in .debug log level only, the idea being that in release mode this should procude no opcodes
    if (std.options.log_level == .debug)
    {
        debugLogHam(&ham);
        //@compileError("if (std.options.log_level == .debug) is compiled!");
    }
}

fn debugLogHam(ham: []const u8) void
{
    for (ham) |b|
        std.log.debug("log.debug: {x:0>2}, {c}", .{ b, b });
    std.debug.print("\n", .{});
    for (ham) |b|
        std.debug.print("debug.print: {x:0>2}, {c}\n", .{ b, b });
    //@compileError("debugLogHam is compiled!");
}

test
{
    if (std.options.log_level == .debug)
    {
        var ham = [_]u8 { 'a', 'b', 'c', 'd', 'e', 'f' };
        debugLogHam(&ham);
        //@compileError("if (std.options.log_level == .debug) is compiled!");
    }
}

When I run zig test log_comptime.zig 2>&1 (2>&1 just in case I’m missing log.debug output because it goes to stderr), I’m getting only the lines printed out by std.debug.print in fn debugLogHam():

$ zig test log_comptime.zig 2>&1                                                                                
Test [1/1] test_0... 
debug.print: 61, a
debug.print: 62, b
debug.print: 63, c
debug.print: 64, d
debug.print: 65, e
debug.print: 66, f
All 1 tests passed.

When I run zig run log_comptime.zig 2>&1, I get lines printed by both std.log.debug and std.debug.print in fn debugLogHam(), as expected.