Java日誌框架logback剖析

時間  2020-12-21
標籤 java 數組 安全 性能優化 app 框架 異步 函數 性能 測試 欄目 Java 简体版
原文   原文鏈接

Logback和log4j很是類似，優勢以下：java

       一、更快的實現數組

       Logback的內核重寫，在一些關鍵執行路徑上性能提高10倍以上。同時，初始化內存加載也更小。安全

       二、很是充分的測試性能優化

       Logback通過數年的測試，這是簡單重要的緣由選擇logback而不是log4j。app

       三、Logback-classic很是天然實現了SLF4j框架

       由於logback-classic很是天然地實現了SLF4J，因此切換到log4j很是容易，只須要提供另外一個jar包就OK，不須要去動經過SLF4JAPI實現的代碼。異步

      四、很是充分的文檔函數

      官方網站有兩百多頁的文檔。性能

      五、自動從新加載配置文件測試

      當配置文件修改了，Logback-classic能自動從新加載配置文件。掃描過程快且安全，它並不須要另外建立一個掃描線程。

      六、Lilith

      Lilith是log事件的觀察者，和log4j的chainsaw相似。而lilith還能處理大數量的log數據 。 

      七、謹慎的模式和很是友好的恢復

      在謹慎模式下，多個FileAppender實例跑在多個JVM下，可以安全地寫到同一個日誌文件。RollingFileAppender會有些限制。Logback的FileAppender和它的子類包括 RollingFileAppender可以很是友好地從I/O異常中恢復。

      八、配置文件能夠處理不一樣的狀況

      開發人員常常須要判斷不一樣的Logback配置文件在不一樣的環境下（開發，測試，生產）。而這些配置文件僅僅只有一些很小的不一樣，能夠經過,來實現，這樣一個配置文件就能夠適應多個環境。

      九、Filters（過濾器）

      有些時候，須要診斷一個問題，須要打出日誌。在log4j，只有下降日誌級別，不過這樣會打出大量的日誌，會影響應用性能。在Logback，你能夠繼續保持那個日誌級別而除掉某種特殊狀況，如alice這個用戶登陸，它的日誌將打在DEBUG級別而其餘用戶能夠繼續打在WARN級別。要實現這個功能只需加4行XML配置。能夠參考MDCFIlter 。

      十、SiftingAppender（一個很是多功能的Appender）

       它能夠用來分割日誌文件根據任何一個給定的運行參數。如，SiftingAppender可以區別日誌事件跟進用戶的Session，而後每一個用戶會有一個日誌文件。

       十一、自動壓縮已經打出來的log

       RollingFileAppender在產生新文件的時候，會自動壓縮已經打出來的日誌文件。壓縮是個異步過程，在壓縮過程當中應用不會受任何影響。 

       十二、堆棧樹帶有包版本

       Logback在打出堆棧樹日誌時，會帶上包的數據。

       1三、自動去除舊的日誌文件

       經過設置TimeBasedRollingPolicy或者SizeAndTimeBasedFNATP的maxHistory屬性，你能夠控制已經產生日誌文件的最大數量。

總而言之，若是你們的項目裏面須要選擇一個日誌框架，那麼我我的很是建議使用logback。

 

logback的加載

咱們簡單分析一下logback加載過程，當咱們使用logback-classic.jar時，應用啓動，那麼logback會按照以下順序進行掃描：

  • 在系統配置文件System Properties中尋找是否有logback.configurationFile對應的value
  • 在classpath下尋找是否有logback.groovy（即logback支持groovy與xml兩種配置方式）
  • 在classpath下尋找是否有logback-test.xml
  • 在classpath下尋找是否有logback.xml

以上任何一項找到了，就不進行後續掃描，按照對應的配置進行logback的初始化，具體代碼實現可見ch.qos.logback.classic.util.ContextInitializer類的findURLOfDefaultConfigurationFile方法。當全部以上四項都找不到的狀況下，logback會調用ch.qos.logback.classic.BasicConfigurator的configure方法，構造一個ConsoleAppender用於向控制檯輸出日誌，默認日誌輸出格式爲"%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n"。

 

logback的configuration

logback的重點應當是Appender、Logger、Pattern，在這以前先簡單瞭解一下logback的<configuration>，<configuration>只有三個屬性：

