淺談融雲即時通訊服務「日誌優化」

《神探狄仁傑》劇迷們對狄仁傑的斷案能力極為歎服，狄大人總是能將非常詭異的案件查得水落石出，連武則天都贊他“神乎其技”。實際上，狄仁傑之所以被稱為“神探”，很大一部分原因，是他擅長通過極為細小的線索推導、還原，進而破案。關注【融雲 RongCloud】，瞭解協同辦公平臺更多幹貨。

對應到軟體開發上，用來記錄系統或程式執行狀態的日誌，已成為程式執行問題的重要“線索”，它可以記錄程式執行過程，快速定位問題，便於程式的監控和優化。

日誌使用

Java 領域有多種日誌框架，Log4j2 是其中一種。Log4j2 憑藉可配置化的整合方式、簡單的 API、強大的功能及效能優勢，成為 Java 領域使用最廣泛的日誌解決方案。

融雲即時通訊服務的日誌框架選擇的就是 Log4j2。

日誌級別

Log4j2 定義了 8 個日誌級別，分別是：OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、 ALL。其中常用的日誌級別是4個，優先順序從低到高為 DEBUG、INFO、WARN、ERROR。

DEBUG
指定細粒度資訊事件是最有用的應用程式除錯，主要用於開發過程中列印一些執行資訊。

INFO
指定能夠突出在粗粒度級別的應用程式執行情況的資訊，可以幫助程式設計師有效瞭解程式的流轉，可用於生產環境中輸出程式執行的一些重要資訊。

WARN
指定具有潛在危害的情況，有些資訊是錯誤資訊，但也需要給程式設計師的一些提示。

ERROR
錯誤事件，可能仍然允許應用程式繼續執行，列印錯誤和異常資訊。

日誌效能

日誌列印對伺服器效能產生損耗，會增大服務的延遲，降低服務吞吐量。尤其在高併發大業務量情況下，日誌列印得越多，服務的效能損耗越大。

即時通訊服務在進行壓力測試過程中，開啟 INFO 級別日誌與開啟 ERROR 級別日誌做比較，隨著業務量級的增大，服務的效能損耗也不斷增大。

而在實際執行中，因私有化部署的約束和對問題排查便利性的考慮，即時通訊服務往往是開啟 INFO 級別日誌，這就對在 INFO 級別下即時通訊服務的效能提出了更嚴峻的考驗和更高的要求。

為此，融雲即時通訊服務除了做好日誌級別分類和日誌內容精簡外，還進行了相關優化。

日誌優化

關閉 Location 資訊

如果 Log4j 配置了%C or $class, %F or %file, %l or %location, %L or %line, %M or %method 等配置項，Log4j 將會獲取堆疊的快照，遍歷堆疊軌跡來獲取 Location 資訊，從而影響效能。

對於同步日誌記錄器來說，速度要慢 1.3 - 5 倍；對於非同步日誌記錄器而言，獲取堆疊快照的效能影響甚至更大，因為有位置的日誌記錄比沒有位置的日誌記錄慢 30-100 倍。因此，非同步日誌記錄器和非同步附加器在預設情況下不包含位置資訊。

所以，融雲即時通訊服務去掉了 %C or $class, %F or %file, %l or %location, %L or %line, %M or %method 等配置，通過在日誌中新增類名以及埋點標識的方式用於快速定位問題程式碼。

使用 Async Loggers

Asynchronous Loggers 是Log4j2中的一個新功能，它們的目標是從對 Logger.log 的呼叫盡快返回到應用程式。

LMAX Disruptor
Asynchronous Loggers 使用了 Disruptor，Disruotor 是一個無鎖的執行緒間通訊庫，不使用佇列，獲得了更高的吞吐量和更低的延遲，可通過 Maven 引入。

優勢
a. 更高的峰值吞吐量
使用非同步日誌記錄器，應用程式可以以 6 – 68 倍於同步日誌記錄器的速度記錄訊息。
b. 更低的響應延遲
響應延遲是在一定工作負載下呼叫 Logger.log 返回所需的時間。

劣勢
錯誤處理。如果在日誌記錄過程中出現問題並丟擲異常，那麼 Asynchronous Logger 或 Appender 不太容易嚮應用程式暴露此問題。不過，可通過混合同步和非同步日誌記錄器的方式處理，即同步和非同步日誌記錄器在配置中組合使用。

全部非同步日誌記錄器

可通過以下方式使所有日誌記錄器非同步。將 disruptor 的 jar 新增到環境變數，並設定服務啟動的 JVM 引數，增加

-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

或

-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.BasicAsyncLoggerContextSelector

混合同步和非同步日誌記錄器

同步和非同步日誌記錄器可以在配置中組合使用，這樣可提供更大的靈活性，但與所有日誌記錄器都是非同步的相比效能略有下降。

效能比較

吞吐量

下圖比較了同步日誌記錄器、非同步 Appender 記錄器和非同步日誌記錄器的吞吐量，這是所有執行緒的總吞吐量。在使用64個執行緒的測試中，非同步日誌記錄器的速度比非同步 Appender 記錄器快 12 倍，比同步日誌記錄器快 68 倍。非同步日誌記錄器的吞吐量隨著執行緒數量的增加而增長，但是不管記錄日誌的執行緒數多少，同步日誌記錄器和非同步 Appender 記錄器的吞吐量基本不變。

下圖將非同步日誌記錄的峰值吞吐量與其他日誌框架中的非同步 Appender 記錄的峰值吞吐量進行了比較，與上圖結果類似。非同步 Appender 記錄器，在新增更多執行緒時，執行緒的日誌吞吐量基本保持不變,非同步日誌記錄器在多執行緒場景中能更有效地利用機器上可用的多個核心。

響應延遲

下圖比較了 Logback 1.1.7、Log4j 1.2.17 與 Log4j 2.6 各種非同步日誌記錄選項的響應時間延遲，可看到 Logback 1.1.7、Log4j 1.2.17 的延遲峰值比 Log4j 2 大了很多數量級。

下圖比較了相同測試的 log4j2 結果，可看到基於ArrayBlockingQueue 的 Async Appender 的響應時間最高， Garbage-free Async Loggers 具有最佳響應時間。