Multi Project build spends linear time applying costly settings transformation when using the TeamCityLogger

[fernandoracca]

We have many sub modules in our project, and using the Custom TC logger means that every time we run a new SBT commands, the step transformation slowly applies to each and every one of them (Update: It also happens using SBT Auto).

This can easily take 45 seconds on a lightly loaded build server. It means we are wasting at least 45 seconds on each build to be able to report unit tests.

Could you please advice? We use SBT 0.13.8 with the following settings:

//Faster compilation via class name hashing
incOptions := incOptions.value.withNameHashing(nameHashing = true),
//Faster sbt dependencies update via jar graph caching,
//and Cached Resolution:  https://github.com/sbt/sbt/pull/1631
updateOptions := updateOptions.value.withCachedResolution(cachedResoluton = true),

Log below:

[10:27:13]SBT main class name will be retrieved from: /home/dev//sbt/bin/sbt-launch.jar
[10:27:13]SBT TeamCity Logger installation: 'Custom' mode was selected in SBT runner plugin settings
[10:27:13]Java home set to: /tools/jdk/1.8.0_31-build001/.exec/x86-64.rhel.5
[10:27:13]SBT home set to: /home/dev//sbt
[10:27:13]Starting: /tools/jdk/1.8.0_31-build001/.exec/x86-64.rhel.5/bin/java -Dagent.home.dir=/builder/TeamCity/buildAgent -Dagent.name=Default Agent -Dagent.ownPort=9090 -Dagent.work.dir=/builder/TeamCity/buildAgent/work -Dbuild.number=872 -Dbuild.vcs.number=44441b709bae0d78d70f4a5c8d12cab4b3eb6c93 -Dbuild.vcs.number.1=44441b709bae0d78d70f4a5c8d12cab4b3eb6c93 -Dbuild.vcs.number.Sse=44441b709bae0d78d70f4a5c8d12cab4b3eb6c93 -Djava.io.tmpdir=/builder/TeamCity/buildAgent/temp/buildTmp -Dsbt.ivy.home=/builder/TeamCity/buildAgent/system/sbt_ivy -Dteamcity.agent.cpuBenchmark=585 -Dteamcity.agent.dotnet.agent_url=http://localhost:9090/RPC2 -Dteamcity.agent.dotnet.build_id=2821 -Dteamcity.build.changedFiles.file=/builder/TeamCity/buildAgent/temp/buildTmp/changedFiles1133884825064034905.txt -Dteamcity.build.checkoutDir=/builder/TeamCity/buildAgent/work/fe6c08143bb88c96 -Dteamcity.build.id=2821 -Dteamcity.build.properties.file=/builder/TeamCity/buildAgent/temp/buildTmp/teamcity.build5967951682709802362.properties -Dteamcity.build.tempDir=/builder/TeamCity/buildAgent/temp/buildTmp -Dteamcity.build.workingDir=/builder/TeamCity/buildAgent/work/fe6c08143bb88c96 -Dteamcity.buildConfName=CompileAndTest -Dteamcity.buildType.id=Xe_CompileAndTest -Dteamcity.configuration.properties.file=/builder/TeamCity/buildAgent/temp/buildTmp/teamcity.config5451174894372366078.properties -Dteamcity.projectName=XE -Dteamcity.runner.properties.file=/builder/TeamCity/buildAgent/temp/buildTmp/teamcity.runner4687350985071097016.properties -Dteamcity.tests.recentlyFailedTests.file=/builder/TeamCity/buildAgent/temp/buildTmp/testsToRunFirst4425321344332664018.txt -Dteamcity.version=8.1.5 (build 30240) -Xms512M -Xmx2048M -XX:ReservedCodeCacheSize=128m -Dsbt.ivy.home=/home/dev/.ivy2 -Dsbt.log.format=false -classpath /home/dev//sbt/bin/sbt-launch.jar:/home/dev//sbt/bin/classes: xsbt.boot.Boot apply -cp /builder/TeamCity/buildAgent/temp/agentTmp/agent-sbt/tc_plugin/sbt-teamcity-logger.jar jetbrains.buildServer.sbtlogger.SbtTeamCityLogger clean ciLogging test
[10:27:13]in directory: /builder/TeamCity/buildAgent/work/fe6c08143bb88c96
[10:27:18][info] Loading project definition from /builder/TeamCity/buildAgent/work/fe6c08143bb88c96/project
[10:27:18][info] Updating {file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/project/}fe6c08143bb88c96-build...
[10:27:18][info] Resolving org.scoverage#sbt-scoverage;1.1.0 ...
[10:27:18][info] Resolving org.scoverage#scalac-scoverage-plugin_2.10;1.1.0 ...
[10:27:18][info] Resolving org.scala-lang#scala-library;2.10.4 ...
[10:27:19][info] Resolving com.github.gseitz#sbt-release;0.8.5 ...
[10:27:19][info] Resolving org.xerial.sbt#sbt-pack;0.6.2 ...
[10:27:19][info] Resolving org.fusesource.scalate#scalate-core_2.10;1.6.1 ...
[10:27:19][info] Resolving org.fusesource.scalate#scalate-util_2.10;1.6.1 ...
[10:27:19][info] Resolving org.slf4j#slf4j-api;1.6.1 ...
[10:27:19][info] Resolving org.scala-lang#scala-compiler;2.10.4 ...
[10:27:19][info] Resolving org.scala-lang#scala-reflect;2.10.4 ...
[10:27:19][info] Resolving org.kamranzafar#jtar;2.2 ...
[10:27:19][info] Resolving org.slf4j#slf4j-nop;1.7.5 ...
[10:27:19][info] Resolving org.slf4j#slf4j-api;1.7.5 ...
[10:27:19][info] Resolving com.typesafe.sbt#sbt-git;0.6.4 ...
[10:27:19][info] Resolving org.eclipse.jgit#org.eclipse.jgit.pgm;3.3.2.201404171909-r ...
[10:27:19][info] Resolving args4j#args4j;2.0.12 ...
[10:27:19][info] Resolving org.apache.commons#commons-compress;1.6 ...
[10:27:19][info] Resolving org.tukaani#xz;1.4 ...
[10:27:19][info] Resolving org.eclipse.jgit#org.eclipse.jgit.archive;3.3.2.201404171909-r ...
[10:27:19][info] Resolving org.eclipse.jgit#org.eclipse.jgit;3.3.2.201404171909-r ...
[10:27:19][info] Resolving com.jcraft#jsch;0.1.50 ...
[10:27:19][info] Resolving com.googlecode.javaewah#JavaEWAH;0.7.9 ...
[10:27:19][info] Resolving org.apache.httpcomponents#httpclient;4.1.3 ...
[10:27:19][info] Resolving org.apache.httpcomponents#httpcore;4.1.4 ...
[10:27:19][info] Resolving commons-logging#commons-logging;1.1.1 ...
[10:27:19][info] Resolving commons-codec#commons-codec;1.4 ...
[10:27:19][info] Resolving org.osgi#org.osgi.core;4.3.1 ...
[10:27:19][info] Resolving org.eclipse.jgit#org.eclipse.jgit.ui;3.3.2.201404171909-r ...
[10:27:19][info] Resolving com.eed3si9n#sbt-buildinfo;0.3.2 ...
[10:27:19][info] Resolving com.eed3si9n#sbt-unidoc;0.3.1 ...
[10:27:19][info] Resolving org.scala-sbt#sbt;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#main;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#actions;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#classpath;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#launcher-interface;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#interface;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#io;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#control;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#completion;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#collections;0.13.8 ...
[10:27:19][info] Resolving jline#jline;2.11 ...
[10:27:19][info] Resolving org.scala-sbt#api;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#compiler-integration;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#incremental-compiler;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#logging;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#process;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#relation;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#compile;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#classfile;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#persist;0.13.8 ...
[10:27:19][info] Resolving org.scala-tools.sbinary#sbinary_2.10;0.4.2 ...
[10:27:19][info] Resolving org.scala-sbt#compiler-ivy-integration;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#ivy;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#cross;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt.ivy#ivy;2.3.0-sbt-fccfbd44c9f64523b61398a0155784dcbaeae28f ...
[10:27:19][info] Resolving com.jcraft#jsch;0.1.46 ...
[10:27:19][info] Resolving org.scala-sbt#serialization_2.10;0.1.1 ...
[10:27:19][info] Resolving org.scala-lang.modules#scala-pickling_2.10;0.10.0 ...
[10:27:19][info] Resolving org.scalamacros#quasiquotes_2.10;2.0.1 ...
[10:27:19][info] Resolving org.json4s#json4s-core_2.10;3.2.10 ...
[10:27:19][info] Resolving org.json4s#json4s-ast_2.10;3.2.10 ...
[10:27:19][info] Resolving com.thoughtworks.paranamer#paranamer;2.6 ...
[10:27:19][info] Resolving org.spire-math#jawn-parser_2.10;0.6.0 ...
[10:27:19][info] Resolving org.spire-math#json4s-support_2.10;0.6.0 ...
[10:27:19][info] Resolving org.scala-sbt#run;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#task-system;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#tasks;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#tracking;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#cache;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#testing;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#test-agent;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#test-interface;1.0 ...
[10:27:19][info] Resolving org.scala-sbt#main-settings;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#apply-macro;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#command;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#logic;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#compiler-interface;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#precompiled-2_8_2;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#precompiled-2_9_2;0.13.8 ...
[10:27:19][info] Resolving org.scala-sbt#precompiled-2_9_3;0.13.8 ...
[10:27:20][info] Resolving org.scala-lang#jline;2.10.4 ...
[10:27:20][info] Resolving org.fusesource.jansi#jansi;1.4 ...
[10:27:20][info] Done updating.
[10:27:20][info] Compiling 11 Scala sources to /builder/TeamCity/buildAgent/work/fe6c08143bb88c96/project/target/scala-2.10/sbt-0.13/classes...
[10:27:33][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:33][info] Applying State transformations jetbrains.buildServer.sbtlogger.SbtTeamCityLogger from /builder/TeamCity/buildAgent/temp/agentTmp/agent-sbt/tc_plugin/sbt-teamcity-logger.jar
[10:27:33][info] Reapplying settings...
[10:27:35][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:35][info] Reapplying settings...
[10:27:37][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:37][info] Reapplying settings...
[10:27:38][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:38][info] Reapplying settings...
[10:27:40][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:40][info] Reapplying settings...
[10:27:42][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:42][info] Reapplying settings...
[10:27:44][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:44][info] Reapplying settings...
[10:27:45][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:45][info] Reapplying settings...
[10:27:47][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:47][info] Reapplying settings...
[10:27:49][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:49][info] Reapplying settings...
[10:27:50][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:50][info] Reapplying settings...
[10:27:52][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:52][info] Reapplying settings...
[10:27:54][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:54][info] Reapplying settings...
[10:27:55][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:55][info] Reapplying settings...
[10:27:57][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:57][info] Reapplying settings...
[10:27:59][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:27:59][info] Reapplying settings...
[10:28:00][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:00][info] Reapplying settings...
[10:28:02][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:02][info] Reapplying settings...
[10:28:04][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:04][info] Reapplying settings...
[10:28:06][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:06][info] Reapplying settings...
[10:28:07][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:07][info] Reapplying settings...
[10:28:09][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:09][info] Reapplying settings...
[10:28:11][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:11][info] Reapplying settings...
[10:28:12][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:12][info] Reapplying settings...
[10:28:14][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:14][info] Reapplying settings...
[10:28:16][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)
[10:28:16][info] Reapplying settings...
[10:28:18][info] Set current project to XE (in build file:/builder/TeamCity/buildAgent/work/fe6c08143bb88c96/)

See Issues:
JetBrains/tc-sbt-runner#8
https://youtrack.jetbrains.com/issue/TW-41253

[neko-kai]

@fractal
This seems to have been fixed in 0.5.0/0.6.0 version of sbt-tc-logger. e.g. now there's a single transformation step for a 50+ module project for me:

[08:57:06]
[info] Applying State transformations jetbrains.buildServer.sbtlogger.SbtTeamCityLogger from /opt/buildAgent/temp/agentTmp/agent-sbt/tc_plugin/1.0/sbt-teamcity-logger.jar
[08:57:06]
Plugin sbt-teamcity-logger was loaded.
[08:57:06]
TeamCity version='2018.2.4 (build 61678)'
[08:57:09]
[success] Total time: 2 s

Try adding

resolvers += Resolver.url("bintray-sbt-plugin-releases", url("https://dl.bintray.com/content/sbt/sbt-plugin-releases"))(Resolver.ivyStylePatterns)

addSbtPlugin("org.jetbrains.teamcity.plugins" % "sbt-teamcity-logger" % "0.6.0")

to project or global plugins