原问题

FROM：《How do I write a correct micro-benchmark in Java?》

Tips about writing micro benchmarks from the creators of Java HotSpot:

Rule 0: Read a reputable paper on JVMs and micro-benchmarking. A good one is Brian Goetz, 2005. Do not expect too much from micro-benchmarks; they measure only a limited range of JVM performance characteristics.

Rule 1: Always include a warmup phase which runs your test kernel all the way through, enough to trigger all initializations and compilations before timing phase(s). (Fewer iterations is OK on the warmup phase. The rule of thumb is several tens of thousands of inner loop iterations.)

Rule 2: Always run with -XX:+PrintCompilation, -verbose:gc, etc., so you can verify that the compiler and other parts of the JVM are not doing unexpected work during your timing phase.

Rule 2.1: Print messages at the beginning and end of timing and warmup phases, so you can verify that there is no output from Rule 2 during the timing phase.

Rule 3: Be aware of the difference between -client and -server, and OSR and regular compilations. The -XX:+PrintCompilation flag reports OSR compilations with an at-sign to denote the non-initial entry point, for example: Trouble$1::run @ 2 (41 bytes). Prefer server to client, and regular to OSR, if you are after best performance.

Rule 4: Be aware of initialization effects. Do not print for the first time during your timing phase, since printing loads and initializes classes. Do not load new classes outside of the warmup phase (or final reporting phase), unless you are testing class loading specifically (and in that case load only the test classes). Rule 2 is your first line of defense against such effects.

Rule 5: Be aware of deoptimization and recompilation effects. Do not take any code path for the first time in the timing phase, because the compiler may junk and recompile the code, based on an earlier optimistic assumption that the path was not going to be used at all. Rule 2 is your first line of defense against such effects.

Rule 6: Use appropriate tools to read the compiler’s mind, and expect to be surprised by the code it produces. Inspect the code yourself before forming theories about what makes something faster or slower.

Rule 7: Reduce noise in your measurements. Run your benchmark on a quiet machine, and run it several times, discarding outliers. Use -Xbatch to serialize the compiler with the application, and consider setting -XX:CICompilerCount=1 to prevent the compiler from running in parallel with itself. Try your best to reduce GC overhead, set Xmx(large enough) equals Xms and use UseEpsilonGC if it is available.

Rule 8: Use a library for your benchmark as it is probably more efficient and was already debugged for this sole purpose. Such as JMH, Caliper or Bill and Paul’s Excellent UCSD Benchmarks for Java.

规则 0：阅读有关 JVM 和微基准测试的知名论文。 Brian Goetz, 2005 是一个很好的例子。不要对微基准期望过高；它们仅测量有限范围的 JVM 性能特征。

规则 1：始终包含一个预热阶段，它会一直运行您的测试内核，足以在计时阶段之前触发所有初始化和编译。 （预热阶段的迭代次数较少。经验法则是数万次内循环迭代。）几万次足以预热大部分东西。

规则 2：始终使用 -XX:+PrintCompilation、-verbose:gc 等运行，这样您就可以验证编译器和 JVM 的其他部分在您的计时阶段没有做预期之外的工作。如果做了它会打印出来。

规则 2.1：在计时和预热阶段的开始和结束时打印消息，以便您可以验证在计时阶段没有规则 2 的输出。如何做到呢，依靠 JMH 吧。

规则 3：注意-client和-server之间的区别，以及 OSR 和常规编译之间的区别。 -XX:+PrintCompilation标志用 at 符号报告 OSR 编译，以表示非初始入口点，例如：Trouble$1::run@2（41 bytes）。如果您追求最佳性能，则更喜欢服务器而不是客户端，并且更喜欢 OSR。我真的看得懂 OSR 的日志吗？

规则 4：注意初始化效果。不要在计时阶段第一次打印，因为打印会加载和初始化类。不要在预热阶段（或最终报告阶段）之外加载新类，除非您专门测试类加载（在这种情况下只加载测试类）。规则 2 是您抵御此类影响的第一道防线。类加载是一种容易被忽略的性能瓶颈，打印是另一种。

规则 5：注意反优化和重新编译的影响。不要在计时阶段才第一次使用任何代码路径，因为编译器可能会根据早先的乐观假设，即根本不会使用该路径，而重新编译代码。规则 2 是您抵御此类影响的第一道防线。

规则 6：使用适当的工具来读懂编译器的想法，并期望对它生成的代码感到惊讶。在形成关于什么使某事更快或更慢的理论之前，自己检查代码。不要以为自己懂编译器。

