Investigate compiler performance problems related to dynamic classloading of compiler plugins

[retronym]

scalameta/scalameta#1181 (comment)

[retronym]

The classloading profiler in JMH (-prof hs_cl) shows that ~0 classes are loaded in each steady state iteration in the baseline, but ~900 classes are loaded when -Xplugin is provided.

⚡ (for EXTRA in "" -Xplugin:/Users/jz/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar; do sbt 'set scalaVersion in compilation := "2.12.4"' "hot -psource=scalap -f1 -wi 5 -i 4 -pextraArgs=$EXTRA -prof hs_cl" 2>&1; done) | egrep "(HotScalacBenchmark.compile|java.cls.loadedClasses) "
[info] HotScalacBenchmark.compile                                                     a8c43dc                    false    scalap  sample   50     831.059 ±      16.278  ms/op
[info] HotScalacBenchmark.compile:·java.cls.loadedClasses                             a8c43dc                    false    scalap  sample    4       1.500 ±      15.383      ?
[info] HotScalacBenchmark.compile                                                     a8c43dc  -Xplugin:/Users/jz/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample   46        913.811 ±        22.850  ms/op
[info] HotScalacBenchmark.compile:·java.cls.loadedClasses                             a8c43dc  -Xplugin:/Users/jz/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample    4        921.750 ±       311.804      ?

If I let them both warm up for 10x10s, I see that the enabling the macro-paradise plugin slows the result from 785ms to 897 (1.14x).

Next experiment is to add macro-paradise to the classpath of the forked JVM directly, to find out how much of that 14% is due to inherent cost of the plugin vs how much is due to the unintended costs of dynamic classlosding.

[retronym]

I've just tested what happens when the plugin is added to the classpath containing scala-compiler.jar. The plugin classes are indeed loaded from this classloader (the compiler still creates a new classloader for the plugin in each instance of Global, but due to parent classloader delegation it doesn't actually reload the classes.

% (for EXTRA in -Xplugin:/Users/jz/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar; do sbt 'set unmanagedJars in compilation in Compile += file("/Users/jz/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar")' 'set scalaVersion in compilation := "2.12.4"' "hot -psource=scalap -f1 -wi 10 -i 8 -pextraArgs=$EXTRA -vEXTRA" 2>&1; done)

Scenario	Score	Factor vs baseline
No Plugin (baseline)	777.467 ± 2.331ms
Plugin statically loaded	818.063 ± 4.678	1.05x
Plugin dynamically loaded	886.732 ± 8.195	1.14x

So the presence of macro paradise slows down this benchmark by 14%, but only 5% of that seems to be the direct fault of the plugin itself.

(Updated numbers with 3 forks in the benchmark)

[retronym]

Macro implementations are also called with a dynamic classloader. It would be interesting to see if the same trick of putting the macro on the compiler classpath (or, just caching the dynamically created classloader) affects the performance of compilation of code that uses macros.

[jvican]

I have a prototype at https://github.com/scalacenter/scala/tree/ticket/sd-458 for both macros and plugins. I'm in the process of benchmarking the impact in small and big OSS projects. I will post benchmark results as soon as I have them, and then open a pull request.

My approach caches dynamically created classloaders only if all the URLs are either jar or zip files (as suggested by @retronym). The invalidation of these files assumes that the last modified time of the zip file changes if one of the zip archive entries changes. This may not be true if a postprocessing step is applied to compilation products, like reproducible-maven-build-plugin, which sets all zip and jar timestamps to zero to achieve build reproducibility.

(However, as I understand it, this breaks classpath caching for the compiler too; so I'm not sure it's an immediate problem we need to solve now. If we aim for a solid solution, we should hash the contents of every classpath entry, but this takes time for huge classpaths.)

If a file that is not a zip or jar is found, the caching doesn't happen. This occurs, by default, when a classpath entry ends with the following classpath entries in sbt (show classpathTypes: Set(eclipse-plugin, bundle, scala-jar, hk2-jar, orbit)). As a note, all other classpath entries whose extension does not appear in the classpathTypes key will be filtered out before compiling.

[jvican]

