超牛逼的效能監控神器！快速定位線上問題

今天想總結的東西是最近工作中使用到的測試工具JMH以及Java執行時監控工具Arthas。他們在我的實際工作中也算是幫了大忙。所以在這裡拋磚引玉一下這些工具的使用方法。同時也加深一下自己對這些工具的熟悉程度。對這兩個工具，我都會首先簡單介紹一下這些工具的大致使用場景，然後會使用一個在工作中真正遇到的效能問題排查為例詳細講解這兩個工具的實際用法。話不多說，直奔主題。

問題描述

為了能夠讓我後面的例項能夠貫穿這兩個工具的使用，我首先簡單描述下我們在開發中遇到的實際的效能問題。然後再引出這兩個效能工具的實際使用，看我們如何使用這兩個工具成功定位到效能瓶頸的。

問題如下：為了能夠支援丟失率，我們將原先log4j2 的Async+自定義Appender的方式進行了修正，把非同步的邏輯放到了自己改版後的Appender中。但我們發現修改後日誌效能要比之前Async+自定義Appender的方式下降不少。這裡由於隱私原因我並沒有用實際公司中的例項，這裡我用了一種其他同樣能夠體現問題的方式。我們暫時先不給出具體的配置檔案，先給出效能測試程式碼和結果。

程式碼

package com.bryantchang.appendertest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class AppenderTest {

    private static final String LOGGER_NAME_DEFAULT = "defaultLogger";
    private static final String LOGGER_NAME_INCLUDE = "includeLocationLogger";
    private static final Logger LOGGER = LoggerFactory.getLogger(LOGGER_NAME_INCLUDE);
    public static final long BATCH = 10000;

    public static void main(String[] args) throws InterruptedException {
        while(true) {
            long start, end;
            start = System.currentTimeMillis();
            for (int i = 0; i < BATCH; i++) {
                LOGGER.info("msg is {}", i);
            }
            end = System.currentTimeMillis();
            System.out.println("duration of " + LOGGER_NAME_INCLUDE +  " is " + (end - start) + "ms");
            Thread.sleep(1000);
        }
    }
}

程式碼邏輯及其簡單，就是呼叫logger.info每次列印10000條日誌，然後記錄耗時。兩者的對比如下。Java 技術資源分享（包括 Java 高階程式設計、架構師、SSM、微服務、Spring Cloud 、Spring全家桶）

從這兩張圖片中我們能夠看到同樣的邏輯，兩個程式的耗時差距相差了數十倍，但看圖片，貌似僅僅是logger的名稱不一樣。對上面的實驗結果進行分析，我們可能會有兩個疑問

• 上面的程式碼測試是否標準，規範
• 如果真的是效能問題，那麼這兩個程式碼到底在哪個方法上有了這麼大的差距導致了最終的效能差異

下面這兩個工具就分別來回答這兩個問題

JMH簡介

第一個問題就是，測試的方法是否標準。我們在編寫程式碼時用的是死迴圈+前後“掐秒錶”的方式。假如我們要再加個多執行緒的測試，我們還需要搞一個執行緒池，除了程式碼本身的邏輯還要關心測試的邏輯。我們會想，有沒有一款工具能夠將我們從測試邏輯中徹底解放出來，只需要關心我們需要測試的程式碼邏輯。JMH就是這樣一款Java的測試框架。下面是JMH的官方定義

JMH 是一個面向 Java 語言或者其他 Java 虛擬機器語言的效能基準測試框架

這裡面我們需要注意的是，JMH所測試的方法約簡單越好，依賴越少越好，最適合的場景就是，測試兩個集合put，get效能，例如ArrayList與LinkedList的對比等，這裡我們需要測試的是批量打一批日誌所需要的時間，也基本符合使用JMH的測試場景。下面是測試程式碼，bench框架程式碼以及主函式。

待測試方法

public class LogBenchMarkWorker {

    private LogBenchMarkWorker() {}

    private static class LogBenchMarkWorkerInstance {
        private static final LogBenchMarkWorker instance = new LogBenchMarkWorker();
    }

    public static LogBenchMarkWorker getInstance() {
        return LogBenchMarkWorkerInstance.instance;
    }

    private static final String LOGGER_DEFAULT_NAME = "defaultLogger";
    private static final String LOGGER_INCLUDE_LOCATION = "includeLocationLogger";
    private static final Logger LOGGER = LoggerFactory.getLogger(LOGGER_DEFAULT_NAME);
    private static long BATCH_SIZE = 10000;

