Auto merge of #64663 - jakoschiko:report-time, r=alexcrichton

libtest: Add --report-time flag to print test execution time

Implements the flag `--report-time` to print the execution time of each executed (successful or failed) test.

Closes #46610

# Example

`cargo test -- --report-time` produces the following output to stdout:
```
running 6 tests
test tests::ignore ... ignored
test tests::noop ... ok 0.000s
test tests::should_panic ... ok 0.000s
test tests::panic_after_10millis ... FAILED 0.010s
test tests::sleep_100millis ... ok 0.100s
test tests::sleep_10secs ... ok 10.001s

failures:

---- tests::panic_after_10millis stdout ----
thread 'tests::panic_after_10millis' panicked at 'foo', src\lib.rs:31:9

failures:
    tests::panic_after_10millis

test result: FAILED. 4 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out
```
`cargo test -- --report-time -Z unstable-options --format=json` produces the following output to stdout:
```
{ "type": "suite", "event": "started", "test_count": 6 }
{ "type": "test", "event": "started", "name": "tests::ignore" }
{ "type": "test", "event": "started", "name": "tests::noop" }
{ "type": "test", "event": "started", "name": "tests::panic_after_10millis" }
{ "type": "test", "event": "started", "name": "tests::should_panic" }
{ "type": "test", "name": "tests::ignore", "event": "ignored" }
{ "type": "test", "event": "started", "name": "tests::sleep_100millis" }
{ "type": "test", "name": "tests::noop", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "event": "started", "name": "tests::sleep_10secs" }
{ "type": "test", "name": "tests::should_panic", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "name": "tests::panic_after_10millis", "event": "failed", "exec_time": "0.010s", "stdout": "thread 'tests::panic_after_10millis' panicked at 'foo', src\\lib.rs:31:9\n" }
{ "type": "test", "name": "tests::sleep_100millis", "event": "ok", "exec_time": "0.101s" }
{ "type": "test", "name": "tests::sleep_10secs", "event": "ok", "exec_time": "10.000s" }
{ "type": "suite", "event": "failed", "passed": 4, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 }
```
`cargo test -- --report-time --logfile foo.log` produces the following logfile:
```
ignored tests::ignore
ok tests::noop 0.000s
ok tests::should_panic 0.000s
failed tests::panic_after_10millis 0.010s
ok tests::sleep_100millis 0.100s
ok tests::sleep_10secs 10.001s
```

src/libtest/formatters/json.rs

