A third of the time rustdoc takes to document windows-rs is <unknown>

[jyn514]

I tried this code: microsoft/windows-docs-rs@3371c03

I expected to see this happen: cargo rustdoc -- -Z self-profile shows where the 50 minutes are being spent.

Instead, this happened: Rustdoc completely loses 20 of the 50 minutes and gives up.

Here's the top 6 items from summarize summarize:

+-------------------------------------------------+-----------+-----------------+----------+------------+
| Item                                            | Self time | % of total time | Time     | Item count |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| <unknown>                                       | 653.09s   | 36.998          | 1336.82s | 24718096   |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| resolve_crate                                   | 540.19s   | 30.602          | 540.19s  | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| render_html                                     | 384.93s   | 21.807          | 386.88s  | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| get_blanket_impls                               | 66.06s    | 3.742           | 76.22s   | 45080      |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| expand_crate                                    | 30.12s    | 1.706           | 30.13s   | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+

Note that <unknown> is at the top.
cc microsoft/windows-rs#420, #74590 (comment)

Meta

rustdoc --version: rustdoc 1.51.0-nightly (a4cbb44ae 2021-01-20)

[jyn514]

I am still baffled what this could be. item_types_checking is clearly being measured, and the only places I see <unknown> are

• rust/compiler/rustc_codegen_cranelift/example/std_example.rs

  Line 24 in 65767e5

  writeln!(stderr, "some {} text", "<unknown>").unwrap();

  (clearly not it)

• rust/compiler/rustc_codegen_llvm/src/debuginfo/metadata.rs

  Line 795 in 65767e5

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

  - seems like a stretch, rustdoc should never be calling codegen

• rust/compiler/rustc_interface/src/passes.rs

  Line 1021 in 65767e5

  // after this point, they'll show up as "<unknown>" in self-profiling data.

  , which seems plausible, but I never see self_profile_alloc_query_strings show up in the output :/

So I don't know what this could possibly be.

[jyn514]

I can also reproduce on rust-lang/cargo@4de00d2, which works on linux and is overall easier to build.

> cargo +stage1 rustdoc -- -Z self-profile
> summarize summarize cargo-30689.mm_profdata
+-------------------------------------------------+-----------+-----------------+----------+------------+
| Item                                            | Self time | % of total time | Time     | Item count |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| expand_crate                                    | 971.54ms  | 18.035          | 991.92ms | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| <unknown>                                       | 884.97ms  | 16.428          | 2.93s    | 709329     |
+-------------------------------------------------+-----------+-----------------+----------+------------+

There are no similar <unknown> queries when running rustc directly.

[jyn514]

This is definitely not from

rust/compiler/rustc_interface/src/passes.rs

Line 1021 in 65767e5

// after this point, they'll show up as "<unknown>" in self-profiling data.

because RUSTC_LOG=rustc_interface doesn't show "Post-codegen" anyway.

[jyn514]

The only places this is emitted in measureme are for https://github.com/rust-lang/measureme/blob/16688a5da98f403b2b7f1942564adf3361c99cff/analyzeme/src/stringtable.rs#L48 and https://github.com/rust-lang/measureme/blob/16688a5da98f403b2b7f1942564adf3361c99cff/analyzeme/src/stringtable.rs#L95.

@michaelwoerister do you have any idea what could be going wrong here?

[jyn514]

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.

@wesleywiser do you remember where you've seen this before?

[wesleywiser]

I had an theory that I ran by @jyn514 and they're testing it out: rustdoc never calls start_codegen() and therefore alloc_self_profile_query_strings() is never called which means the <unknown> events are actually every query in rustc!

This seems to hold if we look at the summarize output for a rustdoc self-profile like this one. As far as I can tell, the only events listed are ones timed using the generic_activity() API which uses a different code path to store the event label. From what I can tell, there are no queries at all listed.

[jyn514]

@wesleywiser that did it! unknown doesn't show up at all any more :)

+-------------------------------------------------+-----------+-----------------+----------+------------+
| Item                                            | Self time | % of total time | Time     | Item count |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| expand_crate                                    | 697.97ms  | 15.614          | 711.88ms | 1          |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| get_blanket_impls                               | 615.38ms  | 13.766          | 707.27ms | 472        |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| render_item                                     | 499.50ms  | 11.174          | 503.16ms | 510        |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| build_extern_trait_impl                         | 415.08ms  | 9.286           | 714.64ms | 22356      |
+-------------------------------------------------+-----------+-----------------+----------+------------+
| get_auto_trait_impls                            | 272.80ms  | 6.103           | 314.81ms | 472        |
+-------------------------------------------------+-----------+-----------------+----------+------------+