规则 7：减少测量中的噪声。在安静的机器上运行您的基准测试，并运行几次，丢弃异常值。使用 -Xbatch 将编译器与应用程序序列化，并考虑设置 -XX:CICompilerCount=1 以防止编译器与自身并行运行。尽量减少 GC 开销，设置 Xmx（足够大）等于 Xms 并在可用时使用 UseEpsilonGC。可以使用无操作垃圾收集器。

规则 8：为您的基准测试使用一个库，因为它可能更有效，并且已经为此目的进行了调试。例如 JMH、Caliper 或 Bill and Paul’s Better UCSD Benchmarks for Java。

Also, never use System.currentTimeMillis() unless you are OK with + or - 15 ms accuracy, which is typical on most OS + JVM combinations.

不要使用 System.nanoTime() 和 System.currentTimeMillis() 这两个 api。但 System.nanoTime() 始终是单调钟，虽然不精确，总是向前的。

样例工程

1
2
3
4
5
6
7
8
9
10
11
12
13
14
<dependency>
            <groupId>org.openjdk.jmh</groupId>
            <artifactId>jmh-core</artifactId>
            <version>1.33</version>
            <scope>test</scope>
        </dependency>

        <!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-generator-annprocess -->
        <dependency>
            <groupId>org.openjdk.jmh</groupId>
            <artifactId>jmh-generator-annprocess</artifactId>
            <version>1.33</version>
            <scope>test</scope>
        </dependency>
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
// 参考 https://github.com/openjdk/jmh/blob/master/jmh-samples/src/main/java/org/openjdk/jmh/samples/JMHSample_03_States.java
@State(Scope.Benchmark)
public class JsonUtilBenchMark {

    @State(Scope.Thread)
    public static class MyState {
        // 在每一个 Invocation 级别做一次 setup。参数随机化要这一步做
        @Setup(Level.Invocation)
        public void doSetup() {
            Map<String, String> map = new HashMap<>();

            for (int i = 0; i < 1024; i++) {
                int boundedRandomValue = ThreadLocalRandom.current().nextInt(-10000000, 10000000);
                map.put(boundedRandomValue + "", boundedRandomValue + 1 + "");
            }
            mapStr = JsonUtils.toJson(map);
            System.out.println("Do Setup");
        }

        @TearDown(Level.Invocation)
        public void doTearDown() {
            System.out.println("Do TearDown");
        }

        public String mapStr;
    }

    @Benchmark
    @BenchmarkMode(Mode.All) // 吞吐量、耗时、采样、冷启动这些模式都跑一遍
    @OutputTimeUnit(TimeUnit.NANOSECONDS)
    public void measureToObj(MyState state) throws IOException {
        System.out.println(JsonUtils.toObj(state.mapStr, Map.class));
    }

    @Benchmark
    @BenchmarkMode(Mode.All)
    @OutputTimeUnit(TimeUnit.NANOSECONDS)
    public void measureToObj2(MyState state) throws IOException {
        System.out.println(JsonUtils.toObj2(state.mapStr, Map.class));
    }

    public static void main(String[] args) throws RunnerException {
        Options opt = new OptionsBuilder()
                .include(JsonUtilBenchMark.class.getSimpleName())
                .threads(80)
                // 4 * 500 秒 = 33.3333333333 分(分钟)
                .warmupIterations(500)
                // 每个循环每个模式跑 1s，如果开 all mode，实际上要跑 4 * 50000 秒等于55.5555555556 时(小时)
                .measurementIterations(50000)
                // https://stackoverflow.com/questions/35046745/what-is-the-purpose-of-jmh-fork
                // fork 是为了实现 JVM 级的隔离
                .measurementIterations(50000)
                .forks(20)
                .build();
        new Runner(opt).run();
    }
}

JMH 教程

参考《JMH 应用指南》。

《基准测试神器 JMH —— 详解 36 个官方例子》

基本概念

  • Iteration - iteration 是 JMH 进行测试的最小单位，包含一组 invocations。
  • Invocation - 一次 benchmark 方法调用。
  • Operation - benchmark 方法中，被测量操作的执行。如果被测试的操作在 benchmark 方法中循环执行，可以使用@OperationsPerInvocation表明循环次数，使测试结果为单次 operation 的性能。
  • Warmup - 在实际进行 benchmark 前先进行预热。因为某个函数被调用多次之后，JIT 会对其进行编译，通过预热可以使测量结果更加接近真实情况。

API

@BenchmarkMode

  • Throughput - 整体吞吐量，例如“1 秒内可以执行多少次调用”。
  • AverageTime - 调用的平均时间，例如“每次调用平均耗时 xxx 毫秒”。
  • SampleTime - 随机取样，最后输出取样结果的分布，例如“99%的调用在 xxx 毫秒以内，99.99%的调用在 xxx 毫秒以内”
  • SingleShotTime - 以上模式都是默认一次 iteration 是 1s，唯有 SingleShotTime 是只运行一次。往往同时把 warmup 次数设为 0，用于测试冷启动时的性能。
  • All - 所有模式