scan：當scan被設置爲true時，當配置文件發生改變，將會被從新加載，默認爲true scanPeriod：檢測配置文件是否有修改的時間間隔，若是沒有給出時間單位，默認爲毫秒，當scan=true時這個值生效，默認時間間隔爲1分鐘 debug：當被設置爲true時，將打印出logback內部日誌信息，實時查看logback運行信息，默認爲false

 

<logger>與<root>

先從最基本的<logger>與<root>開始。

<logger>用來設置某一個包或者具體某一個類的日誌打印級別、以及指定<appender>。

<logger>能夠包含零個或者多個<appender-ref>元素，標識這個appender將會添加到這個logger。

<logger>僅有一個name屬性、一個可選的level屬性和一個可選的additivity屬性：

  • name：用來指定受此logger約束的某一個包或者具體的某一個類
  • level：用來設置打印級別，五個經常使用打印級別從低至高依次爲TRACE、DEBUG、INFO、WARN、ERROR，若是未設置此級別，那麼當前logger會繼承上級的級別
  • additivity：是否向上級logger傳遞打印信息，默認爲true

<root>也是<logger>元素，可是它是根logger，只有一個level屬性，由於它的name就是ROOT，源碼在LoggerContext中：

public LoggerContext() { super(); this.loggerCache = new ConcurrentHashMap<String, Logger>(); this.loggerContextRemoteView = new LoggerContextVO(this); this.root = new Logger(Logger.ROOT_LOGGER_NAME, null, this); this.root.setLevel(Level.DEBUG); loggerCache.put(Logger.ROOT_LOGGER_NAME, root); initEvaluatorMap(); size = 1; this.frameworkPackages = new ArrayList<String>(); }

Logger的構造函數爲：

Logger(String name, Logger parent, LoggerContext loggerContext) {
    this.name = name;
    this.parent = parent;
    this.loggerContext = loggerContext;
}

看到第一個參數就是Root的name，而這個Logger.ROOT_LOGGER_NAME的定義爲final public String ROOT_LOGGER_NAME = "ROOT"，由此能夠看出<root>節點的name就是"ROOT"。

接着寫一段代碼來測試一下：

public class Slf4jTest { @Test public void testSlf4j() { Logger logger = LoggerFactory.getLogger(Object.class); logger.trace("=====trace====="); logger.debug("=====debug====="); logger.info("=====info====="); logger.warn("=====warn====="); logger.error("=====error====="); } }

logback.xml的配置爲：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </layout>
    </appender>
    
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
    
</configuration>

root將打印級別設置爲"info"級別，<appender>暫時無論，控制檯的輸出爲：

2018-03-26 22:57:48.779 [main] INFO  java.lang.Object - =====info=====
2018-03-26 22:57:48.782 [main] WARN  java.lang.Object - =====warn=====
2018-03-26 22:57:48.782 [main] ERROR java.lang.Object - =====error=====

logback.xml的意思是，當Test方法運行時，root節點將日誌級別大於等於info的交給已經配置好的名爲"STDOUT"的<appender>進行處理，"STDOUT"將信息打印到控制檯上。

接着理解一下<logger>節點的做用，logback.xml修改一下，加入一個只有name屬性的<logger>：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </layout>
    </appender>
     
    <logger name="java" />
      
     <root level="debug">
         <appender-ref ref="STDOUT" />
     </root>
      
</configuration>

注意這個name表示的是LoggerFactory.getLogger(XXX.class)，XXX的包路徑，包路徑越少越是父級，咱們測試代碼裏面是Object.class，即name="java"是name="java.lang"的父級，root是全部<logger>的父級。看一下輸出爲：

2018-03-27 23:02:02.963 [main] DEBUG java.lang.Object - =====debug=====
2018-03-27 23:02:02.965 [main] INFO  java.lang.Object - =====info=====
2018-03-27 23:02:02.966 [main] WARN  java.lang.Object - =====warn=====
2018-03-27 23:02:02.966 [main] ERROR java.lang.Object - =====error=====

出現這樣的結果是由於：

  • <logger>中沒有配置level，即繼承父級的level，<logger>的父級爲<root>，那麼level=debug
  • 沒有配置additivity，那麼additivity=true，表示此<logger>的打印信息向父級<root>傳遞
  • 沒有配置<appender-ref>，表示此<logger>不會打印出任何信息

