From 8583db7225795a528445c20c28585de928dbb33a Mon Sep 17 00:00:00 2001 From: John McCardle Date: Fri, 28 Nov 2025 16:13:40 -0500 Subject: [PATCH] feat: Add work_time_ms to benchmark logging for load analysis MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Track actual work time separately from frame time to determine system load percentage: - work_time_ms: Time spent doing actual work before display() - sleep_time = frame_time_ms - work_time_ms This allows calculating load percentage: load% = (work_time / frame_time) * 100 Example at 60fps with light load: - frame_time: 16.67ms, work_time: 2ms - load: 12%, sleep: 14.67ms 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- src/BenchmarkLogger.cpp | 1 + src/BenchmarkLogger.h | 2 ++ src/GameEngine.cpp | 3 +++ src/GameEngine.h | 1 + tests/unit/benchmark_logging_test.py | 12 +++++++++--- 5 files changed, 16 insertions(+), 3 deletions(-) diff --git a/src/BenchmarkLogger.cpp b/src/BenchmarkLogger.cpp index 42ddf39..88df9c1 100644 --- a/src/BenchmarkLogger.cpp +++ b/src/BenchmarkLogger.cpp @@ -16,6 +16,7 @@ void BenchmarkLogger::recordFrame(const ProfilingMetrics& metrics) { frame.frame_time_ms = metrics.frameTime; frame.fps = metrics.fps; + frame.work_time_ms = metrics.workTime; frame.grid_render_ms = metrics.gridRenderTime; frame.entity_render_ms = metrics.entityRenderTime; frame.python_time_ms = metrics.pythonScriptTime; diff --git a/src/BenchmarkLogger.h b/src/BenchmarkLogger.h index 7c93dba..6a0fedb 100644 --- a/src/BenchmarkLogger.h +++ b/src/BenchmarkLogger.h @@ -28,6 +28,7 @@ struct BenchmarkFrame { int fps; // Detailed timing breakdown + float work_time_ms; // Actual work time (frame_time - sleep_time) float grid_render_ms; float entity_render_ms; float python_time_ms; @@ -172,6 +173,7 @@ public: file << " \"timestamp_ms\": " << std::fixed << std::setprecision(3) << f.timestamp_ms << ",\n"; file << " \"frame_time_ms\": " << std::setprecision(3) << f.frame_time_ms << ",\n"; file << " \"fps\": " << f.fps << ",\n"; + file << " \"work_time_ms\": " << std::setprecision(3) << f.work_time_ms << ",\n"; file << " \"grid_render_ms\": " << std::setprecision(3) << f.grid_render_ms << ",\n"; file << " \"entity_render_ms\": " << std::setprecision(3) << f.entity_render_ms << ",\n"; file << " \"python_time_ms\": " << std::setprecision(3) << f.python_time_ms << ",\n"; diff --git a/src/GameEngine.cpp b/src/GameEngine.cpp index 724a699..7bc9e14 100644 --- a/src/GameEngine.cpp +++ b/src/GameEngine.cpp @@ -291,6 +291,9 @@ void GameEngine::run() ImGui::SFML::Render(*window); } + // Record work time before display (which may block for vsync/framerate limit) + metrics.workTime = clock.getElapsedTime().asSeconds() * 1000.0f; + // Display the frame if (headless) { headless_renderer->display(); diff --git a/src/GameEngine.h b/src/GameEngine.h index d4014c8..1c984fd 100644 --- a/src/GameEngine.h +++ b/src/GameEngine.h @@ -34,6 +34,7 @@ struct ProfilingMetrics { float fovOverlayTime = 0.0f; // Time spent rendering FOV overlays (ms) float pythonScriptTime = 0.0f; // Time spent in Python callbacks (ms) float animationTime = 0.0f; // Time spent updating animations (ms) + float workTime = 0.0f; // Total work time before display/sleep (ms) // Grid-specific metrics int gridCellsRendered = 0; // Number of grid cells drawn this frame diff --git a/tests/unit/benchmark_logging_test.py b/tests/unit/benchmark_logging_test.py index 12704ca..387770c 100644 --- a/tests/unit/benchmark_logging_test.py +++ b/tests/unit/benchmark_logging_test.py @@ -57,8 +57,8 @@ def run_test(runtime): # Check frame structure frame = data['frames'][0] required_fields = ['frame_number', 'timestamp_ms', 'frame_time_ms', 'fps', - 'grid_render_ms', 'entity_render_ms', 'python_time_ms', - 'draw_calls', 'ui_elements', 'logs'] + 'work_time_ms', 'grid_render_ms', 'entity_render_ms', + 'python_time_ms', 'draw_calls', 'ui_elements', 'logs'] for field in required_fields: if field not in frame: print(f"FAIL: Missing field '{field}' in frame") @@ -75,7 +75,13 @@ def run_test(runtime): print("FAIL: Log message not found in any frame") sys.exit(1) - print(f" First frame FPS: {data['frames'][0]['fps']}") + # Show timing breakdown + f0 = data['frames'][0] + print(f" First frame FPS: {f0['fps']}") + print(f" Frame time: {f0['frame_time_ms']:.3f}ms, Work time: {f0['work_time_ms']:.3f}ms") + if f0['frame_time_ms'] > 0: + load_pct = (f0['work_time_ms'] / f0['frame_time_ms']) * 100 + print(f" Load: {load_pct:.1f}% (sleep time: {f0['frame_time_ms'] - f0['work_time_ms']:.3f}ms)") print(f" Log messages captured: Yes") # Clean up