Performance regression in ProjectBuilder in 2.14 and 3.0

performance
not-a-bug

(Marcin Zajączkowski) #1

Starting with Gradle 2.14(.1) the first time ProjectBuilder's initialization works significantly slower than in 2.13. For a simple test case:

ProjectBuilder.builder().build()

the time of execution (in a Spock unit test) increased from ~1,3s to ~2,3s. Only the first execution is slower (even in different specifications executed together) and therefor it can be related Asm backed class generator or something else that is common for a JVM (I haven’t profiled the code).

In general, one second is not a big deal, but it is noticeable where you want to run just one “unit” test from IDE.

Btw, I’ve seen related changes in Gradle 3.0-rc-2+, but the problem persists in Gradle 3.0 final. What is more, even if I specify a GradleUserHomeDir manually gradle-api-3.0.jar is not created there.

Gradle Version: 2.14+ (including 3.0)
Operating System: Linux


(Cédric Champeau) #2

Hi Marcin!

Do you have a sample project that reproduces the issue? Ideally, if you have it could you produce build scans for both versions of Gradle?

I have to double check but you’re right we’ve made several changes to the ProjectBuilder in order to appropriately isolate classloaders. This could be responsible for the slowdown you’re seeing.


(Marcin Zajączkowski) #3

Thanks for your reply, Cedric. I don’t know if build scans work at that level - it is not during the build, but in “unit” tests (maybe I undervalue build scans, but probably it would show that test execution phase is longer). To reproduce the problem it is just enough to run ProjectBuilder.builder().build() from a Spock test in any Gradle plugin like project using Gradle 2.13 (the faster one) and later Gradle 2.14.1/3.0 (the slower one - probably also in Gradle build itself).

However, if it would be helpful for you I can prepare that simple project in two versions.


(Cédric Champeau) #4

A sample project will definitely be helpful. BTW Build scans capture everything happening during the build, including test execution, so it will help.


(Marcin Zajączkowski) #5

Here you have the project: https://github.com/szpak/project-builder-perf-issue (master with Gradle 2.14.1 and 2.13 branch with Gradle 2.13).

The test execution with -i on Travis shows ProjectBuilder.builder().build() time as: 0.986S for 2.13 and 2.469S for 2.14.1.

Build scan with 2.13: https://scans.gradle.com/s/2cdax5ry45cyi
Build scan with 2.14.1: https://scans.gradle.com/s/ddba5jd6tsv2m


(Cédric Champeau) #6

Thanks a lot! We’ll keep you informed.


(Mike Kobit) #7

We’ve seen this pop up recently in a new plugin we were developing that also applies built-in Gradle plugins.

Quick example with some very basic duration output:

build.gradle:

plugins {
  id 'groovy'
  id 'java'
  id 'java-gradle-plugin'
  id 'build-dashboard'
}
group 'mytest'
version '1.0-SNAPSHOT'

sourceCompatibility = targetCompatibility = JavaVersion.VERSION_1_8

repositories {
  mavenCentral()
}

dependencies {
  testCompile group: 'junit', name: 'junit', version: '4.12'
  testCompile(group: 'org.spockframework', name: 'spock-core', version: '1.0-groovy-2.4') {
    exclude module: 'groovy-all'
  }
}

model {
  tasks {
    wrapper {
      gradleVersion = '3.1'
    }
  }
}

src/test/groovy/mypackage/MySpec.groovy:

package mypackage

import org.gradle.testfixtures.ProjectBuilder
import spock.lang.Specification

import java.time.Duration
import java.time.Instant

class MySpec extends Specification {
  def "long test"() {
    given:
    final start = Instant.now()
    final project = ProjectBuilder.builder().build()
    final afterProject = Instant.now()

    when:
    final beforeJava = Instant.now()
    project.pluginManager.apply('java')
    final afterJava = Instant.now()
    final beforeGroovy = Instant.now()
    project.pluginManager.apply('groovy')
    final afterGroovy = Instant.now()
    final beforeJGP = Instant.now()
    project.pluginManager.apply('java-gradle-plugin')
    final afterJGP = Instant.now()

    println("Time projectBuilder    : ${Duration.between(start, afterProject)}")
    println("Time java              : ${Duration.between(beforeJava, afterJava)}")
    println("Time groovy            : ${Duration.between(beforeGroovy, afterGroovy)}")
    println("Time java-gradle-plugin: ${Duration.between(beforeJGP, afterJGP)}")

    then:
    1 == 1
  }
}

