#相關免費學習推薦:java基礎教學
不同類別庫可能使用不同日誌框架,相容是個難題
日誌配置文件通常很繁雜,很多同學習慣從其他項目或網上博客直接複製份配置文件,但卻不仔細研究如何修改。常見錯誤發生於重複記錄日誌、同步日誌的效能、非同步記錄的錯誤配置。
例如沒考慮到日誌內容取得的代價、胡亂使用日誌等級等。
Logback、Log4j、Log4j2、commons-logging、JDK自帶的java.util.logging等,都是Java系統的日誌框架,確實非常多。而不同的類別庫,也可能選擇使用不同的日誌框架。這樣一來,日誌的統一管理就變得非常困難。
雖然可用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的橋接。
日誌重複記錄不僅給查看日誌和統計工作帶來不必要的麻煩,還會增加磁碟和日誌收集系統的負擔。
定義一個方法實作debug、info、warn和error四種日誌的記錄
Logback設定
設定看沒啥問題,執行方法後出現日誌重複記錄
分析
CONSOLE這個Appender同時掛載到了兩個Logger,定義的<logger>
和<root>
,由於定義的<logger>
繼承自<root>
,所以同一日誌既會透過logger記錄,也會傳送到root記錄,因此應用package下日誌出現重複記錄。
如此配置的初衷是啥呢?
內心是想實現自訂logger配置,讓應用程式內的日誌暫時開啟DEBUG等級日誌記錄。其實,這無需重複掛載Appender,去掉<logger>
下掛載的Appender即可:
<logger name="org.javaedge.time.commonmistakes.logging" level="DEBUG"/>
若自訂<logger>
請把日誌輸出到不同Appender:
例如
可設定<logger>
的additivity屬性為false,這就不會繼承<root>
的Appender
在記錄日誌到控制台的同時,把日誌記錄依照不同等級記錄到兩個檔案
執行結果
info.log 檔案包含INFO、WARN和ERROR三級日誌,不符合預期
error.log包含WARN和ERROR兩個等級日誌,導致日誌重複收集
#事故問責
有些公司使用自動化ELK方案收集日誌,日誌會同時輸出到控制台和文件,開發人員在本地測試不會關心文件中記錄的日誌,而在測試和生產環境又因為開發人員沒有伺服器存取權限,所以原始日誌文件中的重複問題難以發現。
日誌到底為何重複呢?
日誌等級≥ 設定等級
傳回NEUTRAL,繼續呼叫過濾器鏈上的下個篩選器#該案例我們將ThresholdFilter 置# WARN,因此可記錄WARN和ERROR等級日誌。
用於比較日誌級別,然後進行相應處理。
和ThresholdFilter 不同,LevelFilter僅配置level無法真正運作
。
由於未配置onMatch和onMismatch屬性,所以該過濾器失效,導致INFO以上等級日誌都記錄了。
配置LevelFilter的onMatch屬性為ACCEPT,表示接收INFO等級的日誌;配置onMismatch屬性為DENY,表示除了INFO等級都不記錄:
如此,_info.log
檔案只會有INFO等級日誌,不會再出現日誌重複。
知道到底如何正確將日誌輸出到檔案後,就該考慮如何避免日誌記錄成為系統效能瓶頸。這可解決,磁碟(如機械磁碟)IO效能較差、日誌量又很大的情況下,如何記錄日誌問題。
定義如下的日誌配置,一共有兩個Appender:
FILE是一個FileAppender,用來記錄所有的日誌;
CONSOLE是一個ConsoleAppender,用來記錄帶有time標記的日誌。
把大量日誌輸出到檔案中,日誌檔案會非常大,如果效能測試結果也混在其中的話,就很難找到那個日誌。所以,這裡使用EvaluatorFilter對日誌按照標記進行過濾,並將過濾出的日誌單獨輸出到控制台上。在該案例中給輸出測試結果的那段日誌上做了time標記。
搭配使用標記和EvaluatorFilter,實作日誌的按標籤過濾。
執行程式後可以看到,記錄1000次日誌和10000次日誌的呼叫耗時,分別是5.1秒和39秒
對只記錄檔案日誌的程式碼,這耗時過長。
FileAppender繼承自OutputStreamAppender
在追加日誌時,是直接把日誌寫入OutputStream中,屬同步記錄日誌
所以日志大量写入才会旷日持久。如何才能实现大量日志写入时,不会过多影响业务逻辑执行耗时而影响吞吐量呢?
使用Logback的AsyncAppender
即可实现异步日志记录。AsyncAppender类似装饰模式,在不改变类原有基本功能情况下为其增添新功能。这便可把AsyncAppender附加在其他Appender,将其变为异步。
定义一个异步Appender ASYNCFILE,包装之前的同步文件日志记录的FileAppender, 即可实现异步记录日志到文件
异步日志真的如此高性能?并不,因为这并没有记录下所有日志。
模拟慢日志记录场景:
首先,自定义一个继承自ConsoleAppender的MySlowAppender,作为记录到控制台的输出器,写入日志时休眠1秒。
配置文件中使用AsyncAppender,将MySlowAppender包装为异步日志记录
测试代码
耗时很短但出现日志丢失:要记录1000条日志,最终控制台只能搜索到215条日志,而且日志行号变问号。
原因分析
AsyncAppender提供了一些配置参数,而当前没用对。
队列剩余容量 < 队列长度的20%
,就会丢弃TRACE、DEBUG和INFO级日志public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> { // 是否收集调用方数据 boolean includeCallerData = false; protected boolean isDiscardable(ILoggingEvent event) { Level level = event.getLevel(); // 丢弃 ≤ INFO级日志 return level.toInt() <= Level.INFO_INT; } protected void preprocess(ILoggingEvent eventObject) { eventObject.prepareForDeferredProcessing(); if (includeCallerData) eventObject.getCallerData(); }}public class AsyncAppenderBase<E> 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() < discardingThreshold); } private void put(E eventObject) { if (neverBlock) { //根据neverBlock决定使用不阻塞的offer还是阻塞的put方法 blockingQueue.offer(eventObject); } else { putUninterruptibly(eventObject); } } //以阻塞方式添加数据到队列 private void putUninterruptibly(E eventObject) { boolean interrupted = false; try { while (true) { try { blockingQueue.put(eventObject); break; } catch (InterruptedException e) { interrupted = true; } } } finally { if (interrupted) { Thread.currentThread().interrupt(); } } }}
默认队列大小256,达到80%后开始丢弃<=INFO级日志后,即可理解日志中为什么只有两百多条INFO日志了。
可能导致OOM
默认值256就已经算很小了,且discardingThreshold设置为大于0(或为默认值),队列剩余容量少于discardingThreshold的配置就会丢弃<=INFO日志。这里的坑点有两个:
不是百分比,而是日志条数
。对于总容量10000队列,若希望队列剩余容量少于1000时丢弃,需配置为1000意味总可能会出现阻塞。
queueSize、discardingThreshold和neverBlock三参密不可分,务必按业务需求设置:
neverBlock = true
,永不阻塞discardingThreshold = 0
,即使≤INFO级日志也不会丢。但最好把queueSize设置大一点,毕竟默认的queueSize显然太小,太容易阻塞。以上日志配置最常见两个误区
再看日誌記錄本身的誤解。
SLF4J的{}佔位符語法,到真正記錄日誌時才會取得實際參數,因此解決了日誌數據獲取的效能問題。
這說法對嗎?
#若記錄DEBUG日誌,並設定只記錄>=INFO等級日誌,程式是否也會耗時1秒?
三種方法測試:
前兩個方式都會呼叫slowString,所以都耗時1s。且方式二就是使用佔位符記錄slowString,這種方式雖允許傳Object,不顯式拼接String,但也只是延遲(若日誌不記錄那就是省去)日誌參數物件.toString()和字串拼接的耗時。
本案例除非事先判斷日誌級別,否則必定會呼叫slowString。
所以使用{}佔位符
不能透過延遲參數值來獲取,來解決日誌資料所取得的效能問題。
除事先判斷日誌級別,還可透過lambda表達式延遲參數內容取得。但SLF4J的API還不支援lambda,因此需使用Log4j2日誌API,把Lombok的@Slf4j註解替換為**@Log4j2**註解,即可提供lambda表達式參數的方法:
這樣呼叫debug,簽章Supplier>,參數就會延遲到真正需要記錄日誌時再取得:
Log4j2 API,真正的日誌記錄還是走的Logback,這就是SLF4J適配的好處。
總結以上是搞懂Java日誌級別,重複記錄、遺失日誌問題的詳細內容。更多資訊請關注PHP中文網其他相關文章!