From 100104bbda37335c8d86ebdb37937288455a755a Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 19 Dec 2019 14:57:16 -0800 Subject: [PATCH 1/5] add option to report timing, as well as reporting time taken to output --- lucetc/lucetc/main.rs | 24 ++++++++++++++++++++---- lucetc/lucetc/options.rs | 9 +++++++++ lucetc/src/compiler.rs | 10 ++++++++-- lucetc/src/lib.rs | 35 +++++++++++++++++++++++++++-------- 4 files changed, 64 insertions(+), 14 deletions(-) diff --git a/lucetc/lucetc/main.rs b/lucetc/lucetc/main.rs index 55ddbb67d..fa26b4fe0 100644 --- a/lucetc/lucetc/main.rs +++ b/lucetc/lucetc/main.rs @@ -14,6 +14,7 @@ use lucetc::{ }; use serde::Serialize; use serde_json; +use std::time::Duration; use std::path::PathBuf; use std::process; @@ -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(()) } 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..fbaa934de 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::{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 { + 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,6 +197,8 @@ impl<'a> Compiler<'a> { }) .collect(); + let start = Instant::now(); + let obj = ObjectFile::new( self.clif_module.finish(), module_data_len, @@ -203,7 +206,10 @@ impl<'a> Compiler<'a> { table_names, ) .context(LucetcErrorKind::Output)?; - Ok(obj) + + let duration = start.elapsed(); + + Ok((obj, duration)) } pub fn cranelift_funcs(self) -> Result { diff --git a/lucetc/src/lib.rs b/lucetc/src/lib.rs index a37cf8c9c..0bf2de326 100644 --- a/lucetc/src/lib.rs +++ b/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 LucetcOpts for T { @@ -241,6 +245,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 +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>(&self, output: P) -> Result<(), Error> { + pub fn object_file>(&self, output: P) -> Result { 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>(&self, output: P) -> Result<(), Error> { + pub fn clif_ir>(&self, output: P) -> Result { let (module_contents, bindings) = self.build()?; let compiler = Compiler::new( @@ -339,18 +354,22 @@ 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>(&self, output: P) -> Result<(), Error> { + pub fn shared_object_file>(&self, output: P) -> Result { 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( @@ -358,7 +377,7 @@ impl Lucetc { )?; signature::sign_module(&output, sk)?; } - Ok(()) + Ok(object_build_time) } } From 8a5d3d0f314e12d0a6f3d55a172feca8ec6ae5fc Mon Sep 17 00:00:00 2001 From: iximeow Date: Thu, 19 Dec 2019 15:03:17 -0800 Subject: [PATCH 2/5] rustfmt!!! --- lucetc/lucetc/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lucetc/lucetc/main.rs b/lucetc/lucetc/main.rs index fa26b4fe0..b5844bed3 100644 --- a/lucetc/lucetc/main.rs +++ b/lucetc/lucetc/main.rs @@ -14,9 +14,9 @@ use lucetc::{ }; use serde::Serialize; use serde_json; -use std::time::Duration; use std::path::PathBuf; use std::process; +use std::time::Duration; #[derive(Clone, Debug, Serialize)] pub struct SerializedLucetcError { From dd28cb4bece35314e63484a378cb795c0a840714 Mon Sep 17 00:00:00 2001 From: iximeow Date: Fri, 20 Dec 2019 17:40:28 -0800 Subject: [PATCH 3/5] make timing information respect selected error style --- lucetc/lucetc/main.rs | 64 +++++++++++++++++++++++++----------------- lucetc/src/compiler.rs | 10 +++---- lucetc/src/lib.rs | 23 +++++++-------- 3 files changed, 55 insertions(+), 42 deletions(-) diff --git a/lucetc/lucetc/main.rs b/lucetc/lucetc/main.rs index b5844bed3..d79bbc372 100644 --- a/lucetc/lucetc/main.rs +++ b/lucetc/lucetc/main.rs @@ -10,13 +10,14 @@ 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; -use std::time::Duration; #[derive(Clone, Debug, Serialize)] pub struct SerializedLucetcError { @@ -40,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); } } @@ -136,26 +162,12 @@ pub fn run(opts: &Options) -> Result<(), Error> { c.count_instructions(true); } - 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), + 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(()) } diff --git a/lucetc/src/compiler.rs b/lucetc/src/compiler.rs index fbaa934de..ebe9c297c 100644 --- a/lucetc/src/compiler.rs +++ b/lucetc/src/compiler.rs @@ -23,7 +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}; +use std::time::Instant; #[derive(Debug, Clone, Copy)] pub enum OptLevel { @@ -143,7 +143,7 @@ impl<'a> Compiler<'a> { self.decls.get_module_data(self.module_features()) } - pub fn object_file(mut self) -> Result<(ObjectFile, Duration), LucetcError> { + pub fn object_file(mut self) -> Result { let mut func_translator = FuncTranslator::new(); for (ref func, (code, code_offset)) in self.decls.function_bodies() { @@ -197,7 +197,7 @@ impl<'a> Compiler<'a> { }) .collect(); - let start = Instant::now(); + let object_start = Instant::now(); let obj = ObjectFile::new( self.clif_module.finish(), @@ -207,9 +207,9 @@ impl<'a> Compiler<'a> { ) .context(LucetcErrorKind::Output)?; - let duration = start.elapsed(); + crate::timing::record_output_time(object_start.elapsed()); - Ok((obj, duration)) + Ok(obj) } pub fn cranelift_funcs(self) -> Result { diff --git a/lucetc/src/lib.rs b/lucetc/src/lib.rs index 0bf2de326..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,7 +35,7 @@ pub use lucet_validate::Validator; use signature::{PublicKey, SecretKey}; use std::env; use std::path::{Path, PathBuf}; -use std::time::{Duration, Instant}; +use std::time::Instant; use tempfile; enum LucetcInput { @@ -323,7 +324,7 @@ impl Lucetc { Ok((module_binary, bindings)) } - pub fn object_file>(&self, output: P) -> Result { + pub fn object_file>(&self, output: P) -> Result<(), Error> { let (module_contents, bindings) = self.build()?; let compiler = Compiler::new( @@ -335,13 +336,13 @@ impl Lucetc { self.count_instructions, &self.validator, )?; - let (obj, duration) = compiler.object_file()?; + let obj = compiler.object_file()?; obj.write(output.as_ref()).context("writing object file")?; - Ok(duration) + Ok(()) } - pub fn clif_ir>(&self, output: P) -> Result { + pub fn clif_ir>(&self, output: P) -> Result<(), Error> { let (module_contents, bindings) = self.build()?; let compiler = Compiler::new( @@ -354,22 +355,22 @@ impl Lucetc { &self.validator, )?; - let start = Instant::now(); + let output_start = Instant::now(); compiler .cranelift_funcs()? .write(&output) .context("writing clif file")?; - let duration = start.elapsed(); + timing::record_output_time(output_start.elapsed()); - Ok(duration) + Ok(()) } - pub fn shared_object_file>(&self, output: P) -> Result { + pub fn shared_object_file>(&self, output: P) -> Result<(), Error> { let dir = tempfile::Builder::new().prefix("lucetc").tempdir()?; let objpath = dir.path().join("tmp.o"); - let object_build_time = self.object_file(objpath.clone())?; + self.object_file(objpath.clone())?; link_so(objpath, &output)?; if self.sign { let sk = self.sk.as_ref().ok_or( @@ -377,7 +378,7 @@ impl Lucetc { )?; signature::sign_module(&output, sk)?; } - Ok(object_build_time) + Ok(()) } } From 18d76b071d71eabecedc7a5632f8d143bf97a24a Mon Sep 17 00:00:00 2001 From: iximeow Date: Fri, 20 Dec 2019 17:43:02 -0800 Subject: [PATCH 4/5] wow totally forgot that --- lucetc/src/timing.rs | 68 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 68 insertions(+) create mode 100644 lucetc/src/timing.rs 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(()) + } +} From 665cfa05f19d5e9f5d065be8ee2edf171dda2d1a Mon Sep 17 00:00:00 2001 From: iximeow Date: Fri, 20 Dec 2019 17:48:41 -0800 Subject: [PATCH 5/5] dont need that change to stick around --- lucetc/lucetc/main.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/lucetc/lucetc/main.rs b/lucetc/lucetc/main.rs index d79bbc372..9fa7b3fe9 100644 --- a/lucetc/lucetc/main.rs +++ b/lucetc/lucetc/main.rs @@ -166,8 +166,7 @@ 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(()) }