Reporting improvements & bug fixes

src/dev_support/benchcommon.zig

@@ -1356,7 +1356,7 @@ pub fn calcBenchmarkCSVValuesFromResult(
     const conv_ms = 1.0 / 1e6;
     const cam_inv_ms = result.cam_ms;
     const resolve_ms = result.resolve_ms;
-    const elem_loop_ms = result.raster_ms - cam_inv_ms - resolve_ms;
+    const elem_loop_ms = result.pipeline_times.elem_loop * conv_ms;
     return .{
         .total_elems = @floatFromInt(result.total_elems),
         .vis_elems = @floatFromInt(result.vis_elems),

src/dev_support/benchdicuq.zig

@@ -57,6 +57,7 @@ pub const DicuqFrameRow = struct {
     shaded_px: u64,
     geom_time_ms: F,
     cam_time_ms: F,
+    elem_loop_time_ms: F,
     resolve_time_ms: F,
     raster_time_ms: F,
     save_time_ms: F,
@@ -77,6 +78,7 @@ pub const DicuqE2ERow = struct {
     shaded_px: u64,
     geom_time_ms: F,
     cam_time_ms: F,
+    elem_loop_time_ms: F,
     resolve_time_ms: F,
     raster_time_ms: F,
     save_time_ms: F,
@@ -119,6 +121,7 @@ const DicuqFrameStatsRow = struct {
     shaded_px: F,
     geom_time_ms: F,
     cam_time_ms: F,
+    elem_loop_time_ms: F,
     resolve_time_ms: F,
     raster_time_ms: F,
     save_time_ms: F,
@@ -138,6 +141,7 @@ const DicuqE2EStatsRow = struct {
     shaded_px: F,
     geom_time_ms: F,
     cam_time_ms: F,
+    elem_loop_time_ms: F,
     resolve_time_ms: F,
     raster_time_ms: F,
     save_time_ms: F,
@@ -436,6 +440,8 @@ fn aggregateFrameTimes(
             capture.bench_log.frame_times.raster_loop;
         frame_times.cam_invert +=
             capture.bench_log.frame_times.cam_invert;
+        frame_times.elem_loop +=
+            capture.bench_log.frame_times.elem_loop;
         frame_times.scratch_resolve +=
             capture.bench_log.frame_times.scratch_resolve;
         frame_times.save_frame +=
@@ -609,6 +615,7 @@ fn buildFrameRows(
             .shaded_px = capture.bench_log.total_shaded_px,
             .geom_time_ms = geom_time_ns / 1e6,
             .cam_time_ms = capture.bench_log.frame_times.cam_invert / 1e6,
+            .elem_loop_time_ms = capture.bench_log.frame_times.elem_loop / 1e6,
             .resolve_time_ms = capture.bench_log.frame_times.scratch_resolve / 1e6,
             .raster_time_ms = capture.bench_log.frame_times.raster_loop / 1e6,
             .save_time_ms = capture.bench_log.frame_times.save_frame / 1e6,
@@ -641,6 +648,7 @@ fn buildE2ESummaryRow(
     e2e_ms: ?F,
 ) DicuqE2ERow {
     var geom_time_ms: F = 0.0;
+    var elem_loop_time_ms: F = 0.0;
     var raster_time_ms: F = 0.0;
     var save_time_ms: F = 0.0;
     var frame_time_ms: F = 0.0;
@@ -657,6 +665,7 @@ fn buildE2ESummaryRow(
             }
         }
         geom_time_ms += frame_row.geom_time_ms;
+        elem_loop_time_ms += frame_row.elem_loop_time_ms;
         raster_time_ms += frame_row.raster_time_ms;
         save_time_ms += frame_row.save_time_ms;
         frame_time_ms += frame_row.frame_time_ms;
@@ -712,6 +721,7 @@ fn buildE2ESummaryRow(
             }
             break :blk cam_sum;
         },
+        .elem_loop_time_ms = elem_loop_time_ms,
         .resolve_time_ms = blk: {
             var res_sum: F = 0.0;
             for (frame_rows) |fr| {
@@ -817,8 +827,7 @@ fn appendFrameRowsCSV(
     );
 
     for (frame_rows) |frame_row| {
-        const elem_loop_ms = frame_row.raster_time_ms -
-            frame_row.cam_time_ms - frame_row.resolve_time_ms;
+        const elem_loop_ms = frame_row.elem_loop_time_ms;
         const row = try std.fmt.allocPrint(
             allocator,
             "{d},{s},{d},{d},{d},{d},{d},{d}," ++
@@ -881,8 +890,7 @@ fn appendE2ERowsCSV(
         else
             try allocator.dupe(u8, "");
         defer allocator.free(e2e_tp_text);
-        const elem_loop_ms = e2e_row.raster_time_ms -
-            e2e_row.cam_time_ms - e2e_row.resolve_time_ms;
+        const elem_loop_ms = e2e_row.elem_loop_time_ms;
 
         const row = try std.fmt.allocPrint(
             allocator,
@@ -960,6 +968,8 @@ fn calcFrameStatsRow(
     defer allocator.free(geom_vals);
     var cam_vals = try allocator.alloc(F, count);
     defer allocator.free(cam_vals);
+    var elem_loop_vals = try allocator.alloc(F, count);
+    defer allocator.free(elem_loop_vals);
     var resolve_vals = try allocator.alloc(F, count);
     defer allocator.free(resolve_vals);
     var raster_vals = try allocator.alloc(F, count);
@@ -992,6 +1002,7 @@ fn calcFrameStatsRow(
         total_px_vals[ii] = @floatFromInt(frame_row.total_px);
         geom_vals[ii] = frame_row.geom_time_ms;
         cam_vals[ii] = frame_row.cam_time_ms;
+        elem_loop_vals[ii] = frame_row.elem_loop_time_ms;
         resolve_vals[ii] = frame_row.resolve_time_ms;
         raster_vals[ii] = frame_row.raster_time_ms;
         save_vals[ii] = frame_row.save_time_ms;
@@ -1040,6 +1051,10 @@ fn calcFrameStatsRow(
             try calcFieldStats(allocator, cam_vals),
             kind,
         ),
+        .elem_loop_time_ms = selectDicuqStat(
+            try calcFieldStats(allocator, elem_loop_vals),
+            kind,
+        ),
         .resolve_time_ms = selectDicuqStat(
             try calcFieldStats(allocator, resolve_vals),
             kind,
@@ -1114,6 +1129,8 @@ fn calcE2EStatsRow(
     defer allocator.free(geom_vals);
     var cam_vals = try allocator.alloc(F, count);
     defer allocator.free(cam_vals);
+    var elem_loop_vals = try allocator.alloc(F, count);
+    defer allocator.free(elem_loop_vals);
     var resolve_vals = try allocator.alloc(F, count);
     defer allocator.free(resolve_vals);
     var raster_vals = try allocator.alloc(F, count);
@@ -1145,6 +1162,7 @@ fn calcE2EStatsRow(
             shaded_vals[rr] = @floatFromInt(row.shaded_px);
             geom_vals[rr] = row.geom_time_ms;
             cam_vals[rr] = row.cam_time_ms;
+            elem_loop_vals[rr] = row.elem_loop_time_ms;
             resolve_vals[rr] = row.resolve_time_ms;
             raster_vals[rr] = row.raster_time_ms;
             save_vals[rr] = row.save_time_ms;
@@ -1195,6 +1213,10 @@ fn calcE2EStatsRow(
             try calcFieldStats(allocator, cam_vals),
             kind,
         ),
+        .elem_loop_time_ms = selectDicuqStat(
+            try calcFieldStats(allocator, elem_loop_vals),
+            kind,
+        ),
         .resolve_time_ms = selectDicuqStat(
             try calcFieldStats(allocator, resolve_vals),
             kind,
@@ -1290,8 +1312,7 @@ fn appendFrameStatsRowsCSV(
         else
             try allocator.dupe(u8, "");
         defer allocator.free(e2e_tp_text);
-        const elem_loop_ms = stats_row.raster_time_ms -
-            stats_row.cam_time_ms - stats_row.resolve_time_ms;
+        const elem_loop_ms = stats_row.elem_loop_time_ms;
         const row = try std.fmt.allocPrint(
             allocator,
             "{d},{s},{s},{d:.6},{d:.6},{d:.6},{d:.6}," ++
@@ -1371,8 +1392,7 @@ fn appendE2EStatsRowsCSV(
         else
             try allocator.dupe(u8, "");
         defer allocator.free(e2e_tp_text);
-        const elem_loop_ms = stats_row.raster_time_ms -
-            stats_row.cam_time_ms - stats_row.resolve_time_ms;
+        const elem_loop_ms = stats_row.elem_loop_time_ms;
         const row = try std.fmt.allocPrint(
             allocator,
             "{s},{s},{d:.6},{d:.6},{d:.6},{d:.6}," ++

src/dev_support/benchstats.zig

@@ -22,6 +22,7 @@ pub const CaseSamples = struct {
     geom_times: []F,
     raster_times: []F,
     cam_times: []F,
+    elem_loop_times: []F,
     resolve_times: []F,
     save_frame_times: []F,
     frame_times: []F,
@@ -49,6 +50,7 @@ pub const CaseSamples = struct {
             .geom_times = try allocator.alloc(F, runs),
             .raster_times = try allocator.alloc(F, runs),
             .cam_times = try allocator.alloc(F, runs),
+            .elem_loop_times = try allocator.alloc(F, runs),
             .resolve_times = try allocator.alloc(F, runs),
             .save_frame_times = try allocator.alloc(F, runs),
             .frame_times = try allocator.alloc(F, runs),
@@ -77,6 +79,7 @@ pub const CaseSamples = struct {
         allocator.free(self.geom_times);
         allocator.free(self.raster_times);
         allocator.free(self.cam_times);
+        allocator.free(self.elem_loop_times);
         allocator.free(self.resolve_times);
         allocator.free(self.save_frame_times);
         allocator.free(self.frame_times);
@@ -105,6 +108,7 @@ pub const CaseSamples = struct {
         self.geom_times[rr] = result.geom_ms;
         self.raster_times[rr] = result.raster_ms;
         self.cam_times[rr] = result.cam_ms;
+        self.elem_loop_times[rr] = result.pipeline_times.elem_loop / 1e6;
         self.resolve_times[rr] = result.resolve_ms;
         self.save_frame_times[rr] =
             result.pipeline_times.save_frame / 1e6;
@@ -140,26 +144,6 @@ pub const CaseSamples = struct {
         samp_cfg: ?texops.TextureSampleConfig,
         tex_func_case: ?common.TexFuncCase,
     ) !common.BenchStats {
-        const cam_median = (try common.calcMedianMAD(
-            allocator,
-            self.cam_times,
-        )).median;
-        const resolve_median = (try common.calcMedianMAD(
-            allocator,
-            self.resolve_times,
-        )).median;
-        const raster_median = (try common.calcMedianMAD(
-            allocator,
-            self.raster_times,
-        )).median;
-        const elem_loop_median =
-            raster_median - cam_median - resolve_median;
-        const elem_loop_zero: common.MedianMAD = .{
-            .median = elem_loop_median,
-            .mad = 0,
-            .min = elem_loop_median,
-            .max = elem_loop_median,
-        };
         return .{
             .name = try allocator.dupe(u8, case_name),
             .mesh_type = mesh_type,
@@ -198,7 +182,10 @@ pub const CaseSamples = struct {
                 allocator,
                 self.cam_times,
             ),
-            .elem_loop = elem_loop_zero,
+            .elem_loop = try common.calcMedianMAD(
+                allocator,
+                self.elem_loop_times,
+            ),
             .scratch_resolve = try common.calcMedianMAD(
                 allocator,
                 self.resolve_times,

src/riley/zig/rasterengine_common.zig

@@ -631,8 +631,10 @@ fn rasterTileComm(
         ctx_rast.config.background_value,
     );
 
-    const time_cam_start: ?Timestamp =
-        if (comptime report_mode != .off)
+    // Report aggregate worker-time for the overlap loop. Camera fill is timed
+    // separately and removed below so all three raster phases share one basis.
+    const time_elem_start: ?Timestamp =
+        if (comptime report_mode !=  .off)
             Timestamp.now(io, .awake)
         else
             null;
@@ -653,6 +655,11 @@ fn rasterTileComm(
         switch (mesh_ptr.mesh_type) {
             inline else => |geom_tag| {
                 if (!camera_fill_ready and comptime geom_tag != .tri3opt) {
+                    const time_cam_start: ?Timestamp =
+                        if (comptime report_mode != .off)
+                            Timestamp.now(io, .awake)
+                        else
+                            null;
                     try fillTileIdealCent(
                         ctx_rast,
                         tile,
@@ -1008,6 +1015,16 @@ fn rasterTileComm(
         }
     }
 
+    const elem_duration_ns: u64 = if (comptime report_mode != .off) blk: {
+        const overlap_duration_ns: u64 = @intCast(
+            time_elem_start.?.durationTo(
+                Timestamp.now(io, .awake),
+            ).raw.nanoseconds,
+        );
+        std.debug.assert(overlap_duration_ns >= cam_duration_ns);
+        break :blk overlap_duration_ns - cam_duration_ns;
+    } else 0;
+
     const time_resolve_start: ?Timestamp =
         if (comptime report_mode != .off)
             Timestamp.now(io, .awake)
@@ -1082,6 +1099,7 @@ fn rasterTileComm(
         shaded_px,
         overlaps.len,
         cam_duration_ns,
+        elem_duration_ns,
         resolve_duration_ns,
     );
 }

src/riley/zig/rasterreport.zig

@@ -43,6 +43,7 @@ pub inline fn finishTile(
     shaded_px: u64,
     elem_count: usize,
     cam_duration_ns: u64,
+    elem_duration_ns: u64,
     resolve_duration_ns: u64,
 ) void {
     const screen_px_x = @as(
@@ -66,6 +67,7 @@ pub inline fn finishTile(
     );
 
     ctx_report.recordCamTime(cam_duration_ns);
+    ctx_report.recordElemTime(elem_duration_ns);
     ctx_report.recordResolveTime(resolve_duration_ns);
 }