Spock performance problems

Question

I've some problems with performance with specifications implemented in Spock - I mean execution time in particular. After digging into the problem, I've noticed that it's somehow related with setting spec up - I don't mean setup() method in particular.

After this discovery, I added @Shared annotation to all the fields declared in the specification and it runs 2 times faster than before. Then, I thought, that performance problems may be related to ConcurrentHashMap or random* methods (from commons-lang3) but that wasn't the case.

In the end, in an act of desperation, I decorated all the fields in my specification in the following way:

class EntryFacadeSpec extends Specification {

  static {
    println(System.currentTimeMillis())
  }
  @Shared
  def o = new Object()
  static {
    println(System.currentTimeMillis())
  }
  @Shared
  private salesEntries = new InMemorySalesEntryRepository()
  static {
    println(System.currentTimeMillis())
  }
  @Shared
  private purchaseEntries = new InMemoryPurchaseEntryRepository()
  static { 
    println(System.currentTimeMillis())
  }

  ...

What's interesting, no matter which field is declared as the first one it takes hundreds of milliseconds to initialize the field:

1542801494583
1542801495045
1542801495045
1542801495045
1542801495045
1542801495045
1542801495045
1542801495045
1542801495045
1542801495045
1542801495046
1542801495046
1542801495046
1542801495046
1542801495047
1542801495047

What's the problem? How to save this several hundred milliseconds?

Answer 1

TL;DR

Calling printlnin the first static block initializes about 30k+ objects related to Groovy Development Kit. It can take 50 ms at the minimum to finish, depending on horsepower of the laptop we run this test on.

The details

I couldn't reproduce the lag at the level of hundreds of milliseconds, but I was able to get a lag between 30 to 80 milliseconds. Let's start with the class I used in my local tests that reproduces your use case.

import spock.lang.Shared
import spock.lang.Specification

class EntryFacadeSpec extends Specification {

    static {
        println("${System.currentTimeMillis()} - start")
    }

    @Shared
    def o = new Object()

    static {
        println("${System.currentTimeMillis()} - object")
    }

    @Shared
    private salesEntries = new InMemorySalesEntryRepository()

    static {
        println("${System.currentTimeMillis()} - sales")
    }

    @Shared
    private purchaseEntries = new InMemoryPurchaseEntryRepository()

    static {
        println("${System.currentTimeMillis()} - purchase")
    }

    def "test 1"() {
        setup:
        System.out.println(String.format('%d - test 1', System.currentTimeMillis()))

        when:
        def a = 1

        then:
        a == 1
    }

    def "test 2"() {
        setup:
        System.out.println(String.format('%d - test 2', System.currentTimeMillis()))

        when:
        def a = 2

        then:
        a == 2
    }

    static class InMemorySalesEntryRepository {}

    static class InMemoryPurchaseEntryRepository {}
}

Now, when I run it I see something like this in the console.

1542819186960 - start
1542819187019 - object
1542819187019 - sales
1542819187019 - purchase
1542819187035 - test 1
1542819187058 - test 2

We can see 59 milliseconds lag between the two first static blocks. It doesn't matter what is between these two blocks, because Groovy compiler merges all these 4 static blocks to a single static block that looks like this in plain Java:

static {
    $getCallSiteArray()[0].callStatic(EntryFacadeSpec.class, new GStringImpl(new Object[]{$getCallSiteArray()[1].call(System.class)}, new String[]{"", " - start"}));
    $getCallSiteArray()[2].callStatic(EntryFacadeSpec.class, new GStringImpl(new Object[]{$getCallSiteArray()[3].call(System.class)}, new String[]{"", " - object"}));
    $getCallSiteArray()[4].callStatic(EntryFacadeSpec.class, new GStringImpl(new Object[]{$getCallSiteArray()[5].call(System.class)}, new String[]{"", " - sales"}));
    $getCallSiteArray()[6].callStatic(EntryFacadeSpec.class, new GStringImpl(new Object[]{$getCallSiteArray()[7].call(System.class)}, new String[]{"", " - purchase"}));
}

So this 59 milliseconds lag happens between two first lines. Let's put a breakpoint in the first line and run a debugger.

Let's step over this line to the next line and let's see what happens:

We can see that invoking Groovy's println("${System.currentTimeMillis()} - start") caused creating more than 30k objects in the JVM. Now, let's step over the second line to the 3rd one to see what happens:

Only a few more objects got created.

This example shows that adding

static {
    println(System.currentTimeMillis())
}

adds accidental complexity to the test setup and it does not show there is a lag between initialization of two class methods, but it creates this lag. However, the cost of initializing all Groovy related objects is something we can't completely avoid and it has to be paid somewhere. For instance, if we simplify the test to something like this:

import spock.lang.Specification

class EntryFacadeSpec extends Specification {

