1 日志常見錯因

1.1 日志框架繁多

不同類別庫可能使用不同日志框架，兼容是個難題

1.2 配置復雜且容易出錯

日志組態檔通常很繁雜，很多同學習慣從其他專案或網上博客直接復制份組態檔，但卻不仔細研究如何修改，常見錯誤發生于重復記錄日志、同步日志的性能、異步記錄的錯誤配置，

1.3 日志記錄本身就有些誤區

比如沒考慮到日志內容獲取的代價、胡亂使用日志級別等，

2 SLF4J

Logback、Log4j、Log4j2、commons-logging、JDK自帶的java.util.logging等，都是Java體系的日志框架，確實非常多，而不同的類別庫，還可能選擇使用不同的日志框架，這樣一來，日志的統一管理就變得非常困難，

• SLF4J（Simple Logging Facade For Java）就為解決該問題

• 提供統一的日志門面API，即圖中紫色部分，實作中立的日志記錄API
• 橋接功能，藍色部分，把各種日志框架API（綠色部分）橋接到SLF4J API，這樣即便你的程式中使用各種日志API記錄日志，最終都可橋接到SLF4J門面API，
• 適配功能，紅色部分，可實作SLF4J API和實際日志框架（灰色部分）系結，
  SLF4J只是日志標準，還是需要實際日志框架，日志框架本身未實作SLF4J API，所以需前置轉換，Logback就是按SLF4J API標準實作，所以才無需系結模塊做轉換，

雖然可用log4j-over-slf4j實作Log4j橋接到SLF4J，也可使用slf4j-log4j12實作SLF4J適配到Log4j，也把它們畫到了一列，但是它不能同時使用它們，否則就會產生死回圈，jcl和jul同理，

雖然圖中有4個灰色的日志實作框架，但日常業務使用最多的還是Logback和Log4j，都是同一人開發的，Logback可認為是Log4j改進版，更推薦使用，基本已是主流，

Spring Boot的日志框架也是Logback，那為什么我們沒有手動引入Logback包，就可直接使用Logback？

spring-boot-starter模塊依賴spring-boot-starter-logging模塊
spring-boot-starter-logging模塊自動引入logback-classic（包含SLF4J和Logback日志框架）和SLF4J的一些配接器，其中，log4j-to-slf4j用于實作Log4j2 API到SLF4J的橋接，jul-to-slf4j則是實作java.util.logging API到SLF4J的橋接，

3 日志重復記錄

日志重復記錄不但給查看日志和統計作業帶來不必要的麻煩，還會增加磁盤和日志收集系統的負擔，

logger配置繼承關系導致日志重復記錄

• 定義一個方法實作debug、info、warn和error四種日志的記錄
  

• Logback配置
  

• 配置看沒啥問題，執行方法后出現日志重復記錄
  

• 分析
  CONSOLE這個Appender同時掛載到了倆Logger，定義的<logger>和<root>，由于定義的<logger>繼承自<root>，所以同一條日志既會通過logger記錄，也會發送到root記錄，因此應用package下日志出現重復記錄，

如此配置的初衷是啥呢？
內心是想實作自定義logger配置，讓應用內的日志暫時開啟DEBUG級別日志記錄，其實，這無需重復掛載Appender，去掉<logger>下掛載的Appender即可：

<logger name="org.javaedge.time.commonmistakes.logging" level="DEBUG"/>

若自定義<logger>需把日志輸出到不同Appender：
比如

• 應用日志輸出到檔案app.log
• 其他框架日志輸出到控制臺

可設定<logger>的additivity屬性為false，這就不會繼承<root>的Appender

錯誤配置LevelFilter造成日志重復

• 在記錄日志到控制臺的同時，把日志記錄按照不同級別記錄到倆檔案
  

• 執行結果

• info.log 檔案包含INFO、WARN和ERROR三級日志，不符預期
  

• error.log包含WARN和ERROR倆級別日志，導致日志重復收集

• 事故問責
  一些公司使用自動化ELK方案收集日志，日志會同時輸出到控制臺和檔案，開發人員在本地測驗不會關心檔案中記錄的日志，而在測驗和生產環境又因為開發人員沒有服務器訪問權限，所以原始日志檔案中的重復問題難以發現，

日志到底為何重復呢？

ThresholdFilter原始碼決議

• 當日志級別 ≥ 配置級別 回傳NEUTRAL，繼續呼叫過濾器鏈上的下個過濾器
• 否則回傳DENY，直接拒絕記錄日志
  

該案例我們將 ThresholdFilter 置 WARN，因此可記錄WARN和ERROR級日志，

LevelFilter

用于比較日志級別，然后進行相應處理，

• 若匹配就呼叫onMatch定義的處理方式：默認交給下一個過濾器處理（AbstractMatcherFilter基類中定義的默認值）
• 否則呼叫onMismatch定義的處理方式：默認也是交給下一個過濾器

