一次logback多線程調優的經歷

背景

  在一次項目的性能調優中，發現出現競爭瓶頸，致使在資源未使用滿的狀況下，TPS已經沒法提高。祭起JMC（JAVA MISSON CONTROL）飛行記錄器大法後，發現線程集中等待在logback寫日誌的地方，以下圖所示：

  因爲項目組多線程寫如同一個文件日誌，致使存在IO競爭，通常解決這種問題有三種選擇方式
：

• 異步日誌，可是會存在斷電或者日誌隊列溢出丟失的可能
• 遠程日誌，日誌放入外部消息隊列，保證持久化，但需額外部署日誌存儲隊列
• 多線程日誌，按線程（或線程取模）記錄日誌，減小競爭，日誌也能保證持久化

  項目組權衡再三，決定採用第三種分線程日誌的方式解決。

誤入SiftingAppender大坑

  項目組使用logback做爲日誌組件，loback是否有自動分線程寫日誌的功能呢？網上搜索logack multiThread 的第一篇文章就是教你如何使用SiftingAppender來分線程記錄日誌以下：
https://dzone.com/articles/si...
  SiftingAppender是logback根據mdc中的變量動態建立appender的代理，只要咱們將一個線程號做爲日誌名分發器discriminator注入到SiftingAppender中，它就能夠動態的爲咱們建立不一樣的appender，達到分線程的目的，配置方式舉例以下：

• 配置discriminator

public class ThreadDiscriminator extends ContextBasedDiscriminator {
    String KEY ="threadName";
    /**
     * Return the name of the current context name as found in the logging event.
     */
    public String getDiscriminatingValue(ILoggingEvent event) {
        return event.getThreadName();
    }
    
    public String getDefaultValue() {
        return KEY;
    }
    
    public String getKey() {
        return KEY;
    }
    
    public void setKey(String key) {
        this.KEY = key;
    }
}

• 配置logback appender

<!-- 分線程輸出源 -->
    <appender name="frameworkthread" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator class="ThreadDiscriminator">
            <key>threadName</key>
        </discriminator>
        <sift>
            <appender name="FILE-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <encoder>
                    <Encoding>UTF-8</Encoding>
                    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}[%c][%thread][%X{tradeNo}][%p]-%m%n</pattern>
                </encoder>
                <rollingPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">        
                    <fileNamePattern>D:/test/threadlogs/${threadName}-%d{yyyy-MM-dd}.%i.log
                    </fileNamePattern>
                    <maxFileSize>100MB</maxFileSize>
                    <maxHistory>60</maxHistory>
                    <totalSizeCap>20GB</totalSizeCap>
                </rollingPolicy>
            </appender>
        </sift>
    </appender>

  配置後查看輸出結果也徹底正確，網上的方法很是靠譜，真是piece of cake！可是接下來的性能測試讓我再次懵逼：性能沒有任何提高！反而更加糟糕了！這是怎麼一回事呢？繼續jmc查看線程狀態：

  此次寫文件outputStream的IO等待居然提高到了AppenderBase.doAppender方法級別！查看AppenderBase.doAppender實現，這個方法是Synchronized！這個父類的方法是SiftingAppender的入口方法，這意味着在獲取/建立線程本身真正的Appender和寫入日誌以前都必須排隊阻塞在這個方法上！阻塞的級別提高了，固然性能更糟糕了！

優化logback：增長無需同步的SiftAppender

  logback Appender有兩個最基礎的抽象類，一個是同步AppenderBase，一個是不一樣步的UnsynchronizedAppenderBase，這兩個類功能同樣，只是doAppender方法的同步策略不同（Synchronize VS ThreadLocal）。那麼SiftingAppender爲何繼承了AppenderBase而不是UnsynchronizedAppenderBase呢？分析緣由應該是SiftingAppender做爲Appender的代理集合，它便可能包含了繼承自UnsynchronizedAppenderBase的OutputStreamAppender（FileAppender的基類，自行實現底層同步，doAppend方法未同步），也可能包含了繼承AppenderBase的SocketAppender類（doAppend方法同步），爲防止出現線程安全問題，它直接在自身的doAppend方法上進行了同步。
  在項目組實際使用時，項目組只須要分線程寫文件日誌，這意味這它使用的最終FileAppender應該是線程安全，徹底獨立的。故咱們嘗試在logback新增繼承於UnsynchronizedAppenderBase的ParrelSiftingAppender步驟以下：

• logback core中增長繼承UnsynchronizedAppenderBase的UnsynchronizedSiftingAppenderBase
• logback classic中增長繼承UnsynchronizedSiftingAppenderBase的ParrelSiftingAppender
• logback classic中SiftAction註冊增長ParrelSiftingAppender的工廠註冊

  修改完成後測試發現果真性能提高了5倍左右，CPU資源利用率接近飽和，應該基本達到效果了，JMC分析應該是沒有競爭了把，可是發現新的競爭方法出現了：

Appender<E> appender = appenderTracker.getOrCreate(discriminatingValue, timestamp);

最終改進：使用ConcurrentHashMap替換LinkedHashMap

  原來在SiftingAppender內部使用了LinkedHashMap做爲LRU Cache來管理Appender，會按期移除。因爲LinkedHashMap不是線程安全的，故在getOrCreate方法上增長了Synchronized同步操做，形成競爭等待。
  結合業務場景，這裏徹底可使用ConcurrentHashMap做爲Appender的緩存，ConcurrentHashMap讀寫鎖分離，而且key值分區上鎖，在多讀少寫的狀況下，有很高的併發性能。而且真正生成的日誌Appender也並很少（100個左右），定時清理徹底也不會出現內存溢出問題。
  開始動手修改appenderTracker步驟以下：

• logback core中增長AbstractConcurrentMapComponentTracker
• logback core中增長ConcurrentMapAppenderTracker繼承

AbstractConcurrentMapComponentTracker

• 修改UnsynchronizedSiftingAppenderBase使用ConcurrentMapAppenderTracker進行Appender管理

  最終性能測試結果：在資源相同的狀況下，優化後比使用LinkedHashMap性能提升一倍。至此，整個logback多線程調優結束，經過充分優化同步競爭的方式，最終使得分線程記錄日誌的性能比最原始的多線程寫同一文件提升了10倍（SiftAppender去鎖提升到5倍，Map替換提升2倍）！