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>

         

  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++;
            }
          }
        }

         

• 根據源碼：
  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. 第一個問題里已經說了，日所以志文件在比較的時候(還未比較完成時)，仍然在進行日志輸出，所以日志文件會變大。