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

lucetc/lucetc/main.rs

@@ -16,6 +16,7 @@ use serde::Serialize;
 use serde_json;
 use std::path::PathBuf;
 use std::process;
+use std::time::Duration;
 
 #[derive(Clone, Debug, Serialize)]
 pub struct SerializedLucetcError {
@@ -135,11 +136,26 @@ pub fn run(opts: &Options) -> Result<(), Error> {
         c.count_instructions(true);
     }
 
-    match opts.codegen {
-        CodegenOutput::Obj => c.object_file(&opts.output)?,
-        CodegenOutput::SharedObj => c.shared_object_file(&opts.output)?,
-        CodegenOutput::Clif => c.clif_ir(&opts.output)?,
+    let codegen_result = match opts.codegen {
+        CodegenOutput::Obj => c.object_file(&opts.output),
+        CodegenOutput::SharedObj => c.shared_object_file(&opts.output),
+        CodegenOutput::Clif => c.clif_ir(&opts.output),
+    };
+
+    if opts.report_times {
+        println!("--- compilation timing ---");
+        println!("cranelift:\n{}", cranelift_codegen::timing::take_current());
+    }
+
+    let write_time = codegen_result?;
+
+    if opts.report_times {
+        // Round to nearest ms by adding 500us (copied from cranelift-codegen)
+        let write_time = write_time + Duration::new(0, 500_000);
+        let ms = write_time.subsec_millis();
+        println!("output: {:4}.{:03}", write_time.as_secs(), ms);
     }
+
     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::{Duration, Instant};
 
 #[derive(Debug, Clone, Copy)]
 pub enum OptLevel {
@@ -142,7 +143,7 @@ impl<'a> Compiler<'a> {
         self.decls.get_module_data(self.module_features())
     }
 
-    pub fn object_file(mut self) -> Result<ObjectFile, LucetcError> {
+    pub fn object_file(mut self) -> Result<(ObjectFile, Duration), LucetcError> {
         let mut func_translator = FuncTranslator::new();
 
         for (ref func, (code, code_offset)) in self.decls.function_bodies() {
@@ -196,14 +197,19 @@ impl<'a> Compiler<'a> {
             })
             .collect();
 
+        let start = Instant::now();
+
         let obj = ObjectFile::new(
             self.clif_module.finish(),
             module_data_len,
             function_manifest,
             table_names,
         )
         .context(LucetcErrorKind::Output)?;
-        Ok(obj)
+
+        let duration = start.elapsed();
+
+        Ok((obj, duration))
     }
 
     pub fn cranelift_funcs(self) -> Result<CraneliftFuncs, LucetcError> {

lucetc/src/lib.rs

@@ -34,6 +34,7 @@ pub use lucet_validate::Validator;
 use signature::{PublicKey, SecretKey};
 use std::env;
 use std::path::{Path, PathBuf};
+use std::time::{Duration, Instant};
 use tempfile;
 
 enum LucetcInput {
@@ -54,6 +55,7 @@ pub struct Lucetc {
     sign: bool,
     verify: bool,
     count_instructions: bool,
+    report_times: bool,
 }
 
 pub trait AsLucetc {
@@ -110,6 +112,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 +245,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 +272,7 @@ impl Lucetc {
             sign: false,
             verify: false,
             count_instructions: false,
+            report_times: false,
         }
     }
 
@@ -277,6 +291,7 @@ impl Lucetc {
             sign: false,
             verify: false,
             count_instructions: false,
+            report_times: false,
         })
     }
 
@@ -308,7 +323,7 @@ impl Lucetc {
         Ok((module_binary, bindings))
     }
 
-    pub fn object_file<P: AsRef<Path>>(&self, output: P) -> Result<(), Error> {
+    pub fn object_file<P: AsRef<Path>>(&self, output: P) -> Result<Duration, Error> {
         let (module_contents, bindings) = self.build()?;
 
         let compiler = Compiler::new(
@@ -320,13 +335,13 @@ impl Lucetc {
             self.count_instructions,
             &self.validator,
         )?;
-        let obj = compiler.object_file()?;
+        let (obj, duration) = compiler.object_file()?;
 
         obj.write(output.as_ref()).context("writing object file")?;
-        Ok(())
+        Ok(duration)
     }
 
-    pub fn clif_ir<P: AsRef<Path>>(&self, output: P) -> Result<(), Error> {
+    pub fn clif_ir<P: AsRef<Path>>(&self, output: P) -> Result<Duration, Error> {
         let (module_contents, bindings) = self.build()?;
 
         let compiler = Compiler::new(
@@ -339,26 +354,30 @@ impl Lucetc {
             &self.validator,
         )?;
 
+        let start = Instant::now();
+
         compiler
             .cranelift_funcs()?
             .write(&output)
             .context("writing clif file")?;
 
-        Ok(())
+        let duration = start.elapsed();
+
+        Ok(duration)
     }
 
-    pub fn shared_object_file<P: AsRef<Path>>(&self, output: P) -> Result<(), Error> {
+    pub fn shared_object_file<P: AsRef<Path>>(&self, output: P) -> Result<Duration, Error> {
         let dir = tempfile::Builder::new().prefix("lucetc").tempdir()?;
         let objpath = dir.path().join("tmp.o");
-        self.object_file(objpath.clone())?;
+        let object_build_time = self.object_file(objpath.clone())?;
         link_so(objpath, &output)?;
         if self.sign {
             let sk = self.sk.as_ref().ok_or(
                 format_err!("signing requires a secret key").context(LucetcErrorKind::Signature),
             )?;
             signature::sign_module(&output, sk)?;
         }
-        Ok(())
+        Ok(object_build_time)
     }
 }