英文原文：Micro Benchmarking with JMH: Measure, don’t guess!
翻譯地址：使用JMH進行微基准測試：不要猜，要測試！
原文作者：Antonio
翻譯作者：Hollis
轉載請注明出處。
很多Java開發人員都知道把一個變量聲明為null有助於垃圾回收(譯者注：一般而言,為null的對象都會被作為垃圾處理,所以將不用的對象顯式地設為Null,有利於GC收集器判定垃圾,從而提高了GC的效率。)，也有部分人知道使用final定義一個內聯方法能夠提高性能。但是，我們也知道，如今，JVM在不斷進化，很多你昨天認定的理論到了今天則不一定試用了。（譯者注：因為jvm的不斷優化，大多數時候，即時我們不把不用的變量聲明為null,垃圾回收器也能很快判斷出該對象是否應該被回收。jvm的不斷優化之後，把變量設置為null這一舉動可能並不會帶來顯著的性能提升）那麼，我們如何能夠知道我們寫的代碼是否高效呢？其實，我們不應該去猜測，而是動手去測試。
就像我的朋友 Kirk Pepperdine once said說的那樣 “Measure, don’t guess“. 當我們的代碼出現性能問題的時候，我們總是試圖做一些小的改動（很可能是隨意的改動）希望能對性能有所提升。相反，我們應該建立一個穩定的性能測試環境（包括操作系統，jvm，應用服務器，數據庫等），設置一些性能目標，針對這一目標不斷的進行測試，直到達到你的預期。和持續測試、持續交付類似，我們也應該進行持續的性能測試。
無論如何,性能都是一個黑暗藝術,這不是這篇文章討論的主要內容。我只是想關注微基准測試和向您展示如何在一個真是的用例（本文以日志記錄為例）中使用JMH。
相信很多人和我一樣，在使用了多個日志框架之後，肯定見過下面這些調試日志：
logger.debug("Concatenating strings " + x + y + z);
logger.debug("Using variable arguments {} {} {}", x, y, z);
if (logger.isDebugEnabled())
logger.debug("Using the if debug enabled {} {} {}", x, y, z);
在一般的應用中，日志輸出級別都是INFO或者WARNING。即使使用了WARNING級別，上面這幾斷代碼都可以正常輸出調試信息。但是，調試日志可以卻可以影響應用的表現（性能）。為了證明這一點，我們將使用微基准測試來測試以上三種代碼的性能，這裡使用Java微基准測試工具(JMH)。上面的三種代碼分別可以概括為：使用字符串連接、使用變量參數和使用If進行debug可用檢測。
JMH是一個用於java或者其他JVM語言的，提供構建，運行和分析（按照多種基准：納秒，微妙、毫秒、宏）的工具。通過maven archtype我們可以很快的創建一個JMH工程。
mvn archetype:generate -DinteractiveMode=false -DarchetypeGroupId=org.openjdk.jmh \
-DarchetypeArtifactId=jmh-java-benchmark-archetype -DarchetypeVersion=1.4.1 \
-DgroupId=org.agoncal.sample.jmh -DartifactId=logging -Dversion=1.0
使用該maven原型創建出來的項目結構如下：
一個包含了JMH相關依賴和maven-shade-plugin插件的pom文件
一個使用了
@Benchmark注解的空的MyBenchmark文件
這個時候，雖然我們是什麼都還沒做，但是我們剛剛創建的微基准測試項目已經可以啟動並運行了。使用maven命令打包就能生成一個benchmarks.jar
mvn clean install java -jar target/benchmarks.jar
當我們使用以上命令運行這個jar時，我們就可以在控制台上看到一些有趣的內容輸出：JMH進入循環、預熱JVM，執行@Benchmark注解的空方法，並給出每秒操作的數量。
# Run progress: 30,00% complete, ETA 00:04:41 # Fork: 4 of 10 # Warmup Iteration 1: 2207650172,188 ops/s # Warmup Iteration 2: 2171077515,143 ops/s # Warmup Iteration 3: 2147266359,269 ops/s # Warmup Iteration 4: 2193541731,837 ops/s # Warmup Iteration 5: 2195724915,070 ops/s # Warmup Iteration 6: 2191867717,675 ops/s # Warmup Iteration 7: 2143952349,129 ops/s # Warmup Iteration 8: 2187759638,895 ops/s # Warmup Iteration 9: 2171283214,772 ops/s # Warmup Iteration 10: 2194607294,634 ops/s # Warmup Iteration 11: 2195047447,488 ops/s # Warmup Iteration 12: 2191714465,557 ops/s # Warmup Iteration 13: 2229074852,390 ops/s # Warmup Iteration 14: 2221881356,361 ops/s # Warmup Iteration 15: 2240789717,480 ops/s # Warmup Iteration 16: 2236822727,970 ops/s # Warmup Iteration 17: 2228958137,977 ops/s # Warmup Iteration 18: 2242267603,165 ops/s # Warmup Iteration 19: 2216594798,060 ops/s # Warmup Iteration 20: 2243117972,224 ops/s Iteration 1: 2201097704,736 ops/s Iteration 2: 2224068972,437 ops/s Iteration 3: 2243832903,895 ops/s Iteration 4: 2246595941,792 ops/s Iteration 5: 2241703372,299 ops/s Iteration 6: 2243852186,017 ops/s Iteration 7: 2221541382,551 ops/s Iteration 8: 2196835756,509 ops/s Iteration 9: 2205740069,844 ops/s Iteration 10: 2207837588,402 ops/s Iteration 11: 2192906907,559 ops/s Iteration 12: 2239234959,368 ops/s Iteration 13: 2198998566,646 ops/s Iteration 14: 2201966804,597 ops/s Iteration 15: 2215531292,317 ops/s Iteration 16: 2155095714,297 ops/s Iteration 17: 2146037784,423 ops/s Iteration 18: 2139622262,798 ops/s Iteration 19: 2213499245,208 ops/s Iteration 20: 2191108429,343 ops/s
前面不是說過嗎，我們要測試的用例是日志記錄，那麼在這個項目中我將使用SFL4J和Logback，我們向pom文件中增加依賴：
<dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>1.7.7</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.0.11</version> </dependency>
然後我們增加一個logback.xml配置文件，並設置日志輸出級別為INFO。
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%highlight(%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n)</pattern>
</encoder>
</appender>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder><pattern>%msg%n</pattern></encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
使用maven-shade-plugin的好處是，當我們使用maven對應用進行打包的時候，所有的依賴和配置文件等都會打包到target目錄下。
開始第一個微基准測試：在日志中使用字符串連接。這裡我們將所需代碼寫到由@Benchmark注解標注的方法中，然後其他的事情就交給JMH。
這段代碼中，我們創建x,y,z三個字符串變量，然後在循環中，使用字符串連接的形式將調試日志輸出。代碼如下：
import org.openjdk.jmh.annotations.Benchmark;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MyBenchmark {
private static final Logger logger = LoggerFactory.getLogger(MyBenchmark.class);
@Benchmark
public void testConcatenatingStrings() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i; y += i; z += i;
logger.debug("Concatenating strings " + x + y + z);
}
}
}
然後還是像剛剛一樣，運行這個微基准測試，並查看迭代輸出。
譯者注：後文將統一進行對比。
這個微基准測試中，我們使用變量參數來代替字符串連接，更改代碼內容如下，然後打包執行。
@Benchmark
public void testVariableArguments() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i; y += i; z += i;
logger.debug("Variable arguments {} {} {}", x, y, z);
}
}
最後一個也是最重要的一個，使用日志輸出時使用isDebugEnabled()進行優化
@Benchmark
public void testIfDebugEnabled() {
String x = "", y = "", z = "";
for (int i = 0; i < 100; i++) {
x += i; y += i; z += i;
if (logger.isDebugEnabled())
logger.debug("If debug enabled {} {} {}", x, y, z);
}
}
在運行三個微基准測試之後，我們將預期結果(記住,don’t guess, measure)。每秒的操作次數越多，表示性能越好。如果我們看看下表的最後一行,我們注意到使用isDebugEnabled的性能最好，使用字符串連接最糟糕。同時也能發現，在沒有使用isDebugEnabled而是使用變量參數的測試結果並不差。 綜合代碼的可讀性（較少的boilerplate code(模塊化代碼，也可以理解為不重要，但是又不可缺少的代碼)） 。所以我會選擇使用變量參數的那種形式！
## 結論
在過去的幾十年jvm大幅進化。用十年前的設計模式優化我們的代碼是不可取的。比較兩段代碼的好壞的唯一辦法就是測量它。JMH就是一個簡單高效的進行微基准測試的完美工具。當然,推理的一小部分代碼只有一個步驟,因為我們通常需要分析整個應用程序的性能。因為有了HMH，讓這個第一個步驟變得很容易。
這還有一些JMH的例子,它充滿了有趣的想法。
JMH Samples
Java Performance Tuning Guide
Using JMH for Java Microbenchmarking
Writing Java Micro Benchmarks with JMH: Juicy
【公告】版權聲明
(全文完)
