Unnaturally slow expansion on generated source

[alexcrichton]

In investigating #43572 I was generating some source code, and using the shell script listed in #43572 we can see:

$ rustc +nightly -V
rustc 1.21.0-nightly (aac223f4f 2017-07-30)
$ sh foo.sh
$ rustc +nightly lots-of-unused.rs -Z time-passes 2>&1 | grep 'expansion'
time: 1.567; rss: 110MB expansion

That's a lot of time to expand a crate that doesn't have any macros in it!

[alexcrichton]

cc @jseyfried, you may be interested in this!

[alexcrichton]

A profile of this looks like almost all the time is spent in rustc::hir::map::definitions::Definitions::create_def_with_parent

In which case, cc @michaelwoerister!

[alexcrichton]

Apparently most time is spent computing these hashes

[alexcrichton]

called ~38k times

[jseyfried]

Since we need to build the module graph and resolve imports during expansion for macros 2.0, we must construct node ids and def ids throughout expansion (i.e. interleaved arbitrarily many times until we hit fix-point).

Ideally we'd keep running totals of the time spent assigning node ids, assigning def ids, etc. for more accurate profiling information within the expansion step.

[alexcrichton]

@jseyfried in theory though isn't the fixed point for this crate the crate itself? (e.g. there's no macros here). Or are the def ids persisted for the rest of compilation, so "blaming" expansion isn't quite correct here?

[jseyfried]

@alexcrichton Yeah, the def ids are persisted for the rest of compilation. We could move the "first round" of def id collection (in which we collect the raw, unexpanded source) outside of expansion, but that would introduce more code complexity and wouldn't count the time we spend collecting def ids for AST that comes from macro expansions.

[alexcrichton]

Ah ok, nah it seems fine! I think there's a number of cases where -Z time-passes is attributing time in the wrong place nowadays...

Still it seems odd that 30-50k invocations of this function would take so long to execute?

[michaelwoerister]

@jseyfried Do I understand this correctly that all DefIds generated are actually used, right? There are no "temporary" DefIds?

Still it seems odd that 30-50k invocations of this function would take so long to execute?

Each of these invocations creates a Blake2 hasher. I'd be interested how the performance looks with other hashing algorithms. I'd like to switch to something faster anyway: #41215

[arielb1]

@alexcrichton

Are you sure this isn't the other quadratic case fixed in #43584?

[alexcrichton]

It may very well be! Feel free to close this w/ that PR landing, I'll verify to be sure but I'd imagine you're correct in that it's fixed by #43584

[alexcrichton]

er, didn't mean to close just yet