斯波克性能问题
Spock performance problems
我在 Spock 中实施的规范的性能方面存在一些问题 - 我特别是指执行时间。在深入研究这个问题之后,我注意到它与设置规范有某种关系——我并不是指特定的 setup()
方法。
在这个发现之后,我为规范中声明的所有字段添加了 @Shared
注解,它的运行速度比以前快了 2 倍。然后,我想,性能问题可能与 ConcurrentHashMap
或 random*
方法(来自 commons-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
有什么问题吗?如何节省这几百毫秒?
TL;DR
在第一个静态块中调用 println
会初始化与 Groovy 开发工具包相关的大约 30k+ 个对象。至少需要 50 毫秒才能完成,具体取决于我们 运行 本次测试所用笔记本电脑的马力。
详情
我无法重现数百毫秒级别的延迟,但我能够获得 30 到 80 毫秒之间的延迟。让我们从我在重现您的用例的本地测试中使用的 class 开始。
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 中创建超过 30k 的对象。现在,让我们跨过第二行到第三行,看看会发生什么:
只创建了几个对象。
这个例子表明添加
static {
println(System.currentTimeMillis())
}
给测试设置增加了意外的复杂性,它没有显示两个 class 方法的初始化之间存在滞后,但它造成了这种滞后。但是,初始化所有 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 毫秒(非静态编译)减少到大约 227 毫秒。此外,必须初始化的对象数量也显着减少。如果我 运行 与上面显示的最后一个相同的调试器场景添加了 @CompileStatic
,我将得到如下内容:
它仍然很重要,但我们看到初始化为调用 println
方法的对象数量减少了。
最后一件事值得一提。当我们使用静态编译并且我们希望避免调用 class 静态块中的 Groovy 方法来打印一些输出时,我们可以使用以下组合:
System.out.println(String.format("...", args))
因为 Groovy 正是执行此操作。另一方面,Groovy 中的以下代码:
System.out.printf("...", args)
可能看起来与上一个类似,但它被编译成这样(启用静态编译):
DefaultGroovyMethods.printf(System.out, "...", args)
第二种情况在class静态块中使用时会慢很多,因为此时Groovyjar还没有加载,classloader必须解析DefaultGroovyMethods
class 来自 JAR 文件。当 Spock 执行测试方法时,如果您使用 System.out.println
或 DefaultGroovyMethods.printf
并没有太大区别,因为 Groovy classes 已经加载。
这就是为什么如果我们将您的初始示例重写为如下内容:
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 classes。
我在 Spock 中实施的规范的性能方面存在一些问题 - 我特别是指执行时间。在深入研究这个问题之后,我注意到它与设置规范有某种关系——我并不是指特定的 setup()
方法。
在这个发现之后,我为规范中声明的所有字段添加了 @Shared
注解,它的运行速度比以前快了 2 倍。然后,我想,性能问题可能与 ConcurrentHashMap
或 random*
方法(来自 commons-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
有什么问题吗?如何节省这几百毫秒?
TL;DR
在第一个静态块中调用 println
会初始化与 Groovy 开发工具包相关的大约 30k+ 个对象。至少需要 50 毫秒才能完成,具体取决于我们 运行 本次测试所用笔记本电脑的马力。
详情
我无法重现数百毫秒级别的延迟,但我能够获得 30 到 80 毫秒之间的延迟。让我们从我在重现您的用例的本地测试中使用的 class 开始。
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 中创建超过 30k 的对象。现在,让我们跨过第二行到第三行,看看会发生什么:
只创建了几个对象。
这个例子表明添加
static {
println(System.currentTimeMillis())
}
给测试设置增加了意外的复杂性,它没有显示两个 class 方法的初始化之间存在滞后,但它造成了这种滞后。但是,初始化所有 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 毫秒(非静态编译)减少到大约 227 毫秒。此外,必须初始化的对象数量也显着减少。如果我 运行 与上面显示的最后一个相同的调试器场景添加了 @CompileStatic
,我将得到如下内容:
它仍然很重要,但我们看到初始化为调用 println
方法的对象数量减少了。
最后一件事值得一提。当我们使用静态编译并且我们希望避免调用 class 静态块中的 Groovy 方法来打印一些输出时,我们可以使用以下组合:
System.out.println(String.format("...", args))
因为 Groovy 正是执行此操作。另一方面,Groovy 中的以下代码:
System.out.printf("...", args)
可能看起来与上一个类似,但它被编译成这样(启用静态编译):
DefaultGroovyMethods.printf(System.out, "...", args)
第二种情况在class静态块中使用时会慢很多,因为此时Groovyjar还没有加载,classloader必须解析DefaultGroovyMethods
class 来自 JAR 文件。当 Spock 执行测试方法时,如果您使用 System.out.println
或 DefaultGroovyMethods.printf
并没有太大区别,因为 Groovy classes 已经加载。
这就是为什么如果我们将您的初始示例重写为如下内容:
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 classes。