Performance regression in the flat classpath

[dragos]

tl;dr; The flat classpath implementation is much slower during the Sbt dependency analysis. For a project with a large classpath it's around 1.5s vs. 300ms with the recursive implementation.

I will use 2.11 as a reference point because the recursive classpath was removed in 2.12. However, timings carry over to the 2.12 compiler.

I'm using https://github.com/guardian/frontend/ for benchmarking (more precisely, the applications subproject), which has a (very) large classpath. The time seems to be correlated to the size of the classpath and not so much with sources. The timings I got with the default 2.11 classpath (recursive):

[info] [Extracts dependency information in 232ms]

and with the flat one:

[info] [Extracts dependency information in 4985ms]

The 2.12 branch has a fix by @lrytz to speedup the classpath implementation, but even with this fix applied in the 2.11 branch the phase is about 5x slower:

[info] [Extracts dependency information in 1411ms]

At first glance, a lot of time seems to be spent in string manipulation and growing arrays. This is using VisualVM, so maybe the profiler isn't the best there is, however I think it points in the right direction.

PS. The timings with 2.12.2 for this phase are in the order of seconds, so it leads me to think the regression is still there, even though I didn't have a recursive classpath implementation for 2.12 to compare it against.

[dragos]

I'm guessing that scala/scala#5685 was unknowingly motivated by this regression.

[retronym]

I can see an inefficiency in the implementation. Here's a candidate patch for 2.11.x: https://github.com/scala/scala/compare/2.11.x...retronym:backport/fasterFindClass?expand=1

However, I'm not able to reproduce the baseline slowness you're seeing in that project.

diff --git a/project/Prototypes.scala b/project/Prototypes.scala
index 3d4eea1a9..ce58f8890 100644
--- a/project/Prototypes.scala
+++ b/project/Prototypes.scala
@@ -24,3 +24,3 @@ trait Prototypes {
     scalacOptions := Seq("-unchecked", "-deprecation", "-target:jvm-1.8",
-      "-Xcheckinit", "-encoding", "utf8", "-feature", "-Yinline-warnings","-Xfatal-warnings"),
+      "-Xcheckinit", "-encoding", "utf8", "-feature", "-Yinline-warnings","-Xfatal-warnings", "-verbose"),
     publishArtifact in (Compile, packageDoc) := false,

// ~/.sbt/0.13/plugins/custom.scala
package io.github.retronym

import sbt._
import Keys._

object RawCompile extends AutoPlugin {
  override def trigger = allRequirements
  override def requires = sbt.plugins.JvmPlugin
  val compileRaw = taskKey[Unit]("Compile directly, bypassing the incremental compiler")
  val cleanClasses = taskKey[Unit]("clean the classes directory")
  
  override lazy val projectSettings = List(Compile, Test).flatMap(c => inConfig(c)(Seq(
    addCompileRaw,
    cleanClasses := IO.delete(classDirectory.value)
  )))

  def addCompileRaw = compileRaw := {
    val compiler = new sbt.compiler.RawCompiler(scalaInstance.value, sbt.ClasspathOptions.auto, streams.value.log)
    classDirectory.value.mkdirs()
    compiler.apply(sources.value, classDirectory.value +: dependencyClasspath.value.map(_.data), classDirectory.value, scalacOptions.value)
  }
}

sbt> set logLevel in Global := Level.Warn
sbt> ;applications/cleanClasses; applications/internalDependencyClasspath
[root] $ applications/compile
[success] Total time: 4 s, completed 21/06/2017 2:07:15 PM
[root] $ last-grep Extracts
[info] [Extracts the public API from source files. in 182ms]
[info] [Extracts dependency information in 200ms]

Given that the compilation of applications only takes 4s, I'm assuming I'm not compiling the same thing you were. Perhaps it has since been refactored?

[retronym]

D'oh, I forgot to enable the flat classpath.

[retronym]

Okay, I can repro.

Extracted the info for all projects under 2.11.11 -YclasspathImpl:flat, 2.11.11 -YclasspathImpl:recursive, 2.11.12-bin-CUSTOM -YclasspathImpl:recursive, with:

sbt -J-Xmx6G -Dsbt.log.format=false \
  'set List(parallelExecution in ThisBuild := false, logLevel in Global := Level.Warn)' \
  clean 'test:compile' clean test:compile
egrep -R --include '*compileIncremental*' 'total in|Extracts ' . > overhead-2.11.11-recursive.log

https://gist.github.com/retronym/33400a750785acc05dfec87cfede7107