And an example run:

Time projectBuilder    : PT1.496S
Time java              : PT1.245S
Time groovy            : PT0.034S
Time java-gradle-plugin: PT8.864S

Running this test took around 11-13 seconds each time. I see this long timing behavior on both my home computer and my work laptop. Seems to be happening on 2.14.1, 3.0, and 3.1.

I haven’t dug into --debug logs or into ProjectBuilder to see what is happening yet. Our plugin applies the 'java-gradle-plugin' as well, so any of our ProjectBuilder tests that apply our plugin take an abnormally long time.


(Rishi Goomar) #8

Any update on this performance regression?


(Mike Kobit) #9

Anyway to help for this? Test times posted above cause a lot of personal anguish when writing a bunch of tests against our plugin.


(Benjamin Muschko) #10

You are seeing this behavior as we made some changes to how the dependency gradleApi() is resolved. Starting with 2.14, gradleApi() is generated at runtime and is stored in the local Gradle cache. The generated JAR file lives in a subdirectory of Gradle user home. You can find more information about the reasoning in the release notes.

A project created with ProjectBuilder does not use a shared Gradle user home directory by default. It is created in the project directory for every Project created by a ProjectBuilder instance. This Gradle user home directory can be set from the outside with the method withGradleUserHomeDir(File). Now, when you apply the plugin java-gradle-plugin the project automatically adds gradleApi() to its dependencies and needs to generate the corresponding JAR file. If you do not assign a common Gradle user home directory, the Gradle API JAR file will have to be created over and over again for every test case as the project directory will be different. That’s the reason why you see increased test execution times. I verified the correct behavior with these test cases.

If the goal is to reduce test execution times then I’d suggest you pass a system property to the Test task that points to a common Gradle user home directory. In the test class, you read the system property and set its value via ProjectBuilder.withGradleUserHomeDir(File).


(Marcin Zajączkowski) #11

@bmuschko With what Gradle version have you tested setting gradleUserHomeDir? As I stated in my first post it didn’t change anything (visible):

Btw, I’ve seen related changes3 in Gradle 3.0-rc-2+, but the problem persists in Gradle 3.0 final. What is more, even if I specify a GradleUserHomeDir manually gradle-api-3.0.jar is not created there.

I was setting gradleUserHomeDir using ProjectBuilder. Maybe there is another approach I could use?


(Benjamin Muschko) #12

I added the test case to our master branch which is currently based on Gradle version 3.3. I haven’t seen any changes to the ProjectBuilder implementation that indicate some sort of breakage after withGradleUserHome(File) was introduced. Would you mind trying out your project with a nightly?

Maybe there is another approach I could use?

I’d test your use case with TestKit. It’s far closer to what the end user would experience. I’d say in 98% of all cases you can test what you are trying to test with ProjectBuilder. I usually also try to avoid the use of ProjectBuilder as it has its quirks.


(Marcin Zajączkowski) #13

I will test it with nightly.

I’m aware of ProjectBuilder limitations, but to test things like tasks orchestration in my plugin (I test a lot of scenarios) it is usually enough and it is much faster than nebula-test or TestKit (which I reserve for “real” e2e tests).


Unable to reply to my own (old) thread
(Marcin Zajączkowski) #14

The tests performed with nightly (3.3-20161013000043+0000) end up with the same result - the same regression in comparison to 2.13. However, I spent some time investigating a topic of withGradleUserHome() and it seems that time required to generate API JAR is not a direct issue in that case.

When I set withGradleUserHome() to a new new directory (and force JAR generation) the aforementioned test takes ~15 seconds (!). Using a directory with already generated JAR the time is reduced to ~3,5 seconds.

However, there is more. By default, if an “empty” project with just withGradleUserHome() set is in a ProjectBuilder is created there is no API JAR generated in specified directory. To force this behavior gradleApi() has to be added as a project dependency.

As a conclusion, the originally reported regression is visible even if API JAR is not generated (2 seconds in 3.3-nightly vs ~0,75s in 2.13). With gradleApi() added as a dependency it is much worse (~15 seconds vs ~2s in 2.13).

Btw, semi-manual test with API JAR generation added in a separate 3.3-nightly branch (exact ProjectBuilder operations time visisle with -i).