使用Async-profiler 對程序性能優化實戰

原文在簡書上，
https://www.jianshu.com/p/f8336b835978

1.背景

目前有一個kafka消費者工程,此工程會消費kafka中的消息，並通過fastjson解析該消息為java實體，然后存入到阻塞隊列 BlockingQueue中。另外有若干個線程會從queue中批量拿消息，然后以批量形式寫入到 elasticsearch 中。目前在使用中發現存在性能瓶頸，需要定位是該工程對消息轉化處理較慢，還是寫es操作比較慢。

2.改造准備

為測試此工程最大處理速率，並排出寫 es 的干擾，於是打算直接將最后寫es這一步替換為寫入到本地日志文件中，來看看其處理性能如何。

2.1 修改寫消息到文件代碼

1.將寫es的邏輯改為直接寫入到本地單獨的日志文件

2.單獨的日志logger 命名為 dummy.es.transport

3.使用計數器，每寫入一條消息，就記錄一次，然后通過定時線程每秒打印一次請求速率。

@Component
public class DummyEsTransportOpt {
    /**
     * 定義 dummy.es.transport 作為logger名,將所有收到的消息追加到指定的日志文件中去.
     */
    private static Logger esLogger = LoggerFactory.getLogger("dummy.es.transport");

    private static Logger logger = LoggerFactory.getLogger(DummyEsTransportOpt.class);

    private static ScheduledExecutorService schedule = Executors.newScheduledThreadPool(1);

    /**
     * 消息插入計數器,記錄處理消息數並計算每秒處理速度.
     */
    private static AtomicLong counter = new AtomicLong();

    private static long initialCounter = 0L;

    /**
     * 寫 es 消息主要通過這個方法進行批量寫，這里直接替換為記錄到本地日志中。
     */
    public <T extends BaseElasticsearchEntity> boolean batchAddDocument(List<T> entityList) {

        for (int i = 0; i < entityList.size(); i++) {
            //計數器,以判斷速率.
            counter.incrementAndGet();
            T t = entityList.get(i);
            String json = JSON.toJSONString(t);
            if (t instanceof Annotation) {
                //esLogger 為專門的寫消息的日志文件 appender.
                esLogger.info("A => " + json);
            } else {
                esLogger.info("S => " + json);
            }
        }
        return true;
    }
    /**
     * schedule 統計
     */
    static {
        schedule.scheduleAtFixedRate(new Runnable() {
            @Override
            public void run() {
                long count = counter.get();
                logger.info("運行已處理消息數量: " + count + ",對比上一秒處理速率: " + (count - initialCounter) + "/s");
                initialCounter = count;
            }
        }, 0, 1, TimeUnit.SECONDS);
    }
}

2.2 日志輸出配置

日志框架使用的是 log4j, 單獨配置 dummyEsAppender, logger 名為 dummy.es.transport 的日志將會寫入到 dummy-es-transport.log 這個文件中。

<appender name="dummyEsAppender" class="org.apache.log4j.DailyRollingFileAppender">

    <param name="File" value="./logs/dummy-es-transport.log"/>

    <param name="DatePattern" value="'.'yyyy-MM-dd'.log'"/>

    <layout class="org.apache.log4j.PatternLayout">

        <param name="ConversionPattern"

               value="[%d{yyyy-MM-dd HH:mm:ss SSS\} %-5p] [%t] %c.%M() - %m%n"/>

    </layout>

</appender>

<logger name="dummy.es.transport" additivity="false">

    <level value="info"/>

    <appender-ref ref="dummyEsAppender"/>

</logger>

3.測試

3.1第一次測試

打包程序上線運行,觀察定時線程每秒打印的速率，大概每秒處理寫入的消息為 23000條/s。

有點疑惑這個處理速率是不是太低了一點。懷疑日志框架同步 appender 比較慢，於是將其改為異步。

3.2 第二次測試

日志輸出同步轉異步

在同步模式的基礎上，增加異步的配置模式:

<logger name="dummy.es.transport" additivity="false">
    <level value="info"/>
    <appender-ref ref="async"/>
</logger>

<appender name="async" class="org.apache.log4j.AsyncAppender">
    <param name="BufferSize" value="500"/>
    <appender-ref ref="dummyEsAppender"/>