@Warmup

上面我们提到了，进行基准测试前需要进行预热。一般我们前几次进行程序测试的时候都会比较慢， 所以要让程序进行几轮预热，保证测试的准确性。其中的参数 iterations 也就非常好理解了，就是预热轮数。
为什么需要预热？因为 JVM 的 JIT 机制的存在，如果某个函数被调用多次之后，JVM 会尝试将其编译成为机器码从而提高执行速度。所以为了让 benchmark 的结果更加接近真实情况就需要进行预热。

@Measurement

  • iterations - 进行测试的轮次
  • time - 每轮进行的时长
  • timeUnit - 时长单位

@Threads

每个进程中的测试线程，这个非常好理解，根据具体情况选择，一般为 cpu 乘以 2。

@Fork

进行 fork 的次数。如果 fork 数是 2 的话，则 JMH 会 fork 出两个进程来进行测试。

@OutputTimeUnit

这个比较简单了，基准测试结果的时间类型。一般选择秒、毫秒、微秒。

@Benchmark

方法级注解，表示该方法是需要进行 benchmark 的对象，用法和 JUnit 的 @Test 类似。

@Param

属性级注解，@Param 可以用来指定某项参数的多种情况。特别适合用来测试一个函数在不同的参数输入的情况下的性能。

@Setup

方法级注解，这个注解的作用就是我们需要在测试之前进行一些准备工作，比如对一些数据的初始化之类的。我们可以在每一次 Invocation 以前做一次 Setup。

@TearDown

方法级注解，这个注解的作用就是我们需要在测试之后进行一些结束工作，比如关闭线程池，数据库连接等的，主要用于资源的回收等。这个东西需要很慎重。

@State

当使用 @Setup 参数的时候，必须在类上加这个参数，不然会提示无法运行。
State 用于声明某个类是一个“状态”，然后接受一个 Scope 参数用来表示该状态的共享范围。 因为很多 benchmark 会需要一些表示状态的类，JMH 允许你把这些类以依赖注入的方式注入到 benchmark 函数里。Scope 主要分为三种。

  • Thread - 该状态为每个线程独享。
  • Group - 该状态为同一个组里面所有线程共享。
  • Benchmark - 该状态在所有线程间共享。

解读输出报告

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
255195.938 ±(99.9%) 48484.059 ns/op


Result "类名.方法名":
  N = 20
  mean = 324719.516 ±(99.9%) 302945.897 ns/op

  Histogram, ns/op:
    [      0.000,  125000.000) = 0 
    # 有 14 个 iteration 在 125 微秒中执行完成
    [ 125000.000,  250000.000) = 14 
    [ 250000.000,  375000.000) = 5 
    [ 375000.000,  500000.000) = 0 
    [ 500000.000,  625000.000) = 0 
    [ 625000.000,  750000.000) = 0 
    [ 750000.000,  875000.000) = 0 
    [ 875000.000, 1000000.000) = 0 
    [1000000.000, 1125000.000) = 0 
    [1125000.000, 1250000.000) = 0 
    [1250000.000, 1375000.000) = 0 
    [1375000.000, 1500000.000) = 0 
    [1500000.000, 1625000.000) = 0 
    [1625000.000, 1750000.000) = 0 
    # 有一个 iteration 在1.75 毫秒内执行完成
    [1750000.000, 1875000.000) = 1 

 # 有若干个点在这些 p(50.0000)分位被执行出来。
  Percentiles, ns/op:
      p(0.0000) = 224220.638 ns/op
     p(50.0000) = 237448.319 ns/op
     p(90.0000) = 331986.035 ns/op
     p(95.0000) = 1728070.972 ns/op
     p(99.0000) = 1801399.338 ns/op
     p(99.9000) = 1801399.338 ns/op
     p(99.9900) = 1801399.338 ns/op
     p(99.9990) = 1801399.338 ns/op
     p(99.9999) = 1801399.338 ns/op
    p(100.0000) = 1801399.338 ns/op

# 总共花了 4 分 46 秒执行基准测试
# Run complete. Total time: 00:04:46

