Rollup merge of #144308 - GuillaumeGomez:merged-doctest-times, r=lolbinarycat

[rustdoc] Display total time and compilation time of merged doctests

Fixes #144270.

Does it look good to you `@kpreid?`

<img width="908" height="263" alt="image" src="https://github.com/user-attachments/assets/cd5d082d-c4e0-42ed-91dd-bd263b413dcd" />

Author: samueltardieu

src/librustdoc/doctest.rs

@@ -11,7 +11,8 @@ use std::path::{Path, PathBuf};
 use std::process::{self, Command, Stdio};
 use std::sync::atomic::{AtomicUsize, Ordering};
 use std::sync::{Arc, Mutex};
-use std::{panic, str};
+use std::time::{Duration, Instant};
+use std::{fmt, panic, str};
 
 pub(crate) use make::{BuildDocTestBuilder, DocTestBuilder};
 pub(crate) use markdown::test as test_markdown;
@@ -36,6 +37,50 @@ use crate::config::{Options as RustdocOptions, OutputFormat};
 use crate::html::markdown::{ErrorCodes, Ignore, LangString, MdRelLine};
 use crate::lint::init_lints;
 
+/// Type used to display times (compilation and total) information for merged doctests.
+struct MergedDoctestTimes {
+    total_time: Instant,
+    /// Total time spent compiling all merged doctests.
+    compilation_time: Duration,
+    /// This field is used to keep track of how many merged doctests we (tried to) compile.
+    added_compilation_times: usize,
+}
+
+impl MergedDoctestTimes {
+    fn new() -> Self {
+        Self {
+            total_time: Instant::now(),
+            compilation_time: Duration::default(),
+            added_compilation_times: 0,
+        }
+    }
+
+    fn add_compilation_time(&mut self, duration: Duration) {
+        self.compilation_time += duration;
+        self.added_compilation_times += 1;
+    }
+
+    fn display_times(&self) {
+        // If no merged doctest was compiled, then there is nothing to display since the numbers
+        // displayed by `libtest` for standalone tests are already accurate (they include both
+        // compilation and runtime).
+        if self.added_compilation_times > 0 {
+            println!("{self}");
+        }
+    }
+}
+
+impl fmt::Display for MergedDoctestTimes {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(
+            f,
+            "all doctests ran in {:.2}s; merged doctests compilation took {:.2}s",
+            self.total_time.elapsed().as_secs_f64(),
+            self.compilation_time.as_secs_f64(),
+        )
+    }
+}
+
 /// Options that apply to all doctests in a crate or Markdown file (for `rustdoc foo.md`).
 #[derive(Clone)]
 pub(crate) struct GlobalTestOptions {
@@ -295,6 +340,7 @@ pub(crate) fn run_tests(
 
     let mut nb_errors = 0;
     let mut ran_edition_tests = 0;
+    let mut times = MergedDoctestTimes::new();
     let target_str = rustdoc_options.target.to_string();
 
     for (MergeableTestKey { edition, global_crate_attrs_hash }, mut doctests) in mergeable_tests {
@@ -314,13 +360,15 @@ pub(crate) fn run_tests(
         for (doctest, scraped_test) in &doctests {
             tests_runner.add_test(doctest, scraped_test, &target_str);
         }
-        if let Ok(success) = tests_runner.run_merged_tests(
+        let (duration, ret) = tests_runner.run_merged_tests(
             rustdoc_test_options,
             edition,
             &opts,
             &test_args,
             rustdoc_options,
-        ) {
+        );
+        times.add_compilation_time(duration);
+        if let Ok(success) = ret {
             ran_edition_tests += 1;
             if !success {
                 nb_errors += 1;
@@ -354,11 +402,13 @@ pub(crate) fn run_tests(
         test::test_main_with_exit_callback(&test_args, standalone_tests, None, || {
             // We ensure temp dir destructor is called.
             std::mem::drop(temp_dir.take());
+            times.display_times();
         });
     }
     if nb_errors != 0 {
         // We ensure temp dir destructor is called.
         std::mem::drop(temp_dir);
+        times.display_times();
         // libtest::ERROR_EXIT_CODE is not public but it's the same value.
         std::process::exit(101);
     }
@@ -496,16 +546,19 @@ impl RunnableDocTest {
 ///
 /// This is the function that calculates the compiler command line, invokes the compiler, then
 /// invokes the test or tests in a separate executable (if applicable).
+///
+/// Returns a tuple containing the `Duration` of the compilation and the `Result` of the test.
 fn run_test(
     doctest: RunnableDocTest,
     rustdoc_options: &RustdocOptions,
     supports_color: bool,
     report_unused_externs: impl Fn(UnusedExterns),
-) -> Result<(), TestFailure> {
+) -> (Duration, Result<(), TestFailure>) {
     let langstr = &doctest.langstr;
     // Make sure we emit well-formed executable names for our target.
     let rust_out = add_exe_suffix("rust_out".to_owned(), &rustdoc_options.target);
     let output_file = doctest.test_opts.outdir.path().join(rust_out);
+    let instant = Instant::now();
 
     // Common arguments used for compiling the doctest runner.
     // On merged doctests, the compiler is invoked twice: once for the test code itself,
@@ -589,7 +642,7 @@ fn run_test(
         if std::fs::write(&input_file, &doctest.full_test_code).is_err() {
             // If we cannot write this file for any reason, we leave. All combined tests will be
             // tested as standalone tests.
-            return Err(TestFailure::CompileError);
+            return (Duration::default(), Err(TestFailure::CompileError));
         }
         if !rustdoc_options.nocapture {
             // If `nocapture` is disabled, then we don't display rustc's output when compiling
@@ -660,7 +713,7 @@ fn run_test(
         if std::fs::write(&runner_input_file, merged_test_code).is_err() {
             // If we cannot write this file for any reason, we leave. All combined tests will be
             // tested as standalone tests.
-            return Err(TestFailure::CompileError);
+            return (instant.elapsed(), Err(TestFailure::CompileError));
         }
         if !rustdoc_options.nocapture {
             // If `nocapture` is disabled, then we don't display rustc's output when compiling
@@ -713,7 +766,7 @@ fn run_test(
     let _bomb = Bomb(&out);
     match (output.status.success(), langstr.compile_fail) {
         (true, true) => {
-            return Err(TestFailure::UnexpectedCompilePass);
+            return (instant.elapsed(), Err(TestFailure::UnexpectedCompilePass));
         }
         (true, false) => {}
         (false, true) => {
@@ -729,17 +782,18 @@ fn run_test(
                     .collect();
 
                 if !missing_codes.is_empty() {
-                    return Err(TestFailure::MissingErrorCodes(missing_codes));
+                    return (instant.elapsed(), Err(TestFailure::MissingErrorCodes(missing_codes)));
                 }
             }
         }
         (false, false) => {
-            return Err(TestFailure::CompileError);
+            return (instant.elapsed(), Err(TestFailure::CompileError));
         }
     }
 
+    let duration = instant.elapsed();
     if doctest.no_run {
-        return Ok(());
+        return (duration, Ok(()));
     }
 
     // Run the code!
@@ -771,17 +825,17 @@ fn run_test(
         cmd.output()
     };
     match result {
-        Err(e) => return Err(TestFailure::ExecutionError(e)),
+        Err(e) => return (duration, Err(TestFailure::ExecutionError(e))),
         Ok(out) => {
             if langstr.should_panic && out.status.success() {
-                return Err(TestFailure::UnexpectedRunPass);
+                return (duration, Err(TestFailure::UnexpectedRunPass));
             } else if !langstr.should_panic && !out.status.success() {
-                return Err(TestFailure::ExecutionFailure(out));
+                return (duration, Err(TestFailure::ExecutionFailure(out)));
             }
         }
     }
 
-    Ok(())
+    (duration, Ok(()))
 }
 
 /// Converts a path intended to use as a command to absolute if it is
@@ -1071,7 +1125,7 @@ fn doctest_run_fn(
         no_run: scraped_test.no_run(&rustdoc_options),
         merged_test_code: None,
     };
-    let res =
+    let (_, res) =
         run_test(runnable_test, &rustdoc_options, doctest.supports_color, report_unused_externs);
 
     if let Err(err) = res {

src/librustdoc/doctest/runner.rs

@@ -1,4 +1,5 @@
 use std::fmt::Write;
+use std::time::Duration;
 
 use rustc_data_structures::fx::FxIndexSet;
 use rustc_span::edition::Edition;
@@ -67,14 +68,18 @@ impl DocTestRunner {
         self.nb_tests += 1;
     }
 
+    /// Returns a tuple containing the `Duration` of the compilation and the `Result` of the test.
+    ///
+    /// If compilation failed, it will return `Err`, otherwise it will return `Ok` containing if
+    /// the test ran successfully.
     pub(crate) fn run_merged_tests(
         &mut self,
         test_options: IndividualTestOptions,
         edition: Edition,
         opts: &GlobalTestOptions,
         test_args: &[String],
         rustdoc_options: &RustdocOptions,
-    ) -> Result<bool, ()> {
+    ) -> (Duration, Result<bool, ()>) {
         let mut code = "\
 #![allow(unused_extern_crates)]
 #![allow(internal_features)]
@@ -204,9 +209,9 @@ std::process::Termination::report(test::test_main(test_args, tests, None))
             no_run: false,
             merged_test_code: Some(code),
         };
-        let ret =
+        let (duration, ret) =
             run_test(runnable_test, rustdoc_options, self.supports_color, |_: UnusedExterns| {});
-        if let Err(TestFailure::CompileError) = ret { Err(()) } else { Ok(ret.is_ok()) }
+        (duration, if let Err(TestFailure::CompileError) = ret { Err(()) } else { Ok(ret.is_ok()) })
     }
 }
 

tests/rustdoc-ui/2024-doctests-checks.rs

@@ -3,6 +3,8 @@
 //@ compile-flags: --test --test-args=--test-threads=1
 //@ normalize-stdout: "tests/rustdoc-ui" -> "$$DIR"
 //@ normalize-stdout: "finished in \d+\.\d+s" -> "finished in $$TIME"
+//@ normalize-stdout: "ran in \d+\.\d+s" -> "ran in $$TIME"
+//@ normalize-stdout: "compilation took \d+\.\d+s" -> "compilation took $$TIME"
 //@ normalize-stdout: ".rs:\d+:\d+" -> ".rs:$$LINE:$$COL"
 
 /// ```

tests/rustdoc-ui/2024-doctests-checks.stdout

@@ -1,12 +1,13 @@
 
 running 1 test
-test $DIR/2024-doctests-checks.rs - Foo (line 8) ... ok
+test $DIR/2024-doctests-checks.rs - Foo (line 10) ... ok
 
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in $TIME
 
 
 running 1 test
-test $DIR/2024-doctests-checks.rs - Foo (line 15) ... ok
+test $DIR/2024-doctests-checks.rs - Foo (line 17) ... ok
 
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in $TIME
 
+all doctests ran in $TIME; merged doctests compilation took $TIME

tests/rustdoc-ui/2024-doctests-crate-attribute.rs

@@ -4,6 +4,8 @@
 //@ normalize-stdout: "tests/rustdoc-ui" -> "$$DIR"
 //@ normalize-stdout: "finished in \d+\.\d+s" -> "finished in $$TIME"
 //@ normalize-stdout: ".rs:\d+:\d+" -> ".rs:$$LINE:$$COL"
+//@ normalize-stdout: "ran in \d+\.\d+s" -> "ran in $$TIME"
+//@ normalize-stdout: "compilation took \d+\.\d+s" -> "compilation took $$TIME"
 
 /// This doctest is used to ensure that if a crate attribute is present,
 /// it will not be part of the merged doctests.

tests/rustdoc-ui/2024-doctests-crate-attribute.stdout

@@ -1,12 +1,13 @@
 
 running 1 test
-test $DIR/2024-doctests-crate-attribute.rs - Foo (line 20) ... ok
+test $DIR/2024-doctests-crate-attribute.rs - Foo (line 22) ... ok
 
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in $TIME
 
 
 running 1 test
-test $DIR/2024-doctests-crate-attribute.rs - Foo (line 11) ... ok
+test $DIR/2024-doctests-crate-attribute.rs - Foo (line 13) ... ok
 
 test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in $TIME
 
+all doctests ran in $TIME; merged doctests compilation took $TIME

tests/rustdoc-ui/doctest/dead-code-2024.rs

@@ -4,6 +4,8 @@
 //@ compile-flags:--test
 //@ normalize-stdout: "tests/rustdoc-ui/doctest" -> "$$DIR"
 //@ normalize-stdout: "finished in \d+\.\d+s" -> "finished in $$TIME"
+//@ normalize-stdout: "ran in \d+\.\d+s" -> "ran in $$TIME"
+//@ normalize-stdout: "compilation took \d+\.\d+s" -> "compilation took $$TIME"
 //@ failure-status: 101
 
 #![doc(test(attr(allow(unused_variables), deny(warnings))))]

tests/rustdoc-ui/doctest/dead-code-2024.stdout

@@ -1,18 +1,18 @@
 
 running 1 test
-test $DIR/dead-code-2024.rs - f (line 13) - compile ... FAILED
+test $DIR/dead-code-2024.rs - f (line 15) - compile ... FAILED
 
 failures:
 
----- $DIR/dead-code-2024.rs - f (line 13) stdout ----
+---- $DIR/dead-code-2024.rs - f (line 15) stdout ----
 error: trait `T` is never used
-  --> $DIR/dead-code-2024.rs:14:7
+  --> $DIR/dead-code-2024.rs:16:7
    |
 LL | trait T { fn f(); }
    |       ^
    |
 note: the lint level is defined here
-  --> $DIR/dead-code-2024.rs:12:9
+  --> $DIR/dead-code-2024.rs:14:9
    |
 LL | #![deny(warnings)]
    |         ^^^^^^^^
@@ -23,7 +23,8 @@ error: aborting due to 1 previous error
 Couldn't compile the test.
 
 failures:
-    $DIR/dead-code-2024.rs - f (line 13)
+    $DIR/dead-code-2024.rs - f (line 15)
 
 test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in $TIME
 
+all doctests ran in $TIME; merged doctests compilation took $TIME

tests/rustdoc-ui/doctest/dead-code-items.rs

@@ -4,6 +4,8 @@
 //@ compile-flags:--test --test-args=--test-threads=1
 //@ normalize-stdout: "tests/rustdoc-ui/doctest" -> "$$DIR"
 //@ normalize-stdout: "finished in \d+\.\d+s" -> "finished in $$TIME"
+//@ normalize-stdout: "ran in \d+\.\d+s" -> "ran in $$TIME"
+//@ normalize-stdout: "compilation took \d+\.\d+s" -> "compilation took $$TIME"
 //@ failure-status: 101
 
 #![doc(test(attr(deny(warnings))))]