improving logger

build.zig

@@ -26,12 +26,14 @@ pub fn build(b: *std.Build) void {
         .link_libc = true,
     });
 
+    const zdt = b.dependency("zdt", .{}).module("zdt");
     const vulkan_headers = b.dependency("vulkan_headers", .{});
 
     const vulkan = b.dependency("vulkan_zig", .{
         .registry = vulkan_headers.path("registry/vk.xml"),
     }).module("vulkan-zig");
 
+    base_mod.addImport("zdt", zdt);
     base_mod.addImport("vulkan", vulkan);
     base_mod.addSystemIncludePath(vulkan_headers.path("include"));
 

build.zig.zon

@@ -18,6 +18,10 @@
             .hash = "cpuinfo-0.1.0-V7dMLcghAADJuG7dkd3MnwDPZ232pBK_8uGjxY43eP5u",
             .lazy = true,
         },
+        .zdt = .{
+            .url = "git+https://github.com/FObersteiner/zdt/?ref=v0.8.1#8b551a0a3e5ae64a32b5bad0e6a93119787b43af",
+            .hash = "zdt-0.8.1-xr0_vAxUDwCJRDh9pcAS_mdZBIsvcGTtN-K8JJSWY4I6",
+        },
     },
 
     .paths = .{

src/soft/PhysicalDevice.zig

@@ -47,7 +47,7 @@ pub fn create(allocator: std.mem.Allocator, instance: *const base.Instance) VkEr
     const info = cpuinfo.get(allocator) catch return VkError.InitializationFailed;
     defer info.deinit(allocator);
 
-    var writer = std.io.Writer.fixed(interface.props.device_name[0 .. vk.MAX_PHYSICAL_DEVICE_NAME_SIZE - 1]);
+    var writer = std.Io.Writer.fixed(interface.props.device_name[0 .. vk.MAX_PHYSICAL_DEVICE_NAME_SIZE - 1]);
     writer.print("{s} [Soft Vulkan Driver]", .{info.name}) catch return VkError.InitializationFailed;
 
     self.* = .{

src/soft/lib.zig

@@ -6,6 +6,9 @@ const Device = @import("Device.zig");
 const Instance = @import("Instance.zig");
 const PhysicalDevice = @import("PhysicalDevice.zig");
 
+pub const DRIVER_LOGS_ENV_NAME = base.DRIVER_LOGS_ENV_NAME;
+pub const DRIVER_NAME = "Soft";
+
 pub const VULKAN_VERSION = vk.makeApiVersion(0, 1, 0, 0);
 pub const DRIVER_VERSION = vk.makeApiVersion(0, 0, 0, 1);
 pub const DEVICE_ID = 0x600DCAFE;

src/vulkan/Instance.zig

@@ -25,6 +25,21 @@ pub fn init(allocator: std.mem.Allocator, infos: *const vk.InstanceCreateInfo) V
     };
 }
 