    public void logBatch() {
        for (int i = 0; i < BATCH_SIZE; i++) {
            LOGGER.info("msg is {}", i);
        }
    }
}

可以看到待測試方法非常簡單，就是單批次一次性列印10000條日誌的操作，所以並沒有需要額外說明的部分。下面我們再來看benchmark部分。

public class LogBenchMarkMain {

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(1)
    public void testLog1() {
        LogBenchMarkWorker.getInstance().logBatch();
    }

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(4)
    public void testLog4() {
        LogBenchMarkWorker.getInstance().logBatch();
    }

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(8)
    public void testLog8() {
        LogBenchMarkWorker.getInstance().logBatch();
    }

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(16)
    public void testLog16() {
        LogBenchMarkWorker.getInstance().logBatch();
    }

在這段程式碼中，我們就會發現有了一些JMH中特有的東西，我下面進行簡要介紹。

Benchmark註解：標識在某個具體方法上，表示這個方法將是一個被測試的最小方法，在JMH中成為一個OPS
BenmarkMode:測試型別，JMH提供了幾種不同的Mode
    Throughput:整體吞吐量
    AverageTime:呼叫的平均時間，每次OPS執行的時間
    SampleTime:取樣，給出不同比例的ops時間，例如99%的ops時間，99.99%的ops時間
fork：fork的次數，如果設定為2，JMH會fork出兩個程式來測試
Threads：很容易理解，這個參數列示這個方法同時被多少個執行緒執行

在上面的程式碼中，我定義了4個待測試的方法，方法的Fork，BenchmarkMode均為測試單次OPS的平均時間，但4個方法的執行緒數不同。除了這幾個引數，還有幾個引數，我會在main函式裡面來講，main程式碼如下所示。Java 技術資源分享（包括 Java 高階程式設計、架構師、SSM、微服務、Spring Cloud 、Spring全家桶）

public class Main {
    public static void main(String[] args) throws RunnerException {
        Options options = new OptionsBuilder()
                .include(LogBenchMarkMain.class.getSimpleName())
                .warmupIterations(5)
                .measurementIterations(5)
                .output("logs/BenchmarkCommon.log")
                .build();
        new Runner(options).run();
    }
}

我們可以看到，在main函式中，我們就是要設定JMH的基礎配置，這裡面的幾個配置引數含義如下：

include:benchmark所在類的名字，可以使用正則表達
warmupIteration:預熱的迭代次數，這裡為什麼要預熱的原因是由於JIT的存在，隨著程式碼的執行，會動態對程式碼的執行進行優化。因此在測試過程中需要先預熱幾輪，讓程式碼執行穩定後再實際進行測試
measurementIterations:實際測試輪次
output:測試報告輸出位置

我分別用兩種logger執行一下測試，檢視效能測試報告對比

使用普通logger

LogBenchMarkMain.testLog1   avgt    5  0.006 ± 0.001   s/op
LogBenchMarkMain.testLog16  avgt    5  0.062 ± 0.026   s/op
LogBenchMarkMain.testLog4   avgt    5  0.006 ± 0.002   s/op
LogBenchMarkMain.testLog8   avgt    5  0.040 ± 0.004   s/op

使用了INCLUDE_LOCATION的logger

LogBenchMarkMain.testLog1   avgt    5  0.379 ± 0.007   s/op
LogBenchMarkMain.testLog16  avgt    5  1.784 ± 0.670   s/op
LogBenchMarkMain.testLog4   avgt    5  0.378 ± 0.003   s/op
LogBenchMarkMain.testLog8   avgt    5  0.776 ± 0.070   s/op

這裡我們看到，效能差距立現。使用INCLUDE_LOCATION的效能要明顯低於使用普通logger的效能。這是我們一定很好奇，並且問一句“到底慢在哪”！！

Arthas 我的程式碼在執行時到底做了什麼

Arthas是阿里開源的一款java除錯神器，與greys類似，不過有著比greys更加強大的功能，例如，可以直接繪製java方法呼叫的火焰圖等。這兩個工具的原理都是使用了Java強大的位元組碼技術。畢竟我也不是JVM大佬，所以具體的實現細節沒法展開，我們要做的就是站在巨人的肩膀上，接受並用熟練的使用好這些好用的效能監控工具。

實際操作

talk is cheap, show me your code,既然是工具，我們直接進行實際操作。我們在本機執行我們一開始的程式，然後講解arthas的使用方法。

我們首先通過jps找到程式的程式號，然後直接通過arthas給到的as.sh對我們執行的程式進行位元組碼增強，然後啟動arthas，命令如下

./as.sh pid

可以看到，arthas支援檢視當前jvm的狀態，檢視當前的執行緒狀態，監控某些方法的呼叫時間，trace，profile生成火焰圖等，功能一應俱全 我們這裡也只將幾個比較常用的命令，其他的命令如果大家感興趣可以詳見官網arthas官網。這篇文章主要介紹下面幾個功能

• 反編譯程式碼
• 監控某個方法的呼叫
• 檢視某個方法的呼叫和返回值
• trace某個方法

監控方法呼叫

這個主要的命令為monitor，根據官網的介紹，常用的使用方法為

monitor -c duration className methodName

其中duration代表每隔幾秒展示一次統計結果，即單次的統計週期，className就是類的全限定名，methodname就是方法的名字，這裡面我們檢視的方法是Logger類的info方法，我們分別對使用兩種不同logger的info方法。這裡面的類是org.slf4j.Logger，方法時info，我們的監控語句為

monitor -c 5 org.slf4j.Logger info

監控結果如下

使用普通appender

我們可以看到，使用include appeder的列印日誌方法要比普通的appender高出了3倍，這就不禁讓我們有了疑問，究竟這兩個方法各個步驟耗時如何呢。下面我們就介紹第二條命令，trace方法。

trace命令 & jad命令

這兩個程式的log4j2配置檔案如下

<?xml version="1.0" encoding="UTF-8"?>
<!--status：日誌等級   monitorInterval：更新配置檔案的時間間隔，單位秒-->
<configuration status="warn" monitorInterval="30">
    <!--定義所有的appender -->
    <appenders>
        <!--這個輸出控制檯的配置 -->
        <Console name="console" target="SYSTEM_OUT">
            <!--控制檯只輸出level及以上級別的資訊（onMatch），其他的直接拒絕（onMismatch） -->
            <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
            <!--日誌列印格式 -->
            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] [%-5p] %l - %m%n"/>
        </Console>


        <Async name="AsyncDefault" blocking="false" includeLocation="false">
            <AppenderRef ref="fileAppender"/>
        </Async>

        <Async name="AsyncIncludeLocation" blocking="false" includeLocation="true">
            <AppenderRef ref="fileAppender"/>
        </Async>

        <!--檔案會列印出所有資訊，這個log每次執行程式會自動清空，由append屬性決定，這個也挺有用的，適合臨時測試用 -->
        <!--append為TRUE表示訊息增加到指定檔案中，false表示訊息覆蓋指定的檔案內容，預設值是true -->
        <File name="fileAppender" fileName="log/test.log" append="false">
            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] [%-5p] %l - %m%n"/>
        </File>

        <!--新增過濾器ThresholdFilter,可以有選擇的輸出某個級別以上的類別  onMatch="ACCEPT" onMismatch="DENY"意思是匹配就接受,否則直接拒絕  -->
        <File name="ERROR" fileName="logs/error.log">
            <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="[%d{yyyy.MM.dd 'at' HH:mm:ss z}] [%-5p] %l - %m%n"/>
        </File>

        <!--這個會列印出所有的資訊，每次大小超過size，則這size大小的日誌會自動存入按年份-月份建立的資料夾下面並進行壓縮，作為存檔 -->
        <RollingFile name="rollingFile" fileName="logs/app.log"
                     filePattern="logs/$${date:yyyy-MM}/web-%d{yyyy-MM-dd}.log.gz">
            <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss}] [%-5p] %l - %m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="logs" maxDepth="2">
                    <IfFileName glob="*/*.log.gz" />
                    <IfLastModified age="7d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </appenders>

    <!--然後定義logger，只有定義了logger並引入的appender，appender才會生效 -->
    <loggers>
        <!--過濾掉spring和mybatis的一些無用的DEBUG資訊-->
        <logger name="defaultLogger" additivity="false">
            <appender-ref ref="AsyncDefault"></appender-ref>
        </logger>

        <logger name="includeLocationLogger" additivity="false">
            <appender-ref ref="AsyncIncludeLocation"></appender-ref>
        </logger>

        <!--建立一個預設的root的logger -->
        <root level="INFO">

        </root>
    </loggers>

