Auto merge of rust-lang#75752 - jakoschiko:test-suite-time, r=m-ou-se

libtest: Print the total time taken to execute a test suite

Print the total time taken to execute a test suite by default, without any kind of flag.

Closes rust-lang#75660

# Example
```
anon@anon:~/code/rust/example$ cargo test
   Compiling example v0.1.0 (/home/anon/code/rust/example)
    Finished test [unoptimized + debuginfo] target(s) in 0.18s
     Running target/debug/deps/example-745b64d3885c3565

running 3 tests
test tests::foo ... ok
test tests::bar ... ok
test tests::baz ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.2s

   Doc-tests example

running 3 tests
test src/lib.rs - foo (line 3) ... ok
test src/lib.rs - bar (line 11) ... ok
test src/lib.rs - baz (line 19) ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.3s
```

```
anon@anon:~/code/rust/example$ cargo test -- --format terse
    Finished test [unoptimized + debuginfo] target(s) in 0.08s
     Running target/debug/deps/example-745b64d3885c3565

running 3 tests
...
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.2s

   Doc-tests example

running 3 tests
...
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.3s
```

```
anon@anon:~/code/rust/example$ cargo test -- --format json -Z unstable-options
   Compiling example v0.1.0 (/home/anon/code/rust/example)
    Finished test [unoptimized + debuginfo] target(s) in 0.25s
     Running target/debug/deps/example-745b64d3885c3565
{ "type": "suite", "event": "started", "test_count": 3 }
{ "type": "test", "event": "started", "name": "tests::bar" }
{ "type": "test", "event": "started", "name": "tests::baz" }
{ "type": "test", "event": "started", "name": "tests::foo" }
{ "type": "test", "name": "tests::foo", "event": "ok" }
{ "type": "test", "name": "tests::bar", "event": "ok" }
{ "type": "test", "name": "tests::baz", "event": "ok" }
{ "type": "suite", "event": "ok", "passed": 3, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": "1.2s" }
   Doc-tests example
{ "type": "suite", "event": "started", "test_count": 3 }
{ "type": "test", "event": "started", "name": "src/lib.rs - bar (line 11)" }
{ "type": "test", "event": "started", "name": "src/lib.rs - baz (line 19)" }
{ "type": "test", "event": "started", "name": "src/lib.rs - foo (line 3)" }
{ "type": "test", "name": "src/lib.rs - foo (line 3)", "event": "ok" }
{ "type": "test", "name": "src/lib.rs - bar (line 11)", "event": "ok" }
{ "type": "test", "name": "src/lib.rs - baz (line 19)", "event": "ok" }
{ "type": "suite", "event": "ok", "passed": 3, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": "1.3s" }
```

Author: bors

library/test/src/console.rs

@@ -3,6 +3,7 @@
 use std::fs::File;
 use std::io;
 use std::io::prelude::Write;