+pub fn requestPhysicalDevices(self: *Self, allocator: std.mem.Allocator) VkError!void {
+    try self.dispatch_table.requestPhysicalDevices(self, allocator);
+    if (self.physical_devices.items.len == 0) {
+        std.log.scoped(.vkCreateInstance).info("No VkPhysicalDevice found", .{});
+        return;
+    }
+    for (self.physical_devices.items) |physical_device| {
+        std.log.scoped(.vkCreateInstance).info("Found VkPhysicalDevice named {s}", .{physical_device.object.props.device_name});
+    }
+}
+
+pub fn releasePhysicalDevices(self: *Self, allocator: std.mem.Allocator) VkError!void {
+    try self.dispatch_table.releasePhysicalDevices(self, allocator);
+}
+
 pub fn deinit(self: *Self, allocator: std.mem.Allocator) VkError!void {
     try self.dispatch_table.releasePhysicalDevices(self, allocator);
     try self.dispatch_table.destroyInstance(self, allocator);

src/vulkan/lib.zig

@@ -2,7 +2,7 @@ const std = @import("std");
 const vk = @import("vulkan");
 
 pub const lib_vulkan = @import("lib_vulkan.zig");
-pub const logs = @import("logs.zig");
+pub const logger = @import("logger.zig");
 
 pub const Dispatchable = @import("Dispatchable.zig").Dispatchable;
 pub const VkError = @import("error_set.zig").VkError;
@@ -18,7 +18,7 @@ pub const DRIVER_LOGS_ENV_NAME = "DRIVER_LOGS";
 
 pub const std_options: std.Options = .{
     .log_level = .debug,
-    .logFn = logs.logger,
+    .logFn = logger.log,
 };
 
 pub fn retrieveDriverDataAs(handle: anytype, comptime T: type) !*T {

src/vulkan/lib_vulkan.zig

@@ -2,6 +2,7 @@ const std = @import("std");
 const vk = @import("vulkan");
 const root = @import("lib.zig");
 
+const logger = @import("logger.zig");
 const error_set = @import("error_set.zig");
 const VkError = error_set.VkError;
 const toVkResult = error_set.toVkResult;
@@ -25,6 +26,11 @@ fn functionMapElement(name: []const u8) struct { []const u8, vk.PfnVoidFunction
 }
 
 pub export fn vkGetInstanceProcAddr(p_instance: vk.Instance, p_name: ?[*:0]const u8) callconv(vk.vulkan_call_conv) vk.PfnVoidFunction {
+    if (p_name == null) {
+        return null;
+    }
+    const name = std.mem.span(p_name.?);
+
     const global_pfn_map = std.StaticStringMap(vk.PfnVoidFunction).initComptime(.{
         functionMapElement("vkGetInstanceProcAddr"),
         functionMapElement("vkCreateInstance"),
@@ -42,11 +48,9 @@ pub export fn vkGetInstanceProcAddr(p_instance: vk.Instance, p_name: ?[*:0]const
         functionMapElement("vkDestroyDevice"),
     });
 
-    if (p_name == null) {
-        return null;
-    }
-    const name = std.mem.span(p_name.?);
     std.log.scoped(.vkGetInstanceProcAddr).info("Loading {s}...", .{name});
+    logger.indent();
+    defer logger.unindent();
 
     if (global_pfn_map.get(name)) |pfn| return pfn;
     if (p_instance == .null_handle) return null;
@@ -59,15 +63,23 @@ pub export fn vkCreateInstance(p_infos: ?*const vk.InstanceCreateInfo, callbacks
     if (infos.s_type != .instance_create_info) {
         return .error_initialization_failed;
     }
-    const allocator = VulkanAllocator.init(callbacks, .instance).allocator();
-    const handler = __vkImplCreateInstance(&allocator, infos) orelse return .error_initialization_failed;
-    handler.dispatch_table.requestPhysicalDevices(handler, allocator) catch |err| return toVkResult(err);
+    std.log.scoped(.vkCreateInstance).info("Creating VkInstance", .{});
+    logger.indent();
+    defer logger.unindent();
 
-    p_instance.* = (Dispatchable(Instance).wrap(allocator, handler) catch |err| return toVkResult(err)).toVkHandle(vk.Instance);
+    const allocator = VulkanAllocator.init(callbacks, .instance).allocator();
+    const instance = __vkImplCreateInstance(&allocator, infos) orelse return .error_initialization_failed;
+    instance.requestPhysicalDevices(allocator) catch |err| return toVkResult(err);
+
+    p_instance.* = (Dispatchable(Instance).wrap(allocator, instance) catch |err| return toVkResult(err)).toVkHandle(vk.Instance);
     return .success;
 }
 
 pub export fn vkDestroyInstance(p_instance: vk.Instance, callbacks: ?*const vk.AllocationCallbacks) callconv(vk.vulkan_call_conv) void {
+    std.log.scoped(.vkDestroyInstance).info("Destroying VkInstance", .{});
+    logger.indent();
+    defer logger.unindent();
+
     const allocator = VulkanAllocator.init(callbacks, .instance).allocator();
     const dispatchable = Dispatchable(Instance).fromHandle(p_instance) catch return;
     dispatchable.object.deinit(allocator) catch {};
@@ -102,6 +114,10 @@ pub export fn vkCreateDevice(p_physical_device: vk.PhysicalDevice, p_infos: ?*co
     }
     const allocator = VulkanAllocator.init(callbacks, .instance).allocator();
     const physical_device = Dispatchable(PhysicalDevice).fromHandleObject(p_physical_device) catch |err| return toVkResult(err);
+    std.log.scoped(.vkCreateDevice).info("Creating VkDevice from {s}", .{physical_device.props.device_name});
+    logger.indent();
+    defer logger.unindent();
+
     const device = physical_device.createDevice(allocator, infos) catch |err| return toVkResult(err);
     p_device.* = (Dispatchable(Device).wrap(allocator, device) catch |err| return toVkResult(err)).toVkHandle(vk.Device);
     return .success;
@@ -110,6 +126,10 @@ pub export fn vkCreateDevice(p_physical_device: vk.PhysicalDevice, p_infos: ?*co
 pub export fn vkDestroyDevice(p_device: vk.Device, callbacks: ?*const vk.AllocationCallbacks) callconv(vk.vulkan_call_conv) void {
     const allocator = VulkanAllocator.init(callbacks, .device).allocator();
     const dispatchable = Dispatchable(Device).fromHandle(p_device) catch return;
+    std.log.scoped(.vkDestroyDevice).info("Destroying VkDevice created from {s}", .{dispatchable.object.physical_device.props.device_name});
+    logger.indent();
+    defer logger.unindent();
+
     dispatchable.object.destroy(allocator) catch return;
     dispatchable.destroy(allocator);
 }

src/vulkan/logger.zig

@@ -0,0 +1,91 @@
+const std = @import("std");
+const builtin = @import("builtin");
+const zdt = @import("zdt");
+const root = @import("root");
+
+comptime {
+    if (!@hasDecl(root, "DRIVER_NAME")) {
+        @compileError("Missing DRIVER_NAME in module root");
+    }
+    if (!@hasDecl(root, "DRIVER_LOGS_ENV_NAME")) {
+        @compileError("Missing DRIVER_LOGS_ENV_NAME in module root");
+    }
+}
+
+const is_posix = switch (builtin.os.tag) {
+    .windows, .uefi, .wasi => false,
+    else => true,
+};
+
+var indent_level: usize = 0;
+
+pub fn indent() void {
+    const new_indent_level, const has_overflown = @addWithOverflow(indent_level, 1);
+    if (has_overflown == 0) {
+        indent_level = new_indent_level;
+    }
+}
+
+pub fn unindent() void {
+    const new_indent_level, const has_overflown = @subWithOverflow(indent_level, 1);
+    if (has_overflown == 0) {
+        indent_level = new_indent_level;
+    }
+}
+
+pub fn log(comptime level: std.log.Level, comptime scope: @Type(.enum_literal), comptime format: []const u8, args: anytype) void {
+    if (!std.process.hasEnvVarConstant(root.DRIVER_LOGS_ENV_NAME)) {
+        return;
+    }
+
+    const scope_name = @tagName(scope);
+    const scope_prefix = comptime blk: {
+        const limit = 30 - 4;
+        break :blk if (scope_name.len >= limit)
+            std.fmt.comptimePrint("({s}...): ", .{scope_name[0..(limit - 3)]})
+        else
+            std.fmt.comptimePrint("({s}): ", .{scope_name});
+    };
+
+    const prefix = "[" ++ comptime level.asText() ++ "] ";
+
+    const level_color: std.Io.tty.Color = switch (level) {
+        .info => .blue,
+        .warn => .yellow,
+        .err => .red,
+        .debug => .blue,
+    };
+
+    std.debug.lockStdErr();
+    defer std.debug.unlockStdErr();
+
+    var stderr_buffer: [512]u8 = undefined;
+    var stderr_file = std.fs.File.stderr();
+    var stderr_writer = stderr_file.writer(&stderr_buffer);
+    var writer: *std.Io.Writer = &stderr_writer.interface;
+    var out_config = std.Io.tty.Config.detect(stderr_file);
+
+    const timezone = zdt.Timezone.tzLocal(std.heap.page_allocator) catch zdt.Timezone.UTC;
+    const now = zdt.Datetime.now(.{ .tz = &timezone }) catch return;
+
+    out_config.setColor(writer, .magenta) catch {};
+    writer.print("[" ++ root.DRIVER_NAME ++ "Driver ", .{}) catch return;
+    out_config.setColor(writer, .yellow) catch {};
+    writer.print("{d:02}:{d:02}:{d:02}.{d:03}", .{ now.hour, now.minute, now.second, @divFloor(now.nanosecond, std.time.ns_per_ms) }) catch return;
+    out_config.setColor(writer, .magenta) catch {};
+    writer.print("]", .{}) catch return;
+
+    out_config.setColor(writer, level_color) catch {};
+    writer.print(prefix, .{}) catch return;
+
+    out_config.setColor(writer, .green) catch {};
+    writer.print("{s: >30}", .{scope_prefix}) catch return;
+
+    out_config.setColor(writer, .reset) catch {};
+
+    for (0..indent_level) |_| {
+        writer.print(">   ", .{}) catch return;
+    }
+    writer.print(format ++ "\n", args) catch return;
+    writer.flush() catch return;
+}

src/vulkan/logs.zig

@@ -1,48 +0,0 @@
-const std = @import("std");
-const builtin = @import("builtin");
-const root = @import("lib.zig");
-
-const is_posix = switch (builtin.os.tag) {
-    .windows, .uefi, .wasi => false,
-    else => true,
-};
-
-pub fn logger(comptime level: std.log.Level, comptime scope: @Type(.enum_literal), comptime format: []const u8, args: anytype) void {
-    if (!std.process.hasEnvVarConstant(root.DRIVER_LOGS_ENV_NAME)) {
-        return;
-    }
-    const scope_prefix = "(" ++ @tagName(scope) ++ "): ";
-    const prefix = "[" ++ comptime level.asText() ++ "] ";
-
-    const level_color: std.Io.tty.Color = switch (level) {
-        .info => .blue,
-        .warn => .yellow,
-        .err => .red,
-        .debug => .blue,
-    };
-
-    const instant = std.time.Instant.now() catch return;
-    const now = if (is_posix) instant.timestamp.nsec else instant.timestamp;
-
-    std.debug.lockStdErr();
-    defer std.debug.unlockStdErr();
-
-    var stderr_buffer: [512]u8 = undefined;
-    var stderr_file = std.fs.File.stderr();
-    var stderr_writer = stderr_file.writer(&stderr_buffer);
-    var writer: *std.Io.Writer = &stderr_writer.interface;
-
-    var out_config = std.Io.tty.Config.detect(stderr_file);
-    nosuspend {
-        out_config.setColor(writer, .magenta) catch {};
-        writer.print("[Driver log {}:{}:{}]", .{ @divFloor(now, std.time.ns_per_min), @divFloor(now, std.time.ns_per_s), @divFloor(now, std.time.ns_per_ms) }) catch return;
-        out_config.setColor(writer, level_color) catch {};
-        writer.print(prefix, .{}) catch return;
-        out_config.setColor(writer, .green) catch {};
-        writer.print(scope_prefix, .{}) catch return;
-        out_config.setColor(writer, .reset) catch {};
-
-        writer.print(format ++ "\n", args) catch return;
-        writer.flush() catch return;
-    }
-}

test/c/main.c

@@ -4,6 +4,8 @@
 #define VK_NO_PROTOTYPES
 #include <vulkan/vulkan_core.h>
 
+#include <unistd.h>
+
 #include <dlfcn.h>
 
 #ifndef LIBVK