From 71728709ebf5e57ac0e7639aa35dbd678bb4f2c5 Mon Sep 17 00:00:00 2001 From: Filipe Rodrigues Date: Wed, 16 Feb 2022 00:26:56 +0000 Subject: [PATCH] Added frame timings to `Renderer`. Added several more measuring functions/macros. --- zsw-util/src/lib.rs | 60 +++++++++++++++++++- zsw/src/app/renderer.rs | 118 ++++++++++++++++++++++++++++++---------- 2 files changed, 147 insertions(+), 31 deletions(-) diff --git a/zsw-util/src/lib.rs b/zsw-util/src/lib.rs index 0e120e5..7865b46 100644 --- a/zsw-util/src/lib.rs +++ b/zsw-util/src/lib.rs @@ -82,6 +82,7 @@ use { image::DynamicImage, std::{ fs, + future::Future, path::Path, time::{Duration, Instant}, }, @@ -91,10 +92,67 @@ use { pub fn measure(f: impl FnOnce() -> T) -> (T, Duration) { let start_time = Instant::now(); let value = f(); - let duration = Instant::now().saturating_duration_since(start_time); + let duration = start_time.elapsed(); (value, duration) } +/// Measures how long it took to execute an async function +pub async fn measure_async(f: F) -> (F::Output, Duration) { + let start_time = Instant::now(); + let value = f.await; + let duration = start_time.elapsed(); + (value, duration) +} + +/// Measures how long it took to execute a fallible async function +pub async fn try_measure_async> + Send>(f: F) -> Result<(T, Duration), E> { + let start_time = Instant::now(); + let value = f.await?; + let duration = start_time.elapsed(); + Ok((value, duration)) +} + +/// Measures how long it took to execute a statement +pub macro measure($value:expr) {{ + let start_time = ::std::time::Instant::now(); + match $value { + value => { + let duration = ::std::time::Instant::elapsed(&start_time); + (value, duration) + }, + } +}} + +/// Measures how long it took to execute a fallible statement, +/// returning a `Result<(T, Duration), Err>` +pub macro try_measure($value:expr) {{ + let start_time = ::std::time::Instant::now(); + match $value { + ::std::result::Result::Ok(value) => { + let duration = ::std::time::Instant::elapsed(&start_time); + ::std::result::Result::Ok((value, duration)) + }, + ::std::result::Result::Err(err) => ::std::result::Result::Err(err), + } +}} + +/// Helper trait to measure a future +pub trait MeasureFuture: Future { + /// Future type + type Fut: Future; + + /// Measures this future's execution + fn measure_fut(self) -> Self::Fut; +} + +impl MeasureFuture for F { + type Fut = impl Future; + + fn measure_fut(self) -> Self::Fut { + self::measure_async(self) + } +} + pub macro measure_dbg { () => { ::std::eprintln!("[{}:{}]", ::std::file!(), ::std::line!()) diff --git a/zsw/src/app/renderer.rs b/zsw/src/app/renderer.rs index fb594c6..e2dc55a 100644 --- a/zsw/src/app/renderer.rs +++ b/zsw/src/app/renderer.rs @@ -3,28 +3,31 @@ // Imports use { anyhow::Context, + async_lock::Mutex, pollster::FutureExt, - std::{ - thread, - time::{Duration, Instant}, - }, + std::{thread, time::Duration}, winit::window::Window, zsw_egui::Egui, zsw_img::ImageLoader, zsw_panels::Panels, zsw_settings_window::SettingsWindow, zsw_side_effect_macros::side_effect, - zsw_util::MightLock, + zsw_util::{extse::AsyncLockMutexSe, MightBlock, MightLock}, zsw_wgpu::Wgpu, }; /// Renderer -pub struct Renderer {} +pub struct Renderer { + /// Frame timings + frame_timings: Mutex, +} impl Renderer { /// Creates a new renderer pub fn new() -> Self { - Self {} + Self { + frame_timings: Mutex::new(FrameTimings::new()), + } } /// Runs the renderer @@ -49,40 +52,56 @@ impl Renderer { let sleep_duration = Duration::from_secs_f32(1.0 / 60.0); loop { - let start_instant = Instant::now(); + let ((update_duration, render_duration), total_duration) = zsw_util::measure!({ + // Update + // DEADLOCK: Caller ensures we can lock it + let (_, update_duration) = zsw_util::measure!(Self::update(wgpu, panels, image_loader) + .await + .allow::>() + .map_err(|err| log::warn!("Unable to update: {err:?}"))); - // Update - match Self::update(wgpu, panels, image_loader) - .await - .allow::>() - { - Ok(()) => (), - Err(err) => log::warn!("Unable to update: {err:?}"), - }; + // Render + // DEADLOCK: Caller ensures we can lock it + let (_, render_duration) = + zsw_util::measure!(Self::render(window, wgpu, panels, egui, settings_window) + .await + .allow::>() + .map_err(|err| log::warn!("Unable to render: {err:?}"))); - // Render - // DEADLOCK: Caller ensures we can lock it - match Self::render(window, wgpu, panels, egui, settings_window) + (update_duration, render_duration) + }); + + // Update our frame timings + // DEADLOCK: We don't hold any locks during locking + self.frame_timings + .lock_se() .await - .allow::>() { - Ok(()) => (), - Err(err) => log::warn!("Unable to render: {err:?}"), - }; + .allow::() + .add(FrameTiming { + update: update_duration, + render: render_duration, + total: total_duration, + }); // Then sleep until next frame // TODO: Await while sleeping - let frame_duration = start_instant.elapsed(); - if let Some(duration) = sleep_duration.checked_sub(frame_duration) { + if let Some(duration) = sleep_duration.checked_sub(total_duration) { thread::sleep(duration); } } } + /// Returns all frame timings + pub async fn frame_timings(&self) -> [FrameTiming; 60] { + // DEADLOCK: We don't hold any locks during locking + self.frame_timings.lock_se().await.allow::().timings + } + /// Updates all panels /// /// # Locking @@ -181,3 +200,42 @@ impl Renderer { }) } } + +/// Frame timings +pub struct FrameTimings { + /// Timings + timings: [FrameTiming; 60], + + /// Current index + cur_idx: usize, +} + +impl FrameTimings { + // Creates + fn new() -> Self { + Self { + timings: [FrameTiming::default(); 60], + cur_idx: 0, + } + } + + /// Adds a new frame timing + pub fn add(&mut self, timing: FrameTiming) { + self.timings[self.cur_idx] = timing; + self.cur_idx = (self.cur_idx + 1) % 60; + } +} + +/// Frame timing +#[derive(Clone, Copy, Default, Debug)] +pub struct FrameTiming { + /// Update + pub update: Duration, + + /// Render + // TODO: Split into `FrameRenderTiming` + pub render: Duration, + + /// Total + pub total: Duration, +}