Severe slowdown in CI build when using SBT 2

Question
1

I’m cutting over Kinetic Merge to use SBT 2.x because Scala Steward is nagging me.

I’ve got to the point where both the local and Github CI builds pass, but the Github CI build has a catastrophic slowdown - it takes around 4.5 hours to complete compared to the relatively snappy 20 minutes or so for the mainline build to complete, using SBT 1.x.

These timings vary, but stay in the same ballpark - tens of minutes for SBT 1.x and several hours for SBT 2.x.

I tried a commit on the SBT 2.x branch that reverts to SBT 1.x but keeps as much of the other changes in build.sbt etc on that branch as possible to try to isolate what is causing the slowdown - now the build is back to sensible times again, seeing ~20 minutes when using 1.x.

I’ve tried reading the documentation and also giving Jules a whirl to see if it could brute-force its way to a solution, but to no avail.

The commit going back to SBT 1 from SBT 2 is minimal: Sbt 2 cutover by sageserpent-open · Pull Request #412 · sageserpent-open/kineticMerge · GitHub, the only big difference is the disabling of caching on a task definition whose task isn’t used in the CI build for the SBT 2.x version.

The local build times on my development machine don’t show this kind of slowdown, in fact SBT 2.x seems to be quicker, even when I’m running sbt testFull to ensure all tests are re-run.

The GitHub action uses ubuntu-latest, so I expect to have 16Gb of RAM available at a stretch. The tests do have memory spikes, but not that high.

One hopeful sign - Americium has also been cut over to use SBT 2.x, and that doesn’t exhibit the same slowdown in its CI build - and this uses a very similar build setup to Kinetic Merge, actually a little more complex as it does multiple builds for Scala 2.13/3. So perhaps there is just an odd test somewhere that pushes things over the edge?

​​I’m still digging away, but if this rings any bells, do share your ideas…

​

2

@eed3si9n Quick question for you while I flail around: does SBT 2 do anything to mock / substitute or adjust the system clock, or intercept calls to Instant.now? I ask because there is a passage in the Book of SBT (Caching - The Book of sbt):

As a mental model of the build as a pure function, build engineers sometimes use the term hermetic build, which is a build that takes place in a shipping container in a desert with no clocks or the Internet. If we can produce a JAR file from that state, then the JAR file should be safe to be shared by any machine. Why did I mention the clock? It’s because a JAR file could capture the timestamp, and thus produce slightly different JARs each time. To avoid this, hermetic build tools overwrite the timestamp to a fixed date 2010-01-01 regardless of when the build took place.

I have tests that run on a time budget, so perhaps they are being affected by this (if there is any such effect in the first place). I have also noticed some weirdness in the time increments used by progress reporters when tests are running in CI - negative increments - so I’d like to either include or eliminate this off the list of suspects.

3

I did make some progress, in that some of the property-based tests were writing to stdout with println or whatever rather than logging, as as the test cases number in the hundreds to thousands, this was severely overloading SBT 2 (SBT 1 is fine with this).

Removing these println etc resulted in a definite speedup, as long as some other tests were still disabled; those ones don’t output to stdout at all, but do generate a pile of logging entries.

Moving on to those other tests, I tried various experiments with disabling log buffering, forcing the SUT logging (as opposed to SBT itself) to just ERROR via Logback configuration and disabling caching.

I also replaced the timing strategy used by one of the remaining problem tests with a fixed count in case there was some influence by the hermetic build system.

None of these bring the test times anywhere near SBT 1, although disabling log buffering had a definite effect, bringing the test time down by roughly 50% overall - but don’t read too much into this, as the builds in question have some tests disabled still.

I did try

Test / outputStrategy := Some(
      OutputStrategy.CustomOutput(
        OutputStream.nullOutputStream
      )
    )

, as something of that ilk works for Americium, but this if anything makes it worse for the Kinetic Merge build.

Local builds work just fine with SBT 2, though.

Given that CI builds with the full test suite are taking from 5 to 6 hours (assuming they aren’t automatically cancelled by GitHub), it isn’t really practicable to continue with this.

1 Like
4

did you figure it out? my guess it’s because of this [2.x] build products shouldn't be moved around · Issue #9569 · sbt/sbt · GitHub

5

Unfortunately, no I didn’t - it still remains a mystery to me. :person_shrugging:

I haven’t looked in the last couple of weeks, but from what I recall, this severe slowdown was only a problem on GitHub CI builds; local ones on OS/X work fine.

