authorgravatar for justus@klausecker.deJustus Klausecker <justus@klausecker.de> 2026-01-07 17:07:24+01:00
committergravatar for mlugg@mlugg.co.ukMatthew Lugg <mlugg@mlugg.co.uk> 2026-01-11 11:37:16+00:00
log00d4f3c00188e2b1fcb2669ba6346831787828c2
tree31c34b87c7f22753c6d20929d4eb029a70791721
parent42dea36ce91db4d79711a8005ae9124bfb1364b3
signaturelock-open Commit is signed but in an unrecognized format.

Liveness: improve logging

2 files changed, 43 insertions(+), 35 deletions(-)

src/Air/Liveness.zig+27-24
...@@ -176,7 +176,10 @@ pub fn analyze(zcu: *Zcu, air: Air, intern_pool: *InternPool) Allocator.Error!Li...@@ -176,7 +176,10 @@ pub fn analyze(zcu: *Zcu, air: Air, intern_pool: *InternPool) Allocator.Error!Li
176 data.old_extra = a.extra;176 data.old_extra = a.extra;
177 a.extra = .{};177 a.extra = .{};
178 try analyzeBody(&a, .main_analysis, &data, main_body);178 try analyzeBody(&a, .main_analysis, &data, main_body);
179 assert(data.live_set.count() == 0);179 if (std.debug.runtime_safety and data.live_set.count() != 0) {
180 log.debug("instructions still in live set after analysis: {f}", .{fmtInstSet(&data.live_set)});
181 @panic("liveness analysis failed");
182 }
180 }183 }
181184
182 return .{185 return .{
...@@ -825,10 +828,10 @@ fn analyzeOperands(...@@ -825,10 +828,10 @@ fn analyzeOperands(
825828
826 // This logic must synchronize with `will_die_immediately` in `AnalyzeBigOperands.init`.829 // This logic must synchronize with `will_die_immediately` in `AnalyzeBigOperands.init`.
827 const immediate_death = if (data.live_set.remove(inst)) blk: {830 const immediate_death = if (data.live_set.remove(inst)) blk: {
828 log.debug("[{}] %{d}: removed from live set", .{ pass, @intFromEnum(inst) });831 log.debug("[{t}] {f}: removed from live set", .{ pass, inst });
829 break :blk false;832 break :blk false;
830 } else blk: {833 } else blk: {
831 log.debug("[{}] %{d}: immediate death", .{ pass, @intFromEnum(inst) });834 log.debug("[{t}] {f}: immediate death", .{ pass, inst });
832 break :blk true;835 break :blk true;
833 };836 };
834837
...@@ -849,7 +852,7 @@ fn analyzeOperands(...@@ -849,7 +852,7 @@ fn analyzeOperands(
849 const mask = @as(Bpi, 1) << @as(OperandInt, @intCast(i));852 const mask = @as(Bpi, 1) << @as(OperandInt, @intCast(i));
850853
851 if ((try data.live_set.fetchPut(gpa, operand, {})) == null) {854 if ((try data.live_set.fetchPut(gpa, operand, {})) == null) {
852 log.debug("[{}] %{d}: added %{d} to live set (operand dies here)", .{ pass, @intFromEnum(inst), operand });855 log.debug("[{t}] {f}: added {f} to live set (operand dies here)", .{ pass, inst, operand });
853 tomb_bits |= mask;856 tomb_bits |= mask;
854 }857 }
855 }858 }
...@@ -988,19 +991,19 @@ fn analyzeInstBlock(...@@ -988,19 +991,19 @@ fn analyzeInstBlock(
988 },991 },
989992
990 .main_analysis => {993 .main_analysis => {
991 log.debug("[{}] %{f}: block live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });994 log.debug("[{t}] {f}: block live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });
992 // We can move the live set because the body should have a noreturn995 // We can move the live set because the body should have a noreturn
993 // instruction which overrides the set.996 // instruction which overrides the set.
994 try data.block_scopes.put(gpa, inst, .{997 try data.block_scopes.put(gpa, inst, .{
995 .live_set = data.live_set.move(),998 .live_set = data.live_set.move(),
996 });999 });
997 defer {1000 defer {
998 log.debug("[{}] %{f}: popped block scope", .{ pass, inst });1001 log.debug("[{t}] {f}: popped block scope", .{ pass, inst });
999 var scope = data.block_scopes.fetchRemove(inst).?.value;1002 var scope = data.block_scopes.fetchRemove(inst).?.value;
1000 scope.live_set.deinit(gpa);1003 scope.live_set.deinit(gpa);
1001 }1004 }
10021005
1003 log.debug("[{}] %{f}: pushed new block scope", .{ pass, inst });1006 log.debug("[{t}] {f}: pushed new block scope", .{ pass, inst });
1004 try analyzeBody(a, pass, data, body);1007 try analyzeBody(a, pass, data, body);
10051008
1006 // If the block is noreturn, block deaths not only aren't useful, they're impossible to1009 // If the block is noreturn, block deaths not only aren't useful, they're impossible to
...@@ -1027,7 +1030,7 @@ fn analyzeInstBlock(...@@ -1027,7 +1030,7 @@ fn analyzeInstBlock(
1027 }1030 }
1028 assert(measured_num == num_deaths); // post-live-set should be a subset of pre-live-set1031 assert(measured_num == num_deaths); // post-live-set should be a subset of pre-live-set
1029 try a.special.put(gpa, inst, extra_index);1032 try a.special.put(gpa, inst, extra_index);
1030 log.debug("[{}] %{f}: block deaths are {f}", .{1033 log.debug("[{t}] {f}: block deaths are {f}", .{
1031 pass,1034 pass,
1032 inst,1035 inst,
1033 fmtInstList(@ptrCast(a.extra.items[extra_index + 1 ..][0..num_deaths])),1036 fmtInstList(@ptrCast(a.extra.items[extra_index + 1 ..][0..num_deaths])),
...@@ -1064,7 +1067,7 @@ fn writeLoopInfo(...@@ -1064,7 +1067,7 @@ fn writeLoopInfo(
1064 const block_inst = key.*;1067 const block_inst = key.*;
1065 a.extra.appendAssumeCapacity(@intFromEnum(block_inst));1068 a.extra.appendAssumeCapacity(@intFromEnum(block_inst));
1066 }1069 }
1067 log.debug("[{}] %{f}: includes breaks to {f}", .{ LivenessPass.loop_analysis, inst, fmtInstSet(&data.breaks) });1070 log.debug("[{t}] {f}: includes breaks to {f}", .{ LivenessPass.loop_analysis, inst, fmtInstSet(&data.breaks) });
10681071
1069 // Now we put the live operands from the loop body in too1072 // Now we put the live operands from the loop body in too
1070 const num_live = data.live_set.count();1073 const num_live = data.live_set.count();
...@@ -1076,7 +1079,7 @@ fn writeLoopInfo(...@@ -1076,7 +1079,7 @@ fn writeLoopInfo(
1076 const alive = key.*;1079 const alive = key.*;
1077 a.extra.appendAssumeCapacity(@intFromEnum(alive));1080 a.extra.appendAssumeCapacity(@intFromEnum(alive));
1078 }1081 }
1079 log.debug("[{}] %{f}: maintain liveness of {f}", .{ LivenessPass.loop_analysis, inst, fmtInstSet(&data.live_set) });1082 log.debug("[{t}] {f}: maintain liveness of {f}", .{ LivenessPass.loop_analysis, inst, fmtInstSet(&data.live_set) });
10801083
1081 try a.special.put(gpa, inst, extra_index);1084 try a.special.put(gpa, inst, extra_index);
10821085
...@@ -1117,7 +1120,7 @@ fn resolveLoopLiveSet(...@@ -1117,7 +1120,7 @@ fn resolveLoopLiveSet(
1117 try data.live_set.ensureUnusedCapacity(gpa, @intCast(loop_live.len));1120 try data.live_set.ensureUnusedCapacity(gpa, @intCast(loop_live.len));
1118 for (loop_live) |alive| data.live_set.putAssumeCapacity(alive, {});1121 for (loop_live) |alive| data.live_set.putAssumeCapacity(alive, {});
11191122
1120 log.debug("[{}] %{f}: block live set is {f}", .{ LivenessPass.main_analysis, inst, fmtInstSet(&data.live_set) });1123 log.debug("[{t}] {f}: block live set is {f}", .{ LivenessPass.main_analysis, inst, fmtInstSet(&data.live_set) });
11211124
1122 for (breaks) |block_inst| {1125 for (breaks) |block_inst| {
1123 // We might break to this block, so include every operand that the block needs alive1126 // We might break to this block, so include every operand that the block needs alive
...@@ -1130,7 +1133,7 @@ fn resolveLoopLiveSet(...@@ -1130,7 +1133,7 @@ fn resolveLoopLiveSet(
1130 }1133 }
1131 }1134 }
11321135
1133 log.debug("[{}] %{f}: loop live set is {f}", .{ LivenessPass.main_analysis, inst, fmtInstSet(&data.live_set) });1136 log.debug("[{t}] {f}: loop live set is {f}", .{ LivenessPass.main_analysis, inst, fmtInstSet(&data.live_set) });
1134}1137}
11351138
1136fn analyzeInstLoop(1139fn analyzeInstLoop(
...@@ -1168,7 +1171,7 @@ fn analyzeInstLoop(...@@ -1168,7 +1171,7 @@ fn analyzeInstLoop(
1168 .live_set = data.live_set.move(),1171 .live_set = data.live_set.move(),
1169 });1172 });
1170 defer {1173 defer {
1171 log.debug("[{}] %{f}: popped loop block scop", .{ pass, inst });1174 log.debug("[{t}] {f}: popped loop block scop", .{ pass, inst });
1172 var scope = data.block_scopes.fetchRemove(inst).?.value;1175 var scope = data.block_scopes.fetchRemove(inst).?.value;
1173 scope.live_set.deinit(gpa);1176 scope.live_set.deinit(gpa);
1174 }1177 }
...@@ -1269,13 +1272,13 @@ fn analyzeInstCondBr(...@@ -1269,13 +1272,13 @@ fn analyzeInstCondBr(
1269 }1272 }
1270 }1273 }
12711274
1272 log.debug("[{}] %{f}: 'then' branch mirrored deaths are {f}", .{ pass, inst, fmtInstList(then_mirrored_deaths.items) });1275 log.debug("[{t}] {f}: 'then' branch mirrored deaths are {f}", .{ pass, inst, fmtInstList(then_mirrored_deaths.items) });
1273 log.debug("[{}] %{f}: 'else' branch mirrored deaths are {f}", .{ pass, inst, fmtInstList(else_mirrored_deaths.items) });1276 log.debug("[{t}] {f}: 'else' branch mirrored deaths are {f}", .{ pass, inst, fmtInstList(else_mirrored_deaths.items) });
12741277
1275 data.live_set.deinit(gpa);1278 data.live_set.deinit(gpa);
1276 data.live_set = then_live.move(); // Really the union of both live sets1279 data.live_set = then_live.move(); // Really the union of both live sets
12771280
1278 log.debug("[{}] %{f}: new live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });1281 log.debug("[{t}] {f}: new live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });
12791282
1280 // Write the mirrored deaths to `extra`1283 // Write the mirrored deaths to `extra`
1281 const then_death_count = @as(u32, @intCast(then_mirrored_deaths.items.len));1284 const then_death_count = @as(u32, @intCast(then_mirrored_deaths.items.len));
...@@ -1343,7 +1346,7 @@ fn analyzeInstSwitchBr(...@@ -1343,7 +1346,7 @@ fn analyzeInstSwitchBr(
1343 });1346 });
1344 }1347 }
1345 defer if (is_dispatch_loop) {1348 defer if (is_dispatch_loop) {
1346 log.debug("[{}] %{f}: popped loop block scop", .{ pass, inst });1349 log.debug("[{t}] {f}: popped loop block scope", .{ pass, inst });
1347 var scope = data.block_scopes.fetchRemove(inst).?.value;1350 var scope = data.block_scopes.fetchRemove(inst).?.value;
1348 scope.live_set.deinit(gpa);1351 scope.live_set.deinit(gpa);
1349 };1352 };
...@@ -1401,13 +1404,13 @@ fn analyzeInstSwitchBr(...@@ -1401,13 +1404,13 @@ fn analyzeInstSwitchBr(
1401 }1404 }
14021405
1403 for (mirrored_deaths, 0..) |mirrored, i| {1406 for (mirrored_deaths, 0..) |mirrored, i| {
1404 log.debug("[{}] %{f}: case {} mirrored deaths are {f}", .{ pass, inst, i, fmtInstList(mirrored.items) });1407 log.debug("[{t}] {f}: case {} mirrored deaths are {f}", .{ pass, inst, i, fmtInstList(mirrored.items) });
1405 }1408 }
14061409
1407 data.live_set.deinit(gpa);1410 data.live_set.deinit(gpa);
1408 data.live_set = all_alive.move();1411 data.live_set = all_alive.move();
14091412
1410 log.debug("[{}] %{f}: new live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });1413 log.debug("[{t}] {f}: new live set is {f}", .{ pass, inst, fmtInstSet(&data.live_set) });
1411 }1414 }
14121415
1413 const else_death_count = @as(u32, @intCast(mirrored_deaths[ncases].items.len));1416 const else_death_count = @as(u32, @intCast(mirrored_deaths[ncases].items.len));
...@@ -1506,7 +1509,7 @@ fn AnalyzeBigOperands(comptime pass: LivenessPass) type {...@@ -1506,7 +1509,7 @@ fn AnalyzeBigOperands(comptime pass: LivenessPass) type {
15061509
1507 .main_analysis => {1510 .main_analysis => {
1508 if ((try big.data.live_set.fetchPut(gpa, operand, {})) == null) {1511 if ((try big.data.live_set.fetchPut(gpa, operand, {})) == null) {
1509 log.debug("[{}] %{f}: added %{f} to live set (operand dies here)", .{ pass, big.inst, operand });1512 log.debug("[{t}] {f}: added {f} to live set (operand dies here)", .{ pass, big.inst, operand });
1510 big.extra_tombs[extra_byte] |= @as(u32, 1) << extra_bit;1513 big.extra_tombs[extra_byte] |= @as(u32, 1) << extra_bit;
1511 }1514 }
1512 },1515 },
...@@ -1568,9 +1571,9 @@ const FmtInstSet = struct {...@@ -1568,9 +1571,9 @@ const FmtInstSet = struct {
1568 return;1571 return;
1569 }1572 }
1570 var it = val.set.keyIterator();1573 var it = val.set.keyIterator();
1571 try w.print("%{f}", .{it.next().?.*});1574 try w.print("{f}", .{it.next().?.*});
1572 while (it.next()) |key| {1575 while (it.next()) |key| {
1573 try w.print(" %{f}", .{key.*});1576 try w.print(" {f}", .{key.*});
1574 }1577 }
1575 }1578 }
1576};1579};
...@@ -1587,9 +1590,9 @@ const FmtInstList = struct {...@@ -1587,9 +1590,9 @@ const FmtInstList = struct {
1587 try w.writeAll("[no instructions]");1590 try w.writeAll("[no instructions]");
1588 return;1591 return;
1589 }1592 }
1590 try w.print("%{f}", .{val.list[0]});1593 try w.print("{f}", .{val.list[0]});
1591 for (val.list[1..]) |inst| {1594 for (val.list[1..]) |inst| {
1592 try w.print(" %{f}", .{inst});1595 try w.print(" {f}", .{inst});
1593 }1596 }
1594 }1597 }
1595};1598};
src/Air/Liveness/Verify.zig+16-11
...@@ -73,7 +73,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -73,7 +73,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
73 .trap, .unreach => {73 .trap, .unreach => {
74 try self.verifyInstOperands(inst, .{ .none, .none, .none });74 try self.verifyInstOperands(inst, .{ .none, .none, .none });
75 // This instruction terminates the function, so everything should be dead75 // This instruction terminates the function, so everything should be dead
76 if (self.live.count() > 0) return invalid("%{f}: instructions still alive", .{inst});76 if (self.live.count() > 0) return invalid("{f}: instructions still alive", .{inst});
77 },77 },
7878
79 // unary79 // unary
...@@ -166,7 +166,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -166,7 +166,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
166 const un_op = data[@intFromEnum(inst)].un_op;166 const un_op = data[@intFromEnum(inst)].un_op;
167 try self.verifyInstOperands(inst, .{ un_op, .none, .none });167 try self.verifyInstOperands(inst, .{ un_op, .none, .none });
168 // This instruction terminates the function, so everything should be dead168 // This instruction terminates the function, so everything should be dead
169 if (self.live.count() > 0) return invalid("%{f}: instructions still alive", .{inst});169 if (self.live.count() > 0) return invalid("{f}: instructions still alive", .{inst});
170 },170 },
171 .dbg_var_ptr,171 .dbg_var_ptr,
172 .dbg_var_val,172 .dbg_var_val,
...@@ -441,7 +441,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -441,7 +441,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
441 .repeat => {441 .repeat => {
442 const repeat = data[@intFromEnum(inst)].repeat;442 const repeat = data[@intFromEnum(inst)].repeat;
443 const expected_live = self.loops.get(repeat.loop_inst) orelse443 const expected_live = self.loops.get(repeat.loop_inst) orelse
444 return invalid("%{d}: loop %{d} not in scope", .{ @intFromEnum(inst), @intFromEnum(repeat.loop_inst) });444 return invalid("{f}: loop {f} not in scope", .{ inst, repeat.loop_inst });
445445
446 try self.verifyMatchingLiveness(repeat.loop_inst, expected_live);446 try self.verifyMatchingLiveness(repeat.loop_inst, expected_live);
447 },447 },
...@@ -451,7 +451,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -451,7 +451,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
451 try self.verifyOperand(inst, br.operand, self.liveness.operandDies(inst, 0));451 try self.verifyOperand(inst, br.operand, self.liveness.operandDies(inst, 0));
452452
453 const expected_live = self.loops.get(br.block_inst) orelse453 const expected_live = self.loops.get(br.block_inst) orelse
454 return invalid("%{d}: loop %{d} not in scope", .{ @intFromEnum(inst), @intFromEnum(br.block_inst) });454 return invalid("{f}: loop {f} not in scope", .{ inst, br.block_inst });
455455
456 try self.verifyMatchingLiveness(br.block_inst, expected_live);456 try self.verifyMatchingLiveness(br.block_inst, expected_live);
457 },457 },
...@@ -487,7 +487,12 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -487,7 +487,12 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
487 if (ip.isNoReturn(block_ty.toIntern())) {487 if (ip.isNoReturn(block_ty.toIntern())) {
488 assert(!self.blocks.contains(inst));488 assert(!self.blocks.contains(inst));
489 } else {489 } else {
490 var live = self.blocks.fetchRemove(inst).?.value;490 var live = if (self.blocks.fetchRemove(inst)) |kv| kv.value else {
491 return invalid(
492 "{f}: block of type '{f}' not terminated correctly",
493 .{ inst, block_ty.fmtDebug() },
494 );
495 };
491 defer live.deinit(self.gpa);496 defer live.deinit(self.gpa);
492497
493 try self.verifyMatchingLiveness(inst, live);498 try self.verifyMatchingLiveness(inst, live);
...@@ -502,7 +507,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -502,7 +507,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
502507
503 // The same stuff should be alive after the loop as before it.508 // The same stuff should be alive after the loop as before it.
504 const gop = try self.loops.getOrPut(self.gpa, inst);509 const gop = try self.loops.getOrPut(self.gpa, inst);
505 if (gop.found_existing) return invalid("%{d}: loop already exists", .{@intFromEnum(inst)});510 if (gop.found_existing) return invalid("{f}: loop already exists", .{inst});
506 defer {511 defer {
507 var live = self.loops.fetchRemove(inst).?;512 var live = self.loops.fetchRemove(inst).?;
508 live.value.deinit(self.gpa);513 live.value.deinit(self.gpa);
...@@ -551,7 +556,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {...@@ -551,7 +556,7 @@ fn verifyBody(self: *Verify, body: []const Air.Inst.Index) Error!void {
551 // after the loop as before it.556 // after the loop as before it.
552 {557 {
553 const gop = try self.loops.getOrPut(self.gpa, inst);558 const gop = try self.loops.getOrPut(self.gpa, inst);
554 if (gop.found_existing) return invalid("%{d}: loop already exists", .{@intFromEnum(inst)});559 if (gop.found_existing) return invalid("{f}: loop already exists", .{inst});
555 gop.value_ptr.* = self.live.move();560 gop.value_ptr.* = self.live.move();
556 }561 }
557 defer {562 defer {
...@@ -606,11 +611,11 @@ fn verifyOperand(self: *Verify, inst: Air.Inst.Index, op_ref: Air.Inst.Ref, dies...@@ -606,11 +611,11 @@ fn verifyOperand(self: *Verify, inst: Air.Inst.Index, op_ref: Air.Inst.Ref, dies
606 return;611 return;
607 };612 };
608 if (dies) {613 if (dies) {
609 if (!self.live.remove(operand)) return invalid("%{f}: dead operand %{f} reused and killed again", .{614 if (!self.live.remove(operand)) return invalid("{f}: dead operand {f} reused and killed again", .{
610 inst, operand,615 inst, operand,
611 });616 });
612 } else {617 } else {
613 if (!self.live.contains(operand)) return invalid("%{f}: dead operand %{f} reused", .{ inst, operand });618 if (!self.live.contains(operand)) return invalid("{f}: dead operand {f} reused", .{ inst, operand });
614 }619 }
615}620}
616621
...@@ -635,9 +640,9 @@ fn verifyInst(self: *Verify, inst: Air.Inst.Index) Error!void {...@@ -635,9 +640,9 @@ fn verifyInst(self: *Verify, inst: Air.Inst.Index) Error!void {
635}640}
636641
637fn verifyMatchingLiveness(self: *Verify, block: Air.Inst.Index, live: LiveMap) Error!void {642fn verifyMatchingLiveness(self: *Verify, block: Air.Inst.Index, live: LiveMap) Error!void {
638 if (self.live.count() != live.count()) return invalid("%{f}: different deaths across branches", .{block});643 if (self.live.count() != live.count()) return invalid("{f}: different deaths across branches", .{block});
639 var live_it = self.live.keyIterator();644 var live_it = self.live.keyIterator();
640 while (live_it.next()) |live_inst| if (!live.contains(live_inst.*)) return invalid("%{f}: different deaths across branches", .{block});645 while (live_it.next()) |live_inst| if (!live.contains(live_inst.*)) return invalid("{f}: different deaths across branches", .{block});
641}646}
642647
643fn invalid(comptime fmt: []const u8, args: anytype) error{LivenessInvalid} {648fn invalid(comptime fmt: []const u8, args: anytype) error{LivenessInvalid} {