diff --git a/lucetc/lucetc/main.rs b/lucetc/lucetc/main.rs index 55ddbb67d..9fa7b3fe9 100644 --- a/lucetc/lucetc/main.rs +++ b/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 = 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> = + 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); } } diff --git a/lucetc/lucetc/options.rs b/lucetc/lucetc/options.rs index 332dbbb36..91b74b9e1 100644 --- a/lucetc/lucetc/options.rs +++ b/lucetc/lucetc/options.rs @@ -118,6 +118,7 @@ pub struct Options { pub pk_path: Option, pub sk_path: Option, 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") diff --git a/lucetc/src/compiler.rs b/lucetc/src/compiler.rs index b5f80c4ce..ebe9c297c 100644 --- a/lucetc/src/compiler.rs +++ b/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,6 +197,8 @@ impl<'a> Compiler<'a> { }) .collect(); + let object_start = Instant::now(); + let obj = ObjectFile::new( self.clif_module.finish(), module_data_len, @@ -203,6 +206,9 @@ impl<'a> Compiler<'a> { table_names, ) .context(LucetcErrorKind::Output)?; + + crate::timing::record_output_time(object_start.elapsed()); + Ok(obj) } diff --git a/lucetc/src/lib.rs b/lucetc/src/lib.rs index a37cf8c9c..abaffc14a 100644 --- a/lucetc/src/lib.rs +++ b/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 LucetcOpts for T { @@ -241,6 +246,15 @@ impl 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(()) } diff --git a/lucetc/src/timing.rs b/lucetc/src/timing.rs new file mode 100644 index 000000000..40056a7c6 --- /dev/null +++ b/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 = 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, +} + +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 = 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(()) + } +}