Add benchmark logging

TODO.md

@@ -15,17 +15,22 @@ survivor-like optimized for weak hardware. finding the performance ceiling first
 
 ## phase 2: find the ceiling
 
-- [ ] test on i5-6500T / HD 530 @ 1280x1024
+- [x] test on i5-6500T / HD 530 @ 1280x1024
-- [ ] record entity count where 60fps breaks
+- [x] record entity count where 60fps breaks
-- [ ] identify bottleneck (CPU update vs GPU render)
+- [x] identify bottleneck (CPU update vs GPU render)
-- [ ] document findings
+- [x] document findings
+
+findings (AMD Radeon test):
+- 60fps breaks at ~5000 entities
+- render-bound: update stays <1ms even at 30k entities, render time dominates
+- individual drawCircle calls are the bottleneck
 
 ## phase 3: optimization experiments
 
 based on phase 2 results:
 
-- [ ] if render-bound: batch rendering, instancing
+- [ ] batch rendering, instancing (render-bound confirmed)
-- [ ] if cpu-bound: SIMD, struct-of-arrays, multithreading
+- [ ] ~~if cpu-bound: SIMD, struct-of-arrays, multithreading~~ (not needed)
 - [ ] re-test after each change
 
 ## phase 4: add collision

build.zig

@@ -10,7 +10,7 @@ pub fn build(b: *std.Build) void {
     });
 
     const exe = b.addExecutable(.{
-        .name = "lockstep",
+        .name = "lofivor",
         .root_module = b.createModule(.{
             .root_source_file = b.path("src/main.zig"),
             .target = target,

src/sandbox_main.zig

@@ -12,6 +12,96 @@ const SCREEN_HEIGHT = sandbox.SCREEN_HEIGHT;
 const BG_COLOR = rl.Color{ .r = 10, .g = 10, .b = 18, .a = 255 };
 const CYAN = rl.Color{ .r = 0, .g = 255, .b = 255, .a = 255 };
 
+// logging thresholds
+const TARGET_FRAME_MS: f32 = 16.7; // 60fps
+const THRESHOLD_MARGIN: f32 = 2.0; // hysteresis margin to avoid bounce
+const JUMP_THRESHOLD_MS: f32 = 5.0; // log if frame time jumps by this much
+const HEARTBEAT_INTERVAL: f32 = 10.0; // seconds between periodic logs
+
+const BenchmarkLogger = struct {
+    file: ?std.fs.File,
+    last_logged_frame_ms: f32,
+    was_above_target: bool,
+    last_heartbeat: f32,
+    start_time: i64,
+
+    fn init() BenchmarkLogger {
+        // create log in project root (where zig build runs from)
+        const file = std.fs.cwd().createFile("benchmark.log", .{}) catch |err| blk: {
+            std.debug.print("failed to create benchmark.log: {}\n", .{err});
+            break :blk null;
+        };
+        if (file) |f| {
+            const header = "# lofivor sandbox benchmark\n# time entities frame_ms update_ms render_ms note\n";
+            f.writeAll(header) catch {};
+            std.debug.print("logging to benchmark.log\n", .{});
+        }
+        return .{
+            .file = file,
+            .last_logged_frame_ms = 0,
+            .was_above_target = false,
+            .last_heartbeat = 0,
+            .start_time = std.time.timestamp(),
+        };
+    }
+
+    fn deinit(self: *BenchmarkLogger) void {
+        if (self.file) |f| f.close();
+    }
+
+    fn log(self: *BenchmarkLogger, elapsed: f32, entity_count: usize, frame_ms: f32, update_ms: f32, render_ms: f32) void {
+        const f = self.file orelse return;
+
+        // hysteresis: need to cross threshold + margin to flip state
+        var crossed_threshold = false;
+        var now_above = self.was_above_target;
+        if (self.was_above_target) {
+            // need to drop below target to flip back
+            if (frame_ms < TARGET_FRAME_MS) {
+                now_above = false;
+                crossed_threshold = true;
+            }
+        } else {
+            // need to exceed target + margin to flip
+            if (frame_ms > TARGET_FRAME_MS + THRESHOLD_MARGIN) {
+                now_above = true;
+                crossed_threshold = true;
+            }
+        }
+
+        const big_jump = (frame_ms - self.last_logged_frame_ms) >= JUMP_THRESHOLD_MS;
+        const heartbeat_due = (elapsed - self.last_heartbeat) >= HEARTBEAT_INTERVAL;
+
+        if (!crossed_threshold and !big_jump and !heartbeat_due) return;
+
+        // determine note
+        var note: []const u8 = "";
+        if (crossed_threshold and now_above) {
+            note = "[!60fps]";
+        } else if (crossed_threshold and !now_above) {
+            note = "[+60fps]";
+        } else if (big_jump) {
+            note = "[jump]";
+        }
+
+        var buf: [256]u8 = undefined;
+        const line = std.fmt.bufPrint(&buf, "[{d:.1}s] entities={d} frame={d:.1}ms update={d:.1}ms render={d:.1}ms {s}\n", .{
+            elapsed,
+            entity_count,
+            frame_ms,
+            update_ms,
+            render_ms,
+            note,
+        }) catch return;
+
+        f.writeAll(line) catch {};
+
+        self.last_logged_frame_ms = frame_ms;
+        self.was_above_target = now_above;
+        if (heartbeat_due) self.last_heartbeat = elapsed;
+    }
+};
+
 pub fn main() !void {
     rl.initWindow(@intCast(SCREEN_WIDTH), @intCast(SCREEN_HEIGHT), "lofivor sandbox");
     defer rl.closeWindow();
@@ -22,12 +112,18 @@ pub fn main() !void {
     var rng = prng.random();
 
     var paused = false;
+    var logger = BenchmarkLogger.init();
+    defer logger.deinit();
 
     // timing
     var update_time_us: i64 = 0;
     var render_time_us: i64 = 0;
+    var elapsed: f32 = 0;
 
     while (!rl.windowShouldClose()) {
+        const dt = rl.getFrameTime();
+        elapsed += dt;
+
         // controls
         handleInput(&entities, &rng, &paused);
 
@@ -60,6 +156,12 @@ pub fn main() !void {
         rl.endDrawing();
 
         render_time_us = std.time.microTimestamp() - render_start;
+
+        // smart logging
+        const frame_ms = dt * 1000.0;
+        const update_ms = @as(f32, @floatFromInt(update_time_us)) / 1000.0;
+        const render_ms = @as(f32, @floatFromInt(render_time_us)) / 1000.0;
+        logger.log(elapsed, entities.count, frame_ms, update_ms, render_ms);
     }
 }