Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GeneralPurposeAllocator: use std.log instead of std.debug.print #6012

Merged
merged 1 commit into from
Aug 11, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 19 additions & 0 deletions lib/std/builtin.zig
Original file line number Diff line number Diff line change
Expand Up @@ -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| {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Previously there wasn't anything about this structure that indicated it was a StackTrace for the current process (as opposed to a child process or something else).
Perhaps there should be an enum { CurrentProcess, OtherProcess }?

Alternatively, maybe we could save the buildid? Related: #3047

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does debug_info need to be freed?

return writer.print("\nUnable to print stack trace: Unable to open debug info: {}\n", .{@errorName(err)});
};
const tty_config = std.debug.detectTTYConfig();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Who says that this is being sent to a TTY? what if its being logged to a file? or syslog?

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
Expand Down
68 changes: 42 additions & 26 deletions lib/std/heap/general_purpose_allocator.zig
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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))
Expand All @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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;
}
Expand Down
12 changes: 11 additions & 1 deletion lib/std/special/test_runner.zig
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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);
}
Expand Down
22 changes: 12 additions & 10 deletions src-self-hosted/main.zig
Original file line number Diff line number Diff line change
Expand Up @@ -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) ++ "): ";

Expand Down