Spock性能问题

Question

我在Spock中实现的规范的性能存在一些问题-特别是执行时间。在深入研究问题之后，我注意到它与设置规范有某种联系-我并不是setup()特别指方法。

在发现之后，我将@Shared注释添加到规范中声明的所有字段中，并且注释的运行速度比以前快2倍。于是，我想，那性能问题可能与ConcurrentHashMap或random*方法（从公地lang3），但事实并非如此。

最后，我无奈地用以下方式修饰了规范中的所有字段：

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())
  }

  ...

有趣的是，无论哪个字段被声明为第一个字段，初始化该字段都需要花费数百毫秒的时间：

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

有什么问题？如何节省这几百毫秒？

Answer 1

TL; DR

调用println第一个静态块将初始化约30k +个与Groovy Development Kit相关的对象。最少需要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

我们可以看到两个第一个静态块之间有59毫秒的延迟。这两个块之间的关系无关紧要，因为Groovy编译器将所有这4个静态块合并为一个在纯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"}));
}

因此，这59毫秒的延迟发生在两条第一行之间。让我们在第一行中放置一个断点并运行调试器。

让我们越过这一行到下一行，看看会发生什么：

我们可以看到，调用Groovy println("${System.currentTimeMillis()} - start")导致在JVM中创建了超过3万个对象。现在，让我们越过第二行到第三行，看看会发生什么：

仅创建了几个对象。

这个例子说明

static {
    println(System.currentTimeMillis())
}

在测试设置中增加了意外的复杂性，并且没有显示两个类方法的初始化之间存在时滞，但是却造成了这种时滞。但是，初始化所有与Groovy相关的对象的成本是我们无法完全避免的，必须在某个地方支付。例如，如果我们将测试简化为以下形式：

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

然后在第一个println语句中放置一个断点，然后转到下一个语句，我们将看到以下内容：

它仍然创建了数千个对象，但是比第一个示例少得多，因为我们在第一个示例中看到的大多数对象都是在Spock执行第一个方法之前创建的。

Spock超频测试性能

我们可以做的第一件事就是使用静态编译。在我的简单测试中，它的执行时间从300 ms（非静态编译）减少到大约227 ms。同样，必须初始化的对象数量也大大减少了。如果我运行与上面显示的最后一个相同的调试器场景，并@CompileStatic添加了它，那么我将得到类似以下内容：

它仍然非常重要，但是我们看到初始化为调用println方法的对象数量有所减少。

最后一件事值得一提。当我们使用静态编译时，我们希望避免在类static块中调用Groovy方法来打印一些输出，我们可以使用以下组合：

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

因为Groovy正是执行此操作。另一方面，Groovy中的以下代码：

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

可能看起来与上一个类似，但是它被编译为如下所示（启用了静态编译）：

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

第二种情况在类静态块中使用时会慢得多，因为此时Groovy jar尚未加载，并且类加载器必须DefaultGroovyMethods从JAR文件解析类。当Spock执行测试方法时，如果使用System.out.println或并没有多大区别DefaultGroovyMethods.printf，因为Groovy类已经加载。

这就是为什么如果我们将您的初始示例重写为以下内容：

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类。