Furthermore, Americium seems to build OK via SBT 2 for its GitHub CI build. Only Kinetic Merge seems to be affected. I did try to minimise / workaround the problem, but haven’t yet found a smoking gun or fix.

I’m currently holding off merging the SBT 2 cutover in both projects, and am waiting to see if anyone else experiences similar issues or has advice - I’m OK with SBT 1.x for the foreseeable future, this was only a case of diligently trying to keep up with the ecosystem changes; there are other things that need more attention right now.

Doubtless I’ll come back and revisit this once things have settled down…

1 Like
6

Well, a smidgeon of progress:

I’ve jemmied the logging when testing to being just ERROR by hacking the logback configuration for testing, rather than relying on

Test / logLevel           := Level.Error

in the SBT build definition, as apparently all the logs are shipped over from the forked test process back to the main SBT server process, then they are filtered. All of that data goes down one narrow interprocess channel.

So we have the stanza:

    <root level="${logback-test-root-level:-DEBUG}">
        <appender-ref ref="STDOUT"/>
    </root>

in the Logback configuration, and

Test / javaOptions += "-Dlogback-test-root-level=OFF"

Just turn that noise down, damn it!

I cut over the vast majority of the println calls that say “I’m working on this test case now” in the big property tests so that they log instead, and are thus subject to the test logback configuration.

There is a setting:

Test / testOptions += Tests.Argument(jupiterTestFramework, "-q")

To tell Jupiter to stop mumbling on about each test case that completes.

Despite that, I’m seeing this code in SBT 2’s ForkTestMain.Run:


    private void writeEvents(final TaskDef taskDef, final ForkEvent[] events) {
      ForkEventsInfo info =
          new ForkEventsInfo(
              this.id,
              taskDef.fullyQualifiedName(),
              new ArrayList<ForkEvent>(Arrays.asList(events)));
      String params = this.gson.toJson(info, ForkEventsInfo.class);
      String notification =
          String.format(
              "{ \"jsonrpc\": \"2.0\", \"method\": \"testEvents\", \"params\": %s, \"re\": %d }",
              params, this.id);
      this.originalOut.println(notification);
      this.originalOut.flush();

choking on a block of events from a single property based test that executes circa 30 000 test cases (yes, it really does have to run that many, that’s why we have property based testing, long story, don’t ask). Each one is a report from Jupiter / JUnit5 doing the aformentioned mumbling about “started this test case, ran this test case, it’s was OK”.

The notification string that rolls up all these reports is, ahem, fairly large, and it seems that the interprocess channel is suffering from severe constipation as a result. Several hours worth, if this is the root cause.

I’m still at a loss as to why so much test noise is still being produced, but it’s a glimmer of understanding.

Meanwhile, SBT 1 runs the tests in 12 minutes. :grinning_cat:

ADDENDUM: Some more debugging reveals the source of all those events - sbt-jupiter-interface sets up test execution listeners, and these diligently report back on the tests starting, failing and succeeding back to the SBT worker process as events, which in turn are queued up and drained en-masse when a test suite finishes.

I presume this is how SBT 2 reports how many tests were run, which one failed and also how it generates the XML reports.

So what we have here is multiple components all doing the right thing, but with terrible performance in the case of a property test with a lot of test cases.

I’m at a loss as to what to do about that, so I’m sticking with SBT 1 for the time being, but rhetorical questions I’d ask myself as a maintainer would include:

  1. Why does SBT 1 not have this problem?
  2. Why does the core SBT process need so much information (that notification string came out at ~110 Megabytes)? Does it always need so much - could there be an opt-out?
  3. Do all the events have to be coalesced in the worker, or could they be sent individually or in smaller chunks to the core server process?
7

Claude found a root cause for the slowdown, and created an issue - [2.x] perf: Forked tests with many events take hours · Issue #9982 · sbt/sbt · GitHub

4 Likes
8

Thanks for looking into this, @eed3si9n.

I tried your workaround of upgrading to SBT 2.1.0-RC1, now seeing a CI build time of ~12 minutes, so it’s back on track again. :+1:

I look forward to the full fix when it makes it’s way into in SBT 2.1.0.

Pass my regards on to Claude - that one’s got a promising career ahead. Should stop working for Anthropic as a contractor, though. Maybe Claude and Jules should set up shop together? :grinning_cat:

2 Likes