jvican in /data/rw/code/experiments/compiler-benchmark                                  [19:28:12] 
> $ for SV in "2.12.5--bin-dbd90495c2-SNAPSHOT"; do /usr/bin/sbt "set scalaVersion in ThisBuild := \"$SV\"" "hot -psource=scalap -f1 -wi 10 -i 8 -vEXTRA" 2>&1; done

[info] Benchmark                                   (corpusVersion)  (extraArgs)  (resident)  (source)    Mode  Cnt     Score    Error  Units
[info] HotScalacBenchmark.compile                           latest                    false    scalap  sample   87   975.417 ± 12.725  ms/op
[info] HotScalacBenchmark.compile:compile·p0.00             latest                    false    scalap  sample        918.553           ms/op
[info] HotScalacBenchmark.compile:compile·p0.50             latest                    false    scalap  sample        967.836           ms/op
[info] HotScalacBenchmark.compile:compile·p0.90             latest                    false    scalap  sample       1024.249           ms/op
[info] HotScalacBenchmark.compile:compile·p0.95             latest                    false    scalap  sample       1046.479           ms/op
[info] HotScalacBenchmark.compile:compile·p0.99             latest                    false    scalap  sample       1084.228           ms/op
[info] HotScalacBenchmark.compile:compile·p0.999            latest                    false    scalap  sample       1084.228           ms/op
[info] HotScalacBenchmark.compile:compile·p0.9999           latest                    false    scalap  sample       1084.228           ms/op
[info] HotScalacBenchmark.compile:compile·p1.00             latest                    false    scalap  sample       1084.228           ms/op

jvican in /data/rw/code/experiments/compiler-benchmark                                                                                                                                            [19:19:47] 
> $ for SV in "2.12.5--bin-dbd90495c2-SNAPSHOT" "2.12.5-bin-f18e3c59fd-SNAPSHOT"; do /usr/bin/sbt "set scalaVersion in ThisBuild := \"$SV\"" "hot -psource=scalap -f1 -wi 10 -i 8 -pextraArgs=-Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar -vEXTRA" 2>&1; done

[info] Benchmark                                   (corpusVersion)                                                                                       (extraArgs)  (resident)  (source)    Mode  Cnt     Score    Error  Units
[info] HotScalacBenchmark.compile                           latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample   73  1137.892 ± 17.863  ms/op
[info] HotScalacBenchmark.compile:compile·p0.00             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1060.110           ms/op
[info] HotScalacBenchmark.compile:compile·p0.50             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1130.365           ms/op
[info] HotScalacBenchmark.compile:compile·p0.90             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1200.829           ms/op
[info] HotScalacBenchmark.compile:compile·p0.95             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1221.172           ms/op
[info] HotScalacBenchmark.compile:compile·p0.99             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1270.874           ms/op
[info] HotScalacBenchmark.compile:compile·p0.999            latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1270.874           ms/op
[info] HotScalacBenchmark.compile:compile·p0.9999           latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1270.874           ms/op
[info] HotScalacBenchmark.compile:compile·p1.00             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1270.874           ms/op

[info] Benchmark                                   (corpusVersion)                                                                                       (extraArgs)  (resident)  (source)    Mode  Cnt     Score    Error  Units
[info] HotScalacBenchmark.compile                           latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample   86   985.844 ± 10.220  ms/op
[info] HotScalacBenchmark.compile:compile·p0.00             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample        937.427           ms/op
[info] HotScalacBenchmark.compile:compile·p0.50             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample        981.467           ms/op
[info] HotScalacBenchmark.compile:compile·p0.90             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1027.919           ms/op
[info] HotScalacBenchmark.compile:compile·p0.95             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1033.162           ms/op
[info] HotScalacBenchmark.compile:compile·p0.99             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1077.936           ms/op
[info] HotScalacBenchmark.compile:compile·p0.999            latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1077.936           ms/op
[info] HotScalacBenchmark.compile:compile·p0.9999           latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1077.936           ms/op
[info] HotScalacBenchmark.compile:compile·p1.00             latest  -Xplugin:/home/jvican/.ivy2/cache/org.scalamacros/paradise_2.12.4/jars/paradise_2.12.4-2.1.0.jar       false    scalap  sample       1077.936           ms/op

Summary

