搞懂Java日誌級別，重複記錄、遺失日誌問題

java基礎教學專欄介紹如何解決Java日誌等級等問題

#相關免費學習推薦：java基礎教學

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></logger>和<root></root>，由於定義的<logger></logger>繼承自<root></root>，所以同一日誌既會透過logger記錄，也會傳送到root記錄，因此應用package下日誌出現重複記錄。

如此配置的初衷是啥呢？
內心是想實現自訂logger配置，讓應用程式內的日誌暫時開啟DEBUG等級日誌記錄。其實，這無需重複掛載Appender，去掉<logger></logger>下掛載的Appender即可：

<logger></logger>

若自訂<logger></logger>請把日誌輸出到不同Appender：
例如

• 應用程式日誌輸出到檔案app.log
• 其他框架日誌輸出到控制台

可設定<logger></logger>的additivity屬性為false，這就不會繼承<root></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()  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() <p>默认队列大小256，达到80%后开始丢弃</p>
<h3 id="queueSize-过大">queueSize 过大</h3>
<p>可能导致<strong>OOM</strong></p>
<h3 id="queueSize-较小">queueSize 较小</h3>
<p>默认值256就已经算很小了，且<strong>discardingThreshold</strong>设置为大于0（或为默认值），队列剩余容量少于<strong>discardingThreshold</strong>的配置就会丢弃</p>
<ol>
<li>因为<strong>discardingThreshold</strong>，所以设置<strong>queueSize</strong>时容易踩坑。<br> 比如本案例最大日志并发1000，即便置<strong>queueSize</strong>为1000，同样会导致日志丢失</li>
<li>
<strong>discardingThreshold</strong>参数容易有歧义，它<code>不是百分比，而是日志条数</code>。对于总容量10000队列，若希望队列剩余容量少于1000时丢弃，需配置为1000</li>
</ol>
<h3 id="neverBlock-默认false">neverBlock 默认false</h3>
<p>意味总可能会出现阻塞。</p>
<ul>
<li>若<strong>discardingThreshold = 0</strong>，那么队列满时再有日志写入就会阻塞</li>
<li>若<strong>discardingThreshold != 0</strong>，也只丢弃≤INFO级日志，出现大量错误日志时，还是会阻塞</li>
</ul>
<p>queueSize、discardingThreshold和neverBlock三参密不可分，务必按业务需求设置：</p>
<ul>
<li>若优先绝对性能，设置<code>neverBlock = true</code>，永不阻塞</li>
<li>若优先绝不丢数据，设置<code>discardingThreshold = 0</code>，即使≤INFO级日志也不会丢。但最好把queueSize设置大一点，毕竟默认的queueSize显然太小，太容易阻塞。</li>
<li>若兼顾，可丢弃不重要日志，把<strong>queueSize</strong>设置大点，再设置合理的<strong>discardingThreshold</strong>
</li>
</ul>
<p>以上日志配置最常见两个误区</p>
<p>再看日誌記錄本身的誤解。 </p>
<h1 id="使用日誌佔位符就無需判斷日誌等級">使用日誌佔位符就無需判斷日誌等級?</h1>
<blockquote><p>SLF4J的{}佔位符語法，到真正記錄日誌時才會取得實際參數，因此解決了日誌數據獲取的效能問題。 <br> 這說法對嗎？ </p></blockquote>
<ul><li>驗證程式碼：傳回結果耗時1秒<br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/e7fc3efb9f15d2f5ec90198378217433-25.png?x-oss-process=image/resize,p_40" class="lazy" alt="">
</li></ul>
<p>#若記錄DEBUG日誌，並設定只記錄>=INFO等級日誌，程式是否也會耗時1秒？ <br> 三種方法測試：</p>
<ul>
<li>拼接字串方式記錄slowString</li>
<li>使用佔位符號方式記錄slowString</li>
<li>先判斷日誌等級是否啟用DEBUG。 </li>
</ul>
<p><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/e7fc3efb9f15d2f5ec90198378217433-26.png?x-oss-process=image/resize,p_40" class="lazy" alt=""><br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/f01f4010f24e654f3600415dfe301c38-27.png?x-oss-process=image/resize,p_40" class="lazy" alt=""></p>
<p>前兩個方式都會呼叫slowString，所以都耗時1s。且方式二就是使用佔位符記錄slowString，這種方式雖允許傳Object，不顯式拼接String，但也只是延遲（若日誌不記錄那就是省去）<strong>日誌參數物件.toString()<strong>和</strong>字串拼接</strong>的耗時。 </p>
<p>本案例除非事先判斷日誌級別，否則必定會呼叫slowString。 <br> 所以使用<code>{}佔位符</code>不能透過延遲參數值來獲取，來解決日誌資料所取得的效能問題。 </p>
<p>除事先判斷日誌級別，還可透過lambda表達式延遲參數內容取得。但SLF4J的API還不支援lambda，因此需使用Log4j2日誌API，把<strong>Lombok的@Slf4j註解</strong>替換為**@Log4j2**註解，即可提供lambda表達式參數的方法：<br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/bbdb0952c94176bf08d5fbb1a65f85dd-28.png?x-oss-process=image/resize,p_40" class="lazy" alt=""></p>
<p>這樣呼叫debug，簽章<strong>Supplier></strong>，參數就會延遲到真正需要記錄日誌時再取得：<br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/bbdb0952c94176bf08d5fbb1a65f85dd-29.png?x-oss-process=image/resize,p_40" class="lazy" alt=""><br> <img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/bbdb0952c94176bf08d5fbb1a65f85dd-30.png?x-oss-process=image/resize,p_40" class="lazy" alt=""><br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/deeab6ffd5e5b0d7c8b09b1207355404-31.png?x-oss-process=image/resize,p_40" class="lazy" alt=""><br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/deeab6ffd5e5b0d7c8b09b1207355404-32.png?x-oss-process=image/resize,p_40" class="lazy" alt=""></p>##所以debug4並不會呼叫slowString方法<p><br><img src="/static/imghwm/default1.png" data-src="https://img.php.cn/upload/article/000/000/052/1ce957e5765ac776456a49667e73ba80-33.png?x-oss-process=image/resize,p_40" class="lazy" alt=""></p>只是換成<p>Log4j2 API<strong>，真正的日誌記錄還是走的</strong>Logback<strong>，這就是</strong>SLF4J<strong>適配的好處。 </strong></p>總結<h1></h1>
<ul>SLF4J統一了Java日誌框架。在使用SLF4J時，要理清楚其橋接API和綁定。若程式啟動時出現SLF4J錯誤提示，那可能是設定問題，可使用Maven的dependency:tree指令來梳理依賴關係。 <li>非同步日誌解決效能問題，是用空間換時間。但空間畢竟有限，當空間滿，要考慮阻塞等待or丟棄日誌。如果更希望不丟棄重要日誌，那麼選擇阻塞等待；如果更希望程式不要因為日誌記錄而阻塞，那麼就需要丟棄日誌。 <li>日誌框架提供的參數化日誌記錄方式不能完全取代日誌等級判斷。若你的日誌量很大，取得日誌參數代價也很大，就要判斷日誌級別，避免不記錄日誌也要耗時取得日誌參數。 <li>
</ul></e></e></e></e></iloggingevent>

以上是搞懂Java日誌級別，重複記錄、遺失日誌問題的詳細內容。更多資訊請關注PHP中文網其他相關文章！