由此可知，<logger>的打印信息向<root>傳遞，<root>使用"STDOUT"這個<appender>打印出全部大於等於debug級別的日誌。觸類旁通，咱們將<logger>的additivity配置爲false，那麼控制檯應該不會打印出任何日誌，由於<logger>的打印信息不會向父級<root>傳遞且<logger>沒有配置任何<appender>，你們能夠本身試驗一下。

接着，咱們再配置一個<logger>：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">
 
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </layout>
    </appender>
     
    <logger name="java" additivity="false" />
    <logger name="java.lang" level="warn">
        <appender-ref ref="STDOUT" />
    </logger>
    
    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
     
</configuration>

若是讀懂了上面的例子，那麼這個例子應當很好理解：

  • LoggerFactory.getLogger(Object.class)，首先找到name="java.lang"這個<logger>，將日誌級別大於等於warn的使用"STDOUT"這個<appender>打印出來
  • name="java.lang"這個<logger>沒有配置additivity，那麼additivity=true，打印信息向上傳遞，傳遞給父級name="java"這個<logger>
  • name="java"這個<logger>的additivity=false且不關聯任何<appender>，那麼name="java"這個<appender>不會打印任何信息

由此分析，得出最終的打印結果爲：

2018-03-27 23:12:16.147 [main] WARN  java.lang.Object - =====warn=====
2018-03-27 23:12:16.150 [main] ERROR java.lang.Object - =====error=====

觸類旁通，上面的name="java"這個<appender>能夠把additivity設置爲true試試看是什麼結果，若是對前面的分析理解的朋友應該很容易想到，有兩部分日誌輸出，一部分是日誌級別大於等於warn的、一部分是日誌級別大於等於debug的。

 

<appender>

接着看一下<appender>，<appender>是<configuration>的子節點，是負責寫日誌的組件。<appender>有兩個必要屬性name和class：

  • name指定<appender>的名稱
  • class指定<appender>的全限定名

<appender>有好幾種，上面咱們演示過的是ConsoleAppender，ConsoleAppender的做用是將日誌輸出到控制檯，配置示例爲：

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
     <encoder>
         <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
     </encoder>
 </appender>

其中，encoder表示對參數進行格式化。咱們和上一部分的例子對比一下，發現這裏是有所區別的，上面使用了<layout>定義<pattern>，這裏使用了<encoder>定義<pattern>，簡單說一下：

  • <encoder>是0.9.19版本以後引進的，之前的版本使用<layout>，logback極力推薦的是使用<encoder>而不是<layout>
  • 最經常使用的FileAppender和它的子類的指望是使用<encoder>而再也不使用<layout>

關於<encoder>中的格式下一部分再說。接着咱們看一下FileAppender，FileAppender的做用是將日誌寫到文件中，配置示例爲：

<appender name="FILE" class="ch.qos.logback.core.FileAppender">  
    <file>D:/123.log</file>  
    <append>true</append>  
    <encoder>  
        <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>  
    </encoder>  
</appender>

它的幾個節點爲：

  • <file>表示寫入的文件名，可使相對目錄也能夠是絕對目錄，若是上級目錄不存在則自動建立
  • <appender>若是爲true表示日誌被追加到文件結尾，若是是false表示清空文件
  • <encoder>表示輸出格式，後面說
  • <prudent>若是爲true表示日誌會被安全地寫入文件，即便其餘的FileAppender也在向此文件作寫入操做，效率低，默認爲false

接着來看一下RollingFileAppender，RollingFileAppender的做用是滾動記錄文件，先將日誌記錄到指定文件，當符合某個條件時再將日誌記錄到其餘文件，RollingFileAppender配置比較靈活，所以使用得更多，示例爲：

<appender name="ROLLING-FILE-1" class="ch.qos.logback.core.rolling.RollingFileAppender">   
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">   
        <fileNamePattern>rolling-file-%d{yyyy-MM-dd}.log</fileNamePattern>   
        <maxHistory>30</maxHistory>    
    </rollingPolicy>   
    <encoder>   
        <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>   
    </encoder>   
</appender>

