compiler: integrate @compileLog with incremental compilation

Compile log output is now separated based on the `AnalUnit` which
perfomred the `@compileLog` call, so that we can omit the output for
unreferenced ("dead") units. The units are also sorted when collecting
the `ErrorBundle`, so that compile logs are always printed in a
consistent order, like compile errors are. This is important not only
for incremental compilation, but also for parallel analysis.

Resolves: #23609
This commit is contained in:
mlugg 2025-04-20 03:43:02 +01:00
parent 6561a98a61
commit 8c9c24e09b
No known key found for this signature in database
GPG key ID: 3F5B7DCCBF4AF02E
7 changed files with 272 additions and 64 deletions

View file

@ -2262,8 +2262,6 @@ pub fn update(comp: *Compilation, main_progress_node: std.Progress.Node) !void {
const pt: Zcu.PerThread = .activate(zcu, .main);
defer pt.deactivate();
zcu.compile_log_text.shrinkAndFree(gpa, 0);
zcu.skip_analysis_this_update = false;
// Make sure std.zig is inside the import_table. We unconditionally need
@ -3323,30 +3321,15 @@ pub fn getAllErrorsAlloc(comp: *Compilation) !ErrorBundle {
err: *?Error,
const Error = @typeInfo(
@typeInfo(@TypeOf(Zcu.SrcLoc.span)).@"fn".return_type.?,
@typeInfo(@TypeOf(Zcu.LazySrcLoc.lessThan)).@"fn".return_type.?,
).error_union.error_set;
pub fn lessThan(ctx: @This(), lhs_index: usize, rhs_index: usize) bool {
if (ctx.err.*) |_| return lhs_index < rhs_index;
const lhs_src_loc = ctx.errors[lhs_index].src_loc.upgradeOrLost(ctx.zcu) orelse {
// LHS source location lost, so should never be referenced. Just sort it to the end.
return false;
};
const rhs_src_loc = ctx.errors[rhs_index].src_loc.upgradeOrLost(ctx.zcu) orelse {
// RHS source location lost, so should never be referenced. Just sort it to the end.
return true;
};
return if (lhs_src_loc.file_scope != rhs_src_loc.file_scope) std.mem.order(
u8,
lhs_src_loc.file_scope.sub_file_path,
rhs_src_loc.file_scope.sub_file_path,
).compare(.lt) else (lhs_src_loc.span(ctx.zcu.gpa) catch |e| {
if (ctx.err.* != null) return lhs_index < rhs_index;
return ctx.errors[lhs_index].src_loc.lessThan(ctx.errors[rhs_index].src_loc, ctx.zcu) catch |e| {
ctx.err.* = e;
return lhs_index < rhs_index;
}).main < (rhs_src_loc.span(ctx.zcu.gpa) catch |e| {
ctx.err.* = e;
return lhs_index < rhs_index;
}).main;
};
}
};
@ -3450,28 +3433,76 @@ pub fn getAllErrorsAlloc(comp: *Compilation) !ErrorBundle {
try comp.link_diags.addMessagesToBundle(&bundle, comp.bin_file);
if (comp.zcu) |zcu| {
if (!zcu.skip_analysis_this_update and bundle.root_list.items.len == 0 and zcu.compile_log_sources.count() != 0) {
const values = zcu.compile_log_sources.values();
// First one will be the error; subsequent ones will be notes.
const src_loc = values[0].src();
const err_msg: Zcu.ErrorMsg = .{
.src_loc = src_loc,
.msg = "found compile log statement",
.notes = try gpa.alloc(Zcu.ErrorMsg, zcu.compile_log_sources.count() - 1),
};
defer gpa.free(err_msg.notes);
const compile_log_text: []const u8 = compile_log_text: {
const zcu = comp.zcu orelse break :compile_log_text "";
if (zcu.skip_analysis_this_update) break :compile_log_text "";
if (zcu.compile_logs.count() == 0) break :compile_log_text "";
for (values[1..], err_msg.notes) |src_info, *note| {
note.* = .{
.src_loc = src_info.src(),
.msg = "also here",
// If there are no other errors, we include a "found compile log statement" error.
// Otherwise, we just show the compile log output, with no error.
const include_compile_log_sources = bundle.root_list.items.len == 0;
const refs = try zcu.resolveReferences();
var messages: std.ArrayListUnmanaged(Zcu.ErrorMsg) = .empty;
defer messages.deinit(gpa);
for (zcu.compile_logs.keys(), zcu.compile_logs.values()) |logging_unit, compile_log| {
if (!refs.contains(logging_unit)) continue;
try messages.append(gpa, .{
.src_loc = compile_log.src(),
.msg = undefined, // populated later
.notes = &.{},
// We actually clear this later for most of these, but we populate
// this field for now to avoid having to allocate more data to track
// which compile log text this corresponds to.
.reference_trace_root = logging_unit.toOptional(),
});
}
if (messages.items.len == 0) break :compile_log_text "";
// Okay, there *are* referenced compile logs. Sort them into a consistent order.
const SortContext = struct {
err: *?Error,
zcu: *Zcu,
const Error = @typeInfo(
@typeInfo(@TypeOf(Zcu.LazySrcLoc.lessThan)).@"fn".return_type.?,
).error_union.error_set;
fn lessThan(ctx: @This(), lhs: Zcu.ErrorMsg, rhs: Zcu.ErrorMsg) bool {
if (ctx.err.* != null) return false;
return lhs.src_loc.lessThan(rhs.src_loc, ctx.zcu) catch |e| {
ctx.err.* = e;
return false;
};
}
};
var sort_err: ?SortContext.Error = null;
std.mem.sort(Zcu.ErrorMsg, messages.items, @as(SortContext, .{ .err = &sort_err, .zcu = zcu }), SortContext.lessThan);
if (sort_err) |e| return e;
try addModuleErrorMsg(zcu, &bundle, err_msg);
var log_text: std.ArrayListUnmanaged(u8) = .empty;
defer log_text.deinit(gpa);
// Index 0 will be the root message; the rest will be notes.
// Only the actual message, i.e. index 0, will retain its reference trace.
try appendCompileLogLines(&log_text, zcu, messages.items[0].reference_trace_root.unwrap().?);
messages.items[0].notes = messages.items[1..];
messages.items[0].msg = "found compile log statement";
for (messages.items[1..]) |*note| {
try appendCompileLogLines(&log_text, zcu, note.reference_trace_root.unwrap().?);
note.reference_trace_root = .none; // notes don't have reference traces
note.msg = "also here";
}
}
// We don't actually include the error here if `!include_compile_log_sources`.
// The sorting above was still necessary, though, to get `log_text` in the right order.
if (include_compile_log_sources) {
try addModuleErrorMsg(zcu, &bundle, messages.items[0]);
}
break :compile_log_text try log_text.toOwnedSlice(gpa);
};
// TODO: eventually, this should be behind `std.debug.runtime_safety`. But right now, this is a
// very common way for incremental compilation bugs to manifest, so let's always check it.
@ -3497,10 +3528,24 @@ pub fn getAllErrorsAlloc(comp: *Compilation) !ErrorBundle {
}
};
const compile_log_text = if (comp.zcu) |m| m.compile_log_text.items else "";
return bundle.toOwnedBundle(compile_log_text);
}
/// Writes all compile log lines belonging to `logging_unit` into `log_text` using `zcu.gpa`.
fn appendCompileLogLines(log_text: *std.ArrayListUnmanaged(u8), zcu: *Zcu, logging_unit: InternPool.AnalUnit) Allocator.Error!void {
const gpa = zcu.gpa;
const ip = &zcu.intern_pool;
var opt_line_idx = zcu.compile_logs.get(logging_unit).?.first_line.toOptional();
while (opt_line_idx.unwrap()) |line_idx| {
const line = line_idx.get(zcu).*;
opt_line_idx = line.next;
const line_slice = line.data.toSlice(ip);
try log_text.ensureUnusedCapacity(gpa, line_slice.len + 1);
log_text.appendSliceAssumeCapacity(line_slice);
log_text.appendAssumeCapacity('\n');
}
}
fn anyErrors(comp: *Compilation) bool {
return (totalErrorCount(comp) catch return true) != 0;
}

View file

@ -5884,10 +5884,12 @@ fn zirCompileLog(
) CompileError!Air.Inst.Ref {
const pt = sema.pt;
const zcu = pt.zcu;
const gpa = zcu.gpa;
var managed = zcu.compile_log_text.toManaged(sema.gpa);
defer pt.zcu.compile_log_text = managed.moveToUnmanaged();
const writer = managed.writer();
var buf: std.ArrayListUnmanaged(u8) = .empty;
defer buf.deinit(gpa);
const writer = buf.writer(gpa);
const extra = sema.code.extraData(Zir.Inst.NodeMultiOp, extended.operand);
const src_node = extra.data.src_node;
@ -5906,13 +5908,37 @@ fn zirCompileLog(
try writer.print("@as({}, [runtime value])", .{arg_ty.fmt(pt)});
}
}
try writer.print("\n", .{});
const gop = try zcu.compile_log_sources.getOrPut(sema.gpa, sema.owner);
if (!gop.found_existing) gop.value_ptr.* = .{
.base_node_inst = block.src_base_inst,
.node_offset = src_node,
const line_data = try zcu.intern_pool.getOrPutString(gpa, pt.tid, buf.items, .no_embedded_nulls);
const line_idx: Zcu.CompileLogLine.Index = if (zcu.free_compile_log_lines.pop()) |idx| idx: {
zcu.compile_log_lines.items[@intFromEnum(idx)] = .{
.next = .none,
.data = line_data,
};
break :idx idx;
} else idx: {
try zcu.compile_log_lines.append(gpa, .{
.next = .none,
.data = line_data,
});
break :idx @enumFromInt(zcu.compile_log_lines.items.len - 1);
};
const gop = try zcu.compile_logs.getOrPut(gpa, sema.owner);
if (gop.found_existing) {
const prev_line = gop.value_ptr.last_line.get(zcu);
assert(prev_line.next == .none);
prev_line.next = line_idx.toOptional();
gop.value_ptr.last_line = line_idx;
} else {
gop.value_ptr.* = .{
.base_node_inst = block.src_base_inst,
.node_offset = src_node,
.first_line = line_idx,
.last_line = line_idx,
};
}
return .void_value;
}

View file

@ -130,18 +130,23 @@ transitive_failed_analysis: std.AutoArrayHashMapUnmanaged(AnalUnit, void) = .emp
/// The ErrorMsg memory is owned by the `AnalUnit`, using Module's general purpose allocator.
failed_codegen: std.AutoArrayHashMapUnmanaged(InternPool.Nav.Index, *ErrorMsg) = .empty,
failed_types: std.AutoArrayHashMapUnmanaged(InternPool.Index, *ErrorMsg) = .empty,
/// Keep track of one `@compileLog` callsite per `AnalUnit`.
/// The value is the source location of the `@compileLog` call, convertible to a `LazySrcLoc`.
compile_log_sources: std.AutoArrayHashMapUnmanaged(AnalUnit, extern struct {
/// Keep track of `@compileLog`s per `AnalUnit`.
/// We track the source location of the first `@compileLog` call, and all logged lines as a linked list.
/// The list is singly linked, but we do track its tail for fast appends (optimizing many logs in one unit).
compile_logs: std.AutoArrayHashMapUnmanaged(AnalUnit, extern struct {
base_node_inst: InternPool.TrackedInst.Index,
node_offset: Ast.Node.Offset,
first_line: CompileLogLine.Index,
last_line: CompileLogLine.Index,
pub fn src(self: @This()) LazySrcLoc {
return .{
.base_node_inst = self.base_node_inst,
.offset = LazySrcLoc.Offset.nodeOffset(self.node_offset),
};
}
}) = .{},
}) = .empty,
compile_log_lines: std.ArrayListUnmanaged(CompileLogLine) = .empty,
free_compile_log_lines: std.ArrayListUnmanaged(CompileLogLine.Index) = .empty,
/// Using a map here for consistency with the other fields here.
/// The ErrorMsg memory is owned by the `File`, using Module's general purpose allocator.
failed_files: std.AutoArrayHashMapUnmanaged(*File, ?*ErrorMsg) = .empty,
@ -196,8 +201,6 @@ stage1_flags: packed struct {
reserved: u2 = 0,
} = .{},
compile_log_text: std.ArrayListUnmanaged(u8) = .empty,
test_functions: std.AutoArrayHashMapUnmanaged(InternPool.Nav.Index, void) = .empty,
global_assembly: std.AutoArrayHashMapUnmanaged(AnalUnit, []u8) = .empty,
@ -547,6 +550,31 @@ pub const Export = struct {
};
};
pub const CompileLogLine = struct {
next: Index.Optional,
/// Does *not* include the trailing newline.
data: InternPool.NullTerminatedString,
pub const Index = enum(u32) {
_,
pub fn get(idx: Index, zcu: *Zcu) *CompileLogLine {
return &zcu.compile_log_lines.items[@intFromEnum(idx)];
}
pub fn toOptional(idx: Index) Optional {
return @enumFromInt(@intFromEnum(idx));
}
pub const Optional = enum(u32) {
none = std.math.maxInt(u32),
_,
pub fn unwrap(opt: Optional) ?Index {
return switch (opt) {
.none => null,
_ => @enumFromInt(@intFromEnum(opt)),
};
}
};
};
};
pub const Reference = struct {
/// The `AnalUnit` whose semantic analysis was triggered by this reference.
referenced: AnalUnit,
@ -2464,6 +2492,30 @@ pub const LazySrcLoc = struct {
.lazy = lazy.offset,
};
}
/// Used to sort error messages, so that they're printed in a consistent order.
/// If an error is returned, that error makes sorting impossible.
pub fn lessThan(lhs_lazy: LazySrcLoc, rhs_lazy: LazySrcLoc, zcu: *Zcu) !bool {
const lhs_src = lhs_lazy.upgradeOrLost(zcu) orelse {
// LHS source location lost, so should never be referenced. Just sort it to the end.
return false;
};
const rhs_src = rhs_lazy.upgradeOrLost(zcu) orelse {
// RHS source location lost, so should never be referenced. Just sort it to the end.
return true;
};
if (lhs_src.file_scope != rhs_src.file_scope) {
return std.mem.order(
u8,
lhs_src.file_scope.sub_file_path,
rhs_src.file_scope.sub_file_path,
).compare(.lt);
}
const lhs_span = try lhs_src.span(zcu.gpa);
const rhs_span = try rhs_src.span(zcu.gpa);
return lhs_span.main < rhs_span.main;
}
};
pub const SemaError = error{ OutOfMemory, AnalysisFail };
@ -2506,8 +2558,6 @@ pub fn deinit(zcu: *Zcu) void {
}
zcu.embed_table.deinit(gpa);
zcu.compile_log_text.deinit(gpa);
zcu.local_zir_cache.handle.close();
zcu.global_zir_cache.handle.close();
@ -2535,7 +2585,9 @@ pub fn deinit(zcu: *Zcu) void {
}
zcu.cimport_errors.deinit(gpa);
zcu.compile_log_sources.deinit(gpa);
zcu.compile_logs.deinit(gpa);
zcu.compile_log_lines.deinit(gpa);
zcu.free_compile_log_lines.deinit(gpa);
zcu.all_exports.deinit(gpa);
zcu.free_exports.deinit(gpa);
@ -3412,6 +3464,22 @@ pub fn deleteUnitReferences(zcu: *Zcu, anal_unit: AnalUnit) void {
}
}
/// Delete all compile logs performed by this `AnalUnit`.
/// Re-analysis of the `AnalUnit` will cause logs to be rediscovered.
pub fn deleteUnitCompileLogs(zcu: *Zcu, anal_unit: AnalUnit) void {
const kv = zcu.compile_logs.fetchSwapRemove(anal_unit) orelse return;
const gpa = zcu.gpa;
var opt_line_idx = kv.value.first_line.toOptional();
while (opt_line_idx.unwrap()) |line_idx| {
zcu.free_compile_log_lines.append(gpa, line_idx) catch {
// This space will be reused eventually, so we need not propagate this error.
// Just leak it for now, and let GC reclaim it later on.
return;
};
opt_line_idx = line_idx.get(zcu).next;
}
}
pub fn addUnitReference(zcu: *Zcu, src_unit: AnalUnit, referenced_unit: AnalUnit, ref_src: LazySrcLoc) Allocator.Error!void {
const gpa = zcu.gpa;

View file

@ -599,6 +599,7 @@ pub fn ensureMemoizedStateUpToDate(pt: Zcu.PerThread, stage: InternPool.Memoized
_ = zcu.outdated_ready.swapRemove(unit);
// No need for `deleteUnitExports` because we never export anything.
zcu.deleteUnitReferences(unit);
zcu.deleteUnitCompileLogs(unit);
if (zcu.failed_analysis.fetchSwapRemove(unit)) |kv| {
kv.value.destroy(gpa);
}
@ -749,6 +750,7 @@ pub fn ensureComptimeUnitUpToDate(pt: Zcu.PerThread, cu_id: InternPool.ComptimeU
if (dev.env.supports(.incremental)) {
zcu.deleteUnitExports(anal_unit);
zcu.deleteUnitReferences(anal_unit);
zcu.deleteUnitCompileLogs(anal_unit);
if (zcu.failed_analysis.fetchSwapRemove(anal_unit)) |kv| {
kv.value.destroy(gpa);
}
@ -921,6 +923,7 @@ pub fn ensureNavValUpToDate(pt: Zcu.PerThread, nav_id: InternPool.Nav.Index) Zcu
_ = zcu.outdated_ready.swapRemove(anal_unit);
zcu.deleteUnitExports(anal_unit);
zcu.deleteUnitReferences(anal_unit);
zcu.deleteUnitCompileLogs(anal_unit);
if (zcu.failed_analysis.fetchSwapRemove(anal_unit)) |kv| {
kv.value.destroy(gpa);
}
@ -1293,6 +1296,7 @@ pub fn ensureNavTypeUpToDate(pt: Zcu.PerThread, nav_id: InternPool.Nav.Index) Zc
_ = zcu.outdated_ready.swapRemove(anal_unit);
zcu.deleteUnitExports(anal_unit);
zcu.deleteUnitReferences(anal_unit);
zcu.deleteUnitCompileLogs(anal_unit);
if (zcu.failed_analysis.fetchSwapRemove(anal_unit)) |kv| {
kv.value.destroy(gpa);
}
@ -1527,6 +1531,7 @@ pub fn ensureFuncBodyUpToDate(pt: Zcu.PerThread, maybe_coerced_func_index: Inter
_ = zcu.outdated_ready.swapRemove(anal_unit);
zcu.deleteUnitExports(anal_unit);
zcu.deleteUnitReferences(anal_unit);
zcu.deleteUnitCompileLogs(anal_unit);
if (zcu.failed_analysis.fetchSwapRemove(anal_unit)) |kv| {
kv.value.destroy(gpa);
}
@ -3764,6 +3769,7 @@ pub fn ensureTypeUpToDate(pt: Zcu.PerThread, ty: InternPool.Index) Zcu.SemaError
// reusing the memory which is currently being used to track this state.
zcu.deleteUnitExports(anal_unit);
zcu.deleteUnitReferences(anal_unit);
zcu.deleteUnitCompileLogs(anal_unit);
if (zcu.failed_analysis.fetchSwapRemove(anal_unit)) |kv| {
kv.value.destroy(gpa);
}

View file

@ -12,6 +12,7 @@ comptime {
@compileLog("this is a log");
}
#expect_error=main.zig:3:5: error: this is an error
#expect_compile_log=@as(*const [13:0]u8, "this is a log")
#update=remove the compile error
#file=main.zig
@ -23,3 +24,4 @@ comptime {
@compileLog("this is a log");
}
#expect_error=main.zig:6:5: error: found compile log statement
#expect_compile_log=@as(*const [13:0]u8, "this is a log")

View file

@ -0,0 +1,30 @@
#target=x86_64-linux-selfhosted
#target=x86_64-linux-cbe
#target=x86_64-windows-cbe
#target=wasm32-wasi-selfhosted
#update=initial version with no compile log
#file=main.zig
const std = @import("std");
pub fn main() !void {
try std.io.getStdOut().writeAll("Hello, World!\n");
}
#expect_stdout="Hello, World!\n"
#update=add compile log
#file=main.zig
const std = @import("std");
pub fn main() !void {
try std.io.getStdOut().writeAll("Hello, World!\n");
@compileLog("this is a log");
}
#expect_error=main.zig:4:5: error: found compile log statement
#expect_compile_log=@as(*const [13:0]u8, "this is a log")
#update=remove compile log
#file=main.zig
const std = @import("std");
pub fn main() !void {
try std.io.getStdOut().writeAll("Hello, World!\n");
}
#expect_stdout="Hello, World!\n"

View file

@ -341,9 +341,9 @@ const Eval = struct {
}
fn checkErrorOutcome(eval: *Eval, update: Case.Update, error_bundle: std.zig.ErrorBundle) !void {
const expected_errors = switch (update.outcome) {
const expected = switch (update.outcome) {
.unknown => return,
.compile_errors => |expected_errors| expected_errors,
.compile_errors => |ce| ce,
.stdout, .exit_code => {
const color: std.zig.Color = .auto;
error_bundle.renderToStdErr(color.renderOptions());
@ -354,24 +354,30 @@ const Eval = struct {
var expected_idx: usize = 0;
for (error_bundle.getMessages()) |err_idx| {
if (expected_idx == expected_errors.len) {
if (expected_idx == expected.errors.len) {
const color: std.zig.Color = .auto;
error_bundle.renderToStdErr(color.renderOptions());
eval.fatal("update '{s}': more errors than expected", .{update.name});
}
eval.checkOneError(update, error_bundle, expected_errors[expected_idx], false, err_idx);
eval.checkOneError(update, error_bundle, expected.errors[expected_idx], false, err_idx);
expected_idx += 1;
for (error_bundle.getNotes(err_idx)) |note_idx| {
if (expected_idx == expected_errors.len) {
if (expected_idx == expected.errors.len) {
const color: std.zig.Color = .auto;
error_bundle.renderToStdErr(color.renderOptions());
eval.fatal("update '{s}': more error notes than expected", .{update.name});
}
eval.checkOneError(update, error_bundle, expected_errors[expected_idx], true, note_idx);
eval.checkOneError(update, error_bundle, expected.errors[expected_idx], true, note_idx);
expected_idx += 1;
}
}
if (!std.mem.eql(u8, error_bundle.getCompileLogOutput(), expected.compile_log_output)) {
const color: std.zig.Color = .auto;
error_bundle.renderToStdErr(color.renderOptions());
eval.fatal("update '{s}': unexpected compile log output", .{update.name});
}
}
fn checkOneError(
@ -634,7 +640,10 @@ const Case = struct {
const Outcome = union(enum) {
unknown,
compile_errors: []const ExpectedError,
compile_errors: struct {
errors: []const ExpectedError,
compile_log_output: []const u8,
},
stdout: []const u8,
exit_code: u8,
};
@ -759,7 +768,29 @@ const Case = struct {
try errors.append(arena, parseExpectedError(new_val, line_n));
}
last_update.outcome = .{ .compile_errors = errors.items };
var compile_log_output: std.ArrayListUnmanaged(u8) = .empty;
while (true) {
const next_line = it.peek() orelse break;
if (!std.mem.startsWith(u8, next_line, "#")) break;
var new_line_it = std.mem.splitScalar(u8, next_line, '=');
const new_key = new_line_it.first()[1..];
const new_val = std.mem.trimRight(u8, new_line_it.rest(), "\r");
if (new_val.len == 0) break;
if (!std.mem.eql(u8, new_key, "expect_compile_log")) break;
_ = it.next();
line_n += 1;
try compile_log_output.ensureUnusedCapacity(arena, new_val.len + 1);
compile_log_output.appendSliceAssumeCapacity(new_val);
compile_log_output.appendAssumeCapacity('\n');
}
last_update.outcome = .{ .compile_errors = .{
.errors = errors.items,
.compile_log_output = compile_log_output.items,
} };
} else if (std.mem.eql(u8, key, "expect_compile_log")) {
fatal("line {d}: 'expect_compile_log' must immediately follow 'expect_error'", .{line_n});
} else {
fatal("line {d}: unrecognized key '{s}'", .{ line_n, key });
}