a73x

5f8b00ab

Split gpu_submit into sub-stage timings (bench only)

a73x   2026-04-17 19:31

Commit message
Split gpu_submit into sub-stage timings (bench only)

drawCells takes an optional SubmitTiming out-param populated with
wait_fences / acquire / record / submit / present micros. Callers that
don't care pass null; overhead when null is one branch and nothing else.

Main loop forwards the split into FrameTiming when WAYSTTY_BENCH=1 and,
if WAYSTTY_BENCH_CSV=<path> is set, dumps per-frame timings as CSV for
post-mortem inspection.

Used this to attribute gpu_submit outliers: 7 of top 10 spikes are pure
waitForFences time (previous frame's GPU not yet done), max 922us on a
single frame; one rare spike (182us) is inside queueSubmit itself. Both
paths are driver/compositor scheduling variance, not code issues.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
src/bench_stats.zig
Old New
@@ -6,6 +6,13 @@ pub const FrameTiming = struct {
6 atlas_upload_us: u32 = 0, 6 atlas_upload_us: u32 = 0,
7 instance_upload_us: u32 = 0, 7 instance_upload_us: u32 = 0,
8 gpu_submit_us: u32 = 0, 8 gpu_submit_us: u32 = 0,
9 // Sub-timings inside gpu_submit (drawCells). Sum roughly equals
10 // gpu_submit_us modulo per-call timer overhead.
11 wait_fences_us: u32 = 0,
12 acquire_us: u32 = 0,
13 record_us: u32 = 0,
14 submit_us: u32 = 0,
15 present_us: u32 = 0,
9 16
10 pub fn total(self: FrameTiming) u32 { 17 pub fn total(self: FrameTiming) u32 {
11 return self.snapshot_us + 18 return self.snapshot_us +
@@ -112,6 +119,35 @@ pub fn computeFrameStats(ring: *const FrameTimingRing) FrameTimingStats {
112 }; 119 };
113 } 120 }
114 121
122 /// Dump per-frame timings as CSV when WAYSTTY_BENCH_CSV points to a path.
123 /// Columns: frame,snapshot_us,row_rebuild_us,atlas_upload_us,instance_upload_us,gpu_submit_us,total_us
124 pub fn writeFrameCsv(path: []const u8, ring: *const FrameTimingRing) !void {
125 var ordered_buf: [FrameTimingRing.capacity]FrameTiming = undefined;
126 const entries = ring.orderedSlice(&ordered_buf);
127
128 const file = try std.fs.cwd().createFile(path, .{});
129 defer file.close();
130 var buf: [512]u8 = undefined;
131 _ = try file.write("frame,snapshot_us,row_rebuild_us,atlas_upload_us,instance_upload_us,gpu_submit_us,wait_fences_us,acquire_us,record_us,submit_us,present_us,total_us\n");
132 for (entries, 0..) |e, i| {
133 const line = try std.fmt.bufPrint(&buf, "{d},{d},{d},{d},{d},{d},{d},{d},{d},{d},{d},{d}\n", .{
134 i,
135 e.snapshot_us,
136 e.row_rebuild_us,
137 e.atlas_upload_us,
138 e.instance_upload_us,
139 e.gpu_submit_us,
140 e.wait_fences_us,
141 e.acquire_us,
142 e.record_us,
143 e.submit_us,
144 e.present_us,
145 e.total(),
146 });
147 _ = try file.write(line);
148 }
149 }
150
115 pub fn printFrameStats(stats: FrameTimingStats) void { 151 pub fn printFrameStats(stats: FrameTimingStats) void {
116 const row_fmt = "{s:<20}{d:>6}{d:>6}{d:>6}{d:>6}\n"; 152 const row_fmt = "{s:<20}{d:>6}{d:>6}{d:>6}{d:>6}\n";
117 std.debug.print("\n=== waystty frame timing ({d} frames) ===\n", .{stats.frame_count}); 153 std.debug.print("\n=== waystty frame timing ({d} frames) ===\n", .{stats.frame_count});
src/main.zig
Old New
@@ -669,11 +669,13 @@ fn runTerminal(alloc: std.mem.Allocator) !void {
669 669
670 section_timer = std.time.Timer.start() catch unreachable; 670 section_timer = std.time.Timer.start() catch unreachable;
671 const baseline_coverage = renderer.coverageVariantParams(.baseline); 671 const baseline_coverage = renderer.coverageVariantParams(.baseline);
672 var submit_timing: renderer.Context.SubmitTiming = .{};
672 ctx.drawCells( 673 ctx.drawCells(
673 render_cache.total_instance_count, 674 render_cache.total_instance_count,
674 .{ @floatFromInt(cell_w), @floatFromInt(cell_h) }, 675 .{ @floatFromInt(cell_w), @floatFromInt(cell_h) },
675 default_bg, 676 default_bg,
676 baseline_coverage, 677 baseline_coverage,
678 if (is_bench) &submit_timing else null,
677 ) catch |err| switch (err) { 679 ) catch |err| switch (err) {
678 error.OutOfDateKHR => { 680 error.OutOfDateKHR => {
679 _ = try ctx.vkd.deviceWaitIdle(ctx.device); 681 _ = try ctx.vkd.deviceWaitIdle(ctx.device);
@@ -687,6 +689,11 @@ fn runTerminal(alloc: std.mem.Allocator) !void {
687 else => return err, 689 else => return err,
688 }; 690 };
689 frame_timing.gpu_submit_us = usFromTimer(&section_timer); 691 frame_timing.gpu_submit_us = usFromTimer(&section_timer);
692 frame_timing.wait_fences_us = submit_timing.wait_fences_us;
693 frame_timing.acquire_us = submit_timing.acquire_us;
694 frame_timing.record_us = submit_timing.record_us;
695 frame_timing.submit_us = submit_timing.submit_us;
696 frame_timing.present_us = submit_timing.present_us;
690 697
691 frame_ring.push(frame_timing); 698 frame_ring.push(frame_timing);
692 699
@@ -701,6 +708,11 @@ fn runTerminal(alloc: std.mem.Allocator) !void {
701 writeBenchJson(alloc, final_stats, bench_script) catch |err| { 708 writeBenchJson(alloc, final_stats, bench_script) catch |err| {
702 std.log.warn("bench_json write failed: {s}", .{@errorName(err)}); 709 std.log.warn("bench_json write failed: {s}", .{@errorName(err)});
703 }; 710 };
711 if (std.posix.getenv("WAYSTTY_BENCH_CSV")) |csv_path| {
712 bench_stats.writeFrameCsv(csv_path, &frame_ring) catch |err| {
713 std.log.warn("bench_csv write failed: {s}", .{@errorName(err)});
714 };
715 }
704 716
705 _ = try ctx.vkd.deviceWaitIdle(ctx.device); 717 _ = try ctx.vkd.deviceWaitIdle(ctx.device);
706 } 718 }
@@ -2620,7 +2632,7 @@ fn runDrawSmokeTest(alloc: std.mem.Allocator) !void {
2620 if (!frame_loop.canRender()) continue; 2632 if (!frame_loop.canRender()) continue;
2621 2633
2622 const baseline_coverage = renderer.coverageVariantParams(.baseline); 2634 const baseline_coverage = renderer.coverageVariantParams(.baseline);
2623 ctx.drawCells(1, .{ cell_w, cell_h }, .{ 0.0, 0.0, 0.0, 1.0 }, baseline_coverage) catch |err| switch (err) { 2635 ctx.drawCells(1, .{ cell_w, cell_h }, .{ 0.0, 0.0, 0.0, 1.0 }, baseline_coverage, null) catch |err| switch (err) {
2624 error.OutOfDateKHR => { 2636 error.OutOfDateKHR => {
2625 _ = try ctx.vkd.deviceWaitIdle(ctx.device); 2637 _ = try ctx.vkd.deviceWaitIdle(ctx.device);
2626 try ctx.recreateSwapchain(window.width, window.height); 2638 try ctx.recreateSwapchain(window.width, window.height);
src/renderer.zig
Old New
@@ -1679,6 +1679,17 @@ pub const Context = struct {
1679 self.vkd.cmdDraw(cmd, 6, instance_count, 0, 0); 1679 self.vkd.cmdDraw(cmd, 6, instance_count, 0, 0);
1680 } 1680 }
1681 1681
1682 /// Optional per-stage timings populated by `drawCells` when the caller
1683 /// passes a non-null pointer. Useful for splitting the "gpu_submit"
1684 /// section into its constituent waits/records/submits in bench builds.
1685 pub const SubmitTiming = struct {
1686 wait_fences_us: u32 = 0,
1687 acquire_us: u32 = 0,
1688 record_us: u32 = 0,
1689 submit_us: u32 = 0,
1690 present_us: u32 = 0,
1691 };
1692
1682 /// Full draw pass: bind pipeline, push constants, vertex + instance buffers, draw, present. 1693 /// Full draw pass: bind pipeline, push constants, vertex + instance buffers, draw, present.
1683 pub fn drawCells( 1694 pub fn drawCells(
1684 self: *Context, 1695 self: *Context,
@@ -1686,10 +1697,22 @@ pub const Context = struct {
1686 cell_size: [2]f32, 1697 cell_size: [2]f32,
1687 clear_color: [4]f32, 1698 clear_color: [4]f32,
1688 coverage_params: [2]f32, 1699 coverage_params: [2]f32,
1700 timing_out: ?*SubmitTiming,
1689 ) !void { 1701 ) !void {
1702 var timer = if (timing_out != null) std.time.Timer.start() catch unreachable else undefined;
1703 const readTimer = struct {
1704 fn read(t: *std.time.Timer) u32 {
1705 return @intCast(t.read() / std.time.ns_per_us);
1706 }
1707 }.read;
1708
1690 // Wait for previous frame to finish 1709 // Wait for previous frame to finish
1691 _ = try self.vkd.waitForFences(self.device, 1, @ptrCast(&self.in_flight_fence), .true, std.math.maxInt(u64)); 1710 _ = try self.vkd.waitForFences(self.device, 1, @ptrCast(&self.in_flight_fence), .true, std.math.maxInt(u64));
1692 try self.vkd.resetFences(self.device, 1, @ptrCast(&self.in_flight_fence)); 1711 try self.vkd.resetFences(self.device, 1, @ptrCast(&self.in_flight_fence));
1712 if (timing_out) |t| {
1713 t.wait_fences_us = readTimer(&timer);
1714 timer.reset();
1715 }
1693 1716
1694 // Acquire next image 1717 // Acquire next image
1695 const acquire = self.vkd.acquireNextImageKHR( 1718 const acquire = self.vkd.acquireNextImageKHR(
@@ -1704,6 +1727,10 @@ pub const Context = struct {
1704 }; 1727 };
1705 if (swapchainNeedsRebuild(acquire.result)) return error.OutOfDateKHR; 1728 if (swapchainNeedsRebuild(acquire.result)) return error.OutOfDateKHR;
1706 const image_index = acquire.image_index; 1729 const image_index = acquire.image_index;
1730 if (timing_out) |t| {
1731 t.acquire_us = readTimer(&timer);
1732 timer.reset();
1733 }
1707 1734
1708 // Record command buffer 1735 // Record command buffer
1709 try self.vkd.resetCommandBuffer(self.command_buffer, .{}); 1736 try self.vkd.resetCommandBuffer(self.command_buffer, .{});
@@ -1736,6 +1763,10 @@ pub const Context = struct {
1736 1763
1737 self.vkd.cmdEndRenderPass(self.command_buffer); 1764 self.vkd.cmdEndRenderPass(self.command_buffer);
1738 try self.vkd.endCommandBuffer(self.command_buffer); 1765 try self.vkd.endCommandBuffer(self.command_buffer);
1766 if (timing_out) |t| {
1767 t.record_us = readTimer(&timer);
1768 timer.reset();
1769 }
1739 1770
1740 // Submit 1771 // Submit
1741 const wait_stage = vk.PipelineStageFlags{ .color_attachment_output_bit = true }; 1772 const wait_stage = vk.PipelineStageFlags{ .color_attachment_output_bit = true };
@@ -1748,6 +1779,10 @@ pub const Context = struct {
1748 .signal_semaphore_count = 1, 1779 .signal_semaphore_count = 1,
1749 .p_signal_semaphores = @ptrCast(&self.render_finished), 1780 .p_signal_semaphores = @ptrCast(&self.render_finished),
1750 }), self.in_flight_fence); 1781 }), self.in_flight_fence);
1782 if (timing_out) |t| {
1783 t.submit_us = readTimer(&timer);
1784 timer.reset();
1785 }
1751 1786
1752 // Present 1787 // Present
1753 const present_result = self.vkd.queuePresentKHR(self.present_queue, &vk.PresentInfoKHR{ 1788 const present_result = self.vkd.queuePresentKHR(self.present_queue, &vk.PresentInfoKHR{
@@ -1761,6 +1796,7 @@ pub const Context = struct {
1761 else => return err, 1796 else => return err,
1762 }; 1797 };
1763 if (swapchainNeedsRebuild(present_result)) return error.OutOfDateKHR; 1798 if (swapchainNeedsRebuild(present_result)) return error.OutOfDateKHR;
1799 if (timing_out) |t| t.present_us = readTimer(&timer);
1764 } 1800 }
1765 1801
1766 /// Render `instance_data` into the offscreen target and copy the rendered 1802 /// Render `instance_data` into the offscreen target and copy the rendered