definedTests taking a long time, possibly because of internalDependencyClasspath

[stefanobaghino]

sbt version: 1.9.2

I'm trying to diagnose around 25 seconds of latency between running subproject/testOnly *sometest* and the test actually starting (the subproject is where we aggregate all our code and run end-to-end tests).
Using inspect tree I believe I isolated the culprit, realizing that subproject/definedTests takes basically the whole latency I experienced and then recursively getting to the point where I believe I can safely say what's actually slow is subproject/internalClasspathDependency (going through loadedTestFramework -> testFrameworks -> Test / testLoader -> Test / dependencyClasspath -> Test / dependencyClasspathFiles / outputFileStamps -> Test / dependencyClasspathFiles -> Test / dependencyClasspath). The task itself takes around half of the time I'm observing, but it appears to run every time and not benefit from some caching and it's invoked following two separate paths in the dependency graph (subproject / Test / dependencyClasspathFiles) and (subproject / Test / fullClasspath) so it seems like the main culprit.

Do you agree with my diagnosis? Is there something I can do to lower the time taken by internalDependencyClasspath?

[eed3si9n]

Most of sbt's default tasks are defined in one file called Defaults.scala - https://github.com/sbt/sbt/blob/1.10.x/main/src/main/scala/sbt/Defaults.scala, and according to that definedTest is implemented as:

  definedTests := detectTests.value,
....
  def detectTests: Initialize[Task[Seq[TestDefinition]]] =
    Def.task {
      Tests.discover(loadedTestFrameworks.value.values.toList, compile.value, streams.value.log)._1
    }

so if definedTests takes the majority of time, then next step to figure out might be finding out if Test / compile is taking up the majority of time, or the pure task code happening in Tests.discover(...). It's possible that something in the pure code is slow, and it's also possible that something about compile is breaking the incremental compilation.

If you call Test/compile a bunch of times, do they finish in 0s?

[stefanobaghino]

Unfortunately I cannot answer anymore (trying to figure out why this was taking a long time was my last contribution to a codebase I no longer have access to) but I shared this post with my former colleagues, I hope they can follow up on this. Thank you for your help!

[nmarton-da]

Hi @eed3si9n,

It seems to me that the Tests.discover() call is getting slow for some reason.

The Test/compile does not finish very quickly, and it triggers the definedTests as well, so it is the same essentially (is this normal?)
I took a heavy handed approach and overridden the project's definedTests with

        Test / definedTests := sbt.Def.task {
          (Test / loadedTestFrameworks).value.values.toList // just to have the same task execution dep graph
          (Test / compile).value
          Nil
        }.value,

and then Test/compile then took less than a second.

I also turned on -Dsbt.task.timings=true and piped the debug level output of sbt trough a ts to see where it is getting slow, and the big wait is right at the end (no debug output after the big wait starts, and before I see the timing metrics printed).
I also checked the modified files in the whole project, and (after correlating the timestamp and the begining-end of the big-wait with the sbt debug output) found that after the big-wait-at-the-end only XX_global/_global/definedTestNames/data, XX_global/_global/discoveredMainClasses/data and streams/test/definedTests/_global/streams/out files are getting updated.
The result in the data file contains like 200 names, so that is for sure not too heavy (how could we have an idea about the input?).
During the big-wait I think there was a single threaded CPU load.

What could cause this slow-down?

[eed3si9n]

I guess something in here?

sbt/main-actions/src/main/scala/sbt/Tests.scala

Lines 531 to 593 in 9bd80cf

	def discover(
	frameworks: Seq[Framework],
	analysis: CompileAnalysis,
	log: Logger
	): (Seq[TestDefinition], Set[String]) =
	discover(frameworks flatMap TestFramework.getFingerprints, allDefs(analysis), log)
	def allDefs(analysis: CompileAnalysis) = analysis match {
	case analysis: Analysis =>
	val acs: Seq[xsbti.api.AnalyzedClass] = analysis.apis.internal.values.toVector
	acs.flatMap { ac =>
	val companions = ac.api
	val all =
	Seq(companions.classApi: Definition, companions.objectApi: Definition) ++
	(companions.classApi.structure.declared.toSeq: Seq[Definition]) ++
	(companions.classApi.structure.inherited.toSeq: Seq[Definition]) ++
	(companions.objectApi.structure.declared.toSeq: Seq[Definition]) ++
	(companions.objectApi.structure.inherited.toSeq: Seq[Definition])
	all
	}.toSeq
	}
	def discover(
	fingerprints: Seq[Fingerprint],
	definitions: Seq[Definition],
	log: Logger
	): (Seq[TestDefinition], Set[String]) = {
	val subclasses = fingerprints collect {
	case sub: SubclassFingerprint => (sub.superclassName, sub.isModule, sub)
	};
	val annotations = fingerprints collect {
	case ann: AnnotatedFingerprint => (ann.annotationName, ann.isModule, ann)
	};
	log.debug("Subclass fingerprints: " + subclasses)
	log.debug("Annotation fingerprints: " + annotations)
	def firsts[A, B, C](s: Seq[(A, B, C)]): Set[A] = s.map(_._1).toSet
	def defined(
	in: Seq[(String, Boolean, Fingerprint)],
	names: Set[String],
	IsModule: Boolean
	): Seq[Fingerprint] =
	in collect { case (name, IsModule, print) if names(name) => print }
	def toFingerprints(d: Discovered): Seq[Fingerprint] =
	defined(subclasses, d.baseClasses, d.isModule) ++
	defined(annotations, d.annotations, d.isModule)
	val discovered = Discovery(firsts(subclasses), firsts(annotations))(definitions.filter {
	case c: ClassLike =>
	c.topLevel
	case _ => false
	})
	// TODO: To pass in correct explicitlySpecified and selectors
	val tests =
	for {
	(df, di) <- discovered
	fingerprint <- toFingerprints(di)
	} yield new TestDefinition(df.name, fingerprint, false, Array(new SuiteSelector: Selector))
	val mains = discovered collect { case (df, di) if di.hasMain => df.name }
	(tests, mains.toSet)
	}
	}

[nmarton-da]

Is it normal that this information (the discovered tests) is not cached? (this is executing each and every time with no code changes whatsoever)

[nmarton-da]

Oh I figured out: it is the sbt-jupiter-interface plugin 🎉

I wanted to narrow down what is expensive in that call, so I spelled out the default Tests.discover there, and to my big surprise all the waits disappeared.
Then I was looking for things which override the definedTests, and voila.
The problem in our build was that that plugin is by default activated on all subprojects, and since the definedTests task results are not cached, recursively executes to all subprojects, it causes quite some wait times.
Do you know maybe how to turn around the black-list approach with auto-plugins to a white-list approach? (using the auto plugin but not letting it automatically active in all projects, just explicitly with .enablePlugins())