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};
 usecrate::html::markdown::{ErrorCodes,Ignore,LangString,MdRelLine};
 usecrate::lint::init_lints;
 
+/// Type used to display times (compilation and total) information for merged doctests.
+structMergedDoctestTimes{
+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,
+}
+
+implMergedDoctestTimes{
+fnnew() -> Self{
+Self{
+total_time:Instant::now(),
+compilation_time:Duration::default(),
+added_compilation_times:0,
+}
+}
+
+fnadd_compilation_time(&mutself,duration:Duration){
+self.compilation_time += duration;
+self.added_compilation_times += 1;
+}
+
+fndisplay_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).
+ifself.added_compilation_times > 0{
+println!("{self}");
+}
+}
+}
+
+impl fmt::DisplayforMergedDoctestTimes{
+fnfmt(&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)structGlobalTestOptions{
@@ -295,6 +340,7 @@ pub(crate) fn run_tests(
 
 letmut nb_errors = 0;
 letmut ran_edition_tests = 0;
+letmut 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);
 }
-ifletOk(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);
+ifletOk(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.
 fnrun_test(
 doctest:RunnableDocTest,
 rustdoc_options:&RustdocOptions,
 supports_color:bool,
 report_unused_externs:implFn(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.
-returnErr(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.
-returnErr(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) => {
-returnErr(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(){
-returnErr(TestFailure::MissingErrorCodes(missing_codes));
+return(instant.elapsed(),Err(TestFailure::MissingErrorCodes(missing_codes)));
 }
 }
 }
 (false,false) => {
-returnErr(TestFailure::CompileError);
+return(instant.elapsed(),Err(TestFailure::CompileError));
 }
 }
 
+let duration = instant.elapsed();
 if doctest.no_run{
-returnOk(());
+return(duration,Ok(()));
 }
 
 // Run the code!
@@ -771,17 +825,17 @@ fn run_test(
  cmd.output()
 };
 match result {
-Err(e) => returnErr(TestFailure::ExecutionError(e)),
+Err(e) => return(duration,Err(TestFailure::ExecutionError(e))),
 Ok(out) => {
 if langstr.should_panic && out.status.success(){
-returnErr(TestFailure::UnexpectedRunPass);
+return(duration,Err(TestFailure::UnexpectedRunPass));
 }elseif !langstr.should_panic && !out.status.success(){
-returnErr(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);
 
 ifletErr(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)fnrun_merged_tests(
 &mutself,
 test_options:IndividualTestOptions,
 edition:Edition,
 opts:&GlobalTestOptions,
 test_args:&[String],
 rustdoc_options:&RustdocOptions,
-) -> Result<bool,()>{
+) -> (Duration,Result<bool,()>){
 letmut 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| {});
-ifletErr(TestFailure::CompileError) = ret {Err(())}else{Ok(ret.is_ok())}
+(duration,ifletErr(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))))]