feat: Add work_time_ms to benchmark logging for load analysis
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 <noreply@anthropic.com>
This commit is contained in:
parent
a7fef2aeb6
commit
8583db7225
|
|
@ -16,6 +16,7 @@ void BenchmarkLogger::recordFrame(const ProfilingMetrics& metrics) {
|
||||||
frame.frame_time_ms = metrics.frameTime;
|
frame.frame_time_ms = metrics.frameTime;
|
||||||
frame.fps = metrics.fps;
|
frame.fps = metrics.fps;
|
||||||
|
|
||||||
|
frame.work_time_ms = metrics.workTime;
|
||||||
frame.grid_render_ms = metrics.gridRenderTime;
|
frame.grid_render_ms = metrics.gridRenderTime;
|
||||||
frame.entity_render_ms = metrics.entityRenderTime;
|
frame.entity_render_ms = metrics.entityRenderTime;
|
||||||
frame.python_time_ms = metrics.pythonScriptTime;
|
frame.python_time_ms = metrics.pythonScriptTime;
|
||||||
|
|
|
||||||
|
|
@ -28,6 +28,7 @@ struct BenchmarkFrame {
|
||||||
int fps;
|
int fps;
|
||||||
|
|
||||||
// Detailed timing breakdown
|
// Detailed timing breakdown
|
||||||
|
float work_time_ms; // Actual work time (frame_time - sleep_time)
|
||||||
float grid_render_ms;
|
float grid_render_ms;
|
||||||
float entity_render_ms;
|
float entity_render_ms;
|
||||||
float python_time_ms;
|
float python_time_ms;
|
||||||
|
|
@ -172,6 +173,7 @@ public:
|
||||||
file << " \"timestamp_ms\": " << std::fixed << std::setprecision(3) << f.timestamp_ms << ",\n";
|
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 << " \"frame_time_ms\": " << std::setprecision(3) << f.frame_time_ms << ",\n";
|
||||||
file << " \"fps\": " << f.fps << ",\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 << " \"grid_render_ms\": " << std::setprecision(3) << f.grid_render_ms << ",\n";
|
||||||
file << " \"entity_render_ms\": " << std::setprecision(3) << f.entity_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";
|
file << " \"python_time_ms\": " << std::setprecision(3) << f.python_time_ms << ",\n";
|
||||||
|
|
|
||||||
|
|
@ -291,6 +291,9 @@ void GameEngine::run()
|
||||||
ImGui::SFML::Render(*window);
|
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
|
// Display the frame
|
||||||
if (headless) {
|
if (headless) {
|
||||||
headless_renderer->display();
|
headless_renderer->display();
|
||||||
|
|
|
||||||
|
|
@ -34,6 +34,7 @@ struct ProfilingMetrics {
|
||||||
float fovOverlayTime = 0.0f; // Time spent rendering FOV overlays (ms)
|
float fovOverlayTime = 0.0f; // Time spent rendering FOV overlays (ms)
|
||||||
float pythonScriptTime = 0.0f; // Time spent in Python callbacks (ms)
|
float pythonScriptTime = 0.0f; // Time spent in Python callbacks (ms)
|
||||||
float animationTime = 0.0f; // Time spent updating animations (ms)
|
float animationTime = 0.0f; // Time spent updating animations (ms)
|
||||||
|
float workTime = 0.0f; // Total work time before display/sleep (ms)
|
||||||
|
|
||||||
// Grid-specific metrics
|
// Grid-specific metrics
|
||||||
int gridCellsRendered = 0; // Number of grid cells drawn this frame
|
int gridCellsRendered = 0; // Number of grid cells drawn this frame
|
||||||
|
|
|
||||||
|
|
@ -57,8 +57,8 @@ def run_test(runtime):
|
||||||
# Check frame structure
|
# Check frame structure
|
||||||
frame = data['frames'][0]
|
frame = data['frames'][0]
|
||||||
required_fields = ['frame_number', 'timestamp_ms', 'frame_time_ms', 'fps',
|
required_fields = ['frame_number', 'timestamp_ms', 'frame_time_ms', 'fps',
|
||||||
'grid_render_ms', 'entity_render_ms', 'python_time_ms',
|
'work_time_ms', 'grid_render_ms', 'entity_render_ms',
|
||||||
'draw_calls', 'ui_elements', 'logs']
|
'python_time_ms', 'draw_calls', 'ui_elements', 'logs']
|
||||||
for field in required_fields:
|
for field in required_fields:
|
||||||
if field not in frame:
|
if field not in frame:
|
||||||
print(f"FAIL: Missing field '{field}' 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")
|
print("FAIL: Log message not found in any frame")
|
||||||
sys.exit(1)
|
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")
|
print(f" Log messages captured: Yes")
|
||||||
|
|
||||||
# Clean up
|
# Clean up
|
||||||
|
|
|
||||||
Loading…
Reference in New Issue