Scenario	Scala version	Compilation time (ms)	Factor vs baseline
no plugin (baseline)	2.12.5-bin-dbd90495c2-SNAPSHOT	975
dynamically loaded	2.12.5-bin-dbd90495c2-SNAPSHOT	1137	1.17
dynamically loaded	2.12.5-bin-f18e3c59fd-SNAPSHOT	985	1.01

Where f18e3c59fd is the commit hash of
https://github.com/scalacenter/scala/tree/ticket/sd-458, and dbd90495c2 the
latest commit in the 2.12.5 branch to this date.

These results confirm that caching dynamically loaded compiler plugins works,
where the caching improvements behave as well as the baseline. Before the patch,
dynamically loading a compiler plugin slowed down a warmed up compiler by 17%.

Machine

cat /proc/cpuinfo:

processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 78
model name	: Intel(R) Core(TM) i7-6600U CPU @ 2.60GHz
stepping	: 3
microcode	: 0x88
cpu MHz		: 3213.470
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 0
cpu cores	: 2
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 22
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb invpcid_single pti intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp
bugs		: cpu_meltdown
bogomips	: 5618.00
clflush size	: 64
cache_alignment	: 64
address sizes	: 39 bits physical, 48 bits virtual
power management:

processor	: 1
vendor_id	: GenuineIntel
cpu family	: 6
model		: 78
model name	: Intel(R) Core(TM) i7-6600U CPU @ 2.60GHz
stepping	: 3
microcode	: 0x88
cpu MHz		: 3225.341
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 2
initial apicid	: 2
fpu		: yes
fpu_exception	: yes
cpuid level	: 22
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb invpcid_single pti intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp
bugs		: cpu_meltdown
bogomips	: 5618.00
clflush size	: 64
cache_alignment	: 64
address sizes	: 39 bits physical, 48 bits virtual
power management:

uname -a:

Linux tribox 4.14.13-1-ARCH #1 SMP PREEMPT Wed Jan 10 11:14:50 UTC 2018 x86_64 GNU/Linux

Processor details

Hyper threading is disabled, NUMA is disabled, Turbo boost is disabled, cpu
frequency is set to 3.2GHz. intel_pstate is used.

Implications

Dynamically loaded compiler plugins are the norm, so more or less all builds
that use them will benefit from these speedups.

Next

I'm working on collecting benchmarking results for macro libraries. I will
report them soon.

[jvican]

To measure the impact of this patch against code using macros, I have tried first with case-app, a CLI library built on top of shapeless.

show testsJVM/compile:scalacOptions:

[info] * -feature
[info] * -deprecation
[info] * -Xplugin:/home/jvican/.coursier/cache/v1/https/repo1.maven.org/maven2/org/scalamacros/paradise_2.12.4/2.1.0/paradise_2.12.4-2.1.0.jar

show testsJVM/dependencyClasspath:

[info] * Attributed(/data/rw/code/scala/case-app/core/jvm/target/scala-2.12/classes)
[info] * Attributed(/data/rw/code/scala/case-app/annotations/jvm/target/scala-2.12/classes)
[info] * Attributed(/data/rw/code/scala/case-app/util/jvm/target/scala-2.12/classes)
[info] * Attributed(/data/rw/code/scala/scala-profiling/scalac/build/pack/lib/scala-library.jar)
[info] * Attributed(/home/jvican/.sbt/boot/scala-2.12.4/lib/scala-library.jar)
[info] * Attributed(/home/jvican/.coursier/cache/v1/https/repo1.maven.org/maven2/org/typelevel/macro-compat_2.12/1.1.1/macro-compat_2.12-1.1.1.jar)
[info] * Attributed(/home/jvican/.coursier/cache/v1/https/repo1.maven.org/maven2/com/chuusai/shapeless_2.12/2.3.3/shapeless_2.12-2.3.3.jar)

For the benchmark I've used scalac-profiling's sbt plugin, which has a task that allows sbt to warm up a compiler for a certain duration. Here are the logs of the session. I'd like to try with HotSbtBenchmarking to get better statistics, average and percentiles; but, so far, the results seem to point out to a ~20% speedup (5 seconds with classloaders caches vs ~6 seconds).

Tomorrow I'll gather more fine-grained results for case-app and will try to test bigger projects like circe and scalatest.