//! Lightweight CPU-side performance timing for the Bevy renderer path.
use crate::plugin::MapStateResource;
use bevy::prelude::*;
use std::time::Instant;
/// Rolling CPU-side frame timing for the Bevy integration stages.
#[derive(Resource, Default)]
pub struct PerformanceTraceState {
/// Whether periodic performance logging is enabled.
pub enabled: bool,
frame_count: u32,
elapsed_seconds: f32,
engine_update_accum_ms: f64,
update_stage_accum_ms: f64,
post_update_accum_ms: f64,
update_stage_start: Option<Instant>,
post_update_start: Option<Instant>,
}
impl PerformanceTraceState {
/// Enable or disable performance tracing.
pub fn set_enabled(&mut self, enabled: bool) {
self.enabled = enabled;
if !enabled {
self.reset_window();
}
}
fn reset_window(&mut self) {
self.frame_count = 0;
self.elapsed_seconds = 0.0;
self.engine_update_accum_ms = 0.0;
self.update_stage_accum_ms = 0.0;
self.post_update_accum_ms = 0.0;
self.update_stage_start = None;
self.post_update_start = None;
}
fn record_engine_update(&mut self, elapsed_ms: f64) {
if self.enabled {
self.engine_update_accum_ms += elapsed_ms;
}
}
fn finish_update_stage(&mut self) {
if !self.enabled {
self.update_stage_start = None;
return;
}
if let Some(start) = self.update_stage_start.take() {
self.update_stage_accum_ms += start.elapsed().as_secs_f64() * 1000.0;
}
}
fn finish_post_update_stage(&mut self) {
if !self.enabled {
self.post_update_start = None;
return;
}
if let Some(start) = self.post_update_start.take() {
self.post_update_accum_ms += start.elapsed().as_secs_f64() * 1000.0;
}
}
}
/// Time the engine `MapState::update()` call.
pub fn update_map_state_timed(
mut state: ResMut<MapStateResource>,
mut perf: ResMut<PerformanceTraceState>,
time: Res<Time>,
) {
// Use real wall-clock dt so the camera animator advances in real time.
// On the very first frame Bevy may report dt=0; fall back to ~60 fps.
let dt = {
let raw = time.delta_secs_f64();
if raw > 0.0 {
raw
} else {
1.0 / 60.0
}
};
if !perf.enabled {
state.0.update_with_dt(dt);
return;
}
let start = Instant::now();
state.0.update_with_dt(dt);
perf.record_engine_update(start.elapsed().as_secs_f64() * 1000.0);
}
/// Mark the beginning of the Bevy `Update` sync stage.
pub fn begin_update_stage_timing(mut perf: ResMut<PerformanceTraceState>) {
if perf.enabled {
perf.update_stage_start = Some(Instant::now());
}
}
/// Mark the end of the Bevy `Update` sync stage.
pub fn end_update_stage_timing(mut perf: ResMut<PerformanceTraceState>) {
perf.finish_update_stage();
}
/// Mark the beginning of the Bevy `PostUpdate` upload stage.
pub fn begin_post_update_stage_timing(mut perf: ResMut<PerformanceTraceState>) {
if perf.enabled {
perf.post_update_start = Some(Instant::now());
}
}
/// Mark the end of the Bevy `PostUpdate` upload stage.
pub fn end_post_update_stage_timing(mut perf: ResMut<PerformanceTraceState>) {
perf.finish_post_update_stage();
}
/// Emit a once-per-second rolling performance summary.
pub fn report_performance_trace(
time: Res<Time>,
state: Res<MapStateResource>,
mut perf: ResMut<PerformanceTraceState>,
) {
if !perf.enabled {
return;
}
perf.frame_count += 1;
perf.elapsed_seconds += time.delta_secs();
if perf.elapsed_seconds < 1.0 {
return;
}
let fps = perf.frame_count as f64 / perf.elapsed_seconds as f64;
let frames = perf.frame_count.max(1) as f64;
let engine_ms = perf.engine_update_accum_ms / frames;
let update_ms = perf.update_stage_accum_ms / frames;
let post_ms = perf.post_update_accum_ms / frames;
let tile_diag = state.0.tile_pipeline_diagnostics();
if let Some(diag) = tile_diag {
let source = diag
.source_diagnostics
.as_ref()
.map(|source| {
format!(
" queued={} inflight={}/{} known={} ghost={}",
source.queued_requests,
source.in_flight_requests,
source.max_concurrent_requests,
source.known_requests,
source.cancelled_in_flight_requests,
)
})
.unwrap_or_default();
log::info!(
"perf_trace: fps={fps:.1} engine_update={engine_ms:.3}ms bevy_sync={update_ms:.3}ms post_update={post_ms:.3}ms visible_tiles={} terrain_meshes={} vector_meshes={} models={} symbols={} tile_layer={} selection(raw={} vis={} exact={} fallback={} missing={} overzoom={} req={} hit={} miss={} cancel={} budget_hit={} drop={}) cache(total={} loaded={} expired={} reload={} pending={} failed={} renderable={}) source({}) counters(frames={} req={} hit={} fallback={} miss={} stale_cancel={} evicted_cancel={})",
state.0.visible_tiles().len(),
state.0.terrain_meshes().len(),
state.0.vector_meshes().len(),
state.0.model_instances().len(),
state.0.placed_symbols().len(),
diag.layer_name,
diag.selection_stats.raw_candidate_tiles,
diag.selection_stats.visible_tiles,
diag.selection_stats.exact_visible_tiles,
diag.selection_stats.fallback_visible_tiles,
diag.selection_stats.missing_visible_tiles,
diag.selection_stats.overzoomed_visible_tiles,
diag.selection_stats.requested_tiles,
diag.selection_stats.exact_cache_hits,
diag.selection_stats.cache_misses,
diag.selection_stats.cancelled_stale_pending,
diag.selection_stats.budget_hit,
diag.selection_stats.dropped_by_budget,
diag.cache_stats.total_entries,
diag.cache_stats.loaded_entries,
diag.cache_stats.expired_entries,
diag.cache_stats.reloading_entries,
diag.cache_stats.pending_entries,
diag.cache_stats.failed_entries,
diag.cache_stats.renderable_entries,
source,
diag.counters.frames,
diag.counters.requested_tiles,
diag.counters.exact_cache_hits,
diag.counters.fallback_hits,
diag.counters.cache_misses,
diag.counters.cancelled_stale_pending,
diag.counters.cancelled_evicted_pending,
);
} else {
log::info!(
"perf_trace: fps={fps:.1} engine_update={engine_ms:.3}ms bevy_sync={update_ms:.3}ms post_update={post_ms:.3}ms visible_tiles={} terrain_meshes={} vector_meshes={} models={} symbols={} tile_layer=none",
state.0.visible_tiles().len(),
state.0.terrain_meshes().len(),
state.0.vector_meshes().len(),
state.0.model_instances().len(),
state.0.placed_symbols().len(),
);
}
perf.reset_window();
}