淺析JAVA日誌中的幾則效能實踐與原理解釋

Logger logger = LogFactory.getLogger("PoweredByEDAS");
String product = "EDAS";logger.info("This is powered by product: " + product);

這一篇文章是想透過幾個技術點來說明日誌記錄過程中的效能實踐，計算機領域的效能往往都遵循著冰山法則，即你能看得見的、程式設計師能感知的只是其中的一小部分，還有大量的細節隱藏在冰山之下，如下圖所示：

<Appenders>  <CountingNoOp name="NoOp">  </CountingNoOp></Appenders>

1. 與只寫入記憶體的吞吐量相比，二者的吞吐量隨著日誌內容的變大差距越來越大。

2. 同時隨著輸出內容的數量變多，在磁碟場景下呈現明顯的下滑趨勢，隨著內容的增多，呈現逐漸趨平的趨勢。

壓縮Logger輸出：

package com.alibabacloud.edas.demo;
public class PoweredByEdas {  private static Logger logger = LogFactory.getLogger(        ProweredByEdas.class);
    public void execute() {        String product = "EDAS";         logger.info("Prowered by " + product);    }}

而在進行日誌輸出時，如果 logger 是 Class 將預設輸出對應它所對應的 FQCN，即：com.alibabacloud.edas.demo.PoweredByEdas

// 使用預設 [%logger] 進行輸出2023-11-11 16:14:36.790 INFO [com.alibabacloud.edas.demo.PoweredByEdas] Prowered by EDAS 
// 使用預設 [%logger{5}] 進行輸出2023-11-11 16:24:44.879 INFO [c.a.e.d.PoweredByEdas] Prowered by EDAS

不過這種日誌處理由於做字串的拆分和擷取，會額外耗費一定的 CPU，如果是計算密集型的業務（CPU 佔用本來就很高的情況下）則不建議生產使用。

壓縮異常輸出

1. 保留棧頂的幾幀：棧頂往往包含的是最為關鍵的資訊，是案發的第一現場，他的資訊完整性顯得尤為重要。

2. 保留業務棧幀：在 Java 語言中，大家會遵循給業務程式碼一個單獨包名的實踐，此時我們可以利用包名進行棧幀的過濾和保留操作。

3. 抽樣列印全棧資訊：這裡可以根據具體的業務情況而定，需要將全棧資訊進行隨機輸出的原因是有的時候可能會追蹤到一些系統級別的 BUG 或想了解他的一些機制。全棧資訊的輸出有助於問題的追根溯源。

1. 在進行日誌內容寫入時，透過非同步緩衝區解耦業務程式碼到通道(從日誌框架 到 JVM 到 作業系統 FileSystem）的瓶頸。

2. 在進行檔案內容落盤時，透過大檔案切分成小檔案的方式，儘量解耦硬體級別的瓶頸。

使用非同步日誌

1. Log4j2 AsyncAppender

• shutdownTimeout：等待worker執行緒處理日誌的時間，預設為0，表示無限等待；

• bufferSize：緩衝佇列的大小，預設為1024；

• blocking：是否採用阻塞式，預設為true。當佇列滿時，會同步等待。

<Async name="Async">  <AppenderRef ref="RollingRandomAccessFile"/>  <shutdownTimeout>500</shutdownTimeout>  <bufferSize>1024</bufferSize>  <blocking>true</blocking></Async>

簡單解讀其設計意圖：框架會先提供一個系統緩衝區來快取即將寫入的內容，但是當緩衝區滿時，框架還提供了兩種策略進行選擇，第一種是直接丟棄，第二種是進行等待，但是具體等待多長時間也依然可以配置。

1. Log4j2 AsyncLogger

<dependency>   <groupId>com.lmax</groupId>   <artifactId>disruptor</artifactId></dependency>

與 Log4j 一樣，Logback 也有著類似的策略，這裡我們就不再贅述它的具體使用方式，下面的表格中，我們總結了在各種策略下的優缺點，希望在大家進行選型時能有所幫助：

使用滾動日誌

<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/app.log"                                 filePattern="powered_by/edas-%d{MM-dd-yyyy}-%i.log">    <PatternLayout>        <Pattern>${commonPattern}</Pattern>    </PatternLayout>    <Policies>        <TimeBasedTriggeringPolicy />        <SizeBasedTriggeringPolicy size="100 MB"/>    </Policies>    <DefaultRolloverStrategy>        <max>5</max>    </DefaultRolloverStrategy></RollingRandomAccessFile>

// 不推薦log.debug("Powered by {}", getProductInfoByCode("EDAS"));
// 推薦if (log.isDebugEnabled()) {    log.debug("Powered by {}", getProductInfoByCode("EDAS"));}

上面的邏輯雖然簡單，原理也簡單易懂，但是我們很多的客戶因為這樣的程式碼太多而帶來的效能退化案例不在少數，一個很典型的例子就是JSON序列化大的物件，究其原因程式碼往往是在日常迭代中對於工程實施沒有規範，Code Review 流程的缺失而導致惡化。

String product = "EDAS";//推薦log.debug("Powered by {}", product);
//不推薦log.debug("Powered by " + product);

    public StackTraceElement calcLocation(final String fqcnOfLogger) {        if (fqcnOfLogger == null) {            return null;        }        // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().        final StackTraceElement[] stackTrace = new Throwable().getStackTrace();        boolean found = false;        for (int i = 0; i < stackTrace.length; i++) {            final String className = stackTrace[i].getClassName();            if (fqcnOfLogger.equals(className)) {
                found = true;                continue;            }            if (found && !fqcnOfLogger.equals(className)) {                return stackTrace[i];            }        }        return null;    }

參考連結

Garbage Free: 

Log4j 配置：

Logback 配置：

EDAS 執行時日誌動態調整：