logback架構之——日誌分割所帶來的潛在問題

• 源碼：
  1. logback-test.xml檔案如下，有2個需要我們重點關注的參數：
     1. fileNamePattern：這裡的記錄檔名變動的部分是年月日時，外加1個檔案分割自增變數，警告，年月日時的數值依賴於系統時間，自增變數依賴logback架構裡運行時的記憶體變數。
     2. maxFileSize：這裡記錄檔分割的條件為記錄檔大小達到1M。

        <?xml version="1.0" encoding="UTF-8"?><configuration>    <appender name="testLog"              class="ch.qos.logback.core.rolling.RollingFileAppender">        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">            <!-- 我們的記錄檔名變動的部分是年月日時，外加1個分割自增變數 -->            <fileNamePattern>test-log.%d{yyyy-MM-dd-HH}.%i.log</fileNamePattern>            <!-- 儲存曆史檔案的個數 每產生一個記錄檔，該記錄檔的儲存期限為 7天 -->            <maxHistory>168</maxHistory>            <timeBasedFileNamingAndTriggeringPolicy                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">                <maxFileSize>1MB</maxFileSize><!-- 記錄檔分割的條件為記錄檔大小達到1M -->            </timeBasedFileNamingAndTriggeringPolicy>        </rollingPolicy>        <encoder>            <!-- pattern節點，用來設定日誌的輸入格式 -->            <pattern>                %d{HH:mm:SSS} %p [%thread] (%file:%line\)- %m%n            </pattern>            <!-- 記錄日誌的編碼 -->            <charset>UTF-8</charset>        </encoder>    </appender>    <root level="debug">                <appender-ref ref="testLog" />    </root></configuration>

        View Code

         

  2. 輸出日誌的源碼如下，需要注意的是：
     1. 我們用while迴圈輸出日誌，比正常的日誌輸出強度高許多；
     2. 我們的日誌內容是"Hello logback, line "+i。

        package demo.logback;import org.slf4j.Logger;import org.slf4j.LoggerFactory;public class LogFileCut {  public static void main(String[] args) {    Logger logger = LoggerFactory.getLogger("demo.logback.LogFileCut");    int i = 0;    while(i < 100000) {        logger.debug("Hello logback, line ++++++ "+i);        i++;    }  }}

        View Code

         

• 根據源碼：
  1. 第一步，我們現在要輸出10萬條日誌到記錄檔當中，每個檔案大小為1MB，
     可以看到，實際的檔案大小是不確定的1142KB，1152KB，都大於1MB，最後一個記錄檔因為還沒有填滿而小於1MB。這是我們要弄明白的第一個問題，為什麼記錄檔大小實際上大於我們設定的上限值？
  2. 第二步，因為我們是用main方法輸出日誌，我們再運行一遍就相當於伺服器重啟一遍，這個時候我們把日誌輸出內容換成，“Hello logback, line ++++++”+i。<br/運行結果
     1. 先看檔案數量，迴圈次數相同，新增的記錄檔數量是6個，前面0~6個檔案是第一步裡運行得到的，後面的7~12是這次產生的。
     2. 對比兩張圖裡前面7個檔案0~6,6號分割檔案大小發生變化我們容易理解，但是0~5這6個檔案怎麼都增加了，這是我們要回答的第二個問題？
• logback日誌分割問題分析：
  • 第一個問題：為什麼日誌分割實際大小大於設定的上限值？
    • 證據：如。
    • 原因分析：
      • 一個記錄檔分割時，有兩個操作：
        1. 比較當前記錄檔與設定值的大小，判斷是否分割；
        2. 只要還未完成分割，持續向當前記錄檔寫入日誌。
           當你還在比較的時候，我已經輸出幾百米了。。。行。。。。
      • 當判斷出記錄檔大小已經達到預定值的瞬間，記錄檔還未進行分割，而此時記錄檔仍然被寫入日誌。故正常情況下，記錄檔的實際大小通常要大於設定值的大小。
      • 超出多少：記錄檔實際超出預定值的大小size，基本上取決於判定出記錄檔大小達到臨界值的時間點zeroPoint以後，日誌記錄的寫入相對於記錄檔建立的速度。
      • 通常來說，日誌在代碼中的輸出越頻繁，超出臨界值越多(我們這裡的迴圈輸出日誌，強度是很大的)。
      • 詭譎：JIT在作祟？多次重複以上的單個步驟，觀察日誌分割檔案大小，我們不難發現，記錄檔列表的開頭幾個檔案總是比後面的記錄檔要小一些。換句話說，運行時的日誌輸出速度發生了變化，我猜想這裡極有可能是因為while迴圈被JIT編譯器檢測到為熱點代碼，所以進行了再編譯，從而使日誌的輸出速度變得更快，導致後面的記錄檔更大些。
  • 第二個問題：為什麼“重啟”後，原本應該鎖定的記錄檔，再次被輸入日誌？
    • 證據：檢查0~6號檔案的末尾，我們都可以發現“Hello logback, line ++++++”+i，這段記錄的存在。也就是說，“重啟”之前的、按理說已經“滿格”達到上限值記錄檔，在“重啟”後，發生了日誌再次寫入的問題。
    • 原因分析：
      • 日誌名稱：test-log.2018-08-14-13.0.log。檔案名稱精確到小時，我們“重啟”前後，都是在同一天的13點！
        1. 日誌名稱的變化依賴於時間，以及分割序號，時間由作業系統決定，分割序號由logback架構決定。分割序號對應的變數值是沒有持久化的！一旦重啟，就只能重頭開始，所以在同一個時間段(這裡是同一天的同一個小時)裡發生重啟，不會建立記錄檔，而是在原有的日誌裡追加記錄；
        2. 第一個問題裡已經說了，日所以志檔案在比較的時候(還未比較完成時)，仍然在進行日誌輸出，所以記錄檔會變大。