Support for benchmarking compilation under SBT

[retronym]

SBT adds some overhead to compilation by extracting metadata (the "AnalysisReport") for each compiled file:

• API signatures
• Dependencies on other source and class files
• an index of identifiers

We expect that this will add some overhead, and that should pay off by enabling incremental compilation during the subseqent edit/compile cycle. However, we might not break even on the transaction if this overhead is too large.

In addition running the compiler in process with SBT itself might have some performance implications. We found and fixed one such case in 0.13.13 (sbt/sbt#2754), but there might be more lurking.

This patch enables us to drive an SBT process measure the "lived experience" of a clean build within SBT.

We do this by spawning a child process and stdin/stdout scraping.

Results

The scalap benchmark shows:

Direct	SBT 0.13.12	0.13.15	1.0.0-M6
765ms	1436	1063	1147

Next steps are to analyze the difference in profiles between the direct usage and the SBT usage to see how much of this overhead is inherent, and how much could be tuned away.

It would also be useful for SBT to add a mode to compile without collecting the incremental metadata. This could be useful in CI use cases where clean builds are performed, and no subsequent compilation will be performed to profit from the AnalysisReport. There is already an experimental mode to ignore the metadata on subsequent compiles, and rely only on timestamps (IncOptions.withAntStyle), perhaps this should be mode should be refined to levy no overhead on the initial compilation, either.

UPDATE

Followup analysis in #33

[retronym]

/cc @jvican, who has incorporated JMH benchmarking into sbt/zinc (a newer branch of Zinc than is used within SBT 0.13.x itself).

[jvican]

This is great! @retronym I wanted to do this to get to know the actual overhead of writing/reading huge analysis files. It can also benefit me to know what's the overhead that sbt puts on compile and how to minimize it.

I may port this over 😄. It's the only way I see we can use this in zinc.

[retronym]

@jvican Yes, I was planning to generalize this benchmark to also run on SBT 1.0. That will give us a way to comparing the old and new Zinc implementations (fully alloyed into SBT)

[retronym]

Just updated the PR description with results of a small run that suggest that 26% of SBT's compilation time is overhead. Last time I measured this it was closer to 17%. Scalac itself has sped up in 2.12.3-SNAPSHOT, which would push the overhead % up. The new way of meaasuring with JMH is another varaible factor.

[retronym]

• Disable JLine in the spawned SBT process to avoid hosing the ambient terminal sometimes.

[jvican]

Could it be possible that some of the overhead is created by sbt's cached compilers for compiling the build / classloaders? If all that is in memory, that could slow down compilation of projecs.

[jvican]

Just updated the PR description with results of a small run that suggest that 26% of SBT's compilation time is overhead. Last time I measured this it was closer to 17%. Scalac itself has sped up in 2.12.3-SNAPSHOT, which would push the overhead % up. The new way of meaasuring with JMH is another varaible factor.

I'm focusing on performance before release candidate, so I'll try to make this number lower. I think I'll also add some benchmark facilities to discern how much of that overhead is coming from the bridge overhead, and how much is from the zinc analysis.

[retronym]

YourKit led me to try: https://github.com/sbt/sbt/compare/1.0.x...retronym:faster-phases?expand=1

But that doesn't seem to speed things up (much). Looking at the bigger profile in steady state, after my SBT patch, something like 1% is spent writing the analysis file, 8% in APIPhase, 3% in DependencyPhase. That doesn't quite add up to the difference to HotScalacBenchmark, it's as though something else in the compiler is a little slower by virtue of running under SBT. Need more data and experiments to figure this out...

[jvican]

Interesting. I'll try to see what's happening on Zinc 1.0. Since many things have changed between the two, it would be interesting to profile this with Zinc 1.0. Are you guys planning to upgrade the scalac build to sbt 1.0?

[jvican]

LGTM.

Your profile is interesting. However, i think we should strive for profiling sbt 1.0.0-M6, too many changes have gone into Zinc 1.0.

For instance, your results on writing the analysis files depend on the information collected by the bridge. I would expect this number to vary in Zinc 1.0 since we collect more names and type information.

Also, note that your numbers do not include the amount of time to read the analysis file, only to write it.

We could perhaps use my 0.13.x plugin to use Zinc 1.0.x... It's here. If the profile with this does not work, we may just want to profile direct sbt 1.0.0 builds (this may be the best option). That's why I was asking if you guys were thinking of migrating to sbt 1.0.0-M6 😄.

In any case, this looks great, thanks for pinging me!

[jvican]

Didn't know this is possible.

[retronym]

@jvican I've made the SBT version configurable. We don't need to upgrade the scala or the compiler-benchmark builds themselves to SBT 1.0 to make this possible.

I'm running a comparative benchmark of 0.13.15 and 1.0.0-M6, results should appear https://gist.github.com/1f7a3d1887611e91b07cd4a5d7b214a5 in about 30 minutes.

[retronym]

Compilation times for the scalap benchmark have increased under SBT 1.0.0-M6 by a factor of 1.08x.

Benchmark                                (corpusVersion)  (extraArgs)  (sbtVersion)  (source)    Mode  Cnt     Score    Error  Units
HotSbtBenchmark.compile                          a8c43dc                    0.13.15    scalap  sample  298  1063.872 ±  7.706  ms/op
HotSbtBenchmark.compile:compile·p0.00            a8c43dc                    0.13.15    scalap  sample       1017.119           ms/op
HotSbtBenchmark.compile:compile·p0.50            a8c43dc                    0.13.15    scalap  sample       1055.392           ms/op
HotSbtBenchmark.compile:compile·p0.90            a8c43dc                    0.13.15    scalap  sample       1096.810           ms/op
HotSbtBenchmark.compile:compile·p0.95            a8c43dc                    0.13.15    scalap  sample       1105.199           ms/op
HotSbtBenchmark.compile:compile·p0.99            a8c43dc                    0.13.15    scalap  sample       1298.158           ms/op
HotSbtBenchmark.compile:compile·p0.999           a8c43dc                    0.13.15    scalap  sample       1344.274           ms/op
HotSbtBenchmark.compile:compile·p0.9999          a8c43dc                    0.13.15    scalap  sample       1344.274           ms/op
HotSbtBenchmark.compile:compile·p1.00            a8c43dc                    0.13.15    scalap  sample       1344.274           ms/op
HotSbtBenchmark.compile                          a8c43dc                   1.0.0-M6    scalap  sample  270  1147.888 ± 12.929  ms/op
HotSbtBenchmark.compile:compile·p0.00            a8c43dc                   1.0.0-M6    scalap  sample       1094.713           ms/op
HotSbtBenchmark.compile:compile·p0.50            a8c43dc                   1.0.0-M6    scalap  sample       1130.365           ms/op
HotSbtBenchmark.compile:compile·p0.90            a8c43dc                   1.0.0-M6    scalap  sample       1180.697           ms/op
HotSbtBenchmark.compile:compile·p0.95            a8c43dc                   1.0.0-M6    scalap  sample       1197.264           ms/op
HotSbtBenchmark.compile:compile·p0.99            a8c43dc                   1.0.0-M6    scalap  sample       1541.470           ms/op
HotSbtBenchmark.compile:compile·p0.999           a8c43dc                   1.0.0-M6    scalap  sample       1581.253           ms/op
HotSbtBenchmark.compile:compile·p0.9999          a8c43dc                   1.0.0-M6    scalap  sample       1581.253           ms/op
HotSbtBenchmark.compile:compile·p1.00            a8c43dc                   1.0.0-M6    scalap  sample       1581.253   

SBT 0.13.12 (the version prior to sbt/sbt#2754) scored:

HotSbtBenchmark.compile                          a8c43dc                    0.13.12    scalap  sample  225  1436.363 ±(99.9%) 22.308 ms/op

ie, 0.13.{12 => 15} reduced compile time by 0.74x.

[dragos]

This might be of interest: scala/bug#10289

[retronym]

Compilation times for the scalap benchmark have increased under SBT 1.0.0-M6 by a factor of 1.08x.

Echoing a hypothesis from chat: switching to class based dependency tracking might be a factor, that requires more bookkeeping work but prevents some needless recompiles.

[jvican]

Echoing a hypothesis from chat: switching to class based dependency tracking might be a factor, that requires more bookkeeping work but prevents some needless recompiles.

Yes, it's definitely a possibility, we're keeping track of more term and type names and I wouldn't be surprised if the cost is higher. However, I think it can be further optimized to minimize the overhead. 8% sounds too much.