Huge performance regression in rustdoc between 1/28 and 2/25 nightlies

[jdm]

When using the 1/28 Rust nightly for a Servo CI job on linux, the job that does a variety of builds and unit tests as well as generates docs for every single dependency took 20 minutes total. After updating to the 2/25 nightly, just the doc generation by itself takes 37 minutes, often causing our CI limit of 60 minutes to be exceeded.

[jdm]

Looks like the doc generation used to take 6m 28s.

[euclio]

I added a new docs pass to check codeblock syntax a few days before the 1/28 nightly. The timing's a little off, but you could try running rustdoc without the check-code-block-syntax pass to see if that makes up the difference.

Never mind, that pass is present in the 1/28 nightly.

[Manishearth]

cc @QuietMisdreavus

[Mark-Simulacrum]

It looks like the number of patches landing in master between those two nightlies is actually fairly small when constraining to just src/librustdoc. I might have messed this up though.

f573049 Auto merge of #58232 - ljedrz:HirIdification_continued, r=Zoxc
aadbc45 Auto merge of #57051 - Eijebong:parking_lot, r=nikomatsakis
fcccf06 Auto merge of #56514 - ollie27:rustdoc_test_libdir, r=QuietMisdreavus
32471f7 Auto merge of #58503 - varkor:const-generics-hir, r=petrochenkov
b244f61 Auto merge of #58341 - alexreg:cosmetic-2-doc-comments, r=steveklabnik
0e5a209 Auto merge of #58058 - QuietMisdreavus:use-attr, r=GuillaumeGomez
4b1e39b Auto merge of #57851 - Aaron1011:fix/clean-lifetime, r=GuillaumeGomez

[GuillaumeGomez]

It's very certainly because of my minification process. Although, I didn't expect it to have a noticeable impact...

[QuietMisdreavus]

The only minifier change that landed into rustdoc between those dates was #57884. The minifier was actually in place before then.

[Manishearth]

This may actually be a regression in quote/proc-macro2.

I'm not yet sure if this is the thing causing long doc builds (some things in our server build history disagree with this hypothesis), but our mozjs_sys crate hits a ton of intra-doc-links failures in jsapi.rs, a bindgen-generated file. Normally this is fine, but on some versions of proc-macro2 bindgen is outputting a file that's basically a single giant line (+ some headers). The intra doc link failures have a field day with this, printing out the entire (already giant) file for each warning. There are a lot of such warnings because the autogenerated documentation has things like [[Get]] in it (used in JS specs to talk about properties/methods/slots). This is probably a lot of work for rustc (since it also has to do span computation), as well as a lot of IO traffic, slowing everything down.

[Manishearth]

I've narrowed down the regression range to between 2019-02-07 and 2019-02-10

[Manishearth]

No, the mozjs_sys issues are not the problem. They started becoming a problem at some point, but the commit that did the rust upgrade does not have a giant log, and still takes 55minutes to build

[Manishearth]

These are all the PRs landing in master in that range

d173180 Auto merge of #58266 - GuillaumeGomez:rollup, r=GuillaumeGomez
ad43389 Auto merge of #58010 - Zoxc:parallel-passes, r=michaelwoerister
626e74d Auto merge of #58254 - kennytm:rollup, r=kennytm
825f355 Auto merge of #57998 - niklasf:align-enum, r=nagisa
1efdda1 Auto merge of #58125 - taiki-e:libsyntax-2018, r=Centril
ff9158c Auto merge of #58224 - pietroalbini:revert-appveyor-debug, r=alexcrichton

The first rollup contains a lot of rustdoc PRs.

[Manishearth]

It's probably either #58143 or #57884 from #58266 , verifying that the problematic commit is indeed the rollup (sadly we don't store travis builds for rollup contents)

Servo does have crates with a ton of items in them, so we may be hitting ranges where algorithmic complexity actually matters.

[Manishearth]

Confirmed, the perf regression is inside #58266

[Manishearth]

The regression is caused by #57884 cc @GuillaumeGomez

Unsure what's casing it so far.

[Manishearth]

I suspect it's just that we have some truly giant crates (see https://doc.servo.org/script/) and we're hitting some pathological case

[GuillaumeGomez]

The problem is that I currently re-read the JS a few times. It's worth taking a look at this giant crate now to see how I can improve it (I never focused on speed for it after all).

[Manishearth]

@GuillaumeGomez Is the number of times you reread the JS dependent on the size of the crate?

I'm not yet sure if it is indeed this crate causing this problem, but the crate in question is Servo's script crate. It may also just be the sum total of all the crates being slow.

[GuillaumeGomez]

Potentially. I'll take a look as soon as I can.

[Manishearth]

It seems like the filesize for the generated docs is also just huge. It took forever to delete target/doc. I'm rebuilding it to see the difference against --disable-minification.

[Manishearth]

Nope, they're roughly the same size.

[GuillaumeGomez]

And what the rendering time difference?

[Manishearth]

--disable-minification takes a couple minutes, without it it takes 70

[Manishearth]

With --disable-minification the doc search no longer works

https://doc.servo.org/script/?search=websocket gives

ReferenceError: N is not defined

[jamesmunns]