</appender>

修改好之后，重新啟動程序，觀察處理速率。此時發現處理速度在 4萬/s 左右。

將日志級別調整為 warn，即不輸出日志，重新啟動程序，再次觀察。此時速度能夠達到 70000/s

想不通為什么日志appender的性能消耗這么嚴重，正當不知道如下下手時，領導推薦使用 async-profiler 來定位時間到底耗在了哪里。

4. Async-profiler 和 火焰圖分析

Async-profiler 可以觀測運行程序，每一段代碼所占用的cpu的時間和比例,從而可以分析並找到項目中占用cpu時間最長的代碼片段，優化熱點代碼，達到優化內存的效果。

4.1采集cpu profile數據

我們將代碼回退到第一次測試的情況,並啟動程序，並找到當前進程號(627891)，然后通過如下命令進行采集，並轉換為火焰圖格式 svg。

./profiler.sh -d 15 -i 50ms -o svg -e cpu 627891  > 627891.svg

• -d N   分析持續時間（以秒為單位）。如果未提供啟動，恢復，停止或狀態選項，則探查器將運行指定的時間段，然后自動停止

• -i N 設置分析間隔(以納秒或者毫秒等作為單位),默認分析間隔為10ms

• -o  specifies what information to dump when profiling ends,如果選擇 svg,produce Flame Graph in SVG format.

等待15s，就會產生結果，生成 627891.svg 文件。vim 627891.svg 並刪除第一行，然后下載到本地並使用瀏覽器打開。

結果如下圖，此圖俗稱火焰圖，主要看每個方法的橫軸長度，占用橫坐標越長的操作，其占用的 cpu 即最長，很直觀的。

4.2 性能黑點分析

我們首先發現下圖紅框內的代碼存在嚴重的性能問題。在append的過程中，獲取線程 stack 的過程耗時比較大。從火焰圖中分析，耗時占據了接近50%的是，一個logger操作中去拿線程堆棧的過程，那么我們打印的日志的時候，為啥會進行這個操作呢？

首先觀察消息日志文件,和一般的日志不同,這里還會打印方法名稱，即當前日志時在哪個方法下打印出來的。那么日志框架它是通過線程 stack 去獲取到方法名稱的，如果配置了 %L,即打印日志所在代碼行的情況也是同理。

[2019-10-07 11:50:38 251 INFO ] [PoolDrainDataThreadPool-3] dummy.es.transport.batchAddDocument() - A => {"@timestamp":"2019-10-07T03:50:38.251Z","ipv4":"10.0.49.96:14160;10.0.49.85:14159;10.0.49.85:14160;10.0.49.84:14160;10.0.49.97:14160;10.0.49.96:14159;10.0.49.89:14159;10.0.49.97:14159;10.0.49.86:14159;10.0.49.84:14159;10.0.49.86:14160;10.0.49.89:14160","key":"ss","serviceName":"Redis","spanId":"-496431972509502272","startTs":1570420237,"tag":-1,"timestamp":1570420237329,"traceId":"-2375955836973083482"}

[2019-10-07 11:50:38 251 INFO ] [PoolDrainDataThreadPool-3] dummy.es.transport.batchAddDocument() - A => {"@timestamp":"2019-10-07T03:50:38.251Z","ipv4":"10.0.49.96:14160;10.0.49.85:14159;10.0.49.85:14160;10.0.49.84:14160;10.0.49.97:14160;10.0.49.96:14159;10.0.49.89:14159;10.0.49.97:14159;10.0.49.86:14159;10.0.49.84:14159;10.0.49.86:14160;10.0.49.89:14160","key":"ss","serviceName":"Redis","spanId":"6195051521513685066","startTs":1570420237,"tag":-1,"timestamp":1570420237333,"traceId":"-2375955836973083482"}

觀察配置的日志格式:

<appender name="dummyEsAppender" class="org.apache.log4j.DailyRollingFileAppender">
    <param name="File" value="./logs/dummy-es-transport.log"/>
    <param name="DatePattern" value="'.'yyyy-MM-dd'.log'"/>
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern"
               value="[%d{yyyy-MM-dd HH:mm:ss SSS\} %-5p] [%t] %c.%M() - %m%n"/>
    </layout>
