add option to report timing, as well as reporting time taken to output

lucetc/lucetc/main.rs

@@ -10,10 +10,12 @@ use lucet_module::bindings::Bindings;
 use lucet_validate::Validator;
 use lucetc::{
     signature::{self, PublicKey},
+    timing::TimingInfo,
     Lucetc, LucetcOpts,
 };
 use serde::Serialize;
 use serde_json;
+use serde_json::json;
 use std::path::PathBuf;
 use std::process;
 
@@ -39,20 +41,45 @@ fn main() {
 
     let opts = Options::get().unwrap();
 
-    if let Err(err) = run(&opts) {
-        match opts.error_style {
-            ErrorStyle::Human => {
+    let compile_result = run(&opts);
+
+    let encountered_error = compile_result.is_err();
+
+    let timing_info = if opts.report_times {
+        Some(TimingInfo::collect())
+    } else {
+        None
+    };
+
+    match opts.error_style {
+        ErrorStyle::Human => {
+            if let Err(err) = &compile_result {
                 eprintln!("Error: {}\n", err);
                 if let Some(cause) = err.as_fail().cause() {
                     eprintln!("{}", cause);
                 }
             }
-            ErrorStyle::Json => {
-                let errs: Vec<SerializedLucetcError> = vec![err.into()];
-                let json = serde_json::to_string(&errs).unwrap();
-                eprintln!("{}", json);
+            if let Some(timing_info) = timing_info {
+                // reproduce the header from cranelift-codegen
+                eprintln!("======== ========  ==================================");
+                eprintln!("   Total     Self  Pass");
+                eprintln!("-------- --------- ----------------------------------");
+                eprintln!("{}", timing_info);
             }
         }
+        ErrorStyle::Json => {
+            let errs: Option<Vec<SerializedLucetcError>> =
+                compile_result.err().map(|err| vec![err.into()]);
+            let result = json!({
+                "errors": errs,
+                "timing": timing_info,
+            });
+            let json = serde_json::to_string(&result).unwrap();
+            eprintln!("{}", json);
+        }
+    }
+
+    if encountered_error {
         process::exit(1);
     }
 }
@@ -139,7 +166,8 @@ pub fn run(opts: &Options) -> Result<(), Error> {
         CodegenOutput::Obj => c.object_file(&opts.output)?,
         CodegenOutput::SharedObj => c.shared_object_file(&opts.output)?,
         CodegenOutput::Clif => c.clif_ir(&opts.output)?,
-    }
+    };
+
     Ok(())
 }
 

lucetc/lucetc/options.rs

@@ -118,6 +118,7 @@ pub struct Options {
     pub pk_path: Option<PathBuf>,
     pub sk_path: Option<PathBuf>,
     pub count_instructions: bool,
+    pub report_times: bool,
     pub error_style: ErrorStyle,
 }
 
@@ -196,6 +197,7 @@ impl Options {
         let sk_path = m.value_of("sk_path").map(PathBuf::from);
         let pk_path = m.value_of("pk_path").map(PathBuf::from);
         let count_instructions = m.is_present("count_instructions");
+        let report_times = m.is_present("report_times");
 
         let error_style = match m.value_of("error_style") {
             None => ErrorStyle::default(),
@@ -224,6 +226,7 @@ impl Options {
             sk_path,
             pk_path,
             count_instructions,
+            report_times,
             error_style,
         })
     }
@@ -429,6 +432,12 @@ SSE3 but not AVX:
                     .takes_value(false)
                     .help("Instrument the produced binary to count the number of wasm operations the translated program executes")
             )
+            .arg(
+                Arg::with_name("report_times")
+                    .long("--report-times")
+                    .takes_value(false)
+                    .help("Report times for lucetc and cranelift compilation passes")
+            )
             .arg(
                 Arg::with_name("error_style")
                     .long("error-style")

lucetc/src/compiler.rs

@@ -23,6 +23,7 @@ use failure::{format_err, Fail, ResultExt};
 use lucet_module::bindings::Bindings;
 use lucet_module::{FunctionSpec, ModuleData, ModuleFeatures, MODULE_DATA_SYM};
 use lucet_validate::Validator;
+use std::time::Instant;
 
 #[derive(Debug, Clone, Copy)]
 pub enum OptLevel {
@@ -196,13 +197,18 @@ impl<'a> Compiler<'a> {
             })
             .collect();
 
+        let object_start = Instant::now();
+
         let obj = ObjectFile::new(
             self.clif_module.finish(),
             module_data_len,
             function_manifest,
             table_names,
         )
         .context(LucetcErrorKind::Output)?;
+
+        crate::timing::record_output_time(object_start.elapsed());
+
         Ok(obj)
     }
 

lucetc/src/lib.rs

@@ -17,6 +17,7 @@ pub mod signature;
 mod sparsedata;
 mod stack_probe;
 mod table;
+pub mod timing;
 mod traps;
 mod types;
 
@@ -34,6 +35,7 @@ pub use lucet_validate::Validator;
 use signature::{PublicKey, SecretKey};
 use std::env;
 use std::path::{Path, PathBuf};
+use std::time::Instant;
 use tempfile;
 
 enum LucetcInput {
@@ -54,6 +56,7 @@ pub struct Lucetc {
     sign: bool,
     verify: bool,
     count_instructions: bool,
+    report_times: bool,
 }
 
 pub trait AsLucetc {
@@ -110,6 +113,8 @@ pub trait LucetcOpts {
     fn with_sign(self) -> Self;
     fn count_instructions(&mut self, enable_count: bool);
     fn with_count_instructions(self, enable_count: bool) -> Self;
+    fn report_times(&mut self, report_times: bool);
+    fn with_report_times(self, report_times: bool) -> Self;
 }
 
 impl<T: AsLucetc> LucetcOpts for T {
@@ -241,6 +246,15 @@ impl<T: AsLucetc> LucetcOpts for T {
         self.count_instructions(count_instructions);
         self
     }
+
+    fn report_times(&mut self, report_times: bool) {
+        self.as_lucetc().report_times = report_times;
+    }
+
+    fn with_report_times(mut self, report_times: bool) -> Self {
+        self.report_times(report_times);
+        self
+    }
 }
 
 impl Lucetc {
@@ -259,6 +273,7 @@ impl Lucetc {
             sign: false,
             verify: false,
             count_instructions: false,
+            report_times: false,
         }
     }
 
@@ -277,6 +292,7 @@ impl Lucetc {
             sign: false,
             verify: false,
             count_instructions: false,
+            report_times: false,
         })
     }
 
@@ -339,11 +355,15 @@ impl Lucetc {
             &self.validator,
         )?;
 
+        let output_start = Instant::now();
+
         compiler
             .cranelift_funcs()?
             .write(&output)
             .context("writing clif file")?;
 
+        timing::record_output_time(output_start.elapsed());
+
         Ok(())
     }
 