I think I've run into this too, I'm seeing a 3x slowdown for an embedded crate (pretty full of generated code). In case this is a useful repro case:

james@archx1c6g ➜  /tmp git clone https://github.com/nrf-rs/nrf52832-pac
Cloning into 'nrf52832-pac'...
james@archx1c6g ➜  /tmp cd nrf52832-pac

james@archx1c6g ➜  nrf52832-pac git:(master) time cargo +1.33.0 doc --open
   Compiling semver-parser v0.7.0
   ...
 Documenting nrf52832-pac v0.6.0 (/tmp/nrf52832-pac)
    Finished dev [unoptimized + debuginfo] target(s) in 30.98s
     Opening /tmp/nrf52832-pac/target/doc/nrf52832_pac/index.html
cargo +1.33.0 doc --open  34.23s user 2.07s system 116% cpu 31.205 total

james@archx1c6g ➜  nrf52832-pac git:(master) ✗ cargo clean

james@archx1c6g ➜  nrf52832-pac git:(master) ✗ time cargo +1.34.0 doc --open
   Compiling semver-parser v0.7.0
   ...
    Finished dev [unoptimized + debuginfo] target(s) in 1m 39s
     Opening /tmp/nrf52832-pac/target/doc/nrf52832_pac/index.html
cargo +1.34.0 doc --open  102.90s user 1.71s system 104% cpu 1:39.75 total

Edit: This is specifically a stable-to-stable perf regression between 1.33.0 and 1.34.0.

[matthewkmayer]

Also seeing a large performance regression from 1.33.0 to 1.34.0 in Rusoto. We document a lot of crates (146 right now) and documentation job time went from 16 minutes to timing out at more than 50 minutes.

Our current workaround is to use 1.33.0 to document our code. This will stop working as soon as we adopt anything from the 1.34.0 release.

Anything we can test to help fix this?

[Manishearth]

Can we revert the minification update PR? @GuillaumeGomez

[GuillaumeGomez]

@Manishearth It made a first performance improvement. Removing it doesn't seem to be a good idea...

[jamesmunns]

I took a flamegraph of the problematic sections of nrf52832-pac, using cargo-flamegraph.

I ran cargo +beta doc (the regression also exists there) once to build all deps, then re-ran the specific slow file through flamegraph. My command was this:

flamegraph -o rustdoc.svg /home/james/.rustup/toolchains/beta-x86_64-unknown-linux-gnu/bin/rustdoc --edition=2018 --crate-name nrf52832_pac src/lib.rs --color always -o /tmp/nrf52832-pac/target/doc -L dependency=/tmp/nrf52832-pac/target/debug/deps --extern bare_metal=/tmp/nrf52832-pac/target/debug/deps/libbare_metal-77e06d3286078ba3.rmeta --extern cortex_m=/tmp/nrf52832-pac/target/debug/deps/libcortex_m-3b084aea88ac1290.rmeta --extern vcell=/tmp/nrf52832-pac/target/debug/deps/libvcell-28d9c41f1ae25f64.rmeta

Specifically, __memmove_avx_unaligned_erms is taking 75% of the runtime, with the call graph looking something like:

• rustdoc::html::render::run
  • rustdoc::html::render::write_shared
    *write_minify_replacerstd::fs::File
    * apply
    * { { closure }}
    * aggregate_strings_into_array_with_separation
    * aggregate_strings_into_array_inner
    * insert<minifier::js::token::Token
    * copy<minifier::js:token::Token
    * __memmove_avx_unaligned_erms

In this whole call stack, almost all time is spent in the bottom item.

[Manishearth]

@GuillaumeGomez I don't understand what you mean by that comment.

If it made an improvement but also had extremely adverse effects on some crates, it should be fixed or reverted. That's not a performance improvement.

[GuillaumeGomez]

@Manishearth: I meant by my comment that the situation was worse before my last changes.

@jamesmunns: Thanks! That'll help me a lot!

[Manishearth]

I meant by my comment that the situation was worse before my last changes.

From my measurements on servo and the other measurement in this thread, this is definitely not universally true, and the cases where it's not true it's super bad.

[GuillaumeGomez]

Strange since I removed a few iterations over the full JS tokens... I'll check soon.

[Manishearth]

Any updates on this? I think we should do a more careful performance measurement here, perf updates that make things worse for a lot of crates should be done carefully.

[euclio]

I believe the plan is to remove minification entirely, as discussed in #56359.

[GuillaumeGomez]

Or at least on the search-index.js file. Doesn't hurt to have it on the other files.

[jonas-schievink]

Was this fixed by #66828?

[jamesmunns]

At least with a relevantly recent nightly, this is back down to within the rough area of 1.33.0.

active toolchain
----------------

nightly-x86_64-unknown-linux-gnu (default)
rustc 1.42.0-nightly (c5840f9d2 2020-01-03)

 Documenting nrf52832-pac v0.9.0 (/tmp/nrf52832-pac)
    Finished dev [unoptimized + debuginfo] target(s) in 32.15s
     Opening /tmp/.cargo-build-cache/doc/nrf52832_pac/index.html
cargo +nightly doc --open  36.66s user 2.46s system 120% cpu 32.519 total

[GuillaumeGomez]

I guess it can be closed then!