和ThresholdFilter不同，LevelFilter僅配置level無法真正起作用，

由于未配置onMatch和onMismatch屬性，所以該過濾器失效，導致INFO以上級別日志都記錄了，

修正

配置LevelFilter的onMatch屬性為ACCEPT，表示接收INFO級別的日志；配置onMismatch屬性為DENY，表示除了INFO級別都不記錄：

如此，_info.log檔案只會有INFO級日志，不會再出現日志重復，

4 異步日志提高性能?

知道了到底如何正確將日志輸出到檔案后，就該考慮如何避免日志記錄成為系統性能瓶頸，這可解決，磁盤（比如機械磁盤）IO性能較差、日志量又很大的情況下，如何記錄日志問題，

定義如下的日志配置，一共有兩個Appender：

FILE是一個FileAppender，用于記錄所有的日志；
CONSOLE是一個ConsoleAppender，用于記錄帶有time標記的日志，

把大量日志輸出到檔案中，日志檔案會非常大，如果性能測驗結果也混在其中的話，就很難找到那條日志，所以，這里使用EvaluatorFilter對日志按照標記進行過濾，并將過濾出的日志單獨輸出到控制臺上，該案例中給輸出測驗結果的那條日志上做了time標記，

配合使用標記和EvaluatorFilter，實作日志的按標簽過濾，

• 測驗代碼：實作記錄指定次數的大日志，每條日志包含1MB位元組的模擬資料，最后記錄一條以time為標記的方法執行耗時日志：

執行程式后可以看到，記錄1000次日志和10000次日志的呼叫耗時，分別是5.1秒和39秒

對只記錄檔案日志的代碼，這耗時過長，

原始碼決議

FileAppender繼承自OutputStreamAppender

在追加日志時，是直接把日志寫入OutputStream中，屬同步記錄日志

所以日志大量寫入才會曠日持久，如何才能實作大量日志寫入時，不會過多影響業務邏輯執行耗時而影響吞吐量呢？

AsyncAppender

使用Logback的AsyncAppender

即可實作異步日志記錄，AsyncAppender類似裝飾模式，在不改變類原有基本功能情況下為其增添新功能，這便可把AsyncAppender附加在其他Appender，將其變為異步，

定義一個異步Appender ASYNCFILE，包裝之前的同步檔案日志記錄的FileAppender， 即可實作異步記錄日志到檔案

• 記錄1000次日志和10000次日志的呼叫耗時，分別是537毫秒和1019毫秒
  

異步日志真的如此高性能？并不，因為這并沒有記錄下所有日志，

AsyncAppender異步日志坑

• 記錄異步日志撐爆記憶體
• 記錄異步日志出現日志丟失
• 記錄異步日志出現阻塞，

案例

模擬慢日志記錄場景：
首先，自定義一個繼承自ConsoleAppender的MySlowAppender，作為記錄到控制臺的輸出器，寫入日志時休眠1秒，

• 組態檔中使用AsyncAppender，將MySlowAppender包裝為異步日志記錄
  

• 測驗代碼
  

• 耗時很短但出現日志丟失：要記錄1000條日志，最終控制臺只能搜索到215條日志，而且日志行號變問號，
  

• 原因分析
  AsyncAppender提供了一些配置引數，而當前沒用對，

原始碼決議

• includeCallerData
  默認false：方法行號、方法名等資訊不顯示
• queueSize
  控制阻塞佇列大小，使用的ArrayBlockingQueue阻塞佇列，默認容量256：記憶體中最多保存256條日志
• discardingThreshold
  丟棄日志的閾值，為防止佇列滿后發生阻塞，默認佇列剩余容量 ＜ 佇列長度的20%，就會丟棄TRACE、DEBUG和INFO級日志
• neverBlock
  控制佇列滿時，加入的資料是否直接丟棄，不會阻塞等待，默認是false
  • 佇列滿時：offer不阻塞，而put會阻塞
  • neverBlock為true時，使用offer

