Major regression in type checking performance compiling rustdoc

[tomjakubowski]

A partial log of RUSTFLAGS="-Z time-passes" make x86_64-unknown-linux-gnu/stage2/bin/rustdoc, after doing a fresh rebuild on d77f6d5366b330f9c2061cad0d3ff638c9cc05b7:

time: 0.024     parsing
time: 0.000     recursion limit
time: 0.000     gated macro checking
time: 0.007     configuration 1
time: 0.000     crate injection
time: 0.003     plugin loading
time: 0.000     plugin registration
time: 0.181     expansion
time: 0.006     complete gated feature checking
time: 0.023     configuration 2
time: 0.023     maybe building test harness
time: 0.022     prelude injection
time: 0.003     checking that all macro invocations are gone
time: 0.028     assigning node ids and indexing ast
time: 0.035     external crate/lib resolution
time: 0.006     language item collection
time: 0.128     resolution
time: 0.004     lifetime resolution
time: 0.000     looking for entry point
time: 0.003     looking for plugin registrar
time: 0.017     region resolution
time: 0.003     loop checking
time: 0.000     stability index
time: 0.003     static item recursion checking
time: 0.021     type collecting
time: 0.007     variance inference
time: 0.321     coherence checking
time: 247.499   type checking
time: 0.077     check static items
time: 0.013     const marking
time: 0.003     const checking
time: 0.034     privacy checking
time: 0.008     intrinsic checking
time: 0.007     effect checking
time: 0.155     match checking
time: 0.020     liveness checking
time: 3.802     borrow checking
time: 2.099     rvalue checking
time: 0.003     reachability checking
time: 0.022     death checking
time: 0.173     lint checking
time: 0.000     resolving dependency formats
time: 13.342    translation

Unfortunately I don't have a log of the last time I built rustdoc ~2 weeks ago, but if I recall type checking took no more than 30 or 40 seconds.

[nikomatsakis]

Nominating. We should track this down. Quite possibly due to #20304

[nrc]

cc me

[nrc]

I've been profiling this and the most time was spent in the hash function for Substs. Which is kind of weird.

[nikomatsakis]

interesting, could be related to @huonw's changes to intern Substs

[pnkfelix]

Polish issue, but worth trying to address by 1.0 beta.

[nikomatsakis]

but it's always possible that it's just that we're doing a lot more hashing -- i.e., it's the caller's problem

[jdm]

cc me

[nrc]

I did a bunch more profiling. First off, normalisation and projection barely showed up in the profile, so I think #20304 is a red herring.

Substs interning did, but because it was called a huge number of times, it's not that expensive for each call. I tried disabling interning, for rustdoc this led to OOMs. For libcore which also has a very high type checking time (relative to other phases) this only reduced type checking time by 6%, so I predict it won't be helpful in the rustdoc case.

The majority of the time is coming from trait selection - SelectionContext::evalute_predicate_recursively is the overarching method in the profile. Winnowing in particular is taking ~75% of the time.

So, I don't think caching normalisation and projection is worthwhile, at least here, it might be for other reasons. I need to look a bit closer at the code around selections. AIUI, only first phase is cached and I don't think winnowing is. I wonder if we could cache that too? I also want to check that caching is working as expected and we're not missing where we should hit.

[sanxiyn]

FYI, slowness is caused by trying to infer and check an excessive use of iterator chain.

[nikomatsakis]

Interesting. That fits with @nick29581's profiles, for sure.