微基准测试框架JMH实践

JMH(Java Microbenchmark Harness),作为Java中一款优秀的微基准测试框架。其可以很方便地进行方法级的基准测试,便于开发者更好的测试、验证方法的性能

abstract.png

依赖

JMH的POM依赖如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
<dependencies>

<!--基准测试: JMH-->
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-core</artifactId>
<version>1.19</version>
</dependency>
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-generator-annprocess</artifactId>
<version>1.19</version>
</dependency>

</dependencies>

实践

事实上对于JMH而言,其还是很容易上手的。下面通过两个例子来帮助大家快速入门上手

Demo1

这里通过一个Demo来入门JMH的基本使用,示例程序如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
@BenchmarkMode( Mode.AverageTime )
@OutputTimeUnit( TimeUnit.SECONDS )
@Fork(1)
// 预热次数、时长/次
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
// 测试次数、时长/次
@Measurement(iterations = 6,time = 2, timeUnit = TimeUnit.SECONDS)
public class Demo1 {

public static void main(String[] args) throws RunnerException {
Options options = new OptionsBuilder()
.include( Demo1.class.getName() )
.build();

new Runner(options).run();
}

@Benchmark
public void helloWorld() throws Exception {
Thread.sleep(700);
}

}

其中,涉及到的相关注解说明如下

  • @BenchmarkMode:指定基准测试的模式。具体地有
    1. AverageTime:方法调用的平均时间
    2. Throughput:吞吐量模式,即每秒调用的次数
    3. SampleTime:采样模式,即方法调用的耗时分布
    4. SingleShotTime:上述模式在一次Iteration的时间内会调用方法。而在该模式中一次Iteration仅会调用一次方法。与此同时也会将Warmup预热次数设为0,用于测试方法冷启动时的耗时
    5. All:其会分别使用上述四种模式进行测试
  • @Warmup, @Measurement:设置预热、测试的次数及每次的持续时间
  • @Benchmark:标识这是一个需要测试的方法

测试结果如下所示,helloWorld方法平均耗时703ms,可以看到测试结果与我们在helloWorld中的700ms延时基本吻合

figure 1.jpeg

对于Throughput吞吐量模式而言,其测试的是1秒内方法平均调用次数。显然其与AverageTime平均时间模式而言,是如出一辙的。故这里就不进行赘述了。这里重点对于SampleTime采样模式的输出结果进行介绍,示例如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
// 测试信息

# JMH version: 1.19
# VM version: JDK 1.8.0_251, VM 25.251-b08
...
# Measurement: 6 iterations, 2 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Sampling time
# Benchmark: com.aaron.JMH.Demo1.helloWorld

// 预热、测试 过程

# Run progress: 0.00% complete, ETA 00:00:17
# Fork: 1 of 1
# Warmup Iteration 1: 0.701 s/op
# Warmup Iteration 2: 0.704 s/op
# Warmup Iteration 3: 0.703 s/op
# Warmup Iteration 4: 0.703 s/op
# Warmup Iteration 5: 0.705 s/op

Iteration 1: 0.702 ±(99.9%) 0.022 s/op

// 方法调用耗时,第X百分位数

helloWorld·p0.00: 0.700 s/op
helloWorld·p0.50: 0.703 s/op
helloWorld·p0.90: 0.703 s/op
helloWorld·p0.95: 0.703 s/op
helloWorld·p0.99: 0.703 s/op
helloWorld·p0.999: 0.703 s/op
helloWorld·p0.9999: 0.703 s/op
helloWorld·p1.00: 0.703 s/op

...

Iteration 6: 0.703 ±(99.9%) 0.011 s/op
helloWorld·p0.00: 0.703 s/op
helloWorld·p0.50: 0.704 s/op
helloWorld·p0.90: 0.704 s/op
helloWorld·p0.95: 0.704 s/op
helloWorld·p0.99: 0.704 s/op
helloWorld·p0.999: 0.704 s/op
helloWorld·p0.9999: 0.704 s/op
helloWorld·p1.00: 0.704 s/op


