Merge pull request #564 from googlefonts/what

Capture timing for early stages

fontbe/src/orchestration.rs

@@ -98,22 +98,24 @@ 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 {}
 
 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"),
         }
     }
 }

fontc/src/change_detector.rs

@@ -1,14 +1,14 @@
 //! 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::{
     orchestration::{AnyWorkId, WorkId as BeWorkIdentifier},
     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<ChangeDetector, Error> {
+        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<Workload, Error> {
-        let mut workload = Workload::new(self, t0);
+    pub fn create_workload(&mut self, timer: JobTimer) -> Result<Workload, Error> {
+        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

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<Workload, Error> {
-    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

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(),

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,15 +181,15 @@ 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",
     }
 }
 
 /// Start timing a job.
 ///
 /// 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,

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")
+            }
         }
     }
 

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<AnyWorkId, Vec<AnyWorkId>>,
     pub(crate) jobs_pending: HashMap<AnyWorkId, Job>,
 
-    timing: JobTimer,
+    pub(crate) timer: JobTimer,
 }
 
 /// A unit of executable work plus the identifiers of work that it depends on
@@ -64,15 +63,15 @@ 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,
             success: Default::default(),
             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<AnyWorkId> {
-        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(

fontir/src/orchestration.rs

@@ -327,8 +327,6 @@ pub enum WorkId {
     Features,
     Kerning,
     Anchor(GlyphName),
-    /// Bucket to attribute overhead
-    Overhead,
 }
 
 impl Identifier for WorkId {}

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"),
         }
     }
 }