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

時間 2019-11-20

原文原文鏈接

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

1.背景

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

2.改造準備

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

2.1 修改寫消息到文件代碼

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

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 比較慢，因而將其改成異步。app

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);

}