</appender>

注意輸出格式中的 %M() 一行，這里意味着在打印日志的時候，需要打印當前日志所在執行的方法，這樣看來，這個操作嚴重影響到了性能。

4.3 日志配置規則去除方法名

修改一下日志 append 格式,去掉方法輸出，處理速率一下子就達到了7萬多。

采用上文中的方法繼續使用 async-profiler 生成火焰圖，並用瀏覽器打開。這時候,日志 append 操作所占用的橫軸長度顯著下降，並且此時速度已經達到了關閉日志append 時的速度，說明修改日志輸出格式后能夠帶來顯著的性能提升。

但是觀測上圖，我們發現了新的性能黑點，如紅框所述，我們將其展開,見詳細圖:

這里主要是一個 toHexString 的操作，竟然占用的cpu資源這么大，這里需要定位。

4.4 ObjectId.toHexString 性能優化

查看這一步轉換為16進制的字符串的代碼如下，我們結合上面的火焰圖可以看出來，主要耗時是在 String.format()

這一步操作。

private String toHexString() {

    StringBuilder buf = new StringBuilder(24);

    byte[] bytes = new byte[12];

    bytes[0] = int3(this.timestamp);

    bytes[1] = int2(this.timestamp);

    bytes[2] = int1(this.timestamp);    

    bytes[3] = int0(this.timestamp);

    bytes[4] = int2(this.machineIdentifier);

    bytes[5] = int1(this.machineIdentifier);

    bytes[6] = int0(this.machineIdentifier);

    bytes[7] = short1(this.processIdentifier);

    bytes[8] = short0(this.processIdentifier);

    bytes[9] = int2(this.counter);

    bytes[10] = int1(this.counter);

    bytes[11] = int0(this.counter);  

    for (byte b : bytes) {

        buf.append(String.format("%02x", new Object[]{Integer.valueOf(b & 0xFF)}));

    }

    return buf.toString();

}

上面這種模式存在比較大的性能問題。
byte 數組轉換為 16進制字符串性能最好的代碼：

private static final char[] HEX_ARRAY = "0123456789ABCDEF".toCharArray();

private String toHexString2() {
      //這一步獲取到bytes數組，和上面的操作相同，單獨抽離出來。
   byte[] bytes = this.toByteArray();

    char[] hexChars = new char[bytes.length * 2];

    for (int j = 0; j < bytes.length; j++) {

        int v = bytes[j] & 0xFF;

        hexChars[j * 2] = HEX_ARRAY[v >>> 4];

        hexChars[j * 2 + 1] = HEX_ARRAY[v & 0x0F];

    }

    return new String(hexChars);

}

4.5 重新測試

修改完耗時的 toHexString() 操作之后，打包上傳到服務器，並重新啟動程序，此時發現每秒處理速率已經飆升到了 12萬。這種使用頻繁又耗時的黑點操作解決以后，果然性能能夠得到翻倍的提升。

此時日志輸出格式已經優化，並且 toHexString(）操作也進行了優化。重新使用 async-profiler 查看一下最新的火焰圖信息。

之前的 toHexString() 耗時已經幾乎看不到了，但是感覺日志append 的操作橫軸還是略長，於是將日志輸出關閉來看看極限處理速度。

將日志級別調整為 warn,並啟動程序，觀測到處理速度已經能夠達到 18萬/s了，這相當於 toHexString(）優化前的快3倍了。

此時決定再將日志append 模式改為異步模式，然后啟動程序，觀察，處理速率也能夠達到 18萬/s。

總結

從最開始的 2萬/s 的處理速率提升到 18萬/s。這個提升還是很驚人的，而如果沒有使用 火焰圖進行定位，或許我並不能找到這個程序處理耗時到底耗在哪里。得益於 async-profiler 此神器，能夠非常直觀的進行定位。

日志框架打印方法名或者行號的模式對比正常模式其性能理論上下降至少有10倍，通過本文的逐步分析，我們也能夠看到，確實其性能降低是非常明顯的。建議日志框架禁止打印方法名稱和行號的操作。