8% regression in syntex_syntax compile time

[alexcrichton]

Found through perf.rust-lang.org the compile time for the syntex_syntax has regressed by 8%. The graph points to #43403 as the culprit.

I've downloaded the nightly-2017-08-04 and nightly-2017-08-05 toolchains to analyze this regression, where the 08-05 toolchain includes #43403 while 08-04 does not.

The main differences I found were:

pass	before	after
translation	9.922	11.192
LLVM passes	27.805	29.002
item bodies check	5.635	6.724

cc @RalfJung

[alexcrichton]

The most suspect change may be the reordering of MIR passes in that commit

[RalfJung]

How would I collect that timing data myself?

"translation" is LLVM codegen, or does it also include other things (like e.g. MIR passes)? What does "item bodies check" do? That one sounds like it should happen way before my PR changes anything.

The most suspect change may be the reordering of MIR passes in that commit

Agreed. Unfortunately I have very little idea of what the other passes do exactly; I've gotten lots of help from @arielb1 to get that part of the PR to work.
The only other culprit I could think of is that ClearEndRegions does slightly more work as it now also walks all regions occurring in all types. But that shouldn't be noticeable, should it?

(I'll be traveling soon, so I'll probably not be able to to much of anything before Tuesday.)

[alexcrichton]

Oh heh I also don't know what "item bodies check" is! It typically corresponds to what I think of as typechecking though, I think. The 28->29s could just be noise maybe?

To collect yourself though you can run the compiler with the -Z time-passes flag, which will dump a bunch of info to stdout about how long the passes are. Also no worries! This isn't a huge regression, just one that's good to track!

[RalfJung]

Looking at perf data, LLVM passes seems to be it. The other two are rather noisy, and it's not clear whether the PR in question actually had any effect.

[arielb1]

The only other culprit I could think of is that ClearEndRegions does slightly more work as it now also walks all regions occurring in all types.

That would show up as a borrow-checking regression.

[nikomatsakis]

This certainly seems surprising. Seems like a first step would be to reproduce it.

[alexcrichton]

1.21 is now in beta

[RalfJung]

I built the compiler at the tip of my PR, and then another version that uses the old driver.rs, and can't see any significant difference in the timing... (unfortunately it seems -Ztime-passes does not print the total time?)

With my PR:

time: 5.834; rss: 351MB item-bodies checking
time: 7.430; rss: 961MB translation
time: 19.558; rss: 648MB        LLVM passes

With the old driver.rs:

time: 5.672; rss: 351MB item-bodies checking
time: 7.665; rss: 961MB translation
time: 19.753; rss: 632MB        LLVM passes

[RalfJung]

I also went back to the base commit that my PR rests on:

time: 5.762; rss: 352MB item-bodies checking
time: 7.779; rss: 958MB translation
time: 21.249; rss: 637MB        LLVM passes

And looked at the commit that has my PR merged:

  time: 5.866; rss: 354MB       item-bodies checking
  time: 7.475; rss: 947MB       translation
  time: 20.270; rss: 227MB      LLVM passes

This all looks like well within noise to me... seems I cannot reproduce the regression. I have no idea how to proceed.

(Btw it seems perf broke or lost the ability to look at the times of individual passes :/ or I just can't use it. I always found its UI mystifying.)

[nikomatsakis]

I have to admit, I'm sort of inclined to close this.

[Mark-Simulacrum]

We've recovered the performance on syntex I believe, and in fact it looks like we improved it: https://perf.rust-lang.org/?start=2017-08-01T00%3A00%3A00%2B00%3A00&end=2017-09-12T00%3A00%3A00%2B00%3A00&crates=%5B%22syntex-0.42.2%40000-base%22%5D&stat=instructions%3Au. Closing.

[RalfJung]

FWIW, I tried to reproduce at least the end-to-end behavior (measuring the time it takes to compile the entire crate), and while it looked first like I was onto something...

# fast
    Finished dev [unoptimized + debuginfo] target(s) in 49.46 secs
rustc 1.21.0-dev (5264103de 2017-07-30)
# slow
    Finished dev [unoptimized + debuginfo] target(s) in 54.82 secs
rustc 1.21.0-dev (dd3fed876 2017-09-13)

...even though I did two measurements each time and confirmed they are within 1s, this was entirely unreproducible. Some days later, I now get

    Finished dev [unoptimized + debuginfo] target(s) in 48.81 secs
rustc 1.21.0-dev (dd3fed876 2017-09-13)

So, the noise is bigger than the signal. I'm officially giving up on measuring performance of the compiler; gladly this issue is already closed. ;)