使用JMH做Java微基准测试
一、什么是 JMH
二、为什么要使用 JMH
三、JMH基本参数概念
一、什么是 JMH
JMH 是 Java Microbenchmark Harness 的缩写。中文意思大致是 “JAVA 微基准测试套件”。官网:http://openjdk.java.net/projects/code-tools/jmh/
首先先明白什么是“基准测试”。百度百科给的定义如下:
基准测试是指通过设计科学的测试方法、测试工具和测试系统,实现对一类测试对象的某项性能指标进行定量的和可对比的测试。
可以简单的类比成我们电脑常用的鲁大师,或者手机常用的跑分软件安兔兔之类的性能检测软件。都是按一定的基准或者在特定条件下去测试某一对象的的性能,比如显卡、IO、CPU之类的。
二、为什么要使用 JMH
基准测试的特质有如下几种:
①、可重复性:可进行重复性的测试,这样做有利于比较每次的测试结果,得到性能结果的长期变化趋势,为系统调优和上线前的容量规划做参考。
②、可观测性:通过全方位的监控(包括测试开始到结束,执行机、服务器、数据库),及时了解和分析测试过程发生了什么。
③、可展示性:相关人员可以直观明了的了解测试结果(web界面、仪表盘、折线图树状图等形式)。
④、真实性:测试的结果反映了客户体验到的真实的情况(真实准确的业务场景+与生产一致的配置+合理正确的测试方法)。
⑤、可执行性:相关人员可以快速的进行测试验证修改调优(可定位可分析)。
可见要做一次符合特质的基准测试,是很繁琐也很困难的。外界因素很容易影响到最终的测试结果。特别对于 JAVA的基准测试。
有些文章会告诉我们 JAVA是 C++编写的,一般来说 JAVA编写的程序不太可能比 C++编写的代码运行效率更好。但是JAVA在某些场景的确要比 C++运行的更高效。不要觉得天方夜谭。其实 JVM随着这些年的发展已经变得很智能,它会在运行期间不断的去优化。
这对于我们程序来说是好事,但是对于性能测试就头疼的。你运行的次数与时间不同可能获得的结果也不同,很难获得一个比较稳定的结果。对于这种情况,有一个解决办法就是大量的重复调用,并且在真正测试前还要进行一定的预热,使结果尽可能的准确。
除了这些,对于结果我们还需要一个很好的展示,可以让我们通过这些展示结果判断性能的好坏。
在使用Java编程过程中,我们对于一些代码调用的细节有多种编写方式,但是不确定它们性能时,往往采用重复多次计数的方式来解决。但是随着JVM不断的进化,随着代码执行次数的增加,JVM会不断的进行编译优化,使得重复多少次才能够得到一个稳定的测试结果变得让人疑惑,这时候有经验的同学就会在测试执行前先循环上万次并注释为预热。
没错!这样做确实可以获得一个偏向正确的测试结果,但是我们试想如果每到需要斟酌性能的时候,都要根据场景写一段预热的逻辑吗?当预热完成后,需要多少次迭代来进行正式内容的测量呢?每次测试结果的输出报告是不是都需要用System.out
来输出呢?
其实这些工作都可以交给 JMH (the Java Microbenchmark Harness) ,它被作为Java9的一部分来发布,但是我们完全不需要等待Java9,而可以方便的使用它来简化我们测试,它能够照看好JVM的预热、代码优化,让你的测试过程变得更加简单。
三、JMH基本参数概念
3.1 Mode 表示 JMH 进行 Benchmark 时所使用的模式
Mode 表示 JMH 进行 Benchmark 时所使用的模式。通常是测量的维度不同,或是测量的方式不同。目前 JMH 共有四种模式:
- Throughput: 整体吞吐量,例如“1秒内可以执行多少次调用”。
- AverageTime: 调用的平均时间,例如“每次调用平均耗时xxx毫秒”。
- SampleTime: 随机取样,最后输出取样结果的分布,例如“99%的调用在xxx毫秒以内,99.99%的调用在xxx毫秒以内”
- SingleShotTime: 以上模式都是默认一次 iteration 是 1s,唯有 SingleShotTime 是只运行一次。往往同时把 warmup 次数设为0,用于测试冷启动时的性能。
3.2 Iteration JMH 进行测试的最小单位
Iteration 是 JMH 进行测试的最小单位。在大部分模式下,一次 iteration 代表的是一秒,JMH 会在这一秒内不断调用需要 benchmark 的方法,然后根据模式对其采样,计算吞吐量,计算平均执行时间等。
3.3 Warmup 实际进行 benchmark 前先进行预热的行为
Warmup 是指在实际进行 benchmark 前先进行预热的行为。为什么需要预热?因为 JVM 的 JIT 机制的存在,如果某个函数被调用多次之后,JVM 会尝试将其编译成为机器码从而提高执行速度。为了让 benchmark 的结果更加接近真实情况就需要进行预热。
示例:
@BenchmarkMode({Mode.Throughput, Mode.AverageTime}) // 测试方法平均执行时间 @OutputTimeUnit(TimeUnit.SECONDS) // 输出结果的时间粒度为微秒 @State(Scope.Thread) // 每个测试线程一个实例 public class SimpleBenchmark { @Benchmark public void bench() { add(1, 1); } private static int add(int a, int b) { return a + b; } @Benchmark public String stringConcat() { String a = "a"; String b = "b"; String c = "c"; return a + b + c; } public static void main(String[] args) throws RunnerException { Options options = new OptionsBuilder() .include(SimpleBenchmark.class.getSimpleName()) //代表我要测试的是哪个类的方法 .exclude("stringConcat") //代表测试的时候需要排除stringConcat方法 .forks(2) //指的是做2轮测试,在一轮测试无法得出最满意的结果时,可以多测几轮以便得出更全面的测试结果,而每一轮都是先预热,再正式计量。 .warmupIterations(5) //代表先预热5次 .measurementIterations(5) //正式运行测试5次 .build(); new Runner(options).run(); } }
四、注解与选项
4.1 @BenchmarkMode
对应Mode选项,可用于类或者方法上, 需要注意的是,这个注解的value是一个数组,可以把几种Mode集合在一起执行,还可以设置为Mode.All,即全部执行一遍。
4.2 @State
类注解,JMH测试类必须使用@State注解,State定义了一个类实例的生命周期,可以类比Spring Bean的Scope。由于JMH允许多线程同时执行测试,不同的选项含义如下:
- Scope.Thread:默认的State,每个测试线程分配一个实例;
- Scope.Benchmark:所有测试线程共享一个实例,用于测试有状态实例在多线程共享下的性能;
- Scope.Group:每个线程组共享一个实例;
4.3 @OutputTimeUnit
benchmark 结果所使用的时间单位,可用于类或者方法注解,使用java.util.concurrent.TimeUnit中的标准时间单位。
4.4 @Benchmark
方法注解,表示该方法是需要进行 benchmark 的对象。
4.5 @Setup
方法注解,会在执行 benchmark 之前被执行,正如其名,主要用于初始化。
4.6 @TearDown
方法注解,与@Setup 相对的,会在所有 benchmark 执行结束以后执行,主要用于资源的回收等。
4.7 @Param
成员注解,可以用来指定某项参数的多种情况。特别适合用来测试一个函数在不同的参数输入的情况下的性能。@Param注解接收一个String数组,在@setup方法执行前转化为为对应的数据类型。多个@Param注解的成员之间是乘积关系,譬如有两个用@Param注解的字段,第一个有5个值,第二个字段有2个值,那么每个测试方法会跑5*2=10次。
五、示例
首先在项目中新增依赖,jmh-core
以及jmh-generator-annprocess
的依赖可以在maven仓库中找寻最新版本。
<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>
创建一个Helloworld
类,里面只有一个空方法m()
,标注了@Benchmark
的注解,声明这个方法为一个微基准测试方法,JMH 会在编译期生成基准测试的代码,并运行它。
public class Helloworld {
@Benchmark
public void m() {
}
}
接着添加一个main入口,由它来启动测试。
public class HelloworldRunner {
public static void main(String[] args) throws RunnerException {
Options opt = new OptionsBuilder()
.include("Helloworld")
.exclude("Pref")
.warmupIterations(10)
.measurementIterations(10)
.forks(3)
.build();
new Runner(opt).run();
}
}
简单介绍一下这个HelloworldRunner
,它是一个入口的同时还完成了 JMH 测试的配置工作。默认场景下,JMH 会找寻标注了@Benchmark
类型的方法,可能会跑一些你所不需要的测试,这样就需要通过include
和exclude
两个方法来完成包含以及排除的语义。
warmupIterations(10)
的意思是预热做10轮,measurementIterations(10)
代表正式计量测试做10轮,而每次都是先执行完预热再执行正式计量,内容都是调用标注了@Benchmark
的代码。
forks(3)
指的是做3轮测试,因为一次测试无法有效的代表结果,所以通过3轮测试较为全面的测试,而每一轮都是先预热,再正式计量。
我们运行HelloworldRunner
,经过一段时间,测试结果如下:
Result "com.alibaba.microbenchmark.test.Helloworld.m":
3084697483.521 ±(99.9%) 27096926.646 ops/s [Average]
(min, avg, max) = (2951123277.601, 3084697483.521, 3121456015.904), stdev = 40557407.239
CI (99.9%): [3057600556.875, 3111794410.166] (assumes normal distribution)
# Run complete. Total time: 00:01:02
Benchmark Mode Cnt Score Error Units
Helloworld.m thrpt 30 3084697483.521 ± 27096926.646 ops/s
可以看到分数是30亿次,但是这30亿指的是什么呢?仔细观察 Mode 一项中类型是thrpt
,其实就是Throughput
吞吐量,代表着每秒完成的次数。
测试类型
前面提到测试的类型是吞吐量,也就是一秒钟调用完成的次数,但是如果想知道做一次需要多少时间该怎么办?
其实 1 / 吞吐量 就是这个值
JMH 提供了以下几种类型进行支持:
类型 | 描述 |
---|---|
Throughput | 每段时间执行的次数,一般是秒 |
AverageTime | 平均时间,每次操作的平均耗时 |
SampleTime | 在测试中,随机进行采样执行的时间 |
SingleShotTime | 在每次执行中计算耗时 |
All | 顾名思义,所有模式,这个在内部测试中常用 |
使用这些模式也非常简单,只需要增加@BenchmarkMode
注解即可,例如:
@Benchmark
@BenchmarkMode({Mode.Throughput, Mode.SingleShotTime})
public void m() {
}
配置策略
JMH 支持通过@Fork
注解完成配置,例如:
@Benchmark
@Fork(value = 1, warmups = 2)
@BenchmarkMode(Mode.Throughput)
public void init() {
}
以上注解指init()
方法测试时,预热2轮,正式计量1轮,但是如果测试方法比较多,还是建议通过Options
进行配置,具体可以参考HelloworldRunner
。
数据准备
开始测试前,往往有数据准备的需求,比如:初始化一个变量或者一批数据,可以通过构造函数进行初始化,不过 JMH 提供了一些手段帮助我们完成这个工作。
@State(Scope.Benchmark)
public class Helloworld {
private long i;
@Setup
public void init() {
i = System.currentTimeMillis();
}
}
上面的例子中,初始化了成员变量i
,JMH 会保证在构造Helloworld
后调用init()
方法。@State(Scope.Benchmark)
是修饰成员变量作用域是整个测试,能够被整个测试过程可见。
实现策略
JMH 是通过什么手段来完成测试的呢?预热我们可以通过循环去做,大概1-2万次左右的调用已经足够让代码优化,测试过程我们就通过System.currentTimeMillis()
看一下耗时不就行了?
这个问题先放一下,我们看一下 JMH 是如何驱动你的测试的。当我们运行 JMH 基准测试时,它会生成一些Java代码,通常会通过继承你的测试来完成,比如你的测试类型是A
,测试方法m()
,它会自动生成A_jmhType_B1
、A_jmhType_B2
、A_jmhType_B3
和A_jmhType
以及最终的测试执行逻辑A_m_jmhTest
。生成代码的一般在classes
目录下,看一下生成的类型信息:
public class Helloworld_jmhType_B1 extends com.alibaba.microbenchmark.test.Helloworld {
boolean p000, p001, p002, p003, p004, p005, p006, p007, p008, p009, p010, p011, p012, p013, p014, p015;
boolean p240, p241, p242, p243, p244, p245, p246, p247, p248, p249, p250, p251, p252, p253, p254, p255;
}
可以看到类型中定义了256个boolean,这理论是在做cache line padding,可以猜测 JMH 是想避免CPU缓存对测试过程带来的影响。
public BenchmarkTaskResult m_Throughput(InfraControl control, ThreadParams threadParams) throws Throwable {
Helloworld_jmhType l_helloworld0_G = _jmh_tryInit_f_helloworld0_G(control);
control.preSetup();
control.announceWarmupReady();
while (control.warmupShouldWait) {
l_helloworld0_G.m();
res.allOps++;
}
m_thrpt_jmhStub(control, res, benchmarkParams, iterationParams, threadParams, blackhole, notifyControl, startRndMask, l_helloworld0_G);
}
在最终的测试逻辑代码Helloworld_m_jmhTest
中对吞吐量的测试,首先获取了针对Helloworld
生成的子类,然后调用Setup,接下来预热,最后进行正式计量。
通过介绍 JMH 的测试过程,就可以回答之前的问题,因为 JMH 全面的考虑的性能测试中环境的影响,所以测试更加的客观。
示例1:循环的微基准测试
for
循环大家平时经常使用,但是看到过一个优化策略,就是倒序遍历,比如:for (int i = length; i > 0; i--)
优于for (int i = 0; i < length; i++)
,有些不解。咨询了温少,温少给出的答案是i > 0
优于i < length
,因此倒序有优势,那么我们将这个场景做一下基准测试。
首先是正向循环,次数是1百万次迭代。
public class CountPerf {
@Benchmark
@BenchmarkMode(Mode.Throughput)
public void count() {
for (int i = 0; i < 1_000_000; i++) {
}
}
}
接着是逆向循环,次数也是1百万次。
public class CountPerf {
@Benchmark
@BenchmarkMode(Mode.Throughput)
public void count() {
for (int i = 1_000_000; i > 0; i--) {
}
}
}
最后是一个测试的入口,我们采用3组,每组预热10轮,正式计量10轮,测试类型是吞吐量。
public class BenchmarkRunner {
public static void main(String[] args) throws RunnerException {
Options opt = new OptionsBuilder()
.include("Perf")
.exclude("Helloworld")
.warmupIterations(10)
.measurementIterations(10)
.forks(3)
.build();
new Runner(opt).run();
}
}
测试结果如下,有数据表现可以看到逆序在宏观上是优于正序的。
Result "com.alibaba.microbenchmark.forward.CountPerf.count":
3017436523.994 ±(99.9%) 74706077.393 ops/s [Average]
(min, avg, max) = (2586477493.002, 3017436523.994, 3090537220.013), stdev = 111816548.191
CI (99.9%): [2942730446.601, 3092142601.387] (assumes normal distribution)
# Run complete. Total time: 00:02:05
Benchmark Mode Cnt Score Error Units
c.a.m.backward.CountPerf.count thrpt 30 3070589161.097 ± 30858669.885 ops/s
c.a.m.forward.CountPerf.count thrpt 30 3017436523.994 ± 74706077.393 ops/s
示例2:Calendar和dateTime对比的基准测试
测试结果表明:
runCalendar方法平均运行时间为:619微秒
runJoda方法的平均运行时间为:34微秒
据用例测试结果可以看到,Calendar(非线程安全)在高并发情况下性能远远比不上dateTime(线程安全)。对代码性能和安全性要求比较高的可以放弃使用Calendar和SimpleDateFormat(底层实现是Calendar),转而使用joda-time
示例3:几种字符串拼接方法的基准测试
package com.dxz.statement; import org.openjdk.jmh.annotations.Benchmark; import org.openjdk.jmh.annotations.Mode; import org.openjdk.jmh.runner.Runner; import org.openjdk.jmh.runner.RunnerException; import org.openjdk.jmh.runner.options.Options; import org.openjdk.jmh.runner.options.OptionsBuilder; public class StringConnectBenchmark { /** * 字符串拼接之 StringBuilder 基准测试 */ @Benchmark public void testStringBuilder() { print(new StringBuilder().append(1).append(2).append(3).toString()); } /** * 字符串拼接之直接相加基准测试 */ @Benchmark public void testStringAdd() { print(new String()+ 1 + 2 + 3); } /** * 字符串拼接之String Concat基准测试 */ @Benchmark public void testStringConcat() { print(new String().concat("1").concat("2").concat("3")); } /** * 字符串拼接之 StringBuffer 基准测试 */ @Benchmark public void testStringBuffer() { print(new StringBuffer().append(1).append(2).append(3).toString()); } /** * 字符串拼接之 StringFormat 基准测试 */ @Benchmark public void testStringFormat(){ print(String.format("%s%s%s", 1, 2, 3)); } public void print(String str) { } public static void main( String[] args ) throws RunnerException { Options opt = new OptionsBuilder() // 导入要测试的类 .include(StringConnectBenchmark.class.getSimpleName()) // 预热5轮 .warmupIterations(5) // 度量10轮 .measurementIterations(10) .mode(Mode.Throughput) .forks(3) .build(); new Runner(opt).run(); } }
结果:
C:\java\jdk1.8.0_111\bin\java.exe -Dfile.encoding=UTF-8 -classpath D:\study\jmh\benchmark-demo\target\classes;C:\Users\4cv748wpd3\.m2\repository\org\openjdk\jmh\jmh-core\1.25\jmh-core-1.25.jar;C:\Users\4cv748wpd3\.m2\repository\net\sf\jopt-simple\jopt-simple\4.6\jopt-simple-4.6.jar;C:\Users\4cv748wpd3\.m2\repository\org\apache\commons\commons-math3\3.2\commons-math3-3.2.jar;C:\Users\4cv748wpd3\.m2\repository\junit\junit\4.11\junit-4.11.jar;C:\Users\4cv748wpd3\.m2\repository\org\hamcrest\hamcrest-core\1.3\hamcrest-core-1.3.jar org.openjdk.jmh.Main com.dxz.statement.StringConnectBenchmark.* # JMH version: 1.25 # VM version: JDK 1.8.0_111, Java HotSpot(TM) 64-Bit Server VM, 25.111-b14 # VM invoker: C:\java\jdk1.8.0_111\jre\bin\java.exe # VM options: -Dfile.encoding=UTF-8 # Warmup: 5 iterations, 10 s each # Measurement: 5 iterations, 10 s each # Timeout: 10 min per iteration # Threads: 1 thread, will synchronize iterations # Benchmark mode: Throughput, ops/time # Benchmark: com.dxz.statement.StringConnectBenchmark.testStringAdd # Run progress: 0.00% complete, ETA 00:41:40 # Fork: 1 of 5 # Warmup Iteration 1: 62711684.234 ops/s # Warmup Iteration 2: 59618263.486 ops/s # Warmup Iteration 3: 60014649.317 ops/s # Warmup Iteration 4: 58772171.747 ops/s # Warmup Iteration 5: 58594536.979 ops/s Iteration 1: 58630801.253 ops/s Iteration 2: 58780478.004 ops/s Iteration 3: 58575508.000 ops/s Iteration 4: 59559551.638 ops/s Iteration 5: 59933436.541 ops/s # Run progress: 4.00% complete, ETA 00:40:31 # Fork: 2 of 5 # Warmup Iteration 1: 63815375.015 ops/s # Warmup Iteration 2: 58233477.740 ops/s # Warmup Iteration 3: 58908018.337 ops/s # Warmup Iteration 4: 59638642.706 ops/s # Warmup Iteration 5: 59701753.260 ops/s Iteration 1: 59709525.618 ops/s Iteration 2: 59554418.319 ops/s Iteration 3: 58450779.960 ops/s Iteration 4: 59180593.377 ops/s Iteration 5: 58853053.925 ops/s # Run progress: 8.00% complete, ETA 00:38:44 # Fork: 3 of 5 # Warmup Iteration 1: 64293022.011 ops/s # Warmup Iteration 2: 60090959.287 ops/s # Warmup Iteration 3: 60034240.399 ops/s # Warmup Iteration 4: 60895232.124 ops/s # Warmup Iteration 5: 60827419.501 ops/s Iteration 1: 59449542.357 ops/s Iteration 2: 60924678.198 ops/s Iteration 3: 62238255.902 ops/s Iteration 4: 61680741.515 ops/s Iteration 5: 61810312.038 ops/s # Run progress: 12.00% complete, ETA 00:37:02 # Fork: 4 of 5 # Warmup Iteration 1: 68553455.562 ops/s # Warmup Iteration 2: 61910316.563 ops/s # Warmup Iteration 3: 61973790.977 ops/s # Warmup Iteration 4: 62281899.906 ops/s # Warmup Iteration 5: 62115501.853 ops/s Iteration 1: 62004965.525 ops/s Iteration 2: 62046250.011 ops/s Iteration 3: 61754344.586 ops/s Iteration 4: 61949834.153 ops/s Iteration 5: 63307326.964 ops/s # Run progress: 16.00% complete, ETA 00:35:20 # Fork: 5 of 5 # Warmup Iteration 1: 71107679.386 ops/s # Warmup Iteration 2: 63820558.845 ops/s # Warmup Iteration 3: 63755676.303 ops/s # Warmup Iteration 4: 63053974.144 ops/s # Warmup Iteration 5: 62371607.324 ops/s Iteration 1: 62693680.023 ops/s Iteration 2: 62362935.112 ops/s Iteration 3: 62421022.355 ops/s Iteration 4: 62883599.548 ops/s Iteration 5: 62168159.990 ops/s Result "com.dxz.statement.StringConnectBenchmark.testStringAdd": 60836951.796 ±(99.9%) 1211324.257 ops/s [Average] (min, avg, max) = (58450779.960, 60836951.796, 63307326.964), stdev = 1617083.227 CI (99.9%): [59625627.539, 62048276.054] (assumes normal distribution) # JMH version: 1.25 # VM version: JDK 1.8.0_111, Java HotSpot(TM) 64-Bit Server VM, 25.111-b14 # VM invoker: C:\java\jdk1.8.0_111\jre\bin\java.exe # VM options: -Dfile.encoding=UTF-8 # Warmup: 5 iterations, 10 s each # Measurement: 5 iterations, 10 s each # Timeout: 10 min per iteration # Threads: 1 thread, will synchronize iterations # Benchmark mode: Throughput, ops/time # Benchmark: com.dxz.statement.StringConnectBenchmark.testStringBuffer # Run progress: 20.00% complete, ETA 00:33:38 # Fork: 1 of 5 # Warmup Iteration 1: 100471666.063 ops/s # Warmup Iteration 2: 104535538.373 ops/s # Warmup Iteration 3: 116332675.750 ops/s # Warmup Iteration 4: 116390206.782 ops/s # Warmup Iteration 5: 116769975.834 ops/s Iteration 1: 110281272.718 ops/s Iteration 2: 114689728.881 ops/s Iteration 3: 115952778.447 ops/s Iteration 4: 116395212.520 ops/s Iteration 5: 116039051.418 ops/s # Run progress: 24.00% complete, ETA 00:31:57 # Fork: 2 of 5 # Warmup Iteration 1: 101156087.693 ops/s # Warmup Iteration 2: 104658890.600 ops/s # Warmup Iteration 3: 116158367.822 ops/s # Warmup Iteration 4: 116282230.116 ops/s # Warmup Iteration 5: 114769777.817 ops/s Iteration 1: 115240363.781 ops/s Iteration 2: 114653428.687 ops/s Iteration 3: 114734766.990 ops/s Iteration 4: 114403912.320 ops/s Iteration 5: 116160502.755 ops/s # Run progress: 28.00% complete, ETA 00:30:16 # Fork: 3 of 5 # Warmup Iteration 1: 103517357.282 ops/s # Warmup Iteration 2: 107610389.229 ops/s # Warmup Iteration 3: 116603060.598 ops/s # Warmup Iteration 4: 116511257.752 ops/s # Warmup Iteration 5: 116460595.600 ops/s Iteration 1: 116461474.029 ops/s Iteration 2: 116189113.610 ops/s Iteration 3: 116781421.188 ops/s Iteration 4: 115767863.167 ops/s Iteration 5: 115127246.617 ops/s # Run progress: 32.00% complete, ETA 00:28:35 # Fork: 4 of 5 # Warmup Iteration 1: 105483122.724 ops/s # Warmup Iteration 2: 109492677.923 ops/s # Warmup Iteration 3: 117970020.734 ops/s # Warmup Iteration 4: 117696362.725 ops/s # Warmup Iteration 5: 112629994.219 ops/s Iteration 1: 113387011.351 ops/s Iteration 2: 113538578.911 ops/s Iteration 3: 113357184.935 ops/s Iteration 4: 112381645.060 ops/s Iteration 5: 113089726.147 ops/s # Run progress: 36.00% complete, ETA 00:26:54 # Fork: 5 of 5 # Warmup Iteration 1: 102160077.246 ops/s # Warmup Iteration 2: 106152890.625 ops/s # Warmup Iteration 3: 112648924.920 ops/s # Warmup Iteration 4: 113554549.663 ops/s # Warmup Iteration 5: 111823402.784 ops/s Iteration 1: 111182399.956 ops/s Iteration 2: 111995727.842 ops/s Iteration 3: 114128676.053 ops/s Iteration 4: 117461016.726 ops/s Iteration 5: 117385739.483 ops/s Result "com.dxz.statement.StringConnectBenchmark.testStringBuffer": 114671433.744 ±(99.9%) 1425597.127 ops/s [Average] (min, avg, max) = (110281272.718, 114671433.744, 117461016.726), stdev = 1903131.378 CI (99.9%): [113245836.617, 116097030.870] (assumes normal distribution) # JMH version: 1.25 # VM version: JDK 1.8.0_111, Java HotSpot(TM) 64-Bit Server VM, 25.111-b14 # VM invoker: C:\java\jdk1.8.0_111\jre\bin\java.exe # VM options: -Dfile.encoding=UTF-8 # Warmup: 5 iterations, 10 s each # Measurement: 5 iterations, 10 s each # Timeout: 10 min per iteration # Threads: 1 thread, will synchronize iterations # Benchmark mode: Throughput, ops/time # Benchmark: com.dxz.statement.StringConnectBenchmark.testStringBuilder # Run progress: 40.00% complete, ETA 00:25:13 # Fork: 1 of 5 # Warmup Iteration 1: 105530215.117 ops/s # Warmup Iteration 2: 109521623.130 ops/s # Warmup Iteration 3: 117412751.615 ops/s # Warmup Iteration 4: 117820318.296 ops/s # Warmup Iteration 5: 117311123.685 ops/s Iteration 1: 117693193.275 ops/s Iteration 2: 117603309.277 ops/s Iteration 3: 117464363.937 ops/s Iteration 4: 116837203.388 ops/s Iteration 5: 108363765.743 ops/s # Run progress: 44.00% complete, ETA 00:23:32 # Fork: 2 of 5 # Warmup Iteration 1: 94155684.169 ops/s # Warmup Iteration 2: 97072229.627 ops/s # Warmup Iteration 3: 103404307.612 ops/s # Warmup Iteration 4: 103205644.859 ops/s # Warmup Iteration 5: 102275100.752 ops/s Iteration 1: 99694778.941 ops/s Iteration 2: 103507888.755 ops/s Iteration 3: 103384352.044 ops/s Iteration 4: 101838919.847 ops/s Iteration 5: 102692369.336 ops/s # Run progress: 48.00% complete, ETA 00:21:51 # Fork: 3 of 5 # Warmup Iteration 1: 92892642.256 ops/s # Warmup Iteration 2: 100168144.486 ops/s # Warmup Iteration 3: 106545161.232 ops/s # Warmup Iteration 4: 106326215.672 ops/s # Warmup Iteration 5: 106357036.403 ops/s Iteration 1: 105986648.703 ops/s Iteration 2: 106459899.483 ops/s Iteration 3: 106556973.907 ops/s Iteration 4: 105527219.535 ops/s Iteration 5: 106160558.202 ops/s # Run progress: 52.00% complete, ETA 00:20:10 # Fork: 4 of 5 # Warmup Iteration 1: 95578365.868 ops/s # Warmup Iteration 2: 99776340.139 ops/s # Warmup Iteration 3: 106370340.718 ops/s # Warmup Iteration 4: 106719239.205 ops/s # Warmup Iteration 5: 106951560.960 ops/s Iteration 1: 106611786.221 ops/s Iteration 2: 106306718.276 ops/s Iteration 3: 106426862.975 ops/s Iteration 4: 105824064.135 ops/s Iteration 5: 106770783.507 ops/s # Run progress: 56.00% complete, ETA 00:18:29 # Fork: 5 of 5 # Warmup Iteration 1: 95910707.221 ops/s # Warmup Iteration 2: 100518293.439 ops/s # Warmup Iteration 3: 106795041.731 ops/s # Warmup Iteration 4: 104930286.522 ops/s # Warmup Iteration 5: 102218925.972 ops/s Iteration 1: 103055990.801 ops/s Iteration 2: 103671266.101 ops/s Iteration 3: 102401511.433 ops/s Iteration 4: 102733478.091 ops/s Iteration 5: 103405153.843 ops/s Result "com.dxz.statement.StringConnectBenchmark.testStringBuilder": 106679162.390 ±(99.9%) 3873825.727 ops/s [Average] (min, avg, max) = (99694778.941, 106679162.390, 117693193.275), stdev = 5171446.515 CI (99.9%): [102805336.663, 110552988.118] (assumes normal distribution) # JMH version: 1.25 # VM version: JDK 1.8.0_111, Java HotSpot(TM) 64-Bit Server VM, 25.111-b14 # VM invoker: C:\java\jdk1.8.0_111\jre\bin\java.exe # VM options: -Dfile.encoding=UTF-8 # Warmup: 5 iterations, 10 s each # Measurement: 5 iterations, 10 s each # Timeout: 10 min per iteration # Threads: 1 thread, will synchronize iterations # Benchmark mode: Throughput, ops/time # Benchmark: com.dxz.statement.StringConnectBenchmark.testStringConcat # Run progress: 60.00% complete, ETA 00:16:48 # Fork: 1 of 5 # Warmup Iteration 1: 39047397.305 ops/s # Warmup Iteration 2: 40665559.100 ops/s # Warmup Iteration 3: 41409024.371 ops/s # Warmup Iteration 4: 41571160.597 ops/s # Warmup Iteration 5: 41264604.252 ops/s Iteration 1: 41299338.986 ops/s Iteration 2: 41380579.837 ops/s Iteration 3: 41633458.068 ops/s Iteration 4: 41747399.534 ops/s Iteration 5: 41833640.102 ops/s # Run progress: 64.00% complete, ETA 00:15:07 # Fork: 2 of 5 # Warmup Iteration 1: 39373695.016 ops/s # Warmup Iteration 2: 41146027.330 ops/s # Warmup Iteration 3: 41673738.724 ops/s # Warmup Iteration 4: 41843033.496 ops/s # Warmup Iteration 5: 41800911.168 ops/s Iteration 1: 42010191.865 ops/s Iteration 2: 41822086.542 ops/s Iteration 3: 41970012.060 ops/s Iteration 4: 41777714.465 ops/s Iteration 5: 41855616.418 ops/s # Run progress: 68.00% complete, ETA 00:13:26 # Fork: 3 of 5 # Warmup Iteration 1: 40138092.634 ops/s # Warmup Iteration 2: 41224933.340 ops/s # Warmup Iteration 3: 41747778.396 ops/s # Warmup Iteration 4: 41669514.117 ops/s # Warmup Iteration 5: 41632108.214 ops/s Iteration 1: 41793614.055 ops/s Iteration 2: 41755781.925 ops/s Iteration 3: 41657754.290 ops/s Iteration 4: 41811371.784 ops/s Iteration 5: 41452727.868 ops/s # Run progress: 72.00% complete, ETA 00:11:45 # Fork: 4 of 5 # Warmup Iteration 1: 39303895.148 ops/s # Warmup Iteration 2: 41306221.335 ops/s # Warmup Iteration 3: 41485992.155 ops/s # Warmup Iteration 4: 41826317.168 ops/s # Warmup Iteration 5: 41769239.392 ops/s Iteration 1: 41594017.204 ops/s Iteration 2: 41691229.757 ops/s Iteration 3: 41869145.571 ops/s Iteration 4: 41733935.180 ops/s Iteration 5: 41830238.433 ops/s # Run progress: 76.00% complete, ETA 00:10:05 # Fork: 5 of 5 # Warmup Iteration 1: 40093567.211 ops/s # Warmup Iteration 2: 41125116.267 ops/s # Warmup Iteration 3: 41664834.910 ops/s # Warmup Iteration 4: 41723251.754 ops/s # Warmup Iteration 5: 41596794.033 ops/s Iteration 1: 41796263.846 ops/s Iteration 2: 41347597.552 ops/s Iteration 3: 41674576.043 ops/s Iteration 4: 41645885.337 ops/s Iteration 5: 41651314.433 ops/s Result "com.dxz.statement.StringConnectBenchmark.testStringConcat": 41705419.646 ±(99.9%) 135498.955 ops/s [Average] (min, avg, max) = (41299338.986, 41705419.646, 42010191.865), stdev = 180887.228 CI (99.9%): [41569920.691, 41840918.601] (assumes normal distribution) # JMH version: 1.25 # VM version: JDK 1.8.0_111, Java HotSpot(TM) 64-Bit Server VM, 25.111-b14 # VM invoker: C:\java\jdk1.8.0_111\jre\bin\java.exe # VM options: -Dfile.encoding=UTF-8 # Warmup: 5 iterations, 10 s each # Measurement: 5 iterations, 10 s each # Timeout: 10 min per iteration # Threads: 1 thread, will synchronize iterations # Benchmark mode: Throughput, ops/time # Benchmark: com.dxz.statement.StringConnectBenchmark.testStringFormat # Run progress: 80.00% complete, ETA 00:08:24 # Fork: 1 of 5 # Warmup Iteration 1: 975048.849 ops/s # Warmup Iteration 2: 1005353.182 ops/s # Warmup Iteration 3: 1003633.129 ops/s # Warmup Iteration 4: 1003314.936 ops/s # Warmup Iteration 5: 1005633.422 ops/s Iteration 1: 1004699.196 ops/s Iteration 2: 1000435.363 ops/s Iteration 3: 999416.708 ops/s Iteration 4: 1006986.920 ops/s Iteration 5: 1003941.429 ops/s # Run progress: 84.00% complete, ETA 00:06:43 # Fork: 2 of 5 # Warmup Iteration 1: 945934.002 ops/s # Warmup Iteration 2: 1013994.623 ops/s # Warmup Iteration 3: 1013542.660 ops/s # Warmup Iteration 4: 1014834.973 ops/s # Warmup Iteration 5: 1007721.233 ops/s Iteration 1: 1007100.774 ops/s Iteration 2: 1011266.480 ops/s Iteration 3: 1012228.131 ops/s Iteration 4: 1012071.849 ops/s Iteration 5: 1010444.976 ops/s # Run progress: 88.00% complete, ETA 00:05:02 # Fork: 3 of 5 # Warmup Iteration 1: 996795.163 ops/s # Warmup Iteration 2: 1034566.810 ops/s # Warmup Iteration 3: 1033006.128 ops/s # Warmup Iteration 4: 1033769.206 ops/s # Warmup Iteration 5: 1032642.345 ops/s Iteration 1: 1034079.168 ops/s Iteration 2: 1029908.423 ops/s Iteration 3: 1035955.616 ops/s Iteration 4: 1037266.116 ops/s Iteration 5: 1031665.788 ops/s # Run progress: 92.00% complete, ETA 00:03:21 # Fork: 4 of 5 # Warmup Iteration 1: 1003976.486 ops/s # Warmup Iteration 2: 1022408.984 ops/s # Warmup Iteration 3: 1020572.992 ops/s # Warmup Iteration 4: 1023204.213 ops/s # Warmup Iteration 5: 1020733.074 ops/s Iteration 1: 1020652.780 ops/s Iteration 2: 1072559.478 ops/s Iteration 3: 1074862.664 ops/s Iteration 4: 1076194.231 ops/s Iteration 5: 1076650.831 ops/s # Run progress: 96.00% complete, ETA 00:01:40 # Fork: 5 of 5 # Warmup Iteration 1: 1053092.552 ops/s # Warmup Iteration 2: 1084625.965 ops/s # Warmup Iteration 3: 1085293.339 ops/s # Warmup Iteration 4: 1084669.666 ops/s # Warmup Iteration 5: 1081582.054 ops/s Iteration 1: 1082967.461 ops/s Iteration 2: 1087299.617 ops/s Iteration 3: 1088068.834 ops/s Iteration 4: 1089727.432 ops/s Iteration 5: 1089616.672 ops/s Result "com.dxz.statement.StringConnectBenchmark.testStringFormat": 1039842.677 ±(99.9%) 25605.464 ops/s [Average] (min, avg, max) = (999416.708, 1039842.677, 1089727.432), stdev = 34182.562 CI (99.9%): [1014237.213, 1065448.142] (assumes normal distribution) # Run complete. Total time: 00:42:00 REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial experiments, perform baseline and negative tests that provide experimental control, make sure the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts. Do not assume the numbers tell you what you want them to tell. Benchmark Mode Cnt Score Error Units StringConnectBenchmark.testStringAdd thrpt 25 60836951.796 ± 1211324.257 ops/s StringConnectBenchmark.testStringBuffer thrpt 25 114671433.744 ± 1425597.127 ops/s StringConnectBenchmark.testStringBuilder thrpt 25 106679162.390 ± 3873825.727 ops/s StringConnectBenchmark.testStringConcat thrpt 25 41705419.646 ± 135498.955 ops/s StringConnectBenchmark.testStringFormat thrpt 25 1039842.677 ± 25605.464 ops/s Process finished with exit code 0
结果分析:
结果主要分成三个部分。
第一部分以 “#Warmup Iteration。。。。”这种形式的内容。这表明每次预热迭代的结果。
另一部分以“Iteration。。。”形式内容,这表明每次基准测试迭代的结果。
最后一部分以“Result。。。”形式的内容,这就是所有迭代跑完最终的结果。第一段结果告诉了我们最大值、最小值、平均值的信息。
而最最后的表格结构的信息才是我们分析的重点,但是它输出的结果有点错位,刚开始我一直在纠结 Error是± 906608.141代表什么意思,google了一圈发现,Error它其实什么都没输出,而且 Score 是63728919.269 ± 906608.141。我用表格排板了一下,解释如下:
Benchmark | Mode | Cnt | Score | Error | Units |
---|---|---|---|---|---|
基准测试执行的方法 | 测试模式,这里是吞吐量 | 运行多少次 | 分数 | 错误 | 单位 |
StringConnectBenchmark.testStringAdd | thrpt | 30 | 63728919.269 ± 906608.141 | ops/s | |
StringConnectBenchmark.testStringBuffer | thrpt | 30 | 112423521.098 ± 1157072.848 | ops/s | |
StringConnectBenchmark.testStringBuilder | thrpt | 30 | 110558976.274 ± 654163.111 | ops/s | |
StringConnectBenchmark.testStringConcat | thrpt | 30 | 44820009.200 ± 524305.660 | ops/s | |
StringConnectBenchmark.testStringFormat | thrpt | 30 | 1132633.183 ± 16252.303 | ops/s |
结论:
StringBuffer >= StringBuilder > String直接相加 > StringConcat >> StringFormat
可见 StringBuffer 与 StringBuilder 大致性能相同,都比直接相加高几个数量级,而且直接相加与 Concat 方法相加差不多。但是这里不管哪种都比 StringFormat高 N 个数量级。所以 String的 Format方法一定要慎用、不用、禁用!!!
参考:https://www.jianshu.com/p/bcb0b60c7ca7