這種是僅僅指定了<rollingPolicy>的寫法，<rollingPolicy>的做用是當發生滾動時，定義RollingFileAppender的行爲，其中上面的TimeBasedRollingPolicy是最經常使用的滾動策略，它根據時間指定滾動策略，既負責滾動也負責觸發滾動，有如下節點：

  • <fileNamePattern>，必要節點，包含文件名及"%d"轉換符，"%d"能夠包含一個Java.text.SimpleDateFormat指定的時間格式，如%d{yyyy-MM}，若是直接使用%d那麼格式爲yyyy-MM-dd。RollingFileAppender的file子節點無關緊要，經過設置file能夠爲活動文件和歸檔文件指定不一樣的位置
  • <maxHistory>，可選節點，控制保留的歸檔文件的最大數量，若是超出數量就刪除舊文件，假設設置每月滾動且<maxHistory>是6，則只保存最近6個月的文件

向其餘還有SizeBasedTriggeringPolicy，用於按照文件大小進行滾動，能夠本身查閱一下資料。

 

異步寫日誌

日誌一般來講都以文件形式記錄到磁盤，例如使用<RollingFileAppender>，這樣的話一次寫日誌就會發生一次磁盤IO，這對於性能是一種損耗，所以更多的，對於每次請求必打的日誌（例如請求日誌，記錄請求API、參數、請求時間），咱們會採起異步寫日誌的方式而不讓這次寫日誌發生磁盤IO，阻塞線程從而形成沒必要要的性能損耗。（不要小看這個點，能夠網上查一下服務端性能優化的文章，只是由於將日誌改成異步寫，整個QPS就有了大幅的提升）。

接着咱們看下如何使用logback進行異步寫日誌配置：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
    </appender>
    
    <appender name="ROLLING-FILE-1" class="ch.qos.logback.core.rolling.RollingFileAppender">   
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">   
              <fileNamePattern>D:/rolling-file-%d{yyyy-MM-dd}.log</fileNamePattern>   
              <maxHistory>30</maxHistory>    
        </rollingPolicy>   
        <encoder>
              <pattern>%-4relative [%thread] %-5level %lo{35} - %msg%n</pattern>   
        </encoder>   
    </appender>
    
    <!-- 異步輸出 -->  
    <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender">  
        <!-- 不丟失日誌.默認的,若是隊列的80%已滿,則會丟棄TRACT、DEBUG、INFO級別的日誌 -->  
        <discardingThreshold>0</discardingThreshold>  
        <!-- 更改默認的隊列的深度,該值會影響性能.默認值爲256 -->  
        <queueSize>256</queueSize>  
        <!-- 添加附加的appender,最多隻能添加一個 -->  
        <appender-ref ref ="ROLLING-FILE-1"/>  
    </appender>
    
    <logger name="java" additivity="false" />
    <logger name="java.lang" level="DEBUG">
        <appender-ref ref="ASYNC" />
    </logger>
    
    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
    
</configuration>

即，咱們引入了一個AsyncAppender，先說一下AsyncAppender的原理，再說一下幾個參數：

  
當咱們配置了AsyncAppender，系統啓動時會初始化一條名爲"AsyncAppender-Worker-ASYNC"的線程

當Logging Event進入AsyncAppender後，AsyncAppender會調用appender方法，appender方法中再將event填入Buffer（使用的Buffer爲BlockingQueue，具體實現爲ArrayBlockingQueye）前，會先判斷當前Buffer的容量以及丟棄日誌特性是否開啓，當消費能力不如生產能力時，AsyncAppender會將超出Buffer容量的Logging Event的級別進行丟棄，做爲消費速度一旦跟不上生產速度致使Buffer溢出處理的一種方式。

上面的線程的做用，就是從Buffer中取出Event，交給對應的appender進行後面的日誌推送

從上面的描述咱們能夠看出，AsyncAppender並不處理日誌，只是將日誌緩衝到一個BlockingQueue裏面去，並在內部建立一個工做線程從隊列頭部獲取日誌，以後將獲取的日誌循環記錄到附加的其餘appender上去，從而達到不阻塞主線程的效果。所以AsyncAppender僅僅充當的是事件轉發器，必須引用另一個appender來作事。
 