Benchmark                                                                        Mode      Cnt       Score     Error   Units
RiskOutServiceImplBenchMark.measureJson                                         thrpt       20       0.057 ±   0.008  ops/us
RiskOutServiceImplBenchMark.measureMessageFormat                                thrpt       20       0.057 ±   0.009  ops/us
RiskOutServiceImplBenchMark.measureOrigin                                       thrpt       20       0.066 ±   0.007  ops/us
# 注意，在 avg time 模式下，我们会发现 avg 都很高，主要是因为 tp 的长尾线拉高了 avg
RiskOutServiceImplBenchMark.measureJson                                          avgt       20    1420.907 ± 176.300   us/op
RiskOutServiceImplBenchMark.measureMessageFormat                                 avgt       20    1191.810 ± 142.301   us/op
RiskOutServiceImplBenchMark.measureOrigin                                        avgt       20    1170.264 ± 119.390   us/op
# 在采样模式下看分位线
RiskOutServiceImplBenchMark.measureJson                                        sample  1420574    1175.533 ±  17.038   us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.00                      sample               38.976             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.50                      sample               78.720             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.90                      sample              144.640             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.95                      sample              831.488             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.99                      sample            34537.472             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.999                     sample            65142.784             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p0.9999                    sample           100524.687             us/op
RiskOutServiceImplBenchMark.measureJson:measureJson·p1.00                      sample           249823.232             us/op
RiskOutServiceImplBenchMark.measureMessageFormat                               sample  1490803    1109.570 ±  18.395   us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.00    sample               37.440             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.50    sample               74.624             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.90    sample              115.072             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.95    sample              376.730             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.99    sample            40566.784             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.999   sample            78118.912             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p0.9999  sample           123590.358             us/op
RiskOutServiceImplBenchMark.measureMessageFormat:measureMessageFormat·p1.00    sample           216268.800             us/op
RiskOutServiceImplBenchMark.measureOrigin                                      sample  1426009    1184.753 ±  20.095   us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.00                  sample               36.480             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.50                  sample               73.088             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.90                  sample              114.816             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.95                  sample              376.320             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.99                  sample            38666.240             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.999                 sample            90570.752             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p0.9999                sample           148111.360             us/op
RiskOutServiceImplBenchMark.measureOrigin:measureOrigin·p1.00                  sample           318767.104             us/op
# 下面是冷启动的分数，冷启动时单个操作 525 微秒，高于 5p50，但低于 tp 99
RiskOutServiceImplBenchMark.measureJson                                            ss       20     525.691 ± 294.527   us/op
RiskOutServiceImplBenchMark.measureMessageFormat                                   ss       20     489.662 ± 514.746   us/op
RiskOutServiceImplBenchMark.measureOrigin                                          ss       20     341.841 ± 215.144   us/op

注意标准差： STDEV 基于样本估算标准偏差。标准偏差反映数值相对于平均值(mean) 的离散程度。

  • ops/us - operations (benchmark method executions) per microsecond
  • Cnt - total number of trials (forks*iterations)
  • Score - benchmark result
  • Error - standard error value. Means how much different trials results differ
    Also:
  • thrpt - Throughput mode (how much full benchmark method executions were made in a trial)
  • avgt - Average Time mode (how much measuring units took benchmark method execution on average)

有兴趣还可以试试这两个网站：
JMH Visual Chart
JMH Visualizer

另外一种解释，参考《使用JMH进行基准性能测试》：

数字只能告诉我们 what，通常不能告诉我们 when、where、how 和 why。搞懂 why 是人的工作：

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.

记住：下面的数字只是数据。要获得可重复使用的见解，您需要跟进 为什么数字是这样的。使用分析器（参见 -prof、-lprof），设计因子
实验，执行提供实验控制的基线和负面测试，确保 基准测试环境在 JVM/OS/HW 级别是安全的，请咨询领域专家。
不要假设数字告诉您您希望他们告诉您的内容。

块 说明
参数信息（1-10行） 1：jmh版本
2：jvm版本信息
3：jvm程序（jdk安装路径）
4：jvm参数配置
5：预热参数：预热次数、每次持续时间
6：测试参数：测试次数、每次持续时间
7：每次测试迭代超时时间
8：每个测试进程的测试线程数
9: 测试的模式
10:测试的方法
测试过程（12-75行） 12-23：第1次fork测试 （fork可以理解为1个独立的进程）
12：测试完成进度，预计剩余需要时间
13：当前第几次fork
14-18：预热执行，每次预热执行耗时
19-23：正式测试执行，每次测试执行耗时
25-36：第2次fork测试
38-49：第3次fork测试
51-62：第4次fork测试
64-75：第5次fork测试
测试结果（78-95行） 78-81：测试结果，包括测试的方法、平均耗时[平局耗时的比例]、最大最小 耗时、测试结果数据离散度（stdev）等
84：测试总耗时
86-90：对测试结果的解释
92-93：测试结论{测试的方法、测试类型（Mode）、测试总次数(Cnt)、测试结果(Score)、误差(Error)、单位(Units)}
95：结束