diff --git a/fontbe/src/orchestration.rs b/fontbe/src/orchestration.rs index fd4a71a7..b9ff7754 100644 --- a/fontbe/src/orchestration.rs +++ b/fontbe/src/orchestration.rs @@ -98,6 +98,8 @@ impl Identifier for WorkId {} pub enum AnyWorkId { Fe(FeWorkIdentifier), Be(WorkId), + /// Used to capture timing not associated with work + InternalTiming(&'static str), } impl Identifier for AnyWorkId {} @@ -105,15 +107,15 @@ impl Identifier for AnyWorkId {} impl AnyWorkId { pub fn unwrap_be(&self) -> &WorkId { match self { - AnyWorkId::Fe(..) => panic!("Not a BE identifier"), AnyWorkId::Be(id) => id, + _ => panic!("Not a BE identifier"), } } pub fn unwrap_fe(&self) -> &FeWorkIdentifier { match self { AnyWorkId::Fe(id) => id, - AnyWorkId::Be(..) => panic!("Not a FE identifier"), + _ => panic!("Not a FE identifier"), } } } diff --git a/fontc/src/change_detector.rs b/fontc/src/change_detector.rs index 060f8f11..3ae8b127 100644 --- a/fontc/src/change_detector.rs +++ b/fontc/src/change_detector.rs @@ -1,6 +1,6 @@ //! tracking changes during compilation -use std::{ffi::OsStr, fmt::Debug, fs, path::Path, time::Instant}; +use std::{ffi::OsStr, fmt::Debug, fs, path::Path}; use bitflags::bitflags; use fontbe::{ @@ -8,7 +8,7 @@ use fontbe::{ paths::Paths as BePaths, }; -use crate::{work::AnyWork, workload::Workload, Config, Error}; +use crate::{create_timer, timing::JobTimer, work::AnyWork, workload::Workload, Config, Error}; use fontdrasil::types::GlyphName; use fontir::{ orchestration::WorkId as FeWorkIdentifier, @@ -57,7 +57,12 @@ impl ChangeDetector { config: Config, ir_paths: IrPaths, prev_inputs: Input, + timer: &mut JobTimer, ) -> Result { + let time = create_timer(AnyWorkId::InternalTiming("new change detector")) + .queued() + .run(); + let mut ir_source = ir_source(&config.args.source)?; let mut current_inputs = ir_source.inputs().map_err(Error::FontIrError)?; let be_paths = BePaths::new(ir_paths.build_dir()); @@ -79,6 +84,8 @@ impl ChangeDetector { }); } + timer.add(time.complete()); + Ok(ChangeDetector { glyph_name_filter, ir_paths, @@ -115,6 +122,7 @@ impl ChangeDetector { match work_id { AnyWorkId::Fe(work_id) => self.ir_paths.target_file(work_id).is_file(), AnyWorkId::Be(work_id) => self.be_paths.target_file(work_id).is_file(), + AnyWorkId::InternalTiming(..) => false, } } @@ -165,8 +173,8 @@ impl ChangeDetector { workload.add(work, run); } - pub fn create_workload(&mut self, t0: Instant) -> Result { - let mut workload = Workload::new(self, t0); + pub fn create_workload(&mut self, timer: JobTimer) -> Result { + let mut workload = Workload::new(self, timer); // Create work roughly in the order it would typically occur // Work is eligible to run as soon as all dependencies are complete diff --git a/fontc/src/lib.rs b/fontc/src/lib.rs index 20c0acf3..076773cf 100644 --- a/fontc/src/lib.rs +++ b/fontc/src/lib.rs @@ -13,12 +13,12 @@ pub use change_detector::ChangeDetector; pub use config::Config; pub use error::Error; +pub use timing::{create_timer, JobTimer}; use workload::Workload; use std::{ fs, io, path::{Path, PathBuf}, - time::Instant, }; use fontbe::{ @@ -33,6 +33,7 @@ use fontbe::{ hvar::create_hvar_work, metrics_and_limits::create_metric_and_limit_work, name::create_name_work, + orchestration::AnyWorkId, os2::create_os2_work, post::create_post_work, stat::create_stat_work, @@ -290,9 +291,12 @@ fn add_glyph_be_job(workload: &mut Workload, glyph_name: GlyphName) { //FIXME: I should be a method on ChangeDetector pub fn create_workload( change_detector: &mut ChangeDetector, - t0: Instant, + timer: JobTimer, ) -> Result { - let mut workload = change_detector.create_workload(t0)?; + let time = create_timer(AnyWorkId::InternalTiming("Create workload")) + .queued() + .run(); + let mut workload = change_detector.create_workload(timer)?; // FE: f(source) => IR add_feature_ir_job(&mut workload)?; @@ -319,6 +323,8 @@ pub fn create_workload( // Make a damn font add_font_be_job(&mut workload)?; + workload.timer.add(time.complete()); + Ok(workload) } @@ -344,6 +350,7 @@ mod tests { path::{Path, PathBuf}, str::FromStr, sync::Arc, + time::Instant, }; use chrono::{Duration, TimeZone, Utc}; @@ -497,7 +504,7 @@ mod tests { } fn compile(args: Args) -> TestCompile { - let t0 = Instant::now(); + let mut timer = JobTimer::new(Instant::now()); let _ = env_logger::builder().is_test(true).try_init(); info!("Compile {args:?}"); @@ -508,9 +515,9 @@ mod tests { let prev_inputs = config.init().unwrap(); let mut change_detector = - ChangeDetector::new(config.clone(), ir_paths.clone(), prev_inputs).unwrap(); + ChangeDetector::new(config.clone(), ir_paths.clone(), prev_inputs, &mut timer).unwrap(); - let mut workload = create_workload(&mut change_detector, t0).unwrap(); + let mut workload = create_workload(&mut change_detector, timer).unwrap(); // Try to do the work // As we currently don't stress dependencies just run one by one diff --git a/fontc/src/main.rs b/fontc/src/main.rs index eaa5c2cc..30362527 100644 --- a/fontc/src/main.rs +++ b/fontc/src/main.rs @@ -6,8 +6,10 @@ use std::{ use clap::Parser; -use fontbe::orchestration::Context as BeContext; -use fontc::{init_paths, write_font_file, Args, ChangeDetector, Config, Error}; +use fontbe::orchestration::{AnyWorkId, Context as BeContext}; +use fontc::{ + create_timer, init_paths, write_font_file, Args, ChangeDetector, Config, Error, JobTimer, +}; use fontir::orchestration::{Context as FeContext, Flags}; fn main() { @@ -20,7 +22,10 @@ fn main() { } fn run() -> Result<(), Error> { - let t0 = Instant::now(); + let mut timer = JobTimer::new(Instant::now()); + let time = create_timer(AnyWorkId::InternalTiming("Init logger")) + .queued() + .run(); env_logger::builder() .format(|buf, record| { let ts = buf.timestamp_micros(); @@ -36,14 +41,21 @@ fn run() -> Result<(), Error> { ) }) .init(); + timer.add(time.complete()); + let time = create_timer(AnyWorkId::InternalTiming("Init config")) + .queued() + .run(); let args = Args::parse(); let (ir_paths, be_paths) = init_paths(&args)?; let config = Config::new(args)?; let prev_inputs = config.init()?; + timer.add(time.complete()); + + let mut change_detector = + ChangeDetector::new(config.clone(), ir_paths.clone(), prev_inputs, &mut timer)?; - let mut change_detector = ChangeDetector::new(config.clone(), ir_paths.clone(), prev_inputs)?; - let workload = fontc::create_workload(&mut change_detector, t0)?; + let workload = fontc::create_workload(&mut change_detector, timer)?; let fe_root = FeContext::new_root( config.args.flags(), diff --git a/fontc/src/timing.rs b/fontc/src/timing.rs index 4f3b3779..beff22c0 100644 --- a/fontc/src/timing.rs +++ b/fontc/src/timing.rs @@ -29,7 +29,7 @@ impl JobTimer { } } - pub(crate) fn add(&mut self, timing: JobTime) { + pub fn add(&mut self, timing: JobTime) { self.job_times .entry(timing.thread_id) .or_default() @@ -143,7 +143,7 @@ fn short_name(id: &AnyWorkId) -> &'static str { AnyWorkId::Be(BeWorkIdentifier::Os2) => "OS/2", AnyWorkId::Be(BeWorkIdentifier::Post) => "post", AnyWorkId::Be(BeWorkIdentifier::Stat) => "STAT", - AnyWorkId::Fe(FeWorkIdentifier::Overhead) => ".", + AnyWorkId::InternalTiming(name) => name, } } @@ -181,7 +181,7 @@ fn color(id: &AnyWorkId) -> &'static str { AnyWorkId::Be(BeWorkIdentifier::Os2) => "gray", AnyWorkId::Be(BeWorkIdentifier::Post) => "gray", AnyWorkId::Be(BeWorkIdentifier::Stat) => "gray", - AnyWorkId::Fe(FeWorkIdentifier::Overhead) => "#009a00", + AnyWorkId::InternalTiming(..) => "#009a00", } } @@ -189,7 +189,7 @@ fn color(id: &AnyWorkId) -> &'static str { /// /// Meant to be called when a job is runnable, that is it's ready to be /// submitted to an execution system such as a threadpool. -pub(crate) fn create_timer(id: AnyWorkId) -> JobTimeRunnable { +pub fn create_timer(id: AnyWorkId) -> JobTimeRunnable { JobTimeRunnable { id, runnable: Instant::now(), @@ -199,7 +199,7 @@ pub(crate) fn create_timer(id: AnyWorkId) -> JobTimeRunnable { /// The initial state of a runnable job. /// /// It may have queued from t0 to launchable but now it's go-time! -pub(crate) struct JobTimeRunnable { +pub struct JobTimeRunnable { id: AnyWorkId, runnable: Instant, } @@ -215,7 +215,7 @@ impl JobTimeRunnable { } } -pub(crate) struct JobTimeQueued { +pub struct JobTimeQueued { id: AnyWorkId, runnable: Instant, queued: Instant, @@ -237,7 +237,7 @@ impl JobTimeQueued { } } -pub(crate) struct JobTimeRunning { +pub struct JobTimeRunning { id: AnyWorkId, thread: ThreadId, runnable: Instant, @@ -263,7 +263,7 @@ impl JobTimeRunning { /// Times are relative to t0 in a [JobTimer] #[derive(Debug)] -pub(crate) struct JobTime { +pub struct JobTime { id: AnyWorkId, thread_id: ThreadId, _runnable: Instant, diff --git a/fontc/src/work.rs b/fontc/src/work.rs index 387ca0c6..5a00d7ef 100644 --- a/fontc/src/work.rs +++ b/fontc/src/work.rs @@ -170,6 +170,9 @@ impl AnyContext { Access::custom(move |id: &WorkId| read_access.check(&AnyWorkId::Fe(id.clone()))), Access::custom(move |id: &WorkId| write_access.check(&AnyWorkId::Fe(id.clone()))), )), + AnyWorkId::InternalTiming(..) => { + panic!("Should never create a context for internal timing") + } } } diff --git a/fontc/src/workload.rs b/fontc/src/workload.rs index 5b0ce9cf..f47d5fad 100644 --- a/fontc/src/workload.rs +++ b/fontc/src/workload.rs @@ -7,7 +7,6 @@ use std::{ atomic::{AtomicBool, Ordering}, Arc, }, - time::Instant, }; use crossbeam_channel::{Receiver, TryRecvError}; @@ -37,7 +36,7 @@ pub struct Workload<'a> { also_completes: HashMap>, pub(crate) jobs_pending: HashMap, - timing: JobTimer, + pub(crate) timer: JobTimer, } /// A unit of executable work plus the identifiers of work that it depends on @@ -64,7 +63,7 @@ enum RecvType { } impl<'a> Workload<'a> { - pub fn new(change_detector: &'a ChangeDetector, t0: Instant) -> Workload { + pub fn new(change_detector: &'a ChangeDetector, timer: JobTimer) -> Workload { Workload { change_detector, job_count: 0, @@ -72,7 +71,7 @@ impl<'a> Workload<'a> { error: Default::default(), also_completes: Default::default(), jobs_pending: Default::default(), - timing: JobTimer::new(t0), + timer, } } @@ -166,7 +165,7 @@ impl<'a> Workload<'a> { fn handle_success(&mut self, fe_root: &FeContext, success: AnyWorkId, timing: JobTime) { log::debug!("{success:?} successful"); - self.timing.add(timing); + self.timer.add(timing); self.mark_also_completed(&success); @@ -229,7 +228,7 @@ impl<'a> Workload<'a> { } pub fn launchable(&mut self) -> Vec { - let timing = create_timer(AnyWorkId::Fe(FeWorkIdentifier::Overhead)) + let timing = create_timer(AnyWorkId::InternalTiming("Launchable")) .queued() .run(); @@ -246,7 +245,7 @@ impl<'a> Workload<'a> { .collect(); trace!("Launchable: {launchable:?}"); - self.timing.add(timing.complete()); + self.timer.add(timing.complete()); launchable } @@ -360,7 +359,7 @@ impl<'a> Workload<'a> { ); } - Ok(self.timing) + Ok(self.timer) } fn read_completions( diff --git a/fontir/src/orchestration.rs b/fontir/src/orchestration.rs index 62dc4a1a..42b3deeb 100644 --- a/fontir/src/orchestration.rs +++ b/fontir/src/orchestration.rs @@ -327,8 +327,6 @@ pub enum WorkId { Features, Kerning, Anchor(GlyphName), - /// Bucket to attribute overhead - Overhead, } impl Identifier for WorkId {} diff --git a/fontir/src/paths.rs b/fontir/src/paths.rs index fe161681..d7bf9554 100644 --- a/fontir/src/paths.rs +++ b/fontir/src/paths.rs @@ -65,7 +65,6 @@ impl Paths { } WorkId::Features => self.build_dir.join("features.yml"), WorkId::Kerning => self.build_dir.join("kerning.yml"), - WorkId::Overhead => panic!("Should never write the overhead file"), } } }