為什么使用logback
記得前幾年工作的時候,公司使用的日志框架還是log4j,大約從16年中到現在,不管是我參與的別人已經搭建好的項目還是我自己主導的項目,日志框架基本都換成了logback,總結一下,logback大約有以下的一些優點:
- 內核重寫、測試充分、初始化內存加載更小,這一切讓logback性能和log4j相比有諸多倍的提升
- logback非常自然地直接實現了slf4j,這個嚴格來說算不上優點,只是這樣,再理解slf4j的前提下會很容易理解logback,也同時很容易用其他日志框架替換logback
- logback有比較齊全的200多頁的文檔
- logback當配置文件修改了,支持自動重新加載配置文件,掃描過程快且安全,它並不需要另外創建一個掃描線程
- 支持自動去除舊的日志文件,可以控制已經產生日志文件的最大數量
總而言之,如果大家的項目里面需要選擇一個日志框架,那么我個人非常建議使用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中:
1 public LoggerContext() { 2 super(); 3 this.loggerCache = new ConcurrentHashMap<String, Logger>(); 4 5 this.loggerContextRemoteView = new LoggerContextVO(this); 6 this.root = new Logger(Logger.ROOT_LOGGER_NAME, null, this); 7 this.root.setLevel(Level.DEBUG); 8 loggerCache.put(Logger.ROOT_LOGGER_NAME, root); 9 initEvaluatorMap(); 10 size = 1; 11 this.frameworkPackages = new ArrayList<String>(); 12 }
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"。
接着寫一段代碼來測試一下:
1 public class Slf4jTest { 2 3 @Test 4 public void testSlf4j() { 5 Logger logger = LoggerFactory.getLogger(Object.class); 6 logger.trace("=====trace====="); 7 logger.debug("=====debug====="); 8 logger.info("=====info====="); 9 logger.warn("=====warn====="); 10 logger.error("=====error====="); 11 } 12 13 }
logback.xml的配置為:
1 <?xml version="1.0" encoding="UTF-8" ?> 2 <configuration scan="false" scanPeriod="60000" debug="false"> 3 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 4 <layout class="ch.qos.logback.classic.PatternLayout"> 5 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 6 </layout> 7 </appender> 8 9 <root level="info"> 10 <appender-ref ref="STDOUT" /> 11 </root> 12 13 </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>:
1 <?xml version="1.0" encoding="UTF-8" ?> 2 <configuration scan="false" scanPeriod="60000" debug="false"> 3 4 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 5 <layout class="ch.qos.logback.classic.PatternLayout"> 6 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 7 </layout> 8 </appender> 9 10 <logger name="java" /> 11 12 <root level="debug"> 13 <appender-ref ref="STDOUT" /> 14 </root> 15 16 </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>:
1 <?xml version="1.0" encoding="UTF-8" ?> 2 <configuration scan="false" scanPeriod="60000" debug="false"> 3 4 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 5 <layout class="ch.qos.logback.classic.PatternLayout"> 6 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 7 </layout> 8 </appender> 9 10 <logger name="java" additivity="false" /> 11 <logger name="java.lang" level="warn"> 12 <appender-ref ref="STDOUT" /> 13 </logger> 14 15 <root level="debug"> 16 <appender-ref ref="STDOUT" /> 17 </root> 18 19 </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的作用是將日志輸出到控制台,配置示例為:
1 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 2 <encoder> 3 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 4 </encoder> 5 </appender>
其中,encoder表示對參數進行格式化。我們和上一部分的例子對比一下,發現這里是有所區別的,上面使用了<layout>定義<pattern>,這里使用了<encoder>定義<pattern>,簡單說一下:
- <encoder>是0.9.19版本之后引進的,以前的版本使用<layout>,logback極力推薦的是使用<encoder>而不是<layout>
- 最常用的FileAppender和它的子類的期望是使用<encoder>而不再使用<layout>
關於<encoder>中的格式下一部分再說。接着我們看一下FileAppender,FileAppender的作用是將日志寫到文件中,配置示例為:
1 <appender name="FILE" class="ch.qos.logback.core.FileAppender"> 2 <file>D:/123.log</file> 3 <append>true</append> 4 <encoder> 5 <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern> 6 </encoder> 7 </appender>
它的幾個節點為:
- <file>表示寫入的文件名,可以使相對目錄也可以是絕對目錄,如果上級目錄不存在則自動創建
- <appender>如果為true表示日志被追加到文件結尾,如果是false表示清空文件
- <encoder>表示輸出格式,后面說
- <prudent>如果為true表示日志會被安全地寫入文件,即使其他的FileAppender也在向此文件做寫入操作,效率低,默認為false
接着來看一下RollingFileAppender,RollingFileAppender的作用是滾動記錄文件,先將日志記錄到指定文件,當符合某個條件時再將日志記錄到其他文件,RollingFileAppender配置比較靈活,因此使用得更多,示例為:
1 <appender name="ROLLING-FILE-1" class="ch.qos.logback.core.rolling.RollingFileAppender"> 2 <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> 3 <fileNamePattern>rolling-file-%d{yyyy-MM-dd}.log</fileNamePattern> 4 <maxHistory>30</maxHistory> 5 </rollingPolicy> 6 <encoder> 7 <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern> 8 </encoder> 9 </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進行異步寫日志配置:
1 <?xml version="1.0" encoding="UTF-8" ?> 2 <configuration scan="false" scanPeriod="60000" debug="false"> 3 4 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 5 <encoder> 6 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 7 </encoder> 8 </appender> 9 10 <appender name="ROLLING-FILE-1" class="ch.qos.logback.core.rolling.RollingFileAppender"> 11 <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> 12 <fileNamePattern>D:/rolling-file-%d{yyyy-MM-dd}.log</fileNamePattern> 13 <maxHistory>30</maxHistory> 14 </rollingPolicy> 15 <encoder> 16 <pattern>%-4relative [%thread] %-5level %lo{35} - %msg%n</pattern> 17 </encoder> 18 </appender> 19 20 <!-- 異步輸出 --> 21 <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender"> 22 <!-- 不丟失日志.默認的,如果隊列的80%已滿,則會丟棄TRACT、DEBUG、INFO級別的日志 --> 23 <discardingThreshold>0</discardingThreshold> 24 <!-- 更改默認的隊列的深度,該值會影響性能.默認值為256 --> 25 <queueSize>256</queueSize> 26 <!-- 添加附加的appender,最多只能添加一個 --> 27 <appender-ref ref ="ROLLING-FILE-1"/> 28 </appender> 29 30 <logger name="java" additivity="false" /> 31 <logger name="java.lang" level="DEBUG"> 32 <appender-ref ref="ASYNC" /> 33 </logger> 34 35 <root level="INFO"> 36 <appender-ref ref="STDOUT" /> 37 </root> 38 39 </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>名稱,有幾種情況: 1、不輸入表示輸出完整的<logger>名稱 2、輸入0表示只輸出<logger>最右邊點號之后的字符串 3、輸入其他數字表示輸出小數點最后邊點號之前的字符數量 |
否 |
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:
1 <configuration scan="false" scanPeriod="60000" debug="false"> 2 3 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 4 <encoder> 5 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 6 </encoder> 7 <filter class="ch.qos.logback.classic.filter.LevelFilter"> 8 <level>WARN</level> 9 <onMatch>ACCEPT</onMatch> 10 <onMismatch>DENY</onMismatch> 11 </filter> 12 </appender> 13 14 <logger name="java" additivity="false" /> 15 <logger name="java.lang" level="DEBUG"> 16 <appender-ref ref="STDOUT" /> 17 </logger> 18 19 <root level="INFO"> 20 <appender-ref ref="STDOUT" /> 21 </root> 22 23 </configuration>
看一下輸出:
2018-03-31 22:22:58.843 [main] WARN java.lang.Object - =====warn=====
看到盡管<logger>配置的是DEBUG,但是輸出的只有warn,因為在<filter>中對匹配到WARN級別時做了ACCEPT(接受),對未匹配到WARN級別時做了DENY(拒絕),當然只能打印出WARN級別的日志。
再看一下ThresholdFilter,配置為:
1 <?xml version="1.0" encoding="UTF-8" ?> 2 <configuration scan="false" scanPeriod="60000" debug="false"> 3 4 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> 5 <encoder> 6 <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern> 7 </encoder> 8 <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> 9 <level>INFO</level> 10 </filter> 11 </appender> 12 13 <logger name="java" additivity="false" /> 14 <logger name="java.lang" level="DEBUG"> 15 <appender-ref ref="STDOUT" /> 16 </logger> 17 18 <root level="INFO"> 19 <appender-ref ref="STDOUT" /> 20 </root> 21 22 </configuration>
看一下輸出為:
2018-03-31 22:41:32.353 [main] INFO java.lang.Object - =====info===== 2018-03-31 22:41:32.358 [main] WARN java.lang.Object - =====warn===== 2018-03-31 22:41:32.359 [main] ERROR java.lang.Object - =====error=====
因為ThresholdFilter的策略是,會將日志級別小於<level>的全部進行過濾,因此雖然指定了DEBUG級別,但是只有INFO及以上級別的才能被打印出來。