Auto merge of #64873 - popzxc:prettify-test-time, r=wesleywiser

Enhance report-time option

## Short overview

This PR is a follow-up to a previously closed #64714 PR.

## Changes introduced by this PR

* `libtest` now retrieves the type of the test within `TestDesc` (available types are: `UnitTest`, `IntegrationTest`, `DocTest`, `Unknown`).
* `--report-time` subcommand of the `libtest` now supports colored output (disabled by default).
* Colorized output depends on the threshold values. Default values (proposed by @wesleywiser):
  - For unit-tests: 50ms warn/100ms critical,
  - For integration-tests: 500ms warn/1000ms critical,
  - For doctests: same as for integration tests,
  - For unknown tests: `TEST_WARN_TIMEOUT_S` warn/ `TEST_WARN_TIMEOUT_S * 2` critical (it will only applied single-threaded mode, because otherwise test will be interrupted after reaching `TEST_WARN_TIMEOUT_S`).
  - These values can be overrided by setting environment variables (since those thresholds are somewhat constant for every project, it's more flexible to use environment variables than command line arguments).
* New optional flag `--ensure-test-time` for `libtest`. With this flag applied, exectuion time limit excesss will cause test failure.

## What have not been done

There was a comment that it would be nice to have an entry in the Cargo book about it.

However, changes introduced by this PR (and #64663 in which `report-time` flag was added) aren't related directly to `cargo`, it's more about `libtest` itself.
I'm considering that [The Unstable Book](https://doc.rust-lang.org/unstable-book/) is more appropriate place, but not sure if I'm right (and if so, how exactly it should be described).

As one possible option, this PR may be merged without denoting it in the documentation, and in the next PR adding support of this feature to the `cargo` itself, I'll add a note in the Cargo book.

## Scope of this PR

Logical scope of this PR is `libtest` only. However, to get test types, I had to modify also `libsyntax_ext` and `librustdoc` for them to provide information about test type.

## Rationale

Rationale for colored output was submitted in #64714

Providing the information about kind of test was also proposed in #64714, and as an additional benefit this information may be useful for the tools using `libtest` (e.g. `cargo`).

Adding flag to treat time limits excess seems logical to me, so projects that do care about test execution time won't have to invent a wheel.

## Backward compatibility

All the changes are completely backward compatible.

## Demo

![rustc_enhanced_time](https://user-images.githubusercontent.com/12111581/65818381-c04f6800-e219-11e9-9875-322463abe24f.gif)

r? @wesleywiser

src/doc/unstable-book/src/compiler-flags/report-time.md

@@ -0,0 +1,80 @@
+# `report-time`
+
+The tracking issue for this feature is: [#64888]
+
+[#64888]: https://github.com/rust-lang/rust/issues/64888
+
+------------------------
+
+The `report-time` feature adds a possibility to report execution time of the
+tests generated via `libtest`.
+
+This is unstable feature, so you have to provide `-Zunstable-options` to get
+this feature working.
+
+Sample usage command:
+
+```sh
+./test_executable -Zunstable-options --report-time
+```
+
+Available options:
+
+```sh
+--report-time [plain|colored]
+                Show execution time of each test. Awailable values:
+                plain = do not colorize the execution time (default);
+                colored = colorize output according to the `color`
+                parameter value;
+                Threshold values for colorized output can be
+                configured via
+                `RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION`
+                and
+                `RUST_TEST_TIME_DOCTEST` environment variables.
+                Expected format of environment variable is
+                `VARIABLE=WARN_TIME,CRITICAL_TIME`.
+                Not available for --format=terse
+--ensure-time 
+                Treat excess of the test execution time limit as
+                error.
+                Threshold values for this option can be configured via
+                `RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION`
+                and
+                `RUST_TEST_TIME_DOCTEST` environment variables.
+                Expected format of environment variable is
+                `VARIABLE=WARN_TIME,CRITICAL_TIME`.
+                `CRITICAL_TIME` here means the limit that should not be
+                exceeded by test.
+```
+
+Example of the environment variable format:
+
+```sh
+RUST_TEST_TIME_UNIT=100,200
+```
+
+where 100 stands for warn time, and 200 stands for critical time.
+
+## Examples
+
+```sh
+cargo test --tests -- -Zunstable-options --report-time
+    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
+     Running target/debug/deps/example-27fb188025bec02c
+
+running 3 tests
+test tests::unit_test_quick ... ok <0.000s>
+test tests::unit_test_warn ... ok <0.055s>
+test tests::unit_test_critical ... ok <0.110s>
+
+test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
+
+     Running target/debug/deps/tests-cedb06f6526d15d9
+
+running 3 tests
+test unit_test_quick ... ok <0.000s>
+test unit_test_warn ... ok <0.550s>
+test unit_test_critical ... ok <1.100s>
+
+test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
+```

src/librustdoc/test.rs

@@ -705,6 +705,7 @@ impl Tester for Collector {
                 // compiler failures are test failures
                 should_panic: testing::ShouldPanic::No,
                 allow_fail: config.allow_fail,
+                test_type: testing::TestType::DocTest,
             },
             testfn: testing::DynTestFn(box move || {
                 let res = run_test(

src/libsyntax_ext/test.rs

@@ -106,6 +106,11 @@ pub fn expand_test_or_bench(
         cx.path(sp, vec![test_id, cx.ident_of("ShouldPanic", sp), cx.ident_of(name, sp)])
     };
 
+    // creates test::TestType::$name
+    let test_type_path = |name| {
+        cx.path(sp, vec![test_id, cx.ident_of("TestType", sp), cx.ident_of(name, sp)])
+    };
+
     // creates $name: $expr
     let field = |name, expr| cx.field_imm(sp, cx.ident_of(name, sp), expr);
 
@@ -181,6 +186,17 @@ pub fn expand_test_or_bench(
                             cx.expr_path(should_panic_path("YesWithMessage")),
                             vec![cx.expr_str(sp, sym)]),
                     }),
+                    // test_type: ...
+                    field("test_type", match test_type(cx) {
+                        // test::TestType::UnitTest
+                        TestType::UnitTest => cx.expr_path(test_type_path("UnitTest")),
+                        // test::TestType::IntegrationTest
+                        TestType::IntegrationTest => cx.expr_path(
+                            test_type_path("IntegrationTest")
+                        ),
+                        // test::TestPath::Unknown
+                        TestType::Unknown => cx.expr_path(test_type_path("Unknown")),
+                    }),
                 // },
                 ])),
                 // testfn: test::StaticTestFn(...) | test::StaticBenchFn(...)
@@ -261,6 +277,34 @@ fn should_panic(cx: &ExtCtxt<'_>, i: &ast::Item) -> ShouldPanic {
     }
 }
 
+enum TestType {
+    UnitTest,
+    IntegrationTest,
+    Unknown,
+}
+
+/// Attempts to determine the type of test.
+/// Since doctests are created without macro expanding, only possible variants here
+/// are `UnitTest`, `IntegrationTest` or `Unknown`.
+fn test_type(cx: &ExtCtxt<'_>) -> TestType {
+    // Root path from context contains the topmost sources directory of the crate.
+    // I.e., for `project` with sources in `src` and tests in `tests` folders
+    // (no matter how many nested folders lie inside),
+    // there will be two different root paths: `/project/src` and `/project/tests`.
+    let crate_path = cx.root_path.as_path();
+
+    if crate_path.ends_with("src") {
+        // `/src` folder contains unit-tests.
+        TestType::UnitTest
+    } else if crate_path.ends_with("tests") {
+        // `/tests` folder contains integration tests.
+        TestType::IntegrationTest
+    } else {
+        // Crate layout doesn't match expected one, test type is unknown.
+        TestType::Unknown
+    }
+}
+
 fn has_test_signature(cx: &ExtCtxt<'_>, i: &ast::Item) -> bool {
     let has_should_panic_attr = attr::contains_name(&i.attrs, sym::should_panic);
     let ref sd = cx.parse_sess.span_diagnostic;

src/libtest/formatters/json.rs

@@ -94,6 +94,15 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
                 self.write_event("test", desc.name.as_slice(), "failed", exec_time, stdout, None)
             }
 
+            TrTimedFail => self.write_event(
+                "test",
+                desc.name.as_slice(),
+                "failed",
+                exec_time,
+                stdout,
+                Some(r#""reason": "time limit exceeded""#),
+            ),
+
             TrFailedMsg(ref m) => self.write_event(
                 "test",
                 desc.name.as_slice(),

src/libtest/formatters/pretty.rs

@@ -3,6 +3,7 @@ use super::*;
 pub(crate) struct PrettyFormatter<T> {
     out: OutputLocation<T>,
     use_color: bool,
+    time_options: Option<TestTimeOptions>,
 
     /// Number of columns to fill when aligning names
     max_name_len: usize,
@@ -16,12 +17,14 @@ impl<T: Write> PrettyFormatter<T> {
         use_color: bool,
         max_name_len: usize,
         is_multithreaded: bool,
+        time_options: Option<TestTimeOptions>,
     ) -> Self {
         PrettyFormatter {
             out,
             use_color,
             max_name_len,
             is_multithreaded,
+            time_options
         }
     }
 
@@ -30,20 +33,24 @@ impl<T: Write> PrettyFormatter<T> {
         &self.out
     }
 
-    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_ok(&mut self) -> io::Result<()> {
+        self.write_short_result("ok", term::color::GREEN)
     }
 
-    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_failed(&mut self) -> io::Result<()> {
+        self.write_short_result("FAILED", term::color::RED)
     }
 
-    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_ignored(&mut self) -> io::Result<()> {
+        self.write_short_result("ignored", 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_allowed_fail(&mut self) -> io::Result<()> {
+        self.write_short_result("FAILED (allowed)", term::color::YELLOW)
+    }
+
+    pub fn write_time_failed(&mut self) -> io::Result<()> {
+        self.write_short_result("FAILED (time limit exceeded)", term::color::RED)
     }
 
     pub fn write_bench(&mut self) -> io::Result<()> {
@@ -54,13 +61,8 @@ 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")
+        self.write_pretty(result, color)
     }
 
     pub fn write_pretty(&mut self, word: &str, color: term::color::Color) -> io::Result<()> {
@@ -88,12 +90,48 @@ impl<T: Write> PrettyFormatter<T> {
         self.out.flush()
     }
 
-    pub fn write_successes(&mut self, state: &ConsoleTestState) -> io::Result<()> {
-        self.write_plain("\nsuccesses:\n")?;
-        let mut successes = Vec::new();
+    fn write_time(
+        &mut self,
+        desc: &TestDesc,
+        exec_time: Option<&TestExecTime>
+    ) -> io::Result<()> {
+        if let (Some(opts), Some(time)) = (self.time_options, exec_time) {
+            let time_str = format!(" <{}>", time);
+
+            let color = if opts.colored {
+                if opts.is_critical(desc, time) {
+                    Some(term::color::RED)
+                } else if opts.is_warn(desc, time) {
+                    Some(term::color::YELLOW)
+                } else {
+                    None
+                }
+            } else {
+                None
+            };
+
+            match color {
+                Some(color) => self.write_pretty(&time_str, color)?,
+                None => self.write_plain(&time_str)?
+            }
+        }
+
+        Ok(())
+    }
+
+    fn write_results(
+        &mut self,
+        inputs: &Vec<(TestDesc, Vec<u8>)>,
+        results_type: &str
+    ) -> io::Result<()> {
+        let results_out_str = format!("\n{}:\n", results_type);
+
+        self.write_plain(&results_out_str)?;
+
+        let mut results = Vec::new();
         let mut stdouts = String::new();
-        for &(ref f, ref stdout) in &state.not_failures {
-            successes.push(f.name.to_string());
+        for &(ref f, ref stdout) in inputs {
+            results.push(f.name.to_string());
             if !stdout.is_empty() {
                 stdouts.push_str(&format!("---- {} stdout ----\n", f.name));
                 let output = String::from_utf8_lossy(stdout);
@@ -106,38 +144,24 @@ impl<T: Write> PrettyFormatter<T> {
             self.write_plain(&stdouts)?;
         }
 
-        self.write_plain("\nsuccesses:\n")?;
-        successes.sort();
-        for name in &successes {
+        self.write_plain(&results_out_str)?;
+        results.sort();
+        for name in &results {
             self.write_plain(&format!("    {}\n", name))?;
         }
         Ok(())
     }
 
+    pub fn write_successes(&mut self, state: &ConsoleTestState) -> io::Result<()> {
+        self.write_results(&state.not_failures, "successes")
+    }
+
     pub fn write_failures(&mut self, state: &ConsoleTestState) -> io::Result<()> {
-        self.write_plain("\nfailures:\n")?;
-        let mut failures = Vec::new();
-        let mut fail_out = String::new();
-        for &(ref f, ref stdout) in &state.failures {
-            failures.push(f.name.to_string());
-            if !stdout.is_empty() {
-                fail_out.push_str(&format!("---- {} stdout ----\n", f.name));
-                let output = String::from_utf8_lossy(stdout);
-                fail_out.push_str(&output);
-                fail_out.push_str("\n");
-            }
-        }
-        if !fail_out.is_empty() {
-            self.write_plain("\n")?;
-            self.write_plain(&fail_out)?;
-        }
+        self.write_results(&state.failures, "failures")
+    }
 
-        self.write_plain("\nfailures:\n")?;
-        failures.sort();
-        for name in &failures {
-            self.write_plain(&format!("    {}\n", name))?;
-        }
-        Ok(())
+    pub fn write_time_failures(&mut self, state: &ConsoleTestState) -> io::Result<()> {
+        self.write_results(&state.time_failures, "failures (time limit exceeded)")
     }
 
     fn write_test_name(&mut self, desc: &TestDesc) -> io::Result<()> {
@@ -179,15 +203,19 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
         }
 
         match *result {
-            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),
+            TrOk => self.write_ok()?,
+            TrFailed | TrFailedMsg(_) => self.write_failed()?,
+            TrIgnored => self.write_ignored()?,
+            TrAllowedFail => self.write_allowed_fail()?,
             TrBench(ref bs) => {
                 self.write_bench()?;
-                self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))
+                self.write_plain(&format!(": {}", fmt_bench_samples(bs)))?;
             }
+            TrTimedFail => self.write_time_failed()?,
         }
+
+        self.write_time(desc, exec_time)?;
+        self.write_plain("\n")
     }
 
     fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> {
@@ -207,7 +235,13 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
         }
         let success = state.failed == 0;
         if !success {
-            self.write_failures(state)?;
+            if !state.failures.is_empty() {
+                self.write_failures(state)?;
+            }
+
+            if !state.time_failures.is_empty() {
+                self.write_time_failures(state)?;
+            }
         }
 
         self.write_plain("\ntest result: ")?;

src/libtest/formatters/terse.rs

@@ -180,7 +180,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
     ) -> io::Result<()> {
         match *result {
             TrOk => self.write_ok(),
-            TrFailed | TrFailedMsg(_) => self.write_failed(),
+            TrFailed | TrFailedMsg(_) | TrTimedFail => self.write_failed(),
             TrIgnored => self.write_ignored(),
             TrAllowedFail => self.write_allowed_fail(),
             TrBench(ref bs) => {