From 6ac58fb696ce72a555ea04a843e1872c355d78bf Mon Sep 17 00:00:00 2001 From: Igor Aleksanov Date: Mon, 23 Sep 2019 20:42:00 +0300 Subject: [PATCH] Add --measure-time flag to libtest --- src/libtest/formatters/json.rs | 4 +- src/libtest/formatters/pretty.rs | 35 ++++++- src/libtest/formatters/terse.rs | 2 +- src/libtest/lib.rs | 155 ++++++++++++++++++++++++------- src/libtest/tests.rs | 49 +++++++++- 5 files changed, 202 insertions(+), 43 deletions(-) diff --git a/src/libtest/formatters/json.rs b/src/libtest/formatters/json.rs index e0bea4ce54530..c742cc25e71c5 100644 --- a/src/libtest/formatters/json.rs +++ b/src/libtest/formatters/json.rs @@ -72,13 +72,13 @@ impl OutputFormatter for JsonFormatter { stdout: &[u8], state: &ConsoleTestState, ) -> io::Result<()> { - let stdout = if (state.options.display_output || *result != TrOk) && stdout.len() > 0 { + let stdout = if (state.options.display_output || !result.is_ok()) && stdout.len() > 0 { Some(String::from_utf8_lossy(stdout)) } else { 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", stdout, None), TrFailed => self.write_event("test", desc.name.as_slice(), "failed", stdout, None), diff --git a/src/libtest/formatters/pretty.rs b/src/libtest/formatters/pretty.rs index 88331406a64d0..5391cf6b6fb3e 100644 --- a/src/libtest/formatters/pretty.rs +++ b/src/libtest/formatters/pretty.rs @@ -1,3 +1,4 @@ +use std::time::Duration; use super::*; pub(crate) struct PrettyFormatter { @@ -8,6 +9,8 @@ pub(crate) struct PrettyFormatter { max_name_len: usize, is_multithreaded: bool, + + test_time_params: Option, } impl PrettyFormatter { @@ -16,12 +19,14 @@ impl PrettyFormatter { use_color: bool, max_name_len: usize, is_multithreaded: bool, + test_time_params: Option ) -> Self { PrettyFormatter { out, use_color, max_name_len, is_multithreaded, + test_time_params, } } @@ -30,8 +35,32 @@ impl PrettyFormatter { &self.out } - pub fn write_ok(&mut self) -> io::Result<()> { - self.write_short_result("ok", term::color::GREEN) + fn write_ok_with_duration(&mut self, duration: Duration) -> io::Result<()> { + self.write_pretty("ok", term::color::GREEN)?; + + let time_str = format!(" <{}.{} s>", duration.as_secs(), duration.subsec_millis()); + match &self.test_time_params { + Some(params) => { + if duration >= params.test_time_critical { + self.write_pretty(&time_str, term::color::RED)?; + } else if duration >= params.test_time_warn { + self.write_pretty(&time_str, term::color::YELLOW)?; + } else { + self.write_plain(&time_str)?; + } + } + None => { + self.write_plain(&time_str)?; + } + } + self.write_plain("\n") + } + + pub fn write_ok(&mut self, duration: Option) -> io::Result<()> { + match duration { + Some(d) => self.write_ok_with_duration(d), + None => self.write_short_result("ok", term::color::GREEN) + } } pub fn write_failed(&mut self) -> io::Result<()> { @@ -174,7 +203,7 @@ impl OutputFormatter for PrettyFormatter { } match *result { - TrOk => self.write_ok(), + TrOk(d) => self.write_ok(d), TrFailed | TrFailedMsg(_) => self.write_failed(), TrIgnored => self.write_ignored(), TrAllowedFail => self.write_allowed_fail(), diff --git a/src/libtest/formatters/terse.rs b/src/libtest/formatters/terse.rs index d10b0c5807d57..c14e549556f95 100644 --- a/src/libtest/formatters/terse.rs +++ b/src/libtest/formatters/terse.rs @@ -178,7 +178,7 @@ impl OutputFormatter for TerseFormatter { _: &ConsoleTestState, ) -> io::Result<()> { match *result { - TrOk => self.write_ok(), + TrOk(_) => self.write_ok(), TrFailed | TrFailedMsg(_) => self.write_failed(), TrIgnored => self.write_ignored(), TrAllowedFail => self.write_allowed_fail(), diff --git a/src/libtest/lib.rs b/src/libtest/lib.rs index 09d5fcc89520e..13485141c8044 100644 --- a/src/libtest/lib.rs +++ b/src/libtest/lib.rs @@ -371,6 +371,7 @@ pub struct TestOpts { pub exclude_should_panic: bool, pub run_ignored: RunIgnored, pub run_tests: bool, + pub measure_time: bool, pub bench_benchmarks: bool, pub logfile: Option, pub nocapture: bool, @@ -391,6 +392,7 @@ fn optgroups() -> getopts::Options { .optflag("", "exclude-should-panic", "Excludes tests marked as should_panic") .optflag("", "test", "Run tests and not benchmarks") .optflag("", "bench", "Run benchmarks instead of tests") + .optflag("", "measure-time", "Measure tests execution time") .optflag("", "list", "List all tests and benchmarks") .optflag("h", "help", "Display this message (longer with --help)") .optopt( @@ -588,10 +590,23 @@ pub fn parse_opts(args: &[String]) -> Option { }; } + let measure_time = matches.opt_present("measure-time"); + if measure_time && !run_tests { + return Some(Err( + "The \"measure-time\" flag is only accepted with the \"test\" flag".into(), + )); + } + let test_threads = match matches.opt_str("test-threads") { Some(n_str) => match n_str.parse::() { Ok(0) => return Some(Err("argument for --test-threads must not be 0".to_string())), - Ok(n) => Some(n), + Ok(n) => { + if measure_time && n != 1 { + return Some(Err("The \"measure-time\" flag excepts only one thread".into())); + } + + Some(n) + } Err(e) => { return Some(Err(format!( "argument for --test-threads must be a number > 0 \ @@ -600,7 +615,14 @@ pub fn parse_opts(args: &[String]) -> Option { ))); } }, - None => None, + None => { + if measure_time { + // Use only 1 thread for time measurement. + Some(1) + } else { + None + } + } }; let color = match matches.opt_str("color").as_ref().map(|s| &**s) { @@ -646,6 +668,7 @@ pub fn parse_opts(args: &[String]) -> Option { exclude_should_panic, run_ignored, run_tests, + measure_time, bench_benchmarks, logfile, nocapture, @@ -667,7 +690,7 @@ pub struct BenchSamples { #[derive(Clone, PartialEq)] pub enum TestResult { - TrOk, + TrOk(Option), TrFailed, TrFailedMsg(String), TrIgnored, @@ -675,6 +698,15 @@ pub enum TestResult { TrBench(BenchSamples), } +impl TestResult { + fn is_ok(&self) -> bool { + match self { + TrOk(_) => true, + _ => false, + } + } +} + unsafe impl Send for TestResult {} enum OutputLocation { @@ -748,7 +780,12 @@ impl ConsoleTestState { self.write_log(format!( "{} {}\n", match *result { - TrOk => "ok".to_owned(), + TrOk(Some(d)) => { + let ok_str = format!("ok <{}.{} s>", d.as_secs(), d.subsec_millis()).to_owned(); + + ok_str + } + TrOk(None) => "ok".to_owned(), TrFailed => "failed".to_owned(), TrFailedMsg(ref msg) => format!("failed: {}", msg), TrIgnored => "ignored".to_owned(), @@ -888,7 +925,7 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec) -> io::Resu st.write_log_result(&test, &result)?; out.write_result(&test, &result, &*stdout, &st)?; match result { - TrOk => { + TrOk(_) => { st.passed += 1; st.not_failures.push((test, stdout)); } @@ -932,12 +969,20 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec) -> io::Resu let is_multithreaded = opts.test_threads.unwrap_or_else(get_concurrency) > 1; let mut out: Box = match opts.format { - OutputFormat::Pretty => Box::new(PrettyFormatter::new( - output, - use_color(opts), - max_name_len, - is_multithreaded, - )), + OutputFormat::Pretty => { + let test_time_params = if opts.measure_time { + Some(get_test_time_params()) + } else { + None + }; + Box::new(PrettyFormatter::new( + output, + use_color(opts), + max_name_len, + is_multithreaded, + test_time_params, + )) + } OutputFormat::Terse => Box::new(TerseFormatter::new( output, use_color(opts), @@ -1155,19 +1200,40 @@ where Ok(()) } +fn parse_positive_number(number_str: &str, variable_name: &str) -> usize { + let number: Option = number_str.parse().ok(); + match number { + Some(n) if n > 0 => n, + _ => panic!("{} is `{}`, should be a positive integer.", variable_name, number_str), + } +} + +pub struct TestTimeParams { + pub test_time_warn: Duration, + pub test_time_critical: Duration, +} + +fn get_test_time_params() -> TestTimeParams { + // Attempts to get warn and critical time from env variables RUST_TEST_TIME_WARN + // and RUST_TEST_TIME_CRITICAL, otherwise uses default values. + + let test_time_warn = match env::var("RUST_TEST_TIME_WARN") { + Ok(s) => Duration::from_millis(parse_positive_number(&s, "RUST_TEST_TIME_WARN") as u64), + Err(..) => Duration::from_millis(500), + }; + + let test_time_critical = match env::var("RUST_TEST_TIME_CRITICAL") { + Ok(s) => Duration::from_millis(parse_positive_number(&s, "RUST_TEST_TIME_CRITICAL") as u64), + Err(..) => Duration::from_millis(1000), + }; + + TestTimeParams { test_time_warn, test_time_critical } +} + #[allow(deprecated)] fn get_concurrency() -> usize { return match env::var("RUST_TEST_THREADS") { - Ok(s) => { - let opt_n: Option = s.parse().ok(); - match opt_n { - Some(n) if n > 0 => n, - _ => panic!( - "RUST_TEST_THREADS is `{}`, should be a positive integer.", - s - ), - } - } + Ok(s) => parse_positive_number(&s, "RUST_TEST_THREADS"), Err(..) => num_cpus(), }; @@ -1388,20 +1454,26 @@ pub fn run_test( return; } + struct RunTestOpts { + pub nocapture: bool, + pub concurrency: Concurrent, + pub measure_time: bool, + }; + fn run_test_inner( desc: TestDesc, monitor_ch: Sender, - nocapture: bool, testfn: Box, - concurrency: Concurrent, + opts: RunTestOpts, ) { // Buffer for capturing standard I/O let data = Arc::new(Mutex::new(Vec::new())); let data2 = data.clone(); + let concurrency = opts.concurrency; let name = desc.name.clone(); let runtest = move || { - let oldio = if !nocapture { + let oldio = if !opts.nocapture { Some(( io::set_print(Some(Box::new(Sink(data2.clone())))), io::set_panic(Some(Box::new(Sink(data2)))), @@ -1410,14 +1482,26 @@ pub fn run_test( None }; - let result = catch_unwind(AssertUnwindSafe(testfn)); + let (result, duration) = if opts.measure_time { + let start_time = Instant::now(); + let result = catch_unwind(AssertUnwindSafe(testfn)); + let end_time = Instant::now(); + + let test_duration = end_time - start_time; + + (result, Some(test_duration)) + } else { + let result = catch_unwind(AssertUnwindSafe(testfn)); + + (result, None) + }; if let Some((printio, panicio)) = oldio { io::set_print(printio); io::set_panic(panicio); }; - let test_result = calc_result(&desc, result); + let test_result = calc_result(&desc, result, duration); let stdout = data.lock().unwrap().to_vec(); monitor_ch .send((desc.clone(), test_result, stdout)) @@ -1436,6 +1520,10 @@ pub fn run_test( } } + let nocapture = opts.nocapture; + let measure_time = opts.measure_time; + let run_test_opts = RunTestOpts { nocapture, concurrency, measure_time }; + match testfn { DynBenchFn(bencher) => { crate::bench::benchmark(desc, monitor_ch, opts.nocapture, |harness| { @@ -1449,14 +1537,13 @@ 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, Box::new(cb), run_test_opts) } StaticTestFn(f) => run_test_inner( desc, monitor_ch, - opts.nocapture, Box::new(move || __rust_begin_short_backtrace(f)), - concurrency, + run_test_opts, ), } } @@ -1467,9 +1554,13 @@ fn __rust_begin_short_backtrace(f: F) { f() } -fn calc_result(desc: &TestDesc, task_result: Result<(), Box>) -> TestResult { +fn calc_result( + desc: &TestDesc, + task_result: Result<(), Box>, + duration: Option +) -> TestResult { match (&desc.should_panic, task_result) { - (&ShouldPanic::No, Ok(())) | (&ShouldPanic::Yes, Err(_)) => TrOk, + (&ShouldPanic::No, Ok(())) | (&ShouldPanic::Yes, Err(_)) => TrOk(duration), (&ShouldPanic::YesWithMessage(msg), Err(ref err)) => { if err .downcast_ref::() @@ -1478,7 +1569,7 @@ fn calc_result(desc: &TestDesc, task_result: Result<(), Box>) -> .map(|e| e.contains(msg)) .unwrap_or(false) { - TrOk + TrOk(duration) } else { if desc.allow_fail { TrAllowedFail diff --git a/src/libtest/tests.rs b/src/libtest/tests.rs index afc4217ec1ba2..fe2e37604df94 100644 --- a/src/libtest/tests.rs +++ b/src/libtest/tests.rs @@ -3,7 +3,7 @@ use super::*; use crate::test::{ filter_tests, parse_opts, run_test, DynTestFn, DynTestName, MetricMap, RunIgnored, ShouldPanic, StaticTestName, TestDesc, TestDescAndFn, TestOpts, TrFailed, TrFailedMsg, - TrIgnored, TrOk, + TrIgnored, }; use std::sync::mpsc::channel; @@ -16,6 +16,7 @@ impl TestOpts { exclude_should_panic: false, run_ignored: RunIgnored::No, run_tests: false, + measure_time: false, bench_benchmarks: false, logfile: None, nocapture: false, @@ -68,7 +69,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(); - assert!(res != TrOk); + assert!(!res.is_ok()); } #[test] @@ -106,7 +107,7 @@ fn test_should_panic() { let (tx, rx) = channel(); run_test(&TestOpts::new(), false, desc, tx, Concurrent::No); let (_, res, _) = rx.recv().unwrap(); - assert!(res == TrOk); + assert!(res.is_ok()); } #[test] @@ -126,7 +127,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(); - assert!(res == TrOk); + assert!(res.is_ok()); } #[test] @@ -203,6 +204,44 @@ fn parse_include_ignored_flag() { assert_eq!(opts.run_ignored, RunIgnored::Yes); } +#[test] +fn parse_measure_time_flag() { + // Provide --measure-time and --test flags. + // Opts should be parsed successfully and `test_threads` should be set to `Some(1)`. + let args = vec![ + "progname".to_string(), + "filter".to_string(), + "--test".to_string(), + "--measure-time".to_string(), + ]; + let opts = parse_opts(&args).unwrap().unwrap(); + assert!(opts.measure_time); + assert_eq!(opts.test_threads, Some(1)); + + // Provide --measure-time flag without --test flag and with --bench flag. + // Opts should not be parsed. + let args_bench = vec![ + "progname".to_string(), + "filter".to_string(), + "--bench".to_string(), + "--measure-time".to_string(), + ]; + let expected_err = "The \"measure-time\" flag is only accepted with the \"test\" flag"; + let opts_error = parse_opts(&args_bench).unwrap(); + opts_error.expect_err(expected_err); + + // Provide --measure-time flag with custom --test-threads flag. + let args_bench = vec![ + "progname".to_string(), + "filter".to_string(), + "--test-threads 4".to_string(), + "--measure-time".to_string(), + ]; + let expected_err = "The \"measure-time\" flag excepts only one thread"; + let opts_error = parse_opts(&args_bench).unwrap(); + opts_error.expect_err(expected_err); +} + #[test] pub fn filter_for_ignored_option() { // When we run ignored tests the test filter should filter out all the @@ -499,7 +538,7 @@ fn should_sort_failures_before_printing_them() { allow_fail: false, }; - let mut out = PrettyFormatter::new(Raw(Vec::new()), false, 10, false); + let mut out = PrettyFormatter::new(Raw(Vec::new()), false, 10, false, None); let st = ConsoleTestState { log_out: None,