高併發下log4j的效能瓶頸

開篇

 近期由於業務需要進行業務遷移，期間因為誤設定log4j的日誌級別，導致系統效能整體下降，具體表現在QPS下降明顯，系統RT上升。遷移期間由於各類系統環境較原來有較大差別，因為在排查過程中也走了一些彎路，總結起來避免他人再次踩坑。

問題背景

 問題的背景其實很簡單，線上系統的log4j的日誌級別由warn調整為info，導致大量的呼叫log4j的日誌介面，導致系統的rt上升伴隨著qps下降，具體的影響效果可以看下圖。
 需要額外解釋的就是log4j的這個問題需要在qps較大的情況下才會復現，按照我遇到的情況基本上需要在2k/s以上會比較明顯（資料不一定非常準確），只是為了說明需要在大量請求的情況才會觸發synchronized的問題。
 當然問題的本質在於大量呼叫log4j的日誌介面，導致競爭synchronized影響效能，影響的時間應該也是在ms級別，這其實在另外一個方面說明了只求非常極致追求效能問題才會細緻的去分析這些問題。

優化效果

 優化後qps的提升效果圖，這邊是以分鐘進行統計的。

 優化後系統的響應時間效果圖。

現象分析

 整個分析過程其實並不是那麼具有條理性，只是現在總結起來看上去像那麼回事。

• 對比兩套系統的差異點，發現系統的log4j的日誌級別不一致，嘗試修改日誌級別觀察效果。
• 發現日誌級別調高後系統效能明顯提升，開始懷疑log4j的問題併網上查閱資料。
• jstack列印對應的日誌，發現在不同日誌級別情況下下面的BLOCKED的日誌數量不一樣。
• 發現競爭鎖的日誌waiting to lock <0x00007f3a04020830>。
• 觀察jstack日誌並找到log4j的原始碼發現程式碼當中有同步鎖關鍵字synchronized。

#514 daemon prio=5 os_prio=0 tid=0x00007f369002f800 nid=0x561a waiting for monitor entry [0x00007f348fb96000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    - waiting to lock <0x00007f3a04020830> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)


#521 daemon prio=5 os_prio=0 tid=0x00007f367c042800 nid=0x5617 waiting for monitor entry [0x00007f348fe99000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    - waiting to lock <0x00007f3a04020830> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)

原因分析

 直接定位log4j的原始碼位置，發現synchronized的關鍵字，基本上這時候其實是驗證之前的猜想而已。
關於synchronized的效能問題，可以網上去參考java幾種鎖的效能對比，只記得一個簡單的結論synchronized在大量競爭的情況下劣勢比較明顯各種同步方法效能比較（synchronized,ReentrantLock,Atomic）。

  void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized(c) {
    if(c.aai != null) {
      writes += c.aai.appendLoopOnAppenders(event);
    }
    if(!c.additive) {
      break;
    }
      }
    }

    if(writes == 0) {
      repository.emitNoAppenderWarning(this);
    }
  }

心得

 老大曾說過，凡事做個有心人，會發現更多的東西。