diff --git a/src/libtest/formatters/json.rs b/src/libtest/formatters/json.rs index e0bea4ce54530..d9e4abf61c3dc 100644 --- a/src/libtest/formatters/json.rs +++ b/src/libtest/formatters/json.rs @@ -27,6 +27,7 @@ impl JsonFormatter { ty: &str, name: &str, evt: &str, + exec_time: Option<&TestExecTime>, stdout: Option>, extra: Option<&str>, ) -> io::Result<()> { @@ -34,6 +35,12 @@ impl JsonFormatter { r#"{{ "type": "{}", "name": "{}", "event": "{}""#, ty, name, evt ))?; + if let Some(exec_time) = exec_time { + self.write_message(&*format!( + r#", "exec_time": "{}""#, + exec_time + ))?; + } if let Some(stdout) = stdout { self.write_message(&*format!( r#", "stdout": "{}""#, @@ -69,6 +76,7 @@ impl OutputFormatter for JsonFormatter { &mut self, desc: &TestDesc, result: &TestResult, + exec_time: Option<&TestExecTime>, stdout: &[u8], state: &ConsoleTestState, ) -> io::Result<()> { @@ -78,24 +86,36 @@ impl OutputFormatter for JsonFormatter { None }; match *result { - TrOk => self.write_event("test", desc.name.as_slice(), "ok", stdout, None), + TrOk => { + self.write_event("test", desc.name.as_slice(), "ok", exec_time, stdout, None) + } - TrFailed => self.write_event("test", desc.name.as_slice(), "failed", stdout, None), + TrFailed => { + self.write_event("test", desc.name.as_slice(), "failed", exec_time, stdout, None) + } TrFailedMsg(ref m) => self.write_event( "test", desc.name.as_slice(), "failed", + exec_time, stdout, Some(&*format!(r#""message": "{}""#, EscapedString(m))), ), - TrIgnored => self.write_event("test", desc.name.as_slice(), "ignored", stdout, None), - - TrAllowedFail => { - self.write_event("test", desc.name.as_slice(), "allowed_failure", stdout, None) + TrIgnored => { + self.write_event("test", desc.name.as_slice(), "ignored", exec_time, stdout, None) } + TrAllowedFail => self.write_event( + "test", + desc.name.as_slice(), + "allowed_failure", + exec_time, + stdout, + None, + ), + TrBench(ref bs) => { let median = bs.ns_iter_summ.median as usize; let deviation = (bs.ns_iter_summ.max - bs.ns_iter_summ.min) as usize; diff --git a/src/libtest/formatters/mod.rs b/src/libtest/formatters/mod.rs index cc30b06e5ec38..e97cda76d2318 100644 --- a/src/libtest/formatters/mod.rs +++ b/src/libtest/formatters/mod.rs @@ -16,6 +16,7 @@ pub(crate) trait OutputFormatter { &mut self, desc: &TestDesc, result: &TestResult, + exec_time: Option<&TestExecTime>, stdout: &[u8], state: &ConsoleTestState, ) -> io::Result<()>; diff --git a/src/libtest/formatters/pretty.rs b/src/libtest/formatters/pretty.rs index 88331406a64d0..184726c67d3fb 100644 --- a/src/libtest/formatters/pretty.rs +++ b/src/libtest/formatters/pretty.rs @@ -30,20 +30,20 @@ impl PrettyFormatter { &self.out } - pub fn write_ok(&mut self) -> io::Result<()> { - self.write_short_result("ok", term::color::GREEN) + pub fn write_ok(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> { + self.write_short_result("ok", term::color::GREEN, exec_time) } - pub fn write_failed(&mut self) -> io::Result<()> { - self.write_short_result("FAILED", term::color::RED) + pub fn write_failed(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> { + self.write_short_result("FAILED", term::color::RED, exec_time) } - pub fn write_ignored(&mut self) -> io::Result<()> { - self.write_short_result("ignored", term::color::YELLOW) + pub fn write_ignored(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> { + self.write_short_result("ignored", term::color::YELLOW, exec_time) } - pub fn write_allowed_fail(&mut self) -> io::Result<()> { - self.write_short_result("FAILED (allowed)", term::color::YELLOW) + pub fn write_allowed_fail(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> { + self.write_short_result("FAILED (allowed)", term::color::YELLOW, exec_time) } pub fn write_bench(&mut self) -> io::Result<()> { @@ -54,8 +54,12 @@ impl PrettyFormatter { &mut self, result: &str, color: term::color::Color, + exec_time: Option<&TestExecTime>, ) -> io::Result<()> { self.write_pretty(result, color)?; + if let Some(exec_time) = exec_time { + self.write_plain(format!(" {}", exec_time))?; + } self.write_plain("\n") } @@ -166,6 +170,7 @@ impl OutputFormatter for PrettyFormatter { &mut self, desc: &TestDesc, result: &TestResult, + exec_time: Option<&TestExecTime>, _: &[u8], _: &ConsoleTestState, ) -> io::Result<()> { @@ -174,10 +179,10 @@ impl OutputFormatter for PrettyFormatter { } match *result { - TrOk => self.write_ok(), - TrFailed | TrFailedMsg(_) => self.write_failed(), - TrIgnored => self.write_ignored(), - TrAllowedFail => self.write_allowed_fail(), + TrOk => self.write_ok(exec_time), + TrFailed | TrFailedMsg(_) => self.write_failed(exec_time), + TrIgnored => self.write_ignored(exec_time), + TrAllowedFail => self.write_allowed_fail(exec_time), TrBench(ref bs) => { self.write_bench()?; self.write_plain(&format!(": {}\n", fmt_bench_samples(bs))) diff --git a/src/libtest/formatters/terse.rs b/src/libtest/formatters/terse.rs index d10b0c5807d57..1812c20904c87 100644 --- a/src/libtest/formatters/terse.rs +++ b/src/libtest/formatters/terse.rs @@ -174,6 +174,7 @@ impl OutputFormatter for TerseFormatter { &mut self, desc: &TestDesc, result: &TestResult, + _: Option<&TestExecTime>, _: &[u8], _: &ConsoleTestState, ) -> io::Result<()> { diff --git a/src/libtest/lib.rs b/src/libtest/lib.rs index 09d5fcc89520e..e441514e59738 100644 --- a/src/libtest/lib.rs +++ b/src/libtest/lib.rs @@ -378,6 +378,7 @@ pub struct TestOpts { pub format: OutputFormat, pub test_threads: Option, pub skip: Vec, + pub report_time: bool, pub options: Options, } @@ -460,6 +461,11 @@ fn optgroups() -> getopts::Options { "Enable nightly-only flags: unstable-options = Allow use of experimental features", "unstable-options", + ) + .optflag( + "", + "report-time", + "Show execution time of each test. Not available for --format=terse" ); return opts; } @@ -560,6 +566,13 @@ pub fn parse_opts(args: &[String]) -> Option { )); } + let report_time = matches.opt_present("report-time"); + if !allow_unstable && report_time { + return Some(Err( + "The \"report-time\" flag is only accepted on the nightly compiler".into(), + )); + } + let run_ignored = match (include_ignored, matches.opt_present("ignored")) { (true, true) => { return Some(Err( @@ -653,6 +666,7 @@ pub fn parse_opts(args: &[String]) -> Option { format, test_threads, skip: matches.opt_strs("skip"), + report_time, options: Options::new().display_output(matches.opt_present("show-output")), }; @@ -677,6 +691,16 @@ pub enum TestResult { unsafe impl Send for TestResult {} +/// The meassured execution time of a unit test. +#[derive(Clone, PartialEq)] +pub struct TestExecTime(Duration); + +impl fmt::Display for TestExecTime { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:.3}s", self.0.as_secs_f64()) + } +} + enum OutputLocation { Pretty(Box), Raw(T), @@ -736,17 +760,30 @@ impl ConsoleTestState { }) } - pub fn write_log>(&mut self, msg: S) -> io::Result<()> { - let msg = msg.as_ref(); + pub fn write_log( + &mut self, + msg: F, + ) -> io::Result<()> + where + S: AsRef, + F: FnOnce() -> S, + { match self.log_out { None => Ok(()), - Some(ref mut o) => o.write_all(msg.as_bytes()), + Some(ref mut o) => { + let msg = msg(); + let msg = msg.as_ref(); + o.write_all(msg.as_bytes()) + }, } } - pub fn write_log_result(&mut self, test: &TestDesc, result: &TestResult) -> io::Result<()> { - self.write_log(format!( - "{} {}\n", + pub fn write_log_result(&mut self,test: &TestDesc, + result: &TestResult, + exec_time: Option<&TestExecTime>, + ) -> io::Result<()> { + self.write_log(|| format!( + "{} {}", match *result { TrOk => "ok".to_owned(), TrFailed => "failed".to_owned(), @@ -755,8 +792,12 @@ impl ConsoleTestState { TrAllowedFail => "failed (allowed)".to_owned(), TrBench(ref bs) => fmt_bench_samples(bs), }, - test.name - )) + test.name, + ))?; + if let Some(exec_time) = exec_time { + self.write_log(|| format!(" {}", exec_time))?; + } + self.write_log(|| "\n") } fn current_test_count(&self) -> usize { @@ -843,7 +884,7 @@ pub fn list_tests_console(opts: &TestOpts, tests: Vec) -> io::Res }; writeln!(output, "{}: {}", name, fntype)?; - st.write_log(format!("{} {}\n", fntype, name))?; + st.write_log(|| format!("{} {}\n", fntype, name))?; } fn plural(count: u32, s: &str) -> String { @@ -884,9 +925,9 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec) -> io::Resu TeFilteredOut(filtered_out) => Ok(st.filtered_out = filtered_out), TeWait(ref test) => out.write_test_start(test), TeTimeout(ref test) => out.write_timeout(test), - TeResult(test, result, stdout) => { - st.write_log_result(&test, &result)?; - out.write_result(&test, &result, &*stdout, &st)?; + TeResult(test, result, exec_time, stdout) => { + st.write_log_result(&test, &result, exec_time.as_ref())?; + out.write_result(&test, &result, exec_time.as_ref(), &*stdout, &st)?; match result { TrOk => { st.passed += 1; @@ -1004,12 +1045,12 @@ fn stdout_isatty() -> bool { pub enum TestEvent { TeFiltered(Vec), TeWait(TestDesc), - TeResult(TestDesc, TestResult, Vec), + TeResult(TestDesc, TestResult, Option, Vec), TeTimeout(TestDesc), TeFilteredOut(usize), } -pub type MonitorMsg = (TestDesc, TestResult, Vec); +pub type MonitorMsg = (TestDesc, TestResult, Option, Vec); struct Sink(Arc>>); impl Write for Sink { @@ -1105,8 +1146,8 @@ where let test = remaining.pop().unwrap(); callback(TeWait(test.desc.clone()))?; run_test(opts, !opts.run_tests, test, tx.clone(), Concurrent::No); - let (test, result, stdout) = rx.recv().unwrap(); - callback(TeResult(test, result, stdout))?; + let (test, result, exec_time, stdout) = rx.recv().unwrap(); + callback(TeResult(test, result, exec_time, stdout))?; } } else { while pending > 0 || !remaining.is_empty() { @@ -1135,10 +1176,10 @@ where } } - let (desc, result, stdout) = res.unwrap(); + let (desc, result, exec_time, stdout) = res.unwrap(); running_tests.remove(&desc); - callback(TeResult(desc, result, stdout))?; + callback(TeResult(desc, result, exec_time, stdout))?; pending -= 1; } } @@ -1148,8 +1189,8 @@ where for b in filtered_benchs { callback(TeWait(b.desc.clone()))?; run_test(opts, false, b, tx.clone(), Concurrent::No); - let (test, result, stdout) = rx.recv().unwrap(); - callback(TeResult(test, result, stdout))?; + let (test, result, exec_time, stdout) = rx.recv().unwrap(); + callback(TeResult(test, result, exec_time, stdout))?; } } Ok(()) @@ -1384,7 +1425,7 @@ pub fn run_test( && desc.should_panic != ShouldPanic::No; if force_ignore || desc.ignore || ignore_because_panic_abort { - monitor_ch.send((desc, TrIgnored, Vec::new())).unwrap(); + monitor_ch.send((desc, TrIgnored, None, Vec::new())).unwrap(); return; } @@ -1392,6 +1433,7 @@ pub fn run_test( desc: TestDesc, monitor_ch: Sender, nocapture: bool, + report_time: bool, testfn: Box, concurrency: Concurrent, ) { @@ -1410,7 +1452,16 @@ pub fn run_test( None }; + let start = if report_time { + Some(Instant::now()) + } else { + None + }; let result = catch_unwind(AssertUnwindSafe(testfn)); + let exec_time = start.map(|start| { + let duration = start.elapsed(); + TestExecTime(duration) + }); if let Some((printio, panicio)) = oldio { io::set_print(printio); @@ -1420,7 +1471,7 @@ pub fn run_test( let test_result = calc_result(&desc, result); let stdout = data.lock().unwrap().to_vec(); monitor_ch - .send((desc.clone(), test_result, stdout)) + .send((desc.clone(), test_result, exec_time, stdout)) .unwrap(); }; @@ -1449,12 +1500,20 @@ pub fn run_test( } DynTestFn(f) => { let cb = move || __rust_begin_short_backtrace(f); - run_test_inner(desc, monitor_ch, opts.nocapture, Box::new(cb), concurrency) + run_test_inner( + desc, + monitor_ch, + opts.nocapture, + opts.report_time, + Box::new(cb), + concurrency, + ) } StaticTestFn(f) => run_test_inner( desc, monitor_ch, opts.nocapture, + opts.report_time, Box::new(move || __rust_begin_short_backtrace(f)), concurrency, ), @@ -1702,7 +1761,7 @@ pub mod bench { }; let stdout = data.lock().unwrap().to_vec(); - monitor_ch.send((desc, test_result, stdout)).unwrap(); + monitor_ch.send((desc, test_result, None, stdout)).unwrap(); } pub fn run_once(f: F) diff --git a/src/libtest/tests.rs b/src/libtest/tests.rs index afc4217ec1ba2..13ac8eb91f411 100644 --- a/src/libtest/tests.rs +++ b/src/libtest/tests.rs @@ -23,6 +23,7 @@ impl TestOpts { format: OutputFormat::Pretty, test_threads: None, skip: vec![], + report_time: false, options: Options::new(), } } @@ -67,7 +68,7 @@ pub fn do_not_run_ignored_tests() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res != TrOk); } @@ -85,7 +86,7 @@ pub fn ignored_tests_result_in_ignored() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res == TrIgnored); } @@ -105,7 +106,7 @@ fn test_should_panic() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res == TrOk); } @@ -125,7 +126,7 @@ fn test_should_panic_good_message() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res == TrOk); } @@ -147,7 +148,7 @@ fn test_should_panic_bad_message() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res == TrFailedMsg(format!("{} '{}'", failed_msg, expected))); } @@ -165,10 +166,43 @@ fn test_should_panic_but_succeeds() { }; let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); - let (_, res, _) = rx.recv().unwrap(); + let (_, res, _, _) = rx.recv().unwrap(); assert!(res == TrFailed); } +fn report_time_test_template(report_time: bool) -> Option { + fn f() {} + let desc = TestDescAndFn { + desc: TestDesc { + name: StaticTestName("whatever"), + ignore: false, + should_panic: ShouldPanic::No, + allow_fail: false, + }, + testfn: DynTestFn(Box::new(f)), + }; + let test_opts = TestOpts { + report_time, + ..TestOpts::new() + }; + let (tx, rx) = channel(); + run_test(&test_opts, false, desc, tx, Concurrent::No); + let (_, _, exec_time, _) = rx.recv().unwrap(); + exec_time +} + +#[test] +fn test_should_not_report_time() { + let exec_time = report_time_test_template(false); + assert!(exec_time.is_none()); +} + +#[test] +fn test_should_report_time() { + let exec_time = report_time_test_template(true); + assert!(exec_time.is_some()); +} + #[test] fn parse_ignored_flag() { let args = vec![