</configuration>

我們都是用了一個AsyncAppender套用了一個FileAppender。檢視fileAppender，發現二者相同完全沒區別，只有asyncAppender中的一個選項有區別，這就是includeLocation，一個是false，另一個是true。至於這個引數的含義，我們暫時不討論，我們現在知道問題可能出在AsyncAppender裡面，但是我們該如何驗證呢。trace命令就有了大用場。

trace命令的基本用法與monitor類似，其中主要的一個引數是-n則是代表trace多少次的意思

trace -n trace_times className methodName

我在之前Log4j2的相關部落格裡面講到過，任何一個appender，最核心的方法就是他的append方法。所以我們分別trace兩個程式的append方法。

trace -n 5 org.apache.logging.log4j.core.appender.AsyncAppender append

trace結果如下

使用普通appender

我們立刻可以發現，兩個trace的熱點方法不一樣，在使用include的appender中，耗時最長的方法時org.apache.logging.log4j.core.impl.Log4jLogEvent類中的createMemento方法，那麼怎麼才能知道這個方法到底做了啥呢，那就請出我們下一個常用命令jad，這個命令能夠反編譯出對應方法的程式碼。這裡我們jad一下上面說的那個createMemento方法，命令很簡單

jad org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento

結果如下

watch命令

watch命令能夠觀察到某個特定方法的入參，返回值等資訊，我們使用這個命令檢視一下這個createMemento方法的入參，如果兩個程式的入參不同，那基本可以斷定是這個原因引起命令如下

