diff --git a/crates/coremem/src/diagnostics.rs b/crates/coremem/src/diagnostics.rs new file mode 100644 index 0000000..021adec --- /dev/null +++ b/crates/coremem/src/diagnostics.rs @@ -0,0 +1,92 @@ +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +pub struct Diagnostics { + frames_completed: u64, + time_spent_stepping: Duration, + time_spent_on_stimuli: Duration, + time_spent_prepping_render: Duration, + time_spent_blocked_on_render: Duration, + time_spent_rendering: Duration, + start_time: Instant, +} + +#[derive(Clone)] +pub struct SyncDiagnostics(Arc>); + +impl Diagnostics { + pub fn new() -> Self { + Self { + frames_completed: 0, + time_spent_stepping: Default::default(), + time_spent_on_stimuli: Default::default(), + time_spent_prepping_render: Default::default(), + time_spent_blocked_on_render: Default::default(), + time_spent_rendering: Default::default(), + start_time: Instant::now(), + } + } + + pub fn format(&self) -> String { + let step_time = self.time_spent_stepping.as_secs_f64(); + let stim_time = self.time_spent_on_stimuli.as_secs_f64(); + let render_time = self.time_spent_rendering.as_secs_f64(); + let render_prep_time = self.time_spent_prepping_render.as_secs_f64(); + let block_time = self.time_spent_blocked_on_render.as_secs_f64(); + let overall_time = self.start_time.elapsed().as_secs_f64(); + let fps = (self.frames_completed as f64) / overall_time; + format!("fps: {:6.2} (sim: {:.1}s, stim: {:.1}s, [render: {:.1}s], blocked: {:.1}s, render_prep: {:.1}s, other: {:.1}s)", + fps, + step_time, + stim_time, + render_time, + block_time, + render_prep_time, + overall_time - step_time - stim_time - block_time - render_prep_time, + ) + } +} + +impl SyncDiagnostics { + pub fn new() -> Self { + Self(Arc::new(Mutex::new(Diagnostics::new()))) + } + pub fn format(&self) -> String { + self.0.lock().unwrap().format() + } + /// measure the duration of some arbitrary chunk of code. + /// used internally. + pub fn measure(f: F) -> Duration { + let start = Instant::now(); + f(); + start.elapsed() + } + + /// record the duration of the sim step operation. + pub fn instrument_step(&self, frames: u64, f: F) { + let elapsed = Self::measure(f); + let mut me = self.0.lock().unwrap(); + me.time_spent_stepping += elapsed; + me.frames_completed += frames as u64; + } + + /// record the duration spent preparing for render (i.e. cloning stuff and moving it into a + /// render pool). + pub fn instrument_render_prep(&self, f: F) { + let elapsed = Self::measure(f); + self.0.lock().unwrap().time_spent_prepping_render += elapsed; + } + + /// record the duration actually spent doing CPU render work + pub fn instrument_render_cpu_side(&self, f: F) { + let elapsed = Self::measure(f); + self.0.lock().unwrap().time_spent_rendering += elapsed; + } + + /// record the duration spent blocking the simulation because the render queue is full. + pub fn instrument_render_blocked(&self, f: F) { + let elapsed = Self::measure(f); + self.0.lock().unwrap().time_spent_blocked_on_render += elapsed; + } +} + diff --git a/crates/coremem/src/driver.rs b/crates/coremem/src/driver.rs index 022f53c..d01990c 100644 --- a/crates/coremem/src/driver.rs +++ b/crates/coremem/src/driver.rs @@ -1,3 +1,4 @@ +use crate::diagnostics::SyncDiagnostics; use crate::geom::{Coord, Index, Meters, Region}; use crate::mat; use crate::meas::{self, AbstractMeasurement}; @@ -10,9 +11,9 @@ use crate::stim::{self, AbstractStimulus}; use log::{info, trace}; use serde::{Deserialize, Serialize}; use std::path::PathBuf; -use std::sync::{Arc, Mutex}; +use std::sync::Arc; use std::sync::mpsc::{sync_channel, SyncSender, Receiver}; -use std::time::{Duration, Instant}; +use std::time::Instant; use threadpool::ThreadPool; pub struct Driver { @@ -29,95 +30,6 @@ pub struct Driver { last_diag_time: Instant, } -struct Diagnostics { - frames_completed: u64, - time_spent_stepping: Duration, - time_spent_on_stimuli: Duration, - time_spent_prepping_render: Duration, - time_spent_blocked_on_render: Duration, - time_spent_rendering: Duration, - start_time: Instant, -} - -#[derive(Clone)] -struct SyncDiagnostics(Arc>); - -impl Diagnostics { - fn new() -> Self { - Self { - frames_completed: 0, - time_spent_stepping: Default::default(), - time_spent_on_stimuli: Default::default(), - time_spent_prepping_render: Default::default(), - time_spent_blocked_on_render: Default::default(), - time_spent_rendering: Default::default(), - start_time: Instant::now(), - } - } - - fn format(&self) -> String { - let step_time = self.time_spent_stepping.as_secs_f64(); - let stim_time = self.time_spent_on_stimuli.as_secs_f64(); - let render_time = self.time_spent_rendering.as_secs_f64(); - let render_prep_time = self.time_spent_prepping_render.as_secs_f64(); - let block_time = self.time_spent_blocked_on_render.as_secs_f64(); - let overall_time = self.start_time.elapsed().as_secs_f64(); - let fps = (self.frames_completed as f64) / overall_time; - format!("fps: {:6.2} (sim: {:.1}s, stim: {:.1}s, [render: {:.1}s], blocked: {:.1}s, render_prep: {:.1}s, other: {:.1}s)", - fps, - step_time, - stim_time, - render_time, - block_time, - render_prep_time, - overall_time - step_time - stim_time - block_time - render_prep_time, - ) - } -} - -impl SyncDiagnostics { - fn new() -> Self { - Self(Arc::new(Mutex::new(Diagnostics::new()))) - } - fn format(&self) -> String { - self.0.lock().unwrap().format() - } - /// measure the duration of some arbitrary chunk of code. - /// used internally. - fn measure(f: F) -> Duration { - let start = Instant::now(); - f(); - start.elapsed() - } - - /// record the duration of the sim step operation. - fn instrument_step(&self, frames: u64, f: F) { - let elapsed = Self::measure(f); - let mut me = self.0.lock().unwrap(); - me.time_spent_stepping += elapsed; - me.frames_completed += frames as u64; - } - - /// record the duration spent preparing for render (i.e. cloning stuff and moving it into a - /// render pool). - fn instrument_render_prep(&self, f: F) { - let elapsed = Self::measure(f); - self.0.lock().unwrap().time_spent_prepping_render += elapsed; - } - - /// record the duration actually spent doing CPU render work - fn instrument_render_cpu_side(&self, f: F) { - let elapsed = Self::measure(f); - self.0.lock().unwrap().time_spent_rendering += elapsed; - } - - /// record the duration spent blocking the simulation because the render queue is full. - fn instrument_render_blocked(&self, f: F) { - let elapsed = Self::measure(f); - self.0.lock().unwrap().time_spent_blocked_on_render += elapsed; - } -} - impl Driver { pub fn new(state: S) -> Self { Self { @@ -266,7 +178,6 @@ impl Driver { }); trace!("step end"); if self.last_diag_time.elapsed().as_secs_f64() >= 5.0 { - // TODO: make this a method on the Diagnostics. self.last_diag_time = Instant::now(); let step = self.state.step_no(); let diagstr = self.diag.format(); diff --git a/crates/coremem/src/lib.rs b/crates/coremem/src/lib.rs index 27833ab..7a25090 100644 --- a/crates/coremem/src/lib.rs +++ b/crates/coremem/src/lib.rs @@ -7,6 +7,7 @@ use log::info; +mod diagnostics; pub mod driver; pub mod geom; pub mod meas;