    def "test 1"() {
        setup:
        println "asd ${System.currentTimeMillis()}"
        println "asd ${System.currentTimeMillis()}"

        when:
        def a = 1

        then:
        a == 1
    }

    def "test 2"() {
        setup:
        System.out.println(String.format('%d - test 2', System.currentTimeMillis()))

        when:
        def a = 2

        then:
        a == 2
    }
}

and we put a breakpoint in the first println statement and step over to the next one, we will see something like this:

It still creates a few thousands of objects, but it is much less than in the first example because most of the objects we saw in the first example were already created before Spock executed the first method.

Overclocking Spock test performance

One of the first things we can do is to use static compilation. In case of my simple test it reduced execution time from 300 ms (non static compilation) to 227 ms approximately. Also the number of objects that have to be initialized is significantly reduced. If I run the same debugger scenario as the last one shown above with @CompileStatic added, I will get something like this:

It is still pretty significant, but we see that the number of objects initialized to invoke println method was dropped.

And the last thing worth mentioning. When we use static compilation and we want to avoid calling Groovy methods in the class static block to print some output we can use a combination of:

System.out.println(String.format("...", args))

because Groovy executes exactly this. On the other hand, following code in Groovy:

System.out.printf("...", args)

may look similar to the previous one, but it gets compiled to something like this (with static compilation enabled):

DefaultGroovyMethods.printf(System.out, "...", args)

The second case will be much slower when used in the class static block, because at this point Groovy jar is not yet loaded and the classloader has to resolve DefaultGroovyMethods class from the JAR file. When Spock executes test method it doesn't make much difference if you use System.out.println or DefaultGroovyMethods.printf, because Groovy classes are already loaded.

That is why if we rewrite your initial example to something like this:

import groovy.transform.CompileStatic
import spock.lang.Shared
import spock.lang.Specification

@CompileStatic
class EntryFacadeSpec extends Specification {

    static {
        System.out.println(String.format('%d - start', System.currentTimeMillis()))
    }

    @Shared
    def o = new Object()

    static {
        System.out.println(String.format('%d - object', System.currentTimeMillis()))
    }

    @Shared
    private salesEntries = new InMemorySalesEntryRepository()

    static {
        System.out.println(String.format('%d - sales', System.currentTimeMillis()))
    }

    @Shared
    private purchaseEntries = new InMemoryPurchaseEntryRepository()

    static {
        System.out.println(String.format('%d - purchase', System.currentTimeMillis()))
    }

    def "test 1"() {
        setup:
        System.out.println(String.format('%d - test 1', System.currentTimeMillis()))

        when:
        def a = 1

        then:
        a == 1
    }

    def "test 2"() {
        setup:
        System.out.println(String.format('%d - test 2', System.currentTimeMillis()))

        when:
        def a = 2

        then:
        a == 2
    }

    static class InMemorySalesEntryRepository {}

    static class InMemoryPurchaseEntryRepository {}

}

we will get following console output:

1542821438552 - start
1542821438552 - object
1542821438552 - sales
1542821438552 - purchase
1542821438774 - test 1
1542821438786 - test 2

But what is more important, it doesn't log field initialization time, because Groovy compiles these 4 blocks to a single one like this:

static {
    System.out.println(String.format("%d - start", System.currentTimeMillis()));
    Object var10000 = null;
    System.out.println(String.format("%d - object", System.currentTimeMillis()));
    var10000 = null;
    System.out.println(String.format("%d - sales", System.currentTimeMillis()));
    var10000 = null;
    System.out.println(String.format("%d - purchase", System.currentTimeMillis()));
    var10000 = null;
}

There is no lag between the 1st and 2nd call, because there is no need to load Groovy classes at this point.