From d9ed38f9cc2b975cb3e97c68fd2be9283760dd2d Mon Sep 17 00:00:00 2001 From: chazmm Date: Wed, 9 Sep 2026 01:33:23 +0100 Subject: [PATCH] Capture timestamped render-stage spikes for intermittent hitch diagnosis --- crates/skate-game/src/performance.rs | 37 +++++++++++++++++++++++----- docs/custom-map-lighting.md | 15 +++++++++++ 2 files changed, 46 insertions(+), 6 deletions(-) diff --git a/crates/skate-game/src/performance.rs b/crates/skate-game/src/performance.rs index 4b4ba29e..bc07002b 100644 --- a/crates/skate-game/src/performance.rs +++ b/crates/skate-game/src/performance.rs @@ -5,6 +5,12 @@ use std::sync::{Arc, Mutex}; use std::{collections::BTreeMap, sync::OnceLock}; use std::{path::PathBuf, time::Instant}; +static EPOCH: OnceLock = OnceLock::new(); +static SLOW_SECTIONS: Mutex> = Mutex::new(Vec::new()); +fn timestamp(now: Instant) -> f64 { + EPOCH.get().map_or(0., |epoch| now.duration_since(*epoch).as_secs_f64() * 1000.) +} + static SECTIONS: Mutex> = Mutex::new(BTreeMap::new()); pub(crate) struct Scope { name: &'static str, @@ -24,9 +30,14 @@ impl Scope { impl Drop for Scope { fn drop(&mut self) { if let Some(start) = self.start { + let elapsed = start.elapsed().as_secs_f64() * 1000.; + if elapsed >= 2. { + let mut slow = SLOW_SECTIONS.lock().unwrap(); + if slow.len() < 256 { slow.push((self.name, timestamp(start), elapsed)); } + } let mut sections = SECTIONS.lock().unwrap(); let entry = sections.entry(self.name).or_default(); - entry.0 += start.elapsed().as_secs_f64() * 1000.; + entry.0 += elapsed; entry.1 += 1; } } @@ -41,7 +52,8 @@ pub(crate) struct Performance { physics_ms: f64, ticks: u32, samples: Vec<[f64; 4]>, - render: Arc>>, + sample_times: Vec, + render: Arc>>, } impl Performance { pub(crate) fn physics(&mut self, elapsed: std::time::Duration) { @@ -57,7 +69,8 @@ impl Plugin for PerformancePlugin { return; }; let now = Instant::now(); - let render = Arc::new(Mutex::new(Vec::new())); + let _ = EPOCH.set(now); + let render = Arc::new(Mutex::new(Vec::with_capacity(16384))); if let Some(render_app) = app.get_sub_app_mut(RenderApp) { render_app .insert_resource(RenderPerformance { @@ -126,7 +139,8 @@ impl Plugin for PerformancePlugin { previous: now, physics_ms: 0., ticks: 0, - samples: Vec::new(), + samples: Vec::with_capacity(16384), + sample_times: Vec::with_capacity(16384), render, }) .add_systems(First, begin) @@ -183,6 +197,7 @@ fn finish(mut p: ResMut, mut exit: MessageWriter) { f64::from(p.ticks), ]; p.samples.push(sample); + p.sample_times.push(timestamp(now)); } if elapsed > 25. && !p.samples.is_empty() { let mean = |column: usize| { @@ -205,6 +220,14 @@ fn finish(mut p: ResMut, mut exit: MessageWriter) { "render_assets_ms_mean": render_mean(2), "render_views_ms_mean": render_mean(3), "render_queue_ms_mean": render_mean(4), "sections_ms_per_call": SECTIONS.lock().unwrap().iter().map(|(&k, &(ms, n))| (k, ms / n as f64)).collect::>(), "samples": p.samples, + "sample_elapsed_ms": p.sample_times, + "render_samples": &*render, + "render_sample_columns": ["prepare_ms", "submit_ms", "assets_ms", "views_ms", "queue_ms", "elapsed_ms", "waiting_pipelines"], + "slow_sections": &*SLOW_SECTIONS.lock().unwrap(), + "slow_section_columns": ["section", "start_elapsed_ms", "duration_ms"], + "frame_ms_max": frames[frames.len()-1], + "frame_ms_p99": frames[(frames.len()-1)*99/100], + "frames_over_8ms": frames.iter().filter(|&&ms| ms > 8.).count(), }); match std::fs::write(&p.path, serde_json::to_vec_pretty(&report).unwrap()) { Ok(()) => { @@ -226,7 +249,7 @@ struct RenderPerformance { prepared: Instant, mark: Instant, phases: [f64; 3], - samples: Arc>>, + samples: Arc>>, } fn render_begin(mut p: ResMut) { p.frame = Instant::now(); @@ -248,7 +271,7 @@ fn render_queue_done(mut p: ResMut) { fn render_prepared(mut p: ResMut) { p.prepared = Instant::now(); } -fn render_finish(mut p: ResMut) { +fn render_finish(mut p: ResMut, pipelines: Res) { let now = Instant::now(); if now .duration_since(*p.start.get_or_insert(now)) @@ -261,6 +284,8 @@ fn render_finish(mut p: ResMut) { p.phases[0], p.phases[1], p.phases[2], + timestamp(now), + pipelines.waiting_pipelines().count() as f64, ]); } } diff --git a/docs/custom-map-lighting.md b/docs/custom-map-lighting.md index 0b64698f..62f464db 100644 --- a/docs/custom-map-lighting.md +++ b/docs/custom-map-lighting.md @@ -129,3 +129,18 @@ A new gameplay capture is required to quantify the resulting FPS change. Validation: release build check passed, and the explicit Vulkan GPU cache regression test passed. No gameplay was launched for this change. + +## Remaining hitch investigation + +The next user capture measured 525.1 FPS, 1.90 ms mean frame time and 0.126 ms +mesh binding preparation. Two clusters of slow frames remained; the maximum +was 26.71 ms, with only 4.01 ms in the main schedule and 2.71 ms in physics. +Another 25.53 ms frame contained no physics tick. The aggregate render metrics +cannot identify those individual stalls. No specific hitch cause is confirmed. + +The opt-in profiler now retains timestamped main/render samples, pending +pipeline counts, and bounded slow-section events (at least 2 ms, at most 256). +Main/render sample buffers are preallocated. Reports still write only at the +end of the capture; normal launches do not enable this instrumentation. The +release compile check passed. Another user-run capture is required to locate +the remaining stalls; no game or gameplay automation was launched.