+use std::time::Instant;
 
 use super::{
     bench::fmt_bench_samples,
@@ -14,7 +15,7 @@ use super::{
     options::{Options, OutputFormat},
     run_tests,
     test_result::TestResult,
-    time::TestExecTime,
+    time::{TestExecTime, TestSuiteExecTime},
     types::{NamePadding, TestDesc, TestDescAndFn},
 };
 
@@ -49,6 +50,7 @@ pub struct ConsoleTestState {
     pub allowed_fail: usize,
     pub filtered_out: usize,
     pub measured: usize,
+    pub exec_time: Option<TestSuiteExecTime>,
     pub metrics: MetricMap,
     pub failures: Vec<(TestDesc, Vec<u8>)>,
     pub not_failures: Vec<(TestDesc, Vec<u8>)>,
@@ -72,6 +74,7 @@ impl ConsoleTestState {
             allowed_fail: 0,
             filtered_out: 0,
             measured: 0,
+            exec_time: None,
             metrics: MetricMap::new(),
             failures: Vec::new(),
             not_failures: Vec::new(),
@@ -277,7 +280,14 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
     };
     let mut st = ConsoleTestState::new(opts)?;
 
+    // Prevent the usage of `Instant` in some cases:
+    // - It's currently not supported for wasm targets.
+    // - We disable it for miri because it's not available when isolation is enabled.
+    let is_instant_supported = !cfg!(target_arch = "wasm32") && !cfg!(miri);
+
+    let start_time = is_instant_supported.then(Instant::now);
     run_tests(opts, tests, |x| on_test_event(&x, &mut st, &mut *out))?;
+    st.exec_time = start_time.map(|t| TestSuiteExecTime(t.elapsed()));
 
     assert!(st.current_test_count() == st.total);
 

library/test/src/formatters/json.rs

@@ -47,7 +47,7 @@ impl<T: Write> JsonFormatter<T> {
             evt
         ))?;
         if let Some(exec_time) = exec_time {
-            self.write_message(&*format!(r#", "exec_time": "{}""#, exec_time))?;
+            self.write_message(&*format!(r#", "exec_time": {}"#, exec_time.0.as_secs_f64()))?;
         }
         if let Some(stdout) = stdout {
             self.write_message(&*format!(r#", "stdout": "{}""#, EscapedString(stdout)))?;
@@ -162,24 +162,31 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
     }
 
     fn write_run_finish(&mut self, state: &ConsoleTestState) -> io::Result<bool> {
-        self.writeln_message(&*format!(
+        self.write_message(&*format!(
             "{{ \"type\": \"suite\", \
              \"event\": \"{}\", \
              \"passed\": {}, \
              \"failed\": {}, \
              \"allowed_fail\": {}, \
              \"ignored\": {}, \
              \"measured\": {}, \
-             \"filtered_out\": {} }}",
+             \"filtered_out\": {}",
             if state.failed == 0 { "ok" } else { "failed" },
             state.passed,
             state.failed + state.allowed_fail,
             state.allowed_fail,
             state.ignored,
             state.measured,
-            state.filtered_out
+            state.filtered_out,
         ))?;
 
+        if let Some(ref exec_time) = state.exec_time {
+            let time_str = format!(", \"exec_time\": {}", exec_time.0.as_secs_f64());
+            self.write_message(&time_str)?;
+        }
+
+        self.writeln_message(" }")?;
+
         Ok(state.failed == 0)
     }
 }

library/test/src/formatters/pretty.rs

@@ -259,7 +259,7 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
 
         let s = if state.allowed_fail > 0 {
             format!(
-                ". {} passed; {} failed ({} allowed); {} ignored; {} measured; {} filtered out\n\n",
+                ". {} passed; {} failed ({} allowed); {} ignored; {} measured; {} filtered out",
                 state.passed,
                 state.failed + state.allowed_fail,
                 state.allowed_fail,
@@ -269,13 +269,20 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
             )
         } else {
             format!(
-                ". {} passed; {} failed; {} ignored; {} measured; {} filtered out\n\n",
+                ". {} passed; {} failed; {} ignored; {} measured; {} filtered out",
                 state.passed, state.failed, state.ignored, state.measured, state.filtered_out
             )
         };
 
         self.write_plain(&s)?;
 
+        if let Some(ref exec_time) = state.exec_time {
+            let time_str = format!("; finished in {}", exec_time);
+            self.write_plain(&time_str)?;
+        }
+
+        self.write_plain("\n\n")?;
+
         Ok(success)
     }
 }

library/test/src/formatters/terse.rs

@@ -236,7 +236,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
 
         let s = if state.allowed_fail > 0 {
             format!(
-                ". {} passed; {} failed ({} allowed); {} ignored; {} measured; {} filtered out\n\n",
+                ". {} passed; {} failed ({} allowed); {} ignored; {} measured; {} filtered out",
                 state.passed,
                 state.failed + state.allowed_fail,
                 state.allowed_fail,
@@ -246,13 +246,20 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
             )
         } else {
             format!(
-                ". {} passed; {} failed; {} ignored; {} measured; {} filtered out\n\n",
+                ". {} passed; {} failed; {} ignored; {} measured; {} filtered out",
                 state.passed, state.failed, state.ignored, state.measured, state.filtered_out
             )
         };
 
         self.write_plain(&s)?;
 
+        if let Some(ref exec_time) = state.exec_time {
+            let time_str = format!("; finished in {}", exec_time);
+            self.write_plain(&time_str)?;
+        }
+
+        self.write_plain("\n\n")?;
+
         Ok(success)
     }
 }

library/test/src/tests.rs

@@ -669,6 +669,7 @@ fn should_sort_failures_before_printing_them() {
         allowed_fail: 0,
         filtered_out: 0,
         measured: 0,
+        exec_time: None,
         metrics: MetricMap::new(),
         failures: vec![(test_b, Vec::new()), (test_a, Vec::new())],
         options: Options::new(),

library/test/src/time.rs

@@ -1,8 +1,9 @@
 //! Module `time` contains everything related to the time measurement of unit tests
 //! execution.
-//! Two main purposes of this module:
+//! The purposes of this module:
 //! - Check whether test is timed out.
 //! - Provide helpers for `report-time` and `measure-time` options.
+//! - Provide newtypes for executions times.
 
 use std::env;
 use std::fmt;
@@ -60,7 +61,7 @@ pub fn get_default_test_timeout() -> Instant {
     Instant::now() + Duration::from_secs(TEST_WARN_TIMEOUT_S)
 }
 
-/// The meassured execution time of a unit test.
+/// The measured execution time of a unit test.
 #[derive(Debug, Clone, PartialEq)]
 pub struct TestExecTime(pub Duration);
 
@@ -70,6 +71,16 @@ impl fmt::Display for TestExecTime {
     }
 }
 
+/// The measured execution time of the whole test suite.
+#[derive(Debug, Clone, Default, PartialEq)]
+pub struct TestSuiteExecTime(pub Duration);
+
+impl fmt::Display for TestSuiteExecTime {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "{:.2}s", self.0.as_secs_f64())
+    }
+}
+
 /// Structure denoting time limits for test execution.
 #[derive(Copy, Clone, Debug, Default, PartialEq, Eq)]
 pub struct TimeThreshold {

src/test/run-make-fulldeps/libtest-json/Makefile

@@ -13,6 +13,6 @@ all:
 	cat $(OUTPUT_FILE_DEFAULT) | "$(PYTHON)" validate_json.py
 	cat $(OUTPUT_FILE_STDOUT_SUCCESS) | "$(PYTHON)" validate_json.py
 
-	# Compare to output file
-	diff output-default.json $(OUTPUT_FILE_DEFAULT)
-	diff output-stdout-success.json $(OUTPUT_FILE_STDOUT_SUCCESS)
+	# Normalize the actual output and compare to expected output file
+	cat $(OUTPUT_FILE_DEFAULT) | sed 's/"exec_time": [0-9.]*/"exec_time": $$TIME/' | diff output-default.json -
+	cat $(OUTPUT_FILE_STDOUT_SUCCESS) | sed 's/"exec_time": [0-9.]*/"exec_time": $$TIME/' | diff output-stdout-success.json -

src/test/run-make-fulldeps/libtest-json/output-default.json

@@ -7,4 +7,4 @@
 { "type": "test", "name": "c", "event": "ok" }
 { "type": "test", "event": "started", "name": "d" }
 { "type": "test", "name": "d", "event": "ignored" }
-{ "type": "suite", "event": "failed", "passed": 2, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 }
+{ "type": "suite", "event": "failed", "passed": 2, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0, "exec_time": $TIME }

src/test/run-make-fulldeps/libtest-json/output-stdout-success.json

@@ -7,4 +7,4 @@
 { "type": "test", "name": "c", "event": "ok", "stdout": "thread 'main' panicked at 'assertion failed: false', f.rs:15:5\n" }
 { "type": "test", "event": "started", "name": "d" }
 { "type": "test", "name": "d", "event": "ignored" }
-{ "type": "suite", "event": "failed", "passed": 2, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 }
+{ "type": "suite", "event": "failed", "passed": 2, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0, "exec_time": $TIME }

src/test/rustdoc-ui/cfg-test.rs

@@ -1,6 +1,7 @@
 // check-pass
 // compile-flags:--test --test-args --test-threads=1
 // normalize-stdout-test: "src/test/rustdoc-ui" -> "$$DIR"
+// normalize-stdout-test "finished in \d+\.\d+s" -> "finished in $$TIME"
 
 // Crates like core have doctests gated on `cfg(not(test))` so we need to make
 // sure `cfg(test)` is not active when running `rustdoc --test`.