// 测试结果

Result "com.aaron.JMH.Demo1.helloWorld":

// 直方图

N = 18
mean = 0.702 ±(99.9%) 0.001 s/op

Histogram, s/op:
[0.700, 0.700) = 0
[0.700, 0.701) = 4
[0.701, 0.701) = 0
[0.701, 0.701) = 0
[0.701, 0.701) = 0
[0.701, 0.702) = 1
[0.702, 0.702) = 0
[0.702, 0.702) = 0
[0.702, 0.702) = 0
[0.702, 0.703) = 0
[0.703, 0.703) = 7
[0.703, 0.703) = 0
[0.703, 0.703) = 0
[0.703, 0.704) = 0
[0.704, 0.704) = 6

// 百分位数

Percentiles, s/op:
p(0.0000) = 0.700 s/op
p(50.0000) = 0.703 s/op
p(90.0000) = 0.704 s/op
p(95.0000) = 0.704 s/op
p(99.0000) = 0.704 s/op
p(99.9000) = 0.704 s/op
p(99.9900) = 0.704 s/op
p(99.9990) = 0.704 s/op
p(99.9999) = 0.704 s/op
p(100.0000) = 0.704 s/op


# Run complete. Total time: 00:00:20

// 测试结论

Benchmark Mode Cnt Score Error Units
JMH.Demo1.helloWorld sample 18 0.702 ± 0.001 s/op
JMH.Demo1.helloWorld:helloWorld·p0.00 sample 0.700 s/op
JMH.Demo1.helloWorld:helloWorld·p0.50 sample 0.703 s/op
JMH.Demo1.helloWorld:helloWorld·p0.90 sample 0.704 s/op
JMH.Demo1.helloWorld:helloWorld·p0.95 sample 0.704 s/op
JMH.Demo1.helloWorld:helloWorld·p0.99 sample 0.704 s/op
JMH.Demo1.helloWorld:helloWorld·p0.999 sample 0.704 s/op
JMH.Demo1.helloWorld:helloWorld·p0.9999 sample 0.704 s/op
JMH.Demo1.helloWorld:helloWorld·p1.00 sample 0.704 s/op

Demo2

现在我们通过SingleShotTime模式测试下方法的冷启动性能。示例代码如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
import org.openjdk.jmh.annotations.Param;

/**
* 冷启动测试
*/
@BenchmarkMode( Mode.SingleShotTime )
@OutputTimeUnit( TimeUnit.SECONDS )
@Fork(1)
// 测试次数
@Measurement(iterations = 1)
@State(Scope.Thread)
public class Demo2 {

public static void main(String[] args) throws RunnerException {
Options options = new OptionsBuilder()
.include( Demo2.class.getName() )
// 可通过output将测试结果写入到文件中
//.output("D:/JmhDemo.log")
.build();

new Runner(options).run();
}

@Param({"2","7"})
private Integer num;

// 每个待测方法测试前执行的方法
@Setup
public void init() {
System.out.println("----------- <init: "+ num +" > -----------");
}

// 每个待测方法测试后执行的方法
@TearDown
public void shutdown() {
System.out.println("----------- <shutdown: "+ num +" > -----------");
}

// 待测方法1
@Benchmark
public void test1() throws Exception {
System.out.println("<test1> : " + num);
}

// 待测方法2
@Benchmark
public void test2() throws Exception {
System.out.println("<test2> : " + num);
}

}

这里我们通过@Param注解实现测试多个不同的参数条件。测试结果的部分内容如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
// 测试过程
# Run progress: 0.00% complete, ETA 00:00:00
# Fork: 1 of 1
Iteration 1: ----------- <init: 2 > -----------
<test1> : 2
----------- <shutdown: 2 > -----------
10⁻⁴ s/op

...

