Auto merge of rust-lang#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 rust-lang#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
```

Author: bors

src/libtest/formatters/json.rs

@@ -27,13 +27,20 @@ impl<T: Write> JsonFormatter<T> {
         ty: &str,
         name: &str,
         evt: &str,
+        exec_time: Option<&TestExecTime>,
         stdout: Option<Cow<'_, str>>,
         extra: Option<&str>,
     ) -> io::Result<()> {
         self.write_message(&*format!(
             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),
-
-            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;

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<()> {
-        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<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(),
-            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)))

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