watch org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento "params" -x 2 -n 5 -b -f

這裡面的引數含義如下

• -x 引數展開層次
• -n 執行次數
• -b 檢視方法呼叫前狀態
• -f 方法呼叫後

其中的param代表檢視方法的呼叫引數列表，還有其他的監控項詳見官網官網

最終watch結果如下

使用普通logger

果不其然，這兩個引數果然是一個true一個false，我們簡單看下這個引數是如何傳進來的，我們jad一下AsyncAppender的append方法

不過為了一探究竟，我還是靜態跟了一下這段程式碼

這個includeLocation會在event的createMemento中被用到，在序列化生成物件時會建立一個LogEventProxy，程式碼如下

public LogEventProxy(final LogEvent event, final boolean includeLocation) {
    this.loggerFQCN = event.getLoggerFqcn();
    this.marker = event.getMarker();
    this.level = event.getLevel();
    this.loggerName = event.getLoggerName();

    final Message msg = event.getMessage();
    this.message = msg instanceof ReusableMessage
            ? memento((ReusableMessage) msg)
            : msg;
    this.timeMillis = event.getTimeMillis();
    this.thrown = event.getThrown();
    this.thrownProxy = event.getThrownProxy();
    this.contextData = memento(event.getContextData());
    this.contextStack = event.getContextStack();
    this.source = includeLocation ? event.getSource() : null;
    this.threadId = event.getThreadId();
    this.threadName = event.getThreadName();
    this.threadPriority = event.getThreadPriority();
    this.isLocationRequired = includeLocation;
    this.isEndOfBatch = event.isEndOfBatch();
    this.nanoTime = event.getNanoTime();
}

如果includeLocation為true，那麼就會呼叫getSource函式，跟進去檢視，程式碼如下

public StackTraceElement getSource() {
        if (source != null) {
            return source;
        }
        if (loggerFqcn == null || !includeLocation) {
            return null;
        }
        source = Log4jLogEvent.calcLocation(loggerFqcn);
        return source;
    }
     public static StackTraceElement calcLocation(final String fqcnOfLogger) {
        if (fqcnOfLogger == null) {
            return null;
        }
        // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().
        final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
        StackTraceElement last = null;
        for (int i = stackTrace.length - 1; i > 0; i--) {
            final String className = stackTrace[i].getClassName();
            if (fqcnOfLogger.equals(className)) {
                return last;
            }
            last = stackTrace[i];
        }
        return null;
    }

我們看到他會從整個的呼叫棧中去尋找呼叫這個方法的程式碼行，其效能可想而知。我們用arthas監控一下，驗證一下。

首先我們trace crateMemento方法

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent serialize

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent$LogEventProxy <init>

trace -n 5 trace -n 5 org.apache.logging.log4j.core.LogEvent getSource

至此我們通過結合JMH和arthas共同定位出了一個線上的效能問題。不過我介紹的只是冰山一角，更多常用的命令還希望大家通過官網自己瞭解和實踐，有了幾次親身實踐之後，這個工具也就玩熟了。

來源 | bryantchang.github.io/2019/12/08/java-profile-tools/