[retronym]

There are two paths forward here to fix the regression.

First, we can optimize the new classpath implementation. There are some constant factor improvements that might go part of the way. We probably also need to add an index of package => <classpath entry> into AggregateClasspath.

SBT itself could also be changed to avoid calling this altogether. For symbols sourced from JARs, It actually just needs to AbstractFile of the JAR itself, not of the entry. We can get to that via Symbol.associatedFile.underlyingSource, avoiding a classpath scan. Prototype: sbt/sbt@0.13...retronym:faster-flatclasspath

[lrytz]

@retronym I wrote some doc comments here: https://github.com/scala/scala/compare/2.12.x...lrytz:classpath-doc?expand=1

Can you integrate this (and update where necessary) into your PR?

[retronym]

Promising results in overall build time with my SBT patch:

⚡ for v in 0.13.15 0.13.16-bin-f077a84; do echo $v; sbt -J-Xmx4G -sbt-version $v update &>/dev/null; sbt -sbt-version $v -J-Xmx6G -Dsbt.log.format=false 'set List(parallelExecution in ThisBuild := false, logLevel in Global := Level.Warn)' clean 'test:compile' clean test:compile; done | grep -v 'is not yet in the classpath cach'
0.13.15
[info] Loading global plugins from /Users/jz/.sbt/0.13/plugins
[info] Loading project definition from /Users/jz/code/guardian-frontend/project/project
[info] Loading project definition from /Users/jz/code/guardian-frontend/project
[info] Resolving key references (20783 settings) ...
[info] Set current project to root (in build file:/Users/jz/code/guardian-frontend/)
[info] Defining */*:logLevel, {.}/*:parallelExecution
[info] The new values will be used by admin/*:evicted, admin/*:update and 38 others.
[info] 	Run `last` for details.
[info] Reapplying settings...
[info] Set current project to root (in build file:/Users/jz/code/guardian-frontend/)
[success] Total time: 1 s, completed 21/06/2017 7:43:39 PM
[success] Total time: 102 s, completed 21/06/2017 7:45:20 PM
[success] Total time: 1 s, completed 21/06/2017 7:45:21 PM
[success] Total time: 74 s, completed 21/06/2017 7:46:35 PM
0.13.16-bin-f077a84
[info] Loading global plugins from /Users/jz/.sbt/0.13/plugins
[info] Loading project definition from /Users/jz/code/guardian-frontend/project/project
[info] Loading project definition from /Users/jz/code/guardian-frontend/project
[info] Resolving key references (20783 settings) ...
[info] Set current project to root (in build file:/Users/jz/code/guardian-frontend/)
[info] Defining */*:logLevel, {.}/*:parallelExecution
[info] The new values will be used by admin/*:evicted, admin/*:update and 38 others.
[info] 	Run `last` for details.
[info] Reapplying settings...
[info] Set current project to root (in build file:/Users/jz/code/guardian-frontend/)
[success] Total time: 1 s, completed 21/06/2017 7:47:53 PM
[success] Total time: 93 s, completed 21/06/2017 7:49:26 PM
[success] Total time: 1 s, completed 21/06/2017 7:49:26 PM
[success] Total time: 66 s, completed 21/06/2017 7:50:33 PM

[jvican]

SBT itself could also be changed to avoid calling this altogether. For symbols sourced from JARs, It actually just needs to AbstractFile of the JAR itself, not of the entry. We can get to that via Symbol.associatedFile.underlyingSource, avoiding a classpath scan. Prototype: sbt/sbt@0.13...retronym:faster-flatclasspath

That looks very promising. Good catch!

[dragos]

First, we can optimize the new classpath implementation. There are some constant factor improvements that might go part of the way. We probably also need to add an index of package => <classpath entry> into AggregateClasspath.

I think this might be problematic, or at least, it should support split packages. Unfortunately there are many projects that, knowingly or unknowingly, rely on them.

Otherwise, I think we should fix both the classpath implementation and Sbt. :)

[retronym]

Good point, the index needs to be a multi map.

[retronym]

I've prototyped the fixes in both SBT and Scala. I've tested the performance of interesting combinations after managing to serialize compilation in the multi-project build.

Results: https://gist.github.com/3c89c21c54d27e566dec57a16a4bf208

They suggest that my latest fix to Scala restores the old performance. The SBT fix seems to equalize flat and recursive classpath, but only by slowing down the latter! It probably has a silly bug that I'm not seeing.

My next step is to submit that Scala fix to target 2.12.3.