authorgravatar for andrew@ziglang.orgAndrew Kelley <andrew@ziglang.org> 2020-08-10 19:34:27-07:00
committergravatar for andrew@ziglang.orgAndrew Kelley <andrew@ziglang.org> 2020-08-11 02:01:32-04:00
log20510d209be44590f390c370f9e477d84ab46454
treed8d9cae0a71467a27d54292b1cfbb4aabfd094b4
parent900a897e90eca08f78ef632fd11e01ec9bcb3674

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.

4 files changed, 84 insertions(+), 37 deletions(-)

lib/std/builtin.zig+19
......@@ -52,6 +52,25 @@ pub const subsystem: ?SubSystem = blk: {
5252pub const StackTrace = struct {
5353 index: usize,
5454 instruction_addresses: []usize,
55
56 pub fn format(
57 self: StackTrace,
58 comptime fmt: []const u8,
59 options: std.fmt.FormatOptions,
60 writer: anytype,
61 ) !void {
62 var arena = std.heap.ArenaAllocator.init(std.heap.page_allocator);
63 defer arena.deinit();
64 const debug_info = std.debug.getSelfDebugInfo() catch |err| {
65 return writer.print("\nUnable to print stack trace: Unable to open debug info: {}\n", .{@errorName(err)});
66 };
67 const tty_config = std.debug.detectTTYConfig();
68 try writer.writeAll("\n");
69 std.debug.writeStackTrace(self, writer, &arena.allocator, debug_info, tty_config) catch |err| {
70 try writer.print("Unable to print stack trace: {}\n", .{@errorName(err)});
71 };
72 try writer.writeAll("\n");
73 }
5574};
5675
5776/// This data structure is used by the Zig language code generation and
lib/std/heap/general_purpose_allocator.zig+42-26
......@@ -4,12 +4,12 @@
44//!
55//! ### `OptimizationMode.debug` and `OptimizationMode.release_safe`:
66//!
7//! * Detect double free, and print stack trace of:
7//! * Detect double free, and emit stack trace of:
88//! - Where it was first allocated
99//! - Where it was freed the first time
1010//! - Where it was freed the second time
1111//!
12//! * Detect leaks and print stack trace of:
12//! * Detect leaks and emit stack trace of:
1313//! - Where it was allocated
1414//!
1515//! * 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 {
178178 stack_addresses: [stack_n]usize,
179179
180180 fn dumpStackTrace(self: *LargeAlloc) void {
181 std.debug.dumpStackTrace(self.getStackTrace());
182 }
183
184 fn getStackTrace(self: *LargeAlloc) std.builtin.StackTrace {
181185 var len: usize = 0;
182186 while (len < stack_n and self.stack_addresses[len] != 0) {
183187 len += 1;
184188 }
185 const stack_trace = StackTrace{
189 return .{
186190 .instruction_addresses = &self.stack_addresses,
187191 .index = len,
188192 };
189 std.debug.dumpStackTrace(stack_trace);
190193 }
191194 };
192195 const LargeAllocTable = std.AutoHashMapUnmanaged(usize, LargeAlloc);
......@@ -282,15 +285,9 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type {
282285 while (true) : (bit_index += 1) {
283286 const is_used = @truncate(u1, used_byte >> bit_index) != 0;
284287 if (is_used) {
285 std.debug.print("\nMemory leak detected:\n", .{});
286288 const slot_index = @intCast(SlotIndex, used_bits_byte * 8 + bit_index);
287 const stack_trace = bucketStackTrace(
288 bucket,
289 size_class,
290 slot_index,
291 .alloc,
292 );
293 std.debug.dumpStackTrace(stack_trace);
289 const stack_trace = bucketStackTrace(bucket, size_class, slot_index, .alloc);
290 std.log.err(.std, "Memory leak detected: {}", .{stack_trace});
294291 leaks = true;
295292 }
296293 if (bit_index == math.maxInt(u3))
......@@ -301,8 +298,8 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type {
301298 return leaks;
302299 }
303300
304 /// Returns whether there were leaks.
305 pub fn deinit(self: *Self) bool {
301 /// Emits log messages for leaks and then returns whether there were any leaks.
302 pub fn detectLeaks(self: *Self) bool {
306303 var leaks = false;
307304 for (self.buckets) |optional_bucket, bucket_i| {
308305 const first_bucket = optional_bucket orelse continue;
......@@ -317,10 +314,14 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type {
317314 }
318315 }
319316 for (self.large_allocations.items()) |*large_alloc| {
320 std.debug.print("\nMemory leak detected (0x{x}):\n", .{@ptrToInt(large_alloc.value.bytes.ptr)});
321 large_alloc.value.dumpStackTrace();
317 std.log.err(.std, "Memory leak detected: {}", .{large_alloc.value.getStackTrace()});
322318 leaks = true;
323319 }
320 return leaks;
321 }
322
323 pub fn deinit(self: *Self) bool {
324 const leaks = if (config.safety) self.detectLeaks() else false;
324325 self.large_allocations.deinit(self.backing_allocator);
325326 self.* = undefined;
326327 return leaks;
......@@ -442,13 +443,18 @@ pub fn GeneralPurposeAllocator(comptime config: Config) type {
442443 };
443444
444445 if (config.safety and old_mem.len != entry.value.bytes.len) {
445 std.debug.print("\nAllocation size {} bytes does not match free size {}. Allocated here:\n", .{
446 var addresses: [stack_n]usize = [1]usize{0} ** stack_n;
447 var free_stack_trace = StackTrace{
448 .instruction_addresses = &addresses,
449 .index = 0,
450 };
451 std.debug.captureStackTrace(ret_addr, &free_stack_trace);
452 std.log.err(.std, "Allocation size {} bytes does not match free size {}. Allocation: {} Free: {}", .{
446453 entry.value.bytes.len,
447454 old_mem.len,
455 entry.value.getStackTrace(),
456 free_stack_trace,
448457 });
449 entry.value.dumpStackTrace();
450
451 @panic("\nFree here:");
452458 }
453459
454460 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 {
518524 const is_used = @truncate(u1, used_byte.* >> used_bit_index) != 0;
519525 if (!is_used) {
520526 if (config.safety) {
521 // print allocation stack trace
522 std.debug.print("\nDouble free detected, allocated here:\n", .{});
523527 const alloc_stack_trace = bucketStackTrace(bucket, size_class, slot_index, .alloc);
524 std.debug.dumpStackTrace(alloc_stack_trace);
525 std.debug.print("\nFirst free here:\n", .{});
526528 const free_stack_trace = bucketStackTrace(bucket, size_class, slot_index, .free);
527 std.debug.dumpStackTrace(free_stack_trace);
528 @panic("\nSecond free here:");
529 var addresses: [stack_n]usize = [1]usize{0} ** stack_n;
530 var second_free_stack_trace = StackTrace{
531 .instruction_addresses = &addresses,
532 .index = 0,
533 };
534 std.debug.captureStackTrace(ret_addr, &second_free_stack_trace);
535 std.log.err(.std, "Double free detected. Allocation: {} First free: {} Second free: {}", .{
536 alloc_stack_trace,
537 free_stack_trace,
538 second_free_stack_trace,
539 });
540 if (new_size == 0) {
541 // Recoverable.
542 return @as(usize, 0);
543 }
544 @panic("Unrecoverable double free");
529545 } else {
530546 unreachable;
531547 }
lib/std/special/test_runner.zig+11-1
......@@ -4,6 +4,8 @@ const builtin = @import("builtin");
44
55pub const io_mode: io.Mode = builtin.test_io_mode;
66
7var log_err_count: usize = 0;
8
79pub fn main() anyerror!void {
810 const test_fn_list = builtin.test_functions;
911 var ok_count: usize = 0;
......@@ -75,8 +77,13 @@ pub fn main() anyerror!void {
7577 } else {
7678 std.debug.print("{} passed; {} skipped.\n", .{ ok_count, skip_count });
7779 }
80 if (log_err_count != 0) {
81 std.debug.print("{} errors were logged.\n", .{log_err_count});
82 }
7883 if (leaks != 0) {
79 std.debug.print("{} tests leaked memory\n", .{ok_count});
84 std.debug.print("{} tests leaked memory.\n", .{ok_count});
85 }
86 if (leaks != 0 or log_err_count != 0) {
8087 std.process.exit(1);
8188 }
8289}
......@@ -87,6 +94,9 @@ pub fn log(
8794 comptime format: []const u8,
8895 args: anytype,
8996) void {
97 if (@enumToInt(message_level) <= @enumToInt(std.log.Level.err)) {
98 log_err_count += 1;
99 }
90100 if (@enumToInt(message_level) <= @enumToInt(std.testing.log_level)) {
91101 std.debug.print("[{}] ({}): " ++ format, .{ @tagName(scope), @tagName(message_level) } ++ args);
92102 }
src-self-hosted/main.zig+12-10
......@@ -42,17 +42,19 @@ pub fn log(
4242 comptime format: []const u8,
4343 args: anytype,
4444) void {
45 if (@enumToInt(level) > @enumToInt(std.log.level))
46 return;
47
48 const scope_name = @tagName(scope);
49 const ok = comptime for (build_options.log_scopes) |log_scope| {
50 if (mem.eql(u8, log_scope, scope_name))
51 break true;
52 } else false;
45 // Hide anything more verbose than warn unless it was added with `-Dlog=foo`.
46 if (@enumToInt(level) > @enumToInt(std.log.level) or
47 @enumToInt(level) > @enumToInt(std.log.Level.warn))
48 {
49 const scope_name = @tagName(scope);
50 const ok = comptime for (build_options.log_scopes) |log_scope| {
51 if (mem.eql(u8, log_scope, scope_name))
52 break true;
53 } else false;
5354
54 if (!ok)
55 return;
55 if (!ok)
56 return;
57 }
5658
5759 const prefix = "[" ++ @tagName(level) ++ "] " ++ "(" ++ @tagName(scope) ++ "): ";
5860