[譯]使用JMH進行微基準測試：不要猜，要測試！

英文原文：Micro Benchmarking with JMH: Measure, don’t guess!
翻譯地址：使用JMH進行微基準測試：不要猜，要測試！
原文做者：Antonio
翻譯做者：Hollis
轉載請註明出處。

 

不少Java開發人員都知道把一個變量聲明爲null有助於垃圾回收(譯者注：通常而言,爲null的對象都會被做爲垃圾處理,因此將不用的對象顯式地設爲Null,有利於GC收集器斷定垃圾,從而提升了GC的效率。)，也有部分人知道使用final定義一個內聯方法可以提升性能。可是，咱們也知道，現在，JVM在不斷進化，不少你昨天認定的理論到了今天則不必定試用了。（譯者注：由於jvm的不斷優化，大多數時候，即時咱們不把不用的變量聲明爲null,垃圾回收器也能很快判斷出該對象是否應該被回收。jvm的不斷優化以後，把變量設置爲null這一舉動可能並不會帶來顯著的性能提高）那麼，咱們如何可以知道咱們寫的代碼是否高效呢？其實，咱們不該該去猜想，而是動手去測試。

 

Measure, don’t guess!

就像個人朋友 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設置

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

前面不是說過嗎，咱們要測試的用例是日誌記錄，那麼在這個項目中我將使用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);
  }
}

 

在日誌中使用If判斷語句

最後一個也是最重要的一個，使用日誌輸出時使用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(模塊化代碼，也能夠理解爲不重要，可是又不可缺乏的代碼)） 。因此我會選擇使用變量參數的那種形式！

	String concatenation	Variable arguments	if isDebugEnabled
Iteration 1	57108,635 ops/s	97921,939 ops/s	104993,368 ops/s
Iteration 2	58441,293 ops/s	98036,051 ops/s	104839,216 ops/s
Iteration 3	58231,243 ops/s	97457,222 ops/s	106601,803 ops/s
Iteration 4	58538,842 ops/s	100861,562 ops/s	104643,717 ops/s
Iteration 5	57297,787 ops/s	100405,656 ops/s	104706,503 ops/s
Iteration 6	57838,298 ops/s	98912,545 ops/s	105439,939 ops/s
Iteration 7	56645,371 ops/s	100543,188 ops/s	102893,089 ops/s
Iteration 8	56569,236 ops/s	102239,005 ops/s	104730,682 ops/s
Iteration 9	57349,754 ops/s	94482,508 ops/s	103492,227 ops/s
Iteration 10	56894,075 ops/s	101405,938 ops/s	106790,525 ops/s
Average	57491,4534 ops/s	99226,5614 ops/s	104913,1069 ops/s

 

## 結論
在過去的幾十年jvm大幅進化。用十年前的設計模式優化咱們的代碼是不可取的。比較兩段代碼的好壞的惟一辦法就是測量它。JMH就是一個簡單高效的進行微基準測試的完美工具。固然,推理的一小部分代碼只有一個步驟,由於咱們一般須要分析整個應用程序的性能。由於有了HMH，讓這個第一個步驟變得很容易。

這還有一些JMH的例子,它充滿了有趣的想法。

 

參考資料

JMH Samples

Java Performance Tuning Guide

Using JMH for Java Microbenchmarking

Writing Java Micro Benchmarks with JMH: Juicy

【公告】版權聲明

(全文完)