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

GuillaumeGomez · 2025-07-22T14:03:37Z

Does it look good to you @kpreid?

rustbot · 2025-07-22T14:03:42Z

rustbot has assigned @notriddle.
They will have a look at your PR within the next two weeks and either review your PR or reassign to another reviewer.

Use r? to explicitly pick a reviewer

kpreid · 2025-07-22T14:57:17Z

Does it look good to you @kpreid?

This seems sufficient, in that it communicates the missing information, separately.

However, there is a way in which I predict it will be frequently confusing: there is no spatial or textual association of "merged doctests compilation took…" with which tests are the merged ones. A user wanting to know which doctests this refers to has to reason about what 'merged doctests' means and then, using that fact, figure out they must be the first group since the second group has compile-fail tests.

I strongly recommend that the report of compilation time should not be separated from the tests it refers to by unrelated tests.

When I initially imagined quickly adding this feature, I imagined putting the doctest compilation time at the top, corresponding to when it actually happens, and thus also adjacent to the merged tests. Another option would be to label the group of merged tests as merged, somehow.

GuillaumeGomez · 2025-07-22T15:00:16Z

You can have multiple merged doctests groups, so unless we show it for each group, I'm not sure it's really useful. It tells how much time it spent compiling merged doctests and the total time for all doctests.

kpreid · 2025-07-22T15:05:43Z

Ah, I see, I wasn't aware that there was a possibility of multiple groups. I don't have any further ideas. Thank you for working on this.

src/librustdoc/doctest.rs

lolbinarycat · 2025-07-22T18:54:40Z

src/librustdoc/doctest.rs

+    fn display_times(&self) {
+        // If no merged doctest was compiled, then there is nothing to display.
+        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(),
+        )
+    }
+}


Shouldn't we still print the total compilation time, even if there are no merged doctests?

No because in this case, the numbers displayed by libtest are already accurate.

Some extra info: for standalone tests, libtest reports both compilation and run time as each doctest passed to libtest will call the doctest_run_fn which handles both.

hm, that's odd, that's what i thought initially, but the numbers in the screenshot simply don't add up for that to be the case. not sure what's happening here.

in any case, the comment explaining the rationale for ommitting all the output seems incomplete and mildly misleading.

So calculation is:

merged compilation times + standalone run times + merged run times = total time

With the screenshot numbers:

1.24 + 0.43 + 0.05 = 1.72

That seems to match the numbers. Did I miss something?

ah, i see it now, i wasn't looking at the top section because i've never seen the output for a crate with both standalone and merged doctests, and i didn't expect then to be printed in seperate groups.

i'm not sure if the output is confusing or it's just me, but maybe if the time taken for merged doctest compilation was printed right before the merged doctests were run, that would be more intuitive, saying the times for things as they happen?

i would say we should just add a comment somewhere, but that won't make it more intuitive for users..

but maybe making this 10% more intuitive isn't worth the extra implement effort, i don't know how hard it would be to print things in that order.

another possibility is when it says "running N tests" make it say "running N merged doctests" or "running N standalone doctests" so its more obvious what number refers to what.

i'm not sure if the output is confusing or it's just me, but maybe if the time taken for merged doctest compilation was printed right before the merged doctests were run, that would be more intuitive, saying the times for things as they happen?

What happens if the merged doctests compilation failed then? We still need to show this number but then it's followed by standalone doctests. Seems even more confusing imo.

Putting this information at the end sounds the less confusing option to me.

another possibility is when it says "running N tests" make it say "running N merged doctests" or "running N standalone doctests" so its more obvious what number refers to what.

Sounds like an improvement that can be sent as a follow-up.

What happens if the merged doctests compilation failed then? We still need to show this number but then it's followed by standalone doctests. Seems even more confusing imo.

I don't know why it would be printed before the standalone tests instead of after them, but I'll trust that there's some implementation detail I don't know of.

Sounds like an improvement that can be sent as a follow-up.

Sounds good!

What happens if the merged doctests compilation failed then? We still need to show this number but then it's followed by standalone doctests. Seems even more confusing imo.

I don't know why it would be printed before the standalone tests instead of after them, but I'll trust that there's some implementation detail I don't know of.

This is nothing about technical details, just me trying to underlying that multiplying output is never desirable because of different potential cases. Your starting point was that the current output could be confusing and suggesting some alternatives. And I replied on the suggested alternative, with an example where we might display information about compile time for merged doctests that actually don't appear anywhere (because the compilation failed, reverting them to standalone doctests).

Anyway, even if not perfect, I think the current display is a nice first step.

src/librustdoc/doctest.rs

lolbinarycat · 2025-07-22T19:44:35Z

src/librustdoc/doctest.rs