@@ -27,6 +27,7 @@ impl<T: Write> JsonFormatter<T> {
         ty: &str,
         name: &str,
         evt: &str,
+        exec_time: Option<&TestExecTime>,
         stdout: Option<Cow<'_, str>>,
         extra: Option<&str>,
     ) -> io::Result<()> {
@@ -34,6 +35,12 @@ impl<T: Write> JsonFormatter<T> {
             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<T: Write> OutputFormatter for JsonFormatter<T> {
         &mut self,
         desc: &TestDesc,
         result: &TestResult,
+        exec_time: Option<&TestExecTime>,
         stdout: &[u8],
         state: &ConsoleTestState,
     ) -> io::Result<()> {
@@ -78,24 +86,36 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
             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),
+            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", 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;

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<()>;

src/libtest/formatters/pretty.rs

@@ -30,20 +30,20 @@ impl<T: Write> PrettyFormatter<T> {
         &self.out
     }
 
-    pub fn write_ok(&mut self) -> io::Result<()> {
+    pub fn write_ok(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
-        self.write_short_result("ok", term::color::GREEN)
+        self.write_short_result("ok", term::color::GREEN, exec_time)
     }
 
-    pub fn write_failed(&mut self) -> io::Result<()> {
+    pub fn write_failed(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
-        self.write_short_result("FAILED", term::color::RED)
+        self.write_short_result("FAILED", term::color::RED, exec_time)
     }
 
-    pub fn write_ignored(&mut self) -> io::Result<()> {
+    pub fn write_ignored(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
-        self.write_short_result("ignored", term::color::YELLOW)
+        self.write_short_result("ignored", term::color::YELLOW, exec_time)
     }
 
-    pub fn write_allowed_fail(&mut self) -> io::Result<()> {
+    pub fn write_allowed_fail(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
-        self.write_short_result("FAILED (allowed)", term::color::YELLOW)
+        self.write_short_result("FAILED (allowed)", term::color::YELLOW, exec_time)
     }
 
     pub fn write_bench(&mut self) -> io::Result<()> {
@@ -54,8 +54,12 @@ impl<T: Write> PrettyFormatter<T> {
         &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<T: Write> OutputFormatter for PrettyFormatter<T> {
         &mut self,
         desc: &TestDesc,
         result: &TestResult,
+        exec_time: Option<&TestExecTime>,
         _: &[u8],
         _: &ConsoleTestState,
     ) -> io::Result<()> {
@@ -174,10 +179,10 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
         }
 
         match *result {
-            TrOk => self.write_ok(),
+            TrOk => self.write_ok(exec_time),
-            TrFailed | TrFailedMsg(_) => self.write_failed(),
+            TrFailed | TrFailedMsg(_) => self.write_failed(exec_time),
-            TrIgnored => self.write_ignored(),
+            TrIgnored => self.write_ignored(exec_time),
-            TrAllowedFail => self.write_allowed_fail(),
+            TrAllowedFail => self.write_allowed_fail(exec_time),
             TrBench(ref bs) => {
                 self.write_bench()?;
                 self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))

src/libtest/formatters/terse.rs

@@ -174,6 +174,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
         &mut self,
         desc: &TestDesc,
         result: &TestResult,
+        _: Option<&TestExecTime>,
         _: &[u8],
         _: &ConsoleTestState,
     ) -> io::Result<()> {

src/libtest/lib.rs

@@ -378,6 +378,7 @@ pub struct TestOpts {
     pub format: OutputFormat,
     pub test_threads: Option<usize>,
     pub skip: Vec<String>,
+    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<OptRes> {
         ));
     }
 
+    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<OptRes> {
         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<T> {
     Pretty(Box<term::StdoutTerminal>),
     Raw(T),
@@ -736,17 +760,30 @@ impl ConsoleTestState {
         })
     }
 
-    pub fn write_log<S: AsRef<str>>(&mut self, msg: S) -> io::Result<()> {
+    pub fn write_log<F, S>(
-        let msg = msg.as_ref();
+        &mut self,
+        msg: F,
+    ) -> io::Result<()>
+    where
+        S: AsRef<str>,
+        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<()> {
+    pub fn write_log_result(&mut self,test: &TestDesc,
-        self.write_log(format!(
+        result: &TestResult,
-            "{} {}\n",
+        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<TestDescAndFn>) -> 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<TestDescAndFn>) -> 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) => {
+            TeResult(test, result, exec_time, stdout) => {
-                st.write_log_result(&test, &result)?;
+                st.write_log_result(&test, &result, exec_time.as_ref())?;
-                out.write_result(&test, &result, &*stdout, &st)?;
+                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<TestDesc>),
     TeWait(TestDesc),
-    TeResult(TestDesc, TestResult, Vec<u8>),
+    TeResult(TestDesc, TestResult, Option<TestExecTime>, Vec<u8>),
     TeTimeout(TestDesc),
     TeFilteredOut(usize),
 }
 
-pub type MonitorMsg = (TestDesc, TestResult, Vec<u8>);
+pub type MonitorMsg = (TestDesc, TestResult, Option<TestExecTime>, Vec<u8>);
 
 struct Sink(Arc<Mutex<Vec<u8>>>);
 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();
+            let (test, result, exec_time, stdout) = rx.recv().unwrap();
-            callback(TeResult(test, result, stdout))?;
+            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();
+            let (test, result, exec_time, stdout) = rx.recv().unwrap();
-            callback(TeResult(test, result, stdout))?;
+            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<MonitorMsg>,
         nocapture: bool,
+        report_time: bool,
         testfn: Box<dyn FnOnce() + Send>,
         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: F)

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<TestExecTime> {
+    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![