スポックパフォーマンスの問題

TL; DR

println最初の静的ブロックを呼び出すと、Groovy DevelopmentKitに関連する約30k以上のオブジェクトが初期化されます。このテストを実行するラップトップの馬力によっては、完了するまでに最低50ミリ秒かかる場合があります。

詳細

数百ミリ秒のレベルでラグを再現することはできませんでしたが、30〜80ミリ秒のラグを取得することができました。ユースケースを再現するローカルテストで使用したクラスから始めましょう。

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 {}
}

これを実行すると、コンソールに次のようなものが表示されます。

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

最初の2つの静的ブロック間で59ミリ秒の遅延が見られます。Groovyコンパイラは、これら4つの静的ブロックすべてをプレーンJavaでは次のような単一の静的ブロックにマージするため、これら2つのブロックの間に何があるかは関係ありません。

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"}));
}

したがって、この59ミリ秒の遅延は2つの最初の行の間で発生します。最初の行にブレークポイントを設定して、デバッガーを実行してみましょう。

この行を次の行にステップオーバーして、何が起こるか見てみましょう。

Groovyを呼び出すprintln("${System.currentTimeMillis()} - start")と、JVMに3万を超えるオブジェクトが作成されたことがわかります。それでは、2行目から3行目にステップオーバーして、何が起こるかを見てみましょう。

あと数個のオブジェクトだけが作成されました。

この例は、追加することを示しています

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)

前のものと似ているように見えるかもしれませんが、次のようにコンパイルされます（静的コンパイルが有効になっています）：

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

この時点ではGroovyjarがまだロードされておらず、クラスローダーがDefaultGroovyMethodsJARファイルからクラスを解決する必要があるため、2番目のケースはクラス静的ブロックで使用するとはるかに遅くなります。Spockがテストメソッドを実行するとき、Groovyクラスはすでにロードされているため、System.out.printlnまたはを使用しても大きな違いはありませんDefaultGroovyMethods.printf。

そのため、最初の例を次のように書き直します。

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 {}

}

次のコンソール出力が得られます。

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

しかし、もっと重要なことは、Groovyがこれらの4つのブロックを次のように単一のブロックにコンパイルするため、フィールドの初期化時間をログに記録しないことです。

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;
}

この時点でGroovyクラスをロードする必要がないため、1回目と2回目の呼び出しの間にラグはありません。