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?

3.14.15 Pi Day

Today we have Pi Day! As you probably know my favorite number is Pi and approximation of Pi number is my favorite activity on this blog. Lets focus on new version of groovy closure to count Pi:

Closure<BigDecimal> functionToIntegrate = { Math.sin(it) }
integrate(scale, sumToLimit, functionToIntegrate)  * 2 == expectedResult

Because we can't improve this API without groovy DSL someday I will get back to this  (when I will have to learn more about groovy DSL).
My colleague helped me with this improvement, but also he told me about groovy DSL. Now I can imagine API as beauty as:

integrate functionToIntegrate using scale untilReach sumToLimit andReturnX == expectedResult

This will be nice, but for now I have added a new library to show how long our tests lasted.
With this library we can profile our tests:
PiSpec  should converge to pi   9.252[s] on my laptop.
It's quite nice to achieve proper 3.1415 in 9 seconds.
I found very interesting article on wikipedia about pi approximation history:
http://en.wikipedia.org/wiki/Approximations_of_%CF%80

Groovy closure to find Pi and sqrt(2)

I want to start with very simple math fact - if we draw right triangle and two of edges of this triangle have length equal to sqrt(2). Area of this triangle is of course 1 (because: 1/2*a*h).

Another fact is that area under function sin(x) from 0 to pi/2 is also equal to 1.

Let's use those facts to exploit groovy closures to estimate pi and sqrt(2).

Clone repo: git clone https://github.com/piotrpietrzak/gatchaman.git

git checkout origin/groovypi

We should start with tests - this time we will use spock with "where:" block.

def "should converge to square root of two"(scale, sumToLimit, expectedResult) {
    expect:
    new DefiniteIntegral()
            .compute(scale, sumToLimit , { it }) == expectedResult

    where:
    scale | sumToLimit | expectedResult
    1     | 1          | 1.4

    2     | 1          | 1.41

    3     | 1          | 1.414

    4     | 1          | 1.4142

    5     | 1          | 1.41421

    6     | 1          | 1.414214

}

For pi this is also very simple test:

def "should converge to pi"(scale, sumToLimit, expectedResult) {
    expect:
    new DefiniteIntegral()
            .compute(scale, sumToLimit, { Math.sin(it) }) * 2 == expectedResult

    where:
    scale | sumToLimit | expectedResult
    1     | 1          | 3.2    

    2     | 1          | 3.14

    3     | 1          | 3.142

    4     | 1          | 3.1416

    5     | 1          | 3.14160

    6     | 1          | 3.141592

}

Definite integral is quite simple (from the numerical recipes point of view we can achieve much better results even with this naive approach but I want to keep this simple).

while (sum < integrateTo) {
    x += step
    sum += function(x) * step
}

After this loop we should return x which is our result.

What else can we do better?

Every math lover will tell us other things but IT guys will focus on poor API and unnecessary method. Lets replace this simple solution with this:

class IntegrationClosure {
    final Closure<BigInteger> compute = {
        Integer scale, BigDecimal integrateTo, Closure<BigDecimal> function ->
            BigDecimal sum = 0;
            BigDecimal x = 0;
            BigDecimal step = BigDecimal.valueOf(1, scale)

            while (sum < integrateTo) {
                x += step
                sum += function(x) * step
            }
            x
    }
}

Port conflicts during tests

When I was running tests in very large and sophisticated system I found very interesting problem. During integration tests run in parallel there was port conflicts and port collision prevents tests to run smoothly and in the end they failed. To avoid this behavior I suggested to use very simple solution. My colleagues confirm the need and implementation was done in very short time. Just before you read the solution - please reconsider situation on your own:

• Tests runs on many JVMs
• You don't want to share state between mentioned above JVMs
• You don't want to manually change every test to enter code

The solution suggested was to use random port in range and repeat this until success. Really simple and it just works. 

From technical perspective please focus on this closure from tests:

Server server = new AvailablePortScanner(minPort, maxPort).tryToExecuteWithFreePort(new Closure<Server>(this) {
    @Override    public Server call(Object... args) {
        Integer freePort = (Integer) args[0];
        Server server = new Server(freePort);
        System.setProperty("port", freePort.toString());
        return server;
    }
});

Checkout on branch:

origin/groovy/closure_port_scanner

to play with it. Have fun

Groovy overloaded operator

Groovy overloaded operator (bit shift on objects)

This example come from "Groovy Goodness Notebook".

Clone repo:

git clone https://github.com/piotrpietrzak/gatchaman.git

Switch to branch:

git checkout origin/groovy/multiple_overloaded_operator_methods

Test in spock is quite interesting:

def "should add operation for user" () {
    setup:
    Priviledge priviledge = new Priviledge()
    User user = new User(name: 'Test name')
    Operation operation = new Operation(name: 'Test operation')

    when:
    priviledge << user << operation

    then:
    priviledge.users.contains user
    priviledge.operations.contains operation
}