diff --git a/Cargo.lock b/Cargo.lock index d6fff5a365c..5a10a5f71c2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -86,6 +86,11 @@ name = "quote" version = "0.3.15" source = "registry+https://github.com/rust-lang/crates.io-index" +[[package]] +name = "redox_syscall" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" + [[package]] name = "regex" version = "0.2.2" @@ -120,6 +125,7 @@ dependencies = [ "serde_json 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "strings 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)", "term 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", + "time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)", "toml 0.4.5 (registry+https://github.com/rust-lang/crates.io-index)", "unicode-segmentation 1.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "winapi 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)", @@ -204,6 +210,17 @@ dependencies = [ "unreachable 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)", ] +[[package]] +name = "time" +version = "0.1.38" +source = "registry+https://github.com/rust-lang/crates.io-index" +dependencies = [ + "kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)", + "libc 0.2.33 (registry+https://github.com/rust-lang/crates.io-index)", + "redox_syscall 0.1.31 (registry+https://github.com/rust-lang/crates.io-index)", + "winapi 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)", +] + [[package]] name = "toml" version = "0.4.5" @@ -265,6 +282,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" "checksum memchr 1.0.2 (registry+https://github.com/rust-lang/crates.io-index)" = "148fab2e51b4f1cfc66da2a7c32981d1d3c083a803978268bb11fe4b86925e7a" "checksum num-traits 0.1.40 (registry+https://github.com/rust-lang/crates.io-index)" = "99843c856d68d8b4313b03a17e33c4bb42ae8f6610ea81b28abe076ac721b9b0" "checksum quote 0.3.15 (registry+https://github.com/rust-lang/crates.io-index)" = "7a6e920b65c65f10b2ae65c831a81a073a89edd28c7cce89475bff467ab4167a" +"checksum redox_syscall 0.1.31 (registry+https://github.com/rust-lang/crates.io-index)" = "8dde11f18c108289bef24469638a04dce49da56084f2d50618b226e47eb04509" "checksum regex 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "1731164734096285ec2a5ec7fea5248ae2f5485b3feeb0115af4fda2183b2d1b" "checksum regex-syntax 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)" = "ad890a5eef7953f55427c50575c680c42841653abd2b028b68cd223d157f62db" "checksum serde 1.0.18 (registry+https://github.com/rust-lang/crates.io-index)" = "395993cac4e3599c7c1b70a6a92d3b3f55f4443df9f0b5294e362285ad7c9ecb" @@ -276,6 +294,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" "checksum synom 0.11.3 (registry+https://github.com/rust-lang/crates.io-index)" = "a393066ed9010ebaed60b9eafa373d4b1baac186dd7e008555b0f702b51945b6" "checksum term 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)" = "fa63644f74ce96fbeb9b794f66aff2a52d601cbd5e80f4b97123e3899f4570f1" "checksum thread_local 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)" = "1697c4b57aeeb7a536b647165a2825faddffb1d3bad386d507709bd51a90bb14" +"checksum time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)" = "d5d788d3aa77bc0ef3e9621256885555368b47bd495c13dd2e7413c89f845520" "checksum toml 0.4.5 (registry+https://github.com/rust-lang/crates.io-index)" = "a7540f4ffc193e0d3c94121edb19b055670d369f77d5804db11ae053a45b6e7e" "checksum unicode-segmentation 1.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "a8083c594e02b8ae1654ae26f0ade5158b119bd88ad0e8227a5d8fcd72407946" "checksum unicode-xid 0.0.4 (registry+https://github.com/rust-lang/crates.io-index)" = "8c1f860d7d29cf02cb2f3f359fd35991af3d30bac52c57d265a3c461074cb4dc" diff --git a/src/lib.rs b/src/lib.rs index 1eec30833b9..2f8cf3e04f6 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -32,6 +32,7 @@ use std::io::{self, stdout, Write}; use std::iter::repeat; use std::path::{Path, PathBuf}; use std::rc::Rc; +use std::time::Duration; use errors::{DiagnosticBuilder, Handler}; use errors::emitter::{ColorConfig, EmitterWriter}; @@ -518,6 +519,8 @@ pub fn format_input( } }; + summary.mark_parse_time(); + if parse_session.span_diagnostic.has_errors() { summary.add_parsing_error(); } @@ -532,7 +535,7 @@ pub fn format_input( let mut report = FormatReport::new(); - match format_ast( + let format_result = format_ast( &krate, &mut parse_session, &main_file, @@ -549,7 +552,23 @@ pub fn format_input( } Ok(false) }, - ) { + ); + + summary.mark_format_time(); + + if config.verbose() { + fn duration_to_f32(d: Duration) -> f32 { + d.as_secs() as f32 + d.subsec_nanos() as f32 / 1_000_000_000f32 + } + + println!( + "Spent {0:.3} secs in the parsing phase, and {1:.3} secs in the formatting phase", + duration_to_f32(summary.get_parse_time().unwrap()), + duration_to_f32(summary.get_format_time().unwrap()), + ); + } + + match format_result { Ok((file_map, has_diff)) => { if report.has_warnings() { summary.add_formatting_error(); diff --git a/src/summary.rs b/src/summary.rs index cf034e7dff6..6e99d3392eb 100644 --- a/src/summary.rs +++ b/src/summary.rs @@ -1,3 +1,6 @@ +use std::time::{Duration, Instant}; +use std::default::Default; + #[must_use] #[derive(Debug, Default, Clone)] pub struct Summary { @@ -12,9 +15,42 @@ pub struct Summary { // Formatted code differs from existing code (write-mode diff only). pub has_diff: bool, + + // Keeps track of time spent in parsing and formatting steps. + timer: Timer, } impl Summary { + pub fn mark_parse_time(&mut self) { + self.timer = self.timer.done_parsing(); + } + + pub fn mark_format_time(&mut self) { + self.timer = self.timer.done_formatting(); + } + + /// Returns the time it took to parse the source files in nanoseconds. + pub fn get_parse_time(&self) -> Option { + match self.timer { + Timer::DoneParsing(init, parse_time) | Timer::DoneFormatting(init, parse_time, _) => { + // This should never underflow since `Instant::now()` guarantees monotonicity. + Some(parse_time.duration_since(init)) + } + Timer::Initialized(..) => None, + } + } + + /// Returns the time it took to go from the parsed AST to the formatted output. Parsing time is + /// not included. + pub fn get_format_time(&self) -> Option { + match self.timer { + Timer::DoneFormatting(_init, parse_time, format_time) => { + Some(format_time.duration_since(parse_time)) + } + Timer::DoneParsing(..) | Timer::Initialized(..) => None, + } + } + pub fn has_operational_errors(&self) -> bool { self.has_operational_errors } @@ -65,3 +101,34 @@ impl Summary { println!("{}", exit_codes); } } + +#[derive(Clone, Copy, Debug)] +enum Timer { + Initialized(Instant), + DoneParsing(Instant, Instant), + DoneFormatting(Instant, Instant, Instant), +} + +impl Default for Timer { + fn default() -> Self { + Timer::Initialized(Instant::now()) + } +} + +impl Timer { + fn done_parsing(self) -> Self { + match self { + Timer::Initialized(init_time) => Timer::DoneParsing(init_time, Instant::now()), + _ => panic!("Timer can only transition to DoneParsing from Initialized state"), + } + } + + fn done_formatting(self) -> Self { + match self { + Timer::DoneParsing(init_time, parse_time) => { + Timer::DoneFormatting(init_time, parse_time, Instant::now()) + } + _ => panic!("Timer can only transition to DoneFormatting from DoneParsing state"), + } + } +}