lucetc/src/timing.rs

@@ -0,0 +1,68 @@
+use crate::timing;
+use serde::Serialize;
+use std::cell::RefCell;
+use std::fmt;
+use std::mem;
+use std::time::Duration;
+
+thread_local! {
+    static OUTPUT_TIME: RefCell<Duration> = RefCell::new(Duration::default());
+}
+
+pub(crate) fn record_output_time(duration: Duration) {
+    OUTPUT_TIME.with(|rc| *rc.borrow_mut() = duration);
+}
+
+pub fn take_output_time() -> Duration {
+    OUTPUT_TIME.with(|rc| mem::replace(&mut *rc.borrow_mut(), Duration::default()))
+}
+
+#[derive(Serialize)]
+pub struct TimingInfo {
+    pass_times: Vec<String>,
+}
+
+impl TimingInfo {
+    pub fn collect() -> Self {
+        // `cranelift_codegen::timing::PassTimes` has hidden members at the moment
+        // so the best we can do consistently without deep sins like transmutes is to just split
+        // some strings.
+        let mut pass_times: Vec<String> = vec![];
+        let cranelift_time_text = cranelift_codegen::timing::take_current().to_string();
+        // skip the header text from Cranelift's `Display`, then take until we hit the end (also
+        // "======= ======= ==...")
+        for pass in cranelift_time_text
+            .split("\n")
+            .skip(3)
+            .take_while(|line| !line.starts_with("========"))
+        {
+            pass_times.push(pass.to_string());
+        }
+
+        // and now add our own recording of how long it took to write output
+        let output_time = timing::take_output_time();
+        if output_time != Duration::default() {
+            // Round to nearest ms by adding 500us (copied from cranelift-codegen)
+            let output_time = output_time + Duration::new(0, 500_000);
+            let ms = output_time.subsec_millis();
+            let secs = output_time.as_secs();
+            // match cranelift pass timing format
+            pass_times.push(format!(
+                "{:4}.{:03} {:4}.{:03}  Emit output",
+                secs, ms, secs, ms
+            ));
+        }
+
+        Self { pass_times }
+    }
+}
+
+impl fmt::Display for TimingInfo {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        for pass in self.pass_times.iter() {
+            writeln!(f, "{}", pass)?;
+        }
+
+        Ok(())
+    }
+}