# Run progress: 25.00% complete, ETA 00:00:02
# Fork: 1 of 1
Iteration 1: ----------- <init: 7 > -----------
<test1> : 7
----------- <shutdown: 7 > -----------
10⁻⁴ s/op

...

# Run progress: 50.00% complete, ETA 00:00:01
# Fork: 1 of 1
Iteration 1: ----------- <init: 2 > -----------
<test2> : 2
----------- <shutdown: 2 > -----------
10⁻⁴ s/op

...

# Run progress: 75.00% complete, ETA 00:00:00
# Fork: 1 of 1
Iteration 1: ----------- <init: 7 > -----------
<test2> : 7
----------- <shutdown: 7 > -----------
10⁻⁴ s/op

...

# Run complete. Total time: 00:00:02
// 测试结论
Benchmark (num) Mode Cnt Score Error Units
JMH.Demo2.test1 2 ss ≈ 10⁻⁴ s/op
JMH.Demo2.test1 7 ss ≈ 10⁻⁴ s/op
JMH.Demo2.test2 2 ss ≈ 10⁻⁴ s/op
JMH.Demo2.test2 7 ss ≈ 10⁻⁴ s/op

Note

DCE 死码消除

DCE(Dead code elimination)死码消除,作为编译器中一项常见的优化技术。当我们进行基准测试时,稍有不慎即有可能影响我们的测试结果。下面是一个示例程序,用于测试Math.log方法的性能

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
/**
* 死码消除
*/
@BenchmarkMode( Mode.AverageTime )
@OutputTimeUnit( TimeUnit.NANOSECONDS )
@Fork(1)
// 预热次数、时长/次
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
// 测试次数、时长/次
@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@State(Scope.Thread)
public class DCETest {

public static void main(String[] args) throws RunnerException {
Options options = new OptionsBuilder()
.include( DCETest.class.getName() )
.build();
new Runner(options).run();
}

private double x = Math.PI;

@Benchmark
public void base() {
}

@Benchmark
public void test1() {
Math.log(x);
}

@Benchmark
public double test2() {
return Math.log(x);
}

@Benchmark
public void test3(Blackhole blackhole) {
blackhole.consume( Math.log(x) );
}

}

可以看到,我们使用了三种形式(test1、test2、test3)来进行测试,测试结果如下所示

figure 2.png

可以发现,当我们使用test1的形式进行测试,发现其测试结果明显偏低,几乎等同于一个空方法的耗时。原因就在于我们未显式地使用该计算结果,被检测为死码优化掉了。为了避免该问题一方面我们可以通过return语句来显式的使用,另一方面JMH提供了一个blackhole.consume方法以供对返回结果进行消费来避免发生DCE

常量折叠

所谓常量折叠值得的是,编译器会在编译期间就完成常量间的计算并将结果存储下来,而不再保留常量的计算表达式。对于Java而言,使用final修饰的变量即会在编译期被特殊处理

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
/**
* 常量折叠测试
*/
@BenchmarkMode( Mode.AverageTime )
@OutputTimeUnit( TimeUnit.NANOSECONDS )
@Fork(1)
// 预热次数、时长/次
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
// 测试次数、时长/次
@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@State(Scope.Thread)
public class ConstantTest {
public static void main(String[] args) throws RunnerException {
Options options = new OptionsBuilder()
.include( ConstantTest.class.getName() )
.build();
new Runner(options).run();
}

private double x = Math.PI;

private final double x_final = Math.PI;

@Benchmark
public double base() {
return Math.PI;
}

// Math.PI是final变量,会发生常量折叠
@Benchmark
public double test1() {
return Math.log( Math.PI );
}

// x_final是final变量,会发生常量折叠
@Benchmark
public double test2() {
return Math.log( x_final );
}

@Benchmark
public double test3() {
return Math.log( x );
}

}

测试结果如下所示,可以看到只有test3的测试结果才是可靠的

figure 3.png

0%