使用 JMH benchmark Java／Spring Boot app
Table of contents
1 JMH 簡介
Java Microbenchmark Harness（JMH）係一個用黎做 benchmark Java 程式既一套 library。
佢可以話畀我地知一個 Java method：
- 平均需要幾長時間去執行（average time）
- 一秒鐘執行到幾多次（throughput）
1.1 使用場景
- 想改善某個 method 既執行速度，例如寫 algorithm。
- 想比較 Java 或者 Maven dependency 版本 upgrade 帶黎既性能差別。
2 動手寫
Project structure：
src/main/java/code/jmh/benchmarksAppStartupBenchmark.javaBenchmarkPackageRef.java
JmhApplication.java
ApplicationController.javaMainApplication.java
src/main/resourcesapplication.yml
2.1 Maven dependencies
1<parent> 2 <groupId>org.springframework.boot</groupId> 3 <artifactId>spring-boot-starter-parent</artifactId> 4 <version>3.0.6</version> 5</parent> 6 7<dependencyManagement> 8 <dependencies> 9 <dependency> 10 <groupId>org.springframework.cloud</groupId> 11 <artifactId>spring-cloud-dependencies</artifactId> 12 <version>2022.0.2</version> 13 <type>pom</type> 14 <scope>import</scope> 15 </dependency> 16 </dependencies> 17</dependencyManagement> 18 19<dependencies> 20 <dependency> 21 <groupId>org.springframework.boot</groupId> 22 <artifactId>spring-boot-starter-web</artifactId> 23 </dependency> 24 25 <dependency> 26 <groupId>org.springframework.boot</groupId> 27 <artifactId>spring-boot-starter-actuator</artifactId> 28 </dependency> 29 <dependency> 30 <groupId>org.springframework.boot</groupId> 31 <artifactId>spring-boot-devtools</artifactId> 32 </dependency> 33 34 <dependency> 35 <groupId>commons-io</groupId> 36 <artifactId>commons-io</artifactId> 37 <version>2.11.0</version> 38 </dependency> 39 40 <dependency> 41 <groupId>org.openjdk.jmh</groupId> 42 <artifactId>jmh-core</artifactId> 43 <version>1.36</version> 44 </dependency> 45 <dependency> 46 <groupId>org.openjdk.jmh</groupId> 47 <artifactId>jmh-generator-annprocess</artifactId> 48 <version>1.36</version> 49 </dependency> 50</dependencies> 51 52<build> 53 <plugins> 54 <plugin> 55 <groupId>org.springframework.boot</groupId> 56 <artifactId>spring-boot-maven-plugin</artifactId> 57 <version>3.0.6</version> 58 <configuration> 59 <mainClass>code.jmh.JmhApplication</mainClass> <!-- 只限測試用 --> 60 </configuration> 61 <executions> 62 <execution> 63 <goals> 64 <goal>repackage</goal> 65 </goals> 66 </execution> 67 </executions> 68 </plugin> 69 </plugins> 70</build>
2.2 Java code
JmhApplication.java：1public class JmhApplication { 2 3 public static void main(String [] args) throws Exception { 4 5 final File resultFile = createResultFile(); 6 7 final Options opt = new OptionsBuilder() 8 .include(BenchmarkPackageRef.class.getPackageName()) 9 .shouldDoGC(true) 10 .shouldFailOnError(true) 11 .resultFormat(ResultFormatType.JSON) 12 .result(resultFile.getAbsolutePath()) 13 .build(); 14 15 new Runner(opt).run(); 16 17 printResultFile(resultFile); 18 } 19 20 private static File createResultFile() throws Exception { 21 try { 22 final File file = Files.createTempFile("jmh-results", ".json").toFile(); 23 file.deleteOnExit(); 24 System.out.println("Created JMH result file: " + file.getAbsolutePath()); 25 26 return file; 27 } catch (Exception e) { 28 System.err.println("Failed to create result file for JMH."); 29 throw e; 30 } 31 } 32 33 private static void printResultFile(File resultFile) throws Exception { 34 System.out.println("Printing file content of " + resultFile.getAbsolutePath() + ":"); 35 System.out.println(FileUtils.readFileToString(resultFile, "UTF-8")); 36 } 37}
BenchmarkPackageRef.java：public final class BenchmarkPackageRef { private BenchmarkPackageRef() {} }
AppStartupBenchmark.java：1@Warmup(iterations = 5) 2@Measurement(iterations = 20) 3@State(Scope.Benchmark) 4@BenchmarkMode(Mode.AverageTime) 5@OutputTimeUnit(TimeUnit.MILLISECONDS) 6@Threads(1) 7@Fork(value = 1, jvmArgs = { "-server" }) 8public class AppStartupBenchmark { 9 10 ConfigurableApplicationContext context; 11 12 @Setup(Level.Invocation) 13 public void init() { 14 15 } 16 17 @TearDown(Level.Invocation) 18 public void finish() { 19 if (context!=null && context.isRunning()) { 20 context.close(); 21 } 22 } 23 24 // 我地測試緊 Spring Boot startup 以及 Spring context 初始化 25 @Benchmark 26 public void benchmarkAppStartup() { 27 context = SpringApplication.run(MainApplication.class); 28 Assert.notNull(context.getBean(MyController.class), "Controller bean should not be null."); 29 } 30}
MainApplication.java：1@SpringBootApplication 2public class MainApplication { 3 4 public static void main(String[] args) { 5 SpringApplication.run(MainApplication.class, args); 6 } 7}
MyController.java：1@RestController 2public class MyController { 3 4 @GetMapping 5 public String helloWorld() { 6 return "hello world"; 7 } 8}
application.yml：logging.level.root: ERROR spring.main.banner-mode: off
3 執行 benchmark
有兩個方式：
- IDE 裡面作為 Java app 咁執行
- Build 左 JAR 檔之後執行
3.1 IDE 裡面執行
（以下適用於 Eclipse）
先確保 Eclipse 有安裝到
m2e-apt，亦都 enable 左 annotation processing。- Update 個 Maven project。
- 將
JmhApplicationclass 作為 Java app 咁執行。
3.2 執行 JAR artifact
我地要 build 左個 JAR 檔出黎，然後執行佢：
mvn clean package
cd target java -jar spring-boot-jmh-1.0.0.jar
4 Benchmark 結果樣本
註：
- 我地用既 benchmark mode 係 average time。
- 所以 score 既單位係
ms/op，呢個數字係越低越好。 - 每個 iteration 執行既 operations 次數由 JMH 決定。
- 如果 benchmark mode 用 all，佢會用唔同既 benchmark mode 執行同一個 benchmark。
- 所以 score 既單位係
4.1 Console log
1# JMH version: 1.36 2# VM version: JDK 17.0.7, OpenJDK 64-Bit Server VM, 17.0.7+7-LTS 3# VM invoker: C:\Users\Michael\Desktop\Apps\msjdk17\bin\java.exe 4# VM options: -server 5# Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable) 6# Warmup: 5 iterations, 10 s each 7# Measurement: 20 iterations, 10 s each 8# Timeout: 10 min per iteration 9# Threads: 1 thread, will synchronize iterations 10# Benchmark mode: Average time, time/op 11# Benchmark: code.jmh.benchmarks.AppStartupBenchmark.benchmarkAppStartup 12 13# Run progress: 0.00% complete, ETA 00:04:10 14# Fork: 1 of 1 15# Warmup Iteration 1: 220.079 ms/op 16# Warmup Iteration 2: 129.138 ms/op 17# Warmup Iteration 3: 105.157 ms/op 18# Warmup Iteration 4: 97.996 ms/op 19# Warmup Iteration 5: 89.844 ms/op 20Iteration 1: 89.442 ms/op 21Iteration 2: 89.301 ms/op 22Iteration 3: 87.922 ms/op 23Iteration 4: 86.586 ms/op 24Iteration 5: 87.189 ms/op 25Iteration 6: 85.913 ms/op 26Iteration 7: 88.044 ms/op 27Iteration 8: 86.758 ms/op 28Iteration 9: 86.637 ms/op 29Iteration 10: 86.204 ms/op 30Iteration 11: 87.040 ms/op 31Iteration 12: 87.521 ms/op 32Iteration 13: 87.171 ms/op 33Iteration 14: 89.843 ms/op 34Iteration 15: 85.210 ms/op 35Iteration 16: 84.815 ms/op 36Iteration 17: 84.768 ms/op 37Iteration 18: 88.859 ms/op 38Iteration 19: 84.887 ms/op 39Iteration 20: 87.541 ms/op 40 41 42Result "code.jmh.benchmarks.AppStartupBenchmark.benchmarkAppStartup": 43 87.083 ±(99.9%) 1.334 ms/op [Average] 44 (min, avg, max) = (84.768, 87.083, 89.843), stdev = 1.536 45 CI (99.9%): [85.749, 88.416] (assumes normal distribution) 46 47 48# Run complete. Total time: 00:04:55 49 50REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on 51why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial 52experiments, perform baseline and negative tests that provide experimental control, make sure 53the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts. 54Do not assume the numbers tell you what you want them to tell. 55 56NOTE: Current JVM experimentally supports Compiler Blackholes, and they are in use. Please exercise 57extra caution when trusting the results, look into the generated code to check the benchmark still 58works, and factor in a small probability of new VM bugs. Additionally, while comparisons between 59different JVMs are already problematic, the performance difference caused by different Blackhole 60modes can be very significant. Please make sure you use the consistent Blackhole mode for comparisons. 61 62Benchmark Mode Cnt Score Error Units 63AppStartupBenchmark.benchmarkAppStartup avgt 20 87.083 ± 1.334 ms/op
4.2 JMH result 檔案
1[ 2 { 3 "jmhVersion" : "1.36", 4 "benchmark" : "code.jmh.benchmarks.AppStartupBenchmark.benchmarkAppStartup", 5 "mode" : "avgt", 6 "threads" : 1, 7 "forks" : 1, 8 "jvm" : "C:\\Users\\Michael\\Desktop\\Apps\\msjdk17\\bin\\java.exe", 9 "jvmArgs" : [ 10 "-server" 11 ], 12 "jdkVersion" : "17.0.7", 13 "vmName" : "OpenJDK 64-Bit Server VM", 14 "vmVersion" : "17.0.7+7-LTS", 15 "warmupIterations" : 5, 16 "warmupTime" : "10 s", 17 "warmupBatchSize" : 1, 18 "measurementIterations" : 20, 19 "measurementTime" : "10 s", 20 "measurementBatchSize" : 1, 21 "primaryMetric" : { 22 "score" : 87.08259406398619, 23 "scoreError" : 1.3338545207641799, 24 "scoreConfidence" : [ 25 85.74873954322202, 26 88.41644858475037 27 ], 28 "scorePercentiles" : { 29 "0.0" : 84.76841401869159, 30 "50.0" : 87.10552132326006, 31 "90.0" : 89.42742431372548, 32 "95.0" : 89.82311887254902, 33 "99.0" : 89.84320392156863, 34 "99.9" : 89.84320392156863, 35 "99.99" : 89.84320392156863, 36 "99.999" : 89.84320392156863, 37 "99.9999" : 89.84320392156863, 38 "100.0" : 89.84320392156863 39 }, 40 "scoreUnit" : "ms/op", 41 "rawData" : [ 42 [ 43 89.44150294117647, 44 89.30071666666667, 45 87.92223269230769, 46 86.58622761904762, 47 87.18889134615385, 48 85.91300943396226, 49 88.0441, 50 86.75808476190477, 51 86.63733428571429, 52 86.20367047619048, 53 87.03976476190476, 54 87.52096153846153, 55 87.17127788461538, 56 89.84320392156863, 57 85.20977196261683, 58 84.81511214953271, 59 84.76841401869159, 60 88.85933203883495, 61 84.88701028037383, 62 87.5412625 63 ] 64 ] 65 }, 66 "secondaryMetrics" : { 67 } 68 } 69]
5 已知問題
5.1 ClassNotFoundException：ForkedMain
當我地用舊版既 Spring Boot
2.7.x 而又配置左 @Fork(value = 1) 既話，當我地 build 左個 JAR 檔然後執行佢，就會出現下面既 error。1Error: Could not find or load main class org.openjdk.jmh.runner.ForkedMain 2Caused by: java.lang.ClassNotFoundException: org.openjdk.jmh.runner.ForkedMain 3<forked VM failed with exit code 1> 4<stdout last='20 lines'> 5</stdout> 6<stderr last='20 lines'> 7Error: Could not find or load main class org.openjdk.jmh.runner.ForkedMain 8Caused by: java.lang.ClassNotFoundException: org.openjdk.jmh.runner.ForkedMain 9</stderr> 10 11Benchmark had encountered error, and fail on error was requested 12Exception in thread "main" java.lang.reflect.InvocationTargetException 13 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 14 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 15 at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 16 at java.base/java.lang.reflect.Method.invoke(Method.java:566) 17 at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) 18 at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) 19 at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) 20 at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65) 21Caused by: org.openjdk.jmh.runner.RunnerException: Benchmark caught the exception 22 at org.openjdk.jmh.runner.Runner.runBenchmarks(Runner.java:575) 23 at org.openjdk.jmh.runner.Runner.internalRun(Runner.java:310) 24 at org.openjdk.jmh.runner.Runner.run(Runner.java:209) 25 at code.jmh.JmhApplication.main(JmhApplication.java:28) 26 ... 8 more 27Caused by: org.openjdk.jmh.runner.BenchmarkException: Benchmark error 28 at org.openjdk.jmh.runner.Runner.doFork(Runner.java:768) 29 at org.openjdk.jmh.runner.Runner.runSeparate(Runner.java:660) 30 at org.openjdk.jmh.runner.Runner.runBenchmarks(Runner.java:558) 31 ... 11 more 32 Suppressed: java.lang.IllegalStateException: Forked VM failed with exit code 1 33 ... 14 more
最快捷既解決方法係配置
@Fork(value = 0)，但係 JMH 只係建議喺 debug 既時候唔用 fork。另外唔用 fork 都有個壞處，就係我地會 apply 唔到 JVM args。# Fork: N/A, test runs in the host VM # *** WARNING: Non-forked runs may silently omit JVM options, mess up profilers, disable compiler hints, etc. *** # *** WARNING: Use non-forked runs only for debugging purposes, not for actual performance runs. ***