從上述原理，咱們就能比較清晰地理解幾個參數的做用了：

  • discardingThreshold，假如等於20則表示，表示當還剩20%容量時，將丟棄TRACE、DEBUG、INFO級別的Event，只保留WARN與ERROR級別的Event，爲了保留全部的events，能夠將這個值設置爲0，默認值爲queueSize/5
  • queueSize比較好理解，BlockingQueue的最大容量，默認爲256
  • includeCallerData表示是否提取調用者數據，這個值被設置爲true的代價是至關昂貴的，爲了提高性能，默認當event被加入BlockingQueue時，event關聯的調用者數據不會被提取，只有線程名這些比較簡單的數據
  • appender-ref表示AsyncAppender使用哪一個具體的<appender>進行日誌輸出

 

<encoder>

<encoder>節點負責兩件事情：

  • 把日誌信息轉換爲字節數組
  • 把字節數組寫到輸出流

目前PatternLayoutEncoder是惟一有用的且默認的encoder，有一個<pattern>節點，就像上面演示的，用來設置日誌的輸入格式，使用「%+轉換符"的方式，若是要輸出"%"則必須使用"\%"對"%"進行轉義。

<encoder>的一些可用參數用表格表示一下：

轉換符 做  用 是否避免使用

c{length}

lo{length}

logger{length}

輸出日誌的logger名稱，可有一個整型參數來縮短<logger>名稱，有幾種狀況：

一、不輸入表示輸出完整的<logger>名稱

二、輸入0表示只輸出<logger>最右邊點號以後的字符串

三、輸入其餘數字表示輸出小數點最後邊點號以前的字符數量

否

C{length}

class{length}

 輸出指定記錄的請求的調用者的全限定名，length同上 是

d{pattern}

date{pattern}

 輸出時間格式，模式語法同java.text.SimpleDateFormat兼容 否
caller{depth} 輸出生成日誌的調用者的位置信息，整數選項表示輸出信息深度 否
L 輸出執行日誌的請求行號 是

m

msg

message

 輸出應用程序提供的信息 否
m 輸入執行日誌請求的方法名 是
n 輸出平臺相關的分行符"\n"或者"\r\n"，即換行 否

p

le

level

 輸出日誌級別 否

r

relative

 輸出從程序啓動到建立日誌記錄的時間，單位爲毫秒 否

t

thread

 輸出產生日誌的線程名稱 否

看到最後一列是"是否避免使用"，這是由於這些信息是沒法直接拿到的（好比請求行號、調用方法名），logback必須經過一些特殊手段去獲取這些數據（好比在日誌打印出產生一個堆棧信息），這種操做會比較影響效率，所以除非必要，不然不建議打印這些數據。

 

Filter

最後來看一下<filter>，<filter>是<appender>的一個子節點，表示在當前給到的日誌級別下再進行一次過濾，最基本的Filter有ch.qos.logback.classic.filter.LevelFilter和ch.qos.logback.classic.filter.ThresholdFilter，首先看一下LevelFilter：

<configuration scan="false" scanPeriod="60000" debug="false">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>
    
    <logger name="java" additivity="false" />
    <logger name="java.lang" level="DEBUG">
        <appender-ref ref="STDOUT" />
    </logger>
    
    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
    
</configuration>

看一下輸出：

2020-03-18 22:22:58.843 [main] WARN  java.lang.Object - =====warn=====

看到儘管<logger>配置的是DEBUG，可是輸出的只有warn，由於在<filter>中對匹配到WARN級別時作了ACCEPT（接受），對未匹配到WARN級別時作了DENY（拒絕），固然只能打印出WARN級別的日誌。

再看一下ThresholdFilter，配置爲：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="false" scanPeriod="60000" debug="false">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>
    
    <logger name="java" additivity="false" />
    <logger name="java.lang" level="DEBUG">
        <appender-ref ref="STDOUT" />
    </logger>
    
    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
    
</configuration>

看一下輸出爲：

2020-03-18 22:41:32.353 [main] INFO  java.lang.Object - =====info=====
2020-03-18 22:41:32.358 [main] WARN  java.lang.Object - =====warn=====
2020-03-18 22:41:32.359 [main] ERROR java.lang.Object - =====error=====

由於ThresholdFilter的策略是，會將日誌級別小於<level>的所有進行過濾，所以雖然指定了DEBUG級別，可是隻有INFO及以上級別的才能被打印出來。

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程