@@ -1071,7 +1120,7 @@ fn doctest_run_fn(
        no_run: scraped_test.no_run(&rustdoc_options),
        merged_test_code: None,
    };
-    let res =
+    let (_, res) =


Is there a reason we're not also tracking this, so we can report (time compiling standalone tests, time compiling merged tests)?

I believe doctests are run with some level of parallelism, so currently we would be reporting the total absolute wall clock time for the total compilation time, but for merged doctests, we're reporting the sum of the amount of time each thread spent compiling. This inconsistency could over-report the impact of merged doctests.

Also, if parallelism is involved, then I think perhaps a more useful metric for minimizing compilation time would be how long the longest test took.

We only compile and run standalone tests in parallel, merged doctests are never compiled in parallel (but still run in parallel).

We report raw numbers. Also we cannot get which tests took the longest to run as only libtest has this information in theory (but they don't keep track of it). Finally, I don't see how this is an issue to say how much time was spent in compiling merged doctests.

GuillaumeGomez · 2025-07-30T09:04:33Z

@bors r=lolbinarycat rollup

bors · 2025-07-30T09:04:37Z

📌 Commit 64e3078 has been approved by lolbinarycat

It is now in the queue for this repository.

Rollup of 4 pull requests Successful merges: - #143465 (Support multiple crate versions in --extern-html-root-url) - #144308 ([rustdoc] Display total time and compilation time of merged doctests) - #144655 (clean up codegen fn attrs) - #144675 (Reject running `compiletest` self-tests against stage 0 rustc unless explicitly allowed) r? `@ghost` `@rustbot` modify labels: rollup

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" />

arpadav · 2025-08-01T20:29:01Z

@GuillaumeGomez this is breaks the --format json unstable option, since the time displayed goes to stdout. as a result, if you run something like:

cargo +nightly test --doc -- -Z unstable-options --format json > doc-test.json

then

...
{ "type": "suite", "event": "ok", "passed": 0, "failed": 0, "ignored": 5, "measured": 0, "filtered_out": 0, "exec_time": 0.000229133 }
all doctests ran in 0.17s; merged doctests compilation took 0.17s

this line is at the end of each output. in addition, when using the --workspace flag, it appears after every library is doc-tested.

I assume this is not intended? It can easily be dealt with, but I realized my CICD started failing when parsing this output so I wanted to ask/report

GuillaumeGomez · 2025-08-01T20:47:41Z

No indeed. Please open an issue and ping me on it. I'll take a look in the next days.

rustbot assigned notriddle Jul 22, 2025

rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-rustdoc Relevant to the rustdoc team, which will review and decide on the PR/issue. labels Jul 22, 2025

lolbinarycat requested changes Jul 22, 2025

View reviewed changes

GuillaumeGomez force-pushed the merged-doctest-times branch from a3d520c to d0ec770 Compare July 23, 2025 17:49

GuillaumeGomez added 2 commits July 24, 2025 11:06

Display total time and compilation time of merged doctests

d622bfd

Update rustdoc ui tests

64e3078

GuillaumeGomez force-pushed the merged-doctest-times branch from d0ec770 to 64e3078 Compare July 24, 2025 09:06

lolbinarycat mentioned this pull request Jul 28, 2025

libtest: print the type of test being run #144596

Open

lolbinarycat approved these changes Jul 29, 2025

View reviewed changes

bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jul 30, 2025

samueltardieu mentioned this pull request Jul 30, 2025

Rollup of 4 pull requests #144692

Merged

bors merged commit 61760fb into rust-lang:master Jul 30, 2025
10 checks passed

rustbot added this to the 1.90.0 milestone Jul 30, 2025

GuillaumeGomez deleted the merged-doctest-times branch July 31, 2025 09:01

arpadav mentioned this pull request Aug 1, 2025

[rustdoc] Non-json time diagnostics in stdout when using --format json #144798

Open

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

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

Uh oh!

Conversation

GuillaumeGomez commented Jul 22, 2025 • edited by rustbot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rustbot commented Jul 22, 2025

Uh oh!

kpreid commented Jul 22, 2025

Uh oh!

GuillaumeGomez commented Jul 22, 2025

Uh oh!

kpreid commented Jul 22, 2025

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lolbinarycat Jul 23, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

GuillaumeGomez commented Jul 30, 2025

Uh oh!

bors commented Jul 30, 2025

Uh oh!

Uh oh!

arpadav commented Aug 1, 2025

Uh oh!

GuillaumeGomez commented Aug 1, 2025

Uh oh!

Uh oh!

GuillaumeGomez commented Jul 22, 2025 •

edited by rustbot

Loading

lolbinarycat Jul 23, 2025 •

edited

Loading