背景
在一次項目的性能調優中，發現出現競爭瓶頸，導致在資源未使用滿的情況下，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倍）！