From b1eba51d3919d7f131aa4299219d815e93e7fc26 Mon Sep 17 00:00:00 2001 From: Andrew Kelley Date: Mon, 10 Aug 2020 19:34:27 -0700 Subject: [PATCH] GeneralPurposeAllocator: use std.log instead of std.debug.print `std.builtin.StackTrace` gains a `format` function. GeneralPurposeAllocator uses `std.log.err` instead of directly printing to stderr. Some errors are recoverable. The test runner is modified to fail the test run if any log messages of "err" or worse severity are encountered. self-hosted is modified to always print log messages of "err" severity or worse even if they have not been explicitly enabled. This makes GeneralPurposeAllocator available on the freestanding target. --- lib/std/builtin.zig | 19 ++++++ lib/std/heap/general_purpose_allocator.zig | 68 +++++++++++++--------- lib/std/special/test_runner.zig | 12 +++- src-self-hosted/main.zig | 22 +++---- 4 files changed, 84 insertions(+), 37 deletions(-) diff --git a/lib/std/builtin.zig b/lib/std/builtin.zig index 499011eab9c3..e9c53d7ee52e 100644 --- a/lib/std/builtin.zig +++ b/lib/std/builtin.zig @@ -52,6 +52,25 @@ pub const subsystem: ?SubSystem = blk: { pub const StackTrace = struct { index: usize, instruction_addresses: []usize, + + pub fn format( + self: StackTrace, + comptime fmt: []const u8, + options: std.fmt.FormatOptions, + writer: anytype, + ) !void { + var arena = std.heap.ArenaAllocator.init(std.heap.page_allocator); + defer arena.deinit(); + const debug_info = std.debug.getSelfDebugInfo() catch |err| { + return writer.print("\nUnable to print stack trace: Unable to open debug info: {}\n", .{@errorName(err)}); + }; + const tty_config = std.debug.detectTTYConfig(); + try writer.writeAll("\n"); + std.debug.writeStackTrace(self, writer, &arena.allocator, debug_info, tty_config) catch |err| { + try writer.print("Unable to print stack trace: {}\n", .{@errorName(err)}); + }; + try writer.writeAll("\n"); + } }; /// This data structure is used by the Zig language code generation and diff --git a/lib/std/heap/general_purpose_allocator.zig b/lib/std/heap/general_purpose_allocator.zig index cb7f36fcc334..957c38939ce2 100644 --- a/lib/std/heap/general_purpose_allocator.zig +++ b/lib/std/heap/general_purpose_allocator.zig @@ -4,12 +4,12 @@ //! //! ### `OptimizationMode.debug` and `OptimizationMode.release_safe`: //! -//! * Detect double free, and print stack trace of: +//! * Detect double free, and emit stack trace of: //! - Where it was first allocated //! - Where it was freed the first time //! - Where it was freed the second time //! -//! * Detect leaks and print stack trace of: +//! * Detect leaks and emit stack trace of: //! - Where it was allocated //! //! * When a page of memory is no longer needed, give it back to resident memory @@ -178,15 +178,18 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { stack_addresses: [stack_n]usize, fn dumpStackTrace(self: *LargeAlloc) void { + std.debug.dumpStackTrace(self.getStackTrace()); + } + + fn getStackTrace(self: *LargeAlloc) std.builtin.StackTrace { var len: usize = 0; while (len < stack_n and self.stack_addresses[len] != 0) { len += 1; } - const stack_trace = StackTrace{ + return .{ .instruction_addresses = &self.stack_addresses, .index = len, }; - std.debug.dumpStackTrace(stack_trace); } }; const LargeAllocTable = std.AutoHashMapUnmanaged(usize, LargeAlloc); @@ -282,15 +285,9 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { while (true) : (bit_index += 1) { const is_used = @truncate(u1, used_byte >> bit_index) != 0; if (is_used) { - std.debug.print("\nMemory leak detected:\n", .{}); const slot_index = @intCast(SlotIndex, used_bits_byte * 8 + bit_index); - const stack_trace = bucketStackTrace( - bucket, - size_class, - slot_index, - .alloc, - ); - std.debug.dumpStackTrace(stack_trace); + const stack_trace = bucketStackTrace(bucket, size_class, slot_index, .alloc); + std.log.err(.std, "Memory leak detected: {}", .{stack_trace}); leaks = true; } if (bit_index == math.maxInt(u3)) @@ -301,8 +298,8 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { return leaks; } - /// Returns whether there were leaks. - pub fn deinit(self: *Self) bool { + /// Emits log messages for leaks and then returns whether there were any leaks. + pub fn detectLeaks(self: *Self) bool { var leaks = false; for (self.buckets) |optional_bucket, bucket_i| { const first_bucket = optional_bucket orelse continue; @@ -317,10 +314,14 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { } } for (self.large_allocations.items()) |*large_alloc| { - std.debug.print("\nMemory leak detected (0x{x}):\n", .{@ptrToInt(large_alloc.value.bytes.ptr)}); - large_alloc.value.dumpStackTrace(); + std.log.err(.std, "Memory leak detected: {}", .{large_alloc.value.getStackTrace()}); leaks = true; } + return leaks; + } + + pub fn deinit(self: *Self) bool { + const leaks = if (config.safety) self.detectLeaks() else false; self.large_allocations.deinit(self.backing_allocator); self.* = undefined; return leaks; @@ -442,13 +443,18 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { }; if (config.safety and old_mem.len != entry.value.bytes.len) { - std.debug.print("\nAllocation size {} bytes does not match free size {}. Allocated here:\n", .{ + var addresses: [stack_n]usize = [1]usize{0} ** stack_n; + var free_stack_trace = StackTrace{ + .instruction_addresses = &addresses, + .index = 0, + }; + std.debug.captureStackTrace(ret_addr, &free_stack_trace); + std.log.err(.std, "Allocation size {} bytes does not match free size {}. Allocation: {} Free: {}", .{ entry.value.bytes.len, old_mem.len, + entry.value.getStackTrace(), + free_stack_trace, }); - entry.value.dumpStackTrace(); - - @panic("\nFree here:"); } const result_len = try self.backing_allocator.resizeFn(self.backing_allocator, old_mem, old_align, new_size, len_align, ret_addr); @@ -518,14 +524,24 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type { const is_used = @truncate(u1, used_byte.* >> used_bit_index) != 0; if (!is_used) { if (config.safety) { - // print allocation stack trace - std.debug.print("\nDouble free detected, allocated here:\n", .{}); const alloc_stack_trace = bucketStackTrace(bucket, size_class, slot_index, .alloc); - std.debug.dumpStackTrace(alloc_stack_trace); - std.debug.print("\nFirst free here:\n", .{}); const free_stack_trace = bucketStackTrace(bucket, size_class, slot_index, .free); - std.debug.dumpStackTrace(free_stack_trace); - @panic("\nSecond free here:"); + var addresses: [stack_n]usize = [1]usize{0} ** stack_n; + var second_free_stack_trace = StackTrace{ + .instruction_addresses = &addresses, + .index = 0, + }; + std.debug.captureStackTrace(ret_addr, &second_free_stack_trace); + std.log.err(.std, "Double free detected. Allocation: {} First free: {} Second free: {}", .{ + alloc_stack_trace, + free_stack_trace, + second_free_stack_trace, + }); + if (new_size == 0) { + // Recoverable. + return @as(usize, 0); + } + @panic("Unrecoverable double free"); } else { unreachable; } diff --git a/lib/std/special/test_runner.zig b/lib/std/special/test_runner.zig index 384cd7f572f6..f4c8c6de9d7e 100644 --- a/lib/std/special/test_runner.zig +++ b/lib/std/special/test_runner.zig @@ -4,6 +4,8 @@ const builtin = @import("builtin"); pub const io_mode: io.Mode = builtin.test_io_mode; +var log_err_count: usize = 0; + pub fn main() anyerror!void { const test_fn_list = builtin.test_functions; var ok_count: usize = 0; @@ -75,8 +77,13 @@ pub fn main() anyerror!void { } else { std.debug.print("{} passed; {} skipped.\n", .{ ok_count, skip_count }); } + if (log_err_count != 0) { + std.debug.print("{} errors were logged.\n", .{log_err_count}); + } if (leaks != 0) { - std.debug.print("{} tests leaked memory\n", .{ok_count}); + std.debug.print("{} tests leaked memory.\n", .{ok_count}); + } + if (leaks != 0 or log_err_count != 0) { std.process.exit(1); } } @@ -87,6 +94,9 @@ pub fn log( comptime format: []const u8, args: anytype, ) void { + if (@enumToInt(message_level) <= @enumToInt(std.log.Level.err)) { + log_err_count += 1; + } if (@enumToInt(message_level) <= @enumToInt(std.testing.log_level)) { std.debug.print("[{}] ({}): " ++ format, .{ @tagName(scope), @tagName(message_level) } ++ args); } diff --git a/src-self-hosted/main.zig b/src-self-hosted/main.zig index 2795da00175d..2f6610da28f0 100644 --- a/src-self-hosted/main.zig +++ b/src-self-hosted/main.zig @@ -42,17 +42,19 @@ pub fn log( comptime format: []const u8, args: anytype, ) void { - if (@enumToInt(level) > @enumToInt(std.log.level)) - return; - - const scope_name = @tagName(scope); - const ok = comptime for (build_options.log_scopes) |log_scope| { - if (mem.eql(u8, log_scope, scope_name)) - break true; - } else false; + // Hide anything more verbose than warn unless it was added with `-Dlog=foo`. + if (@enumToInt(level) > @enumToInt(std.log.level) or + @enumToInt(level) > @enumToInt(std.log.Level.warn)) + { + const scope_name = @tagName(scope); + const ok = comptime for (build_options.log_scopes) |log_scope| { + if (mem.eql(u8, log_scope, scope_name)) + break true; + } else false; - if (!ok) - return; + if (!ok) + return; + } const prefix = "[" ++ @tagName(level) ++ "] " ++ "(" ++ @tagName(scope) ++ "): ";