Test profiler

I guess you have seen this many times - your tests last so long and you skip them once, maybe even twice and then you skip them all the times.

We want to prevent this situation with team I am working with. To do this my colleagues invent many tweaks to improve build time and they cut this significantly.

Main trick was to run tests in parallel. This is quite simple with gradle, but how to measure the results?

Example 1:

First we will start with simple project for example we can use groovypi - this project have two long lasting tests: one for pi and other for sqrt(2).

Sequential:

01:27:12: Executing external tasks 'clean build profileTests'...

:clean

:compileJava UP-TO-DATE

:compileGroovy

:processResources UP-TO-DATE

:classes

:jar

:assemble

:compileTestJava UP-TO-DATE

:compileTestGroovy

:addTimeout

:processTestResources UP-TO-DATE

:testClasses

:test

Your tests report is ready at [/Users/piotr/github/gatchaman/build/reports/test_profiling/testsProfile.csv]

:buildDashboard

:check

:build

:profileTests

Your combined report is available here [/Users/piotr/github/gatchaman/build/reports/test_profiling/summary.csv]

BUILD SUCCESSFUL

Total time: 39.538 secs

01:27:51: External tasks execution finished 'clean build profileTests'.

Parallel:

01:29:47: Executing external tasks 'clean build profileTests'...

Parallel execution is an incubating feature.

:clean

:compileJava UP-TO-DATE

:compileGroovy

:processResources UP-TO-DATE

:classes

:jar

:assemble

:compileTestJava UP-TO-DATE

:compileTestGroovy

:addTimeout

:processTestResources UP-TO-DATE

:testClasses

:test

Your tests report is ready at [/Users/piotr/github/gatchaman/build/reports/test_profiling/testsProfile.csv]

:buildDashboard

:check

:build

:profileTests

Your combined report is available here [/Users/piotr/github/gatchaman/build/reports/test_profiling/summary.csv]

BUILD SUCCESSFUL

Total time: 39.082 secs

01:30:27: External tasks execution finished 'clean build profileTests'.

Important lines from those two runs was:

sequential:

Total time: 39.538 secs

parallel:

Total time: 39.082 secs

It was not that fast I was expecting. Why? Where is the field to improvements?

To find the answer lets go back to tests - our build process in some parts will be sequential by nature of matter. We can improve only tasks that can run in parallel. Tests are obvious candidate.

How to measure test performance?

We can use plugin (authored by my colleagues: Adam Chudzik and Marcin Grzejszczak) named: gradle-test-profiler.

To apply this plugin to project you have to add few lines to your build.gradle file:

buildscript {
    repositories {
        mavenLocal()
        jcenter()
    }
    dependencies {
        classpath 'com.blogspot.toomuchcoding:gradle-test-profiler:0.2.3-SNAPSHOT'    }
}

apply plugin: 'com.blogspot.toomuchcoding.testprofiler'

Next we have to setup new task (profileTests) in gradle. In my case it was as simple as this:

Because I have written down those results we can compare results of runing tests in parallel and sequentially:

Sequential:

module test class name test name test execution time in [s] test class execution time in [s]
: SquarRooteOfTwoSpec should converge to square root of two 27.398 27.398
: PiSpec should converge to pi 8.405 8.405

Parallel:

module test class name test name test execution time in [s] test class execution time in [s]
: SquarRooteOfTwoSpec should converge to square root of two 28.044 28.044
: PiSpec should converge to pi 7.582 7.582

How we should interpret the results?

Can we identify long lasting tests?

Can we break build with long lasting tests?