public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
	// 是否收集呼叫方資料
    boolean includeCallerData = false;
    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        // 丟棄 ≤ INFO級日志
        return level.toInt() <= Level.INFO_INT;
    }
    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }
}
public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

	// 阻塞佇列：實作異步日志的核心
    BlockingQueue<E> blockingQueue;
    // 默認佇列大小
    public static final int DEFAULT_QUEUE_SIZE = 256;
    int queueSize = DEFAULT_QUEUE_SIZE;
    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    // 當佇列滿時：加入資料時是否直接丟棄，不會阻塞等待
    boolean neverBlock = false;

    @Override
    public void start() {
       	...
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
        if (discardingThreshold == UNDEFINED)
        //默認丟棄閾值是佇列剩余量低于佇列長度的20%，參見isQueueBelowDiscardingThreshold方法
            discardingThreshold = queueSize / 5;
        ...
    }

    @Override
    protected void append(E eventObject) {
        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { //判斷是否可以丟資料
            return;
        }
        preprocess(eventObject);
        put(eventObject);
    }

    private boolean isQueueBelowDiscardingThreshold() {
        return (blockingQueue.remainingCapacity() < discardingThreshold);
    }

    private void put(E eventObject) {
        if (neverBlock) { //根據neverBlock決定使用不阻塞的offer還是阻塞的put方法
            blockingQueue.offer(eventObject);
        } else {
            putUninterruptibly(eventObject);
        }
    }
    //以阻塞方式添加資料到佇列
    private void putUninterruptibly(E eventObject) {
        boolean interrupted = false;
        try {
            while (true) {
                try {
                    blockingQueue.put(eventObject);
                    break;
                } catch (InterruptedException e) {
                    interrupted = true;
                }
            }
        } finally {
            if (interrupted) {
                Thread.currentThread().interrupt();
            }
        }
    }
}  

默認佇列大小256，達到80%后開始丟棄<=INFO級日志后，即可理解日志中為什么只有兩百多條INFO日志了，

queueSize 過大

可能導致OOM

queueSize 較小

默認值256就已經算很小了，且discardingThreshold設定為大于0（或為默認值），佇列剩余容量少于discardingThreshold的配置就會丟棄<=INFO日志，這里的坑點有兩個：

1. 因為discardingThreshold，所以設定queueSize時容易踩坑，
   比如本案例最大日志并發1000，即便置queueSize為1000，同樣會導致日志丟失
2. discardingThreshold引數容易有歧義，它不是百分比，而是日志條數，對于總容量10000佇列，若希望佇列剩余容量少于1000時丟棄，需配置為1000

neverBlock 默認false

意味總可能會出現阻塞，

• 若discardingThreshold = 0，那么佇列滿時再有日志寫入就會阻塞
• 若discardingThreshold != 0，也只丟棄≤INFO級日志，出現大量錯誤日志時，還是會阻塞

queueSize、discardingThreshold和neverBlock三參密不可分，務必按業務需求設定：

• 若優先絕對性能，設定neverBlock = true，永不阻塞
• 若優先絕不丟資料，設定discardingThreshold = 0，即使≤INFO級日志也不會丟，但最好把queueSize設定大一點，畢竟默認的queueSize顯然太小，太容易阻塞，
• 若兼顧，可丟棄不重要日志，把queueSize設定大點，再設定合理的discardingThreshold

以上日志配置最常見兩個誤區

再看日志記錄本身的誤區，

使用日志占位符就無需判斷日志級別?

SLF4J的{}占位符語法，到真正記錄日志時才會獲取實際引數，因此解決了日志資料獲取的性能問題，
這說法對嗎？

• 驗證代碼：回傳結果耗時1秒
  

若記錄DEBUG日志，并設定只記錄>=INFO級日志，程式是否也會耗時1秒？
三種方法測驗：

• 拼接字串方式記錄slowString
• 使用占位符方式記錄slowString
• 先判斷日志級別是否啟用DEBUG，

前倆方式都呼叫slowString，所以都耗時1s，且方式二就是使用占位符記錄slowString，這種方式雖允許傳Object，不顯式拼接String，但也只是延遲（若日志不記錄那就是省去）日志引數物件.toString()和字串拼接的耗時，

本案例除非事先判斷日志級別，否則必呼叫slowString，
所以使用{}占位符不能通過延遲引數值獲取，來解決日志資料獲取的性能問題，

除事先判斷日志級別，還可通過lambda運算式延遲引數內容獲取，但SLF4J的API還不支持lambda，因此需使用Log4j2日志API，把Lombok的@Slf4j注解替換為**@Log4j2**注解，即可提供lambda運算式引數的方法：

這樣呼叫debug，簽名Supplier<?>，引數就會延遲到真正需要記錄日志時再獲取：

所以debug4并不會呼叫slowString方法

只是換成Log4j2 API，真正的日志記錄還是走的Logback，這就是SLF4J適配的好處，

總結

• SLF4J統一了Java日志框架，在使用SLF4J時，要理清楚其橋接API和系結，若程式啟動時出現SLF4J錯誤提示，那可能是配置問題，可使用Maven的dependency:tree命令梳理依賴關系，
• 異步日志解決性能問題，是用空間換時間，但空間畢竟有限，當空間滿，要考慮阻塞等待or丟棄日志，如果更希望不丟棄重要日志，那么選擇阻塞等待；如果更希望程式不要因為日志記錄而阻塞，那么就需要丟棄日志，
• 日志框架提供的引數化日志記錄方式不能完全取代日志級別判斷，若你的日志量很大，獲取日志引數代價也很大，就要判斷日志級別，避免不記錄日志也要耗時獲取日志引數，