Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add some timing info to rustdoc #74590

Merged
merged 9 commits into from
Aug 24, 2020
Merged

Add some timing info to rustdoc #74590

merged 9 commits into from
Aug 24, 2020

Conversation

jyn514
Copy link
Member

@jyn514 jyn514 commented Jul 21, 2020

There are various improvements, but the main one is to time each pass
that rustdoc performs (rustdoc::passes).

Before, these were the top five timings for cargo doc on the cargo
repository:

+---------------------------------+-----------+-----------------+----------+------------+
| Item                            | Self time | % of total time | Time     | Item count |
+---------------------------------+-----------+-----------------+----------+------------+
| <unknown>                       | 854.70ms  | 20.888          | 2.47s    | 744823     |
+---------------------------------+-----------+-----------------+----------+------------+
| expand_crate                    | 795.29ms  | 19.436          | 848.00ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| metadata_decode_entry           | 256.73ms  | 6.274           | 279.49ms | 518344     |
+---------------------------------+-----------+-----------------+----------+------------+
| resolve_crate                   | 240.56ms  | 5.879           | 242.86ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| hir_lowering                    | 146.79ms  | 3.587           | 146.79ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+

Now the timings are:

+---------------------------------+-----------+-----------------+----------+------------+
| Item                            | Self time | % of total time | Time     | Item count |
+---------------------------------+-----------+-----------------+----------+------------+
| <unknown>                       | 1.40s     | 22.662          | 3.73s    | 771430     |
+---------------------------------+-----------+-----------------+----------+------------+
| collect-trait-impls             | 1.34s     | 21.672          | 2.87s    | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| expand_crate                    | 1.21s     | 19.577          | 1.28s    | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| build extern trait impl         | 704.66ms  | 11.427          | 1.07s    | 21893      |
+---------------------------------+-----------+-----------------+----------+------------+
| metadata_decode_entry           | 354.84ms  | 5.754           | 391.81ms | 544919     |
+---------------------------------+-----------+-----------------+----------+------------+

The goal is to help me debug regressions like #74518 (comment) (currently I have no idea what could have gone wrong).

r? @eddyb or @Mark-Simulacrum

@jyn514 jyn514 added I-slow Issue: Problems and improvements with respect to performance of generated code. T-rustdoc Relevant to the rustdoc team, which will review and decide on the PR/issue. labels Jul 21, 2020
@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Jul 21, 2020
@Mark-Simulacrum
Copy link
Member

Do we have some idea where the unknown is coming from? The time spent in it seems to have ... gone up?

@jyn514
Copy link
Member Author

jyn514 commented Jul 21, 2020

@Mark-Simulacrum the overall time went up as well, I think because of one of the regressions in https://github.com/rust-lang/rustc-perf/blob/master/triage/2020-07-21.md. I would look at the percentages instead.

@jyn514
Copy link
Member Author

jyn514 commented Jul 21, 2020

I'm not sure where the <unknown> is coming from - I tried to wrap all of rustdoc::core in a timer but that didn't work because the main function doesn't have access to a compile session.

@jyn514 jyn514 added I-compiletime Issue: Problems and improvements with respect to compile times. and removed I-slow Issue: Problems and improvements with respect to performance of generated code. labels Aug 5, 2020
@bors
Copy link
Contributor

bors commented Aug 6, 2020

☔ The latest upstream changes (presumably #75008) made this pull request unmergeable. Please resolve the merge conflicts.

@eddyb
Copy link
Member

eddyb commented Aug 16, 2020

@jyn514 You don't need to wrap the entirety of rustdoc, just the outermost thing that has access to a timer/profiler.

r? @Mark-Simulacrum or @wesleywiser

Comment on lines 405 to 414
EmitIgnoredResolutionErrors::new(tcx).visit_body(body);
tcx.sess.time("emit ignored resolution errors", || {
EmitIgnoredResolutionErrors::new(tcx).visit_body(body);
});
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: not a bad change, but would not have been marked as <unknown> before (it would show up as part of typeck).

src/librustdoc/core.rs Outdated Show resolved Hide resolved
src/librustdoc/core.rs Outdated Show resolved Hide resolved
@eddyb
Copy link
Member

eddyb commented Aug 16, 2020

At the very least, it looks like the entirety of global_ctxt.enter(|tcx| { could be wrapped in a named region (if not more).

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

Addressed review comments. I separated the enormous closure into a separate function, so best to view with whitespace changes disabled. Building rustdoc now to see if that got rid of most of the <unknown>.

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

Timing the global context didn't seem to help much.

+-------------------------------------------------+-----------+-----------------+----------+------------+
| Item                                            | Self time | % of total time | Time     | Item count |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| collect-trait-impls                             | 1.46s     | 23.619          | 3.26s    | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| expand_crate                                    | 1.20s     | 19.538          | 1.25s    | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| <unknown>                                       | 1.09s     | 17.746          | 3.17s    | 753829     |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| run_global_ctxt                                 | 3.34ms    | 0.054           | 4.24s    | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

I did find this comment though:

fn finalize_tcx(tcx: TyCtxt<'_>) {
tcx.sess.time("assert_dep_graph", || ::rustc_incremental::assert_dep_graph(tcx));
tcx.sess.time("serialize_dep_graph", || ::rustc_incremental::save_dep_graph(tcx));
// We assume that no queries are run past here. If there are new queries
// after this point, they'll show up as "<unknown>" in self-profiling data.
{
let _prof_timer = tcx.prof.generic_activity("self_profile_alloc_query_strings");
tcx.alloc_self_profile_query_strings();
}
}

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

Aha, I think I found the issue: all of the html rendering isn't timed.

rust/src/librustdoc/lib.rs

Lines 525 to 533 in 1d69e3b

let diag = core::new_handler(error_format, None, &debugging_options);
match output_format {
None | Some(config::OutputFormat::Html) => {
run_renderer::<html::render::Context>(krate, renderopts, renderinfo, &diag, edition)
}
Some(config::OutputFormat::Json) => {
run_renderer::<json::JsonRenderer>(krate, renderopts, renderinfo, &diag, edition)
}
}

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

Well, that helped a little.

$ summarize summarize time-html/unknown-crate-3300.events 
+-------------------------------------------------+-----------+-----------------+----------+------------+
| Item                                            | Self time | % of total time | Time     | Item count |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| collect-trait-impls                             | 1.46s     | 21.568          | 3.29s    | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| expand_crate                                    | 1.22s     | 18.103          | 1.27s    | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| <unknown>                                       | 1.12s     | 16.504          | 3.35s    | 753829     |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| build extern trait impl                         | 822.75ms  | 12.162          | 1.34s    | 21968      |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| render html                                     | 439.39ms  | 6.495           | 439.39ms | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

It's coming from item_types_checking.
flamegraph
rustdoc.zip

@jyn514
Copy link
Member Author

jyn514 commented Aug 16, 2020

Anyone know why this might be getting the timing name reset?

    tcx.sess.time("item_types_checking", || {
        for &module in tcx.hir().krate().modules.keys() {
            tcx.sess.time("check_mod_item_types", || {
            tcx.ensure().check_mod_item_types(tcx.hir().local_def_id(module));
            });
        }
    });

check_mod_item_types works fine and shows almost exactly 0 time spent in it, instead there's half a second of <unknown>.
https://github.com/rust-lang/rust/pull/74590/files?diff=unified&w=1#diff-0de644786a2f1fd88c7d7f44bc3fa4bbR497

@Mark-Simulacrum
Copy link
Member

I would personally like us to track down the problem with unknown timing before merging this in, though I don't have great ideas for doing that. Maybe @wesleywiser has suggestions?

@Mark-Simulacrum Mark-Simulacrum removed the I-compiletime Issue: Problems and improvements with respect to compile times. label Aug 18, 2020
@bors
Copy link
Contributor

bors commented Aug 24, 2020

☔ The latest upstream changes (presumably #74489) made this pull request unmergeable. Please resolve the merge conflicts.

@jyn514
Copy link
Member Author

jyn514 commented Aug 24, 2020

@Mark-Simulacrum I don't expect to have time to debug this soon ... are you okay with merging the current changes and opening an issue for the <unknown>? I'd rather have some timing than having to guess.

There are various improvements, but the main one is to time each pass
that rustdoc performs (`rustdoc::passes`).

Before, these were the top five timings for `cargo doc` on the cargo
repository:

```
+---------------------------------+-----------+-----------------+----------+------------+
| Item                            | Self time | % of total time | Time     | Item count |
+---------------------------------+-----------+-----------------+----------+------------+
| <unknown>                       | 854.70ms  | 20.888          | 2.47s    | 744823     |
+---------------------------------+-----------+-----------------+----------+------------+
| expand_crate                    | 795.29ms  | 19.436          | 848.00ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| metadata_decode_entry           | 256.73ms  | 6.274           | 279.49ms | 518344     |
+---------------------------------+-----------+-----------------+----------+------------+
| resolve_crate                   | 240.56ms  | 5.879           | 242.86ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| hir_lowering                    | 146.79ms  | 3.587           | 146.79ms | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
```

Now the timings are:

```
+---------------------------------+-----------+-----------------+----------+------------+
| Item                            | Self time | % of total time | Time     | Item count |
+---------------------------------+-----------+-----------------+----------+------------+
| <unknown>                       | 1.40s     | 22.662          | 3.73s    | 771430     |
+---------------------------------+-----------+-----------------+----------+------------+
| collect-trait-impls             | 1.34s     | 21.672          | 2.87s    | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| expand_crate                    | 1.21s     | 19.577          | 1.28s    | 1          |
+---------------------------------+-----------+-----------------+----------+------------+
| build extern trait impl         | 704.66ms  | 11.427          | 1.07s    | 21893      |
+---------------------------------+-----------+-----------------+----------+------------+
| metadata_decode_entry           | 354.84ms  | 5.754           | 391.81ms | 544919     |
+---------------------------------+-----------+-----------------+----------+------------+
```
Had to use -Xignore-whitespace-conflicts to avoid awful conflicts, but
that threw off the indentation
@wesleywiser
Copy link
Member

I've only skimmed the PR but I think we should not block merging this with resolving the unknown issue. We've seen that before in other profiles so it's probably another instance of the existing issue. I hope to have some time this week to look into it.

@Mark-Simulacrum
Copy link
Member

Okay, knowing that we've seen this before is indeed helpful and that convinces me that it should be fine to move ahead here.

@bors r+

@bors
Copy link
Contributor

bors commented Aug 24, 2020

📌 Commit 6e3e74d has been approved by Mark-Simulacrum

@bors 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-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Aug 24, 2020
@bors
Copy link
Contributor

bors commented Aug 24, 2020

⌛ Testing commit 6e3e74d with merge 0301700...

@bors
Copy link
Contributor

bors commented Aug 24, 2020

☀️ Test successful - checks-actions, checks-azure
Approved by: Mark-Simulacrum
Pushing 0301700 to master...

@bors bors added the merged-by-bors This PR was explicitly merged by bors. label Aug 24, 2020
@bors bors merged commit 0301700 into rust-lang:master Aug 24, 2020
@jyn514 jyn514 deleted the timing branch August 24, 2020 15:05
@camelid
Copy link
Member

camelid commented Nov 25, 2020

You may already know this, but this seems to be the rustc code that produces the <unknown> name:

let file_name = file_name.as_deref().unwrap_or("<unknown>");

Not sure why it's happening though.

@jyn514
Copy link
Member Author

jyn514 commented Nov 25, 2020

That's under debuginfo, so I wouldn't expect it to be related.

I did notice a while back that rustdoc doesn't include the crate name in the .events file - I think that might be because doctree passes None for the crate name? I need to test it.
https://github.com/rust-lang/rust/blob/master/src/librustdoc/visit_ast.rs#L71

@jyn514
Copy link
Member Author

jyn514 commented Dec 3, 2020

I did notice a while back that rustdoc doesn't include the crate name in the .events file - I think that might be because doctree passes None for the crate name? I need to test it.

This was #79586.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
merged-by-bors This PR was explicitly merged by bors. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-rustdoc Relevant to the rustdoc team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants