前言
1. 日志框架眾多,兼容問題
2. 日志配置復雜,容易出錯
3. 日志異步亂用,導致日志錯亂
4. DefaultErrorHandler存在線程安全問題
5. 需要禁止的一些操作
6. 需要注意的一些操作
7. 系統異常處理原則和實踐
總結
前言
在日常開發中,如果你是一名后端開發人員,想必應該非常清楚在應用系統運行期間,打印日志有多么重要。
它不但能夠記錄服務運行情況及軌跡,還有助于提升故障排查及定位問題的效率,甚至還可以對其進行分析及監控,洞察系統隱患,提前預警防范。
如果輸出的日志是毫無價值的,或者是存在問題的時候,會給我我們帶來很多不必要的麻煩。
今天和大家聊一聊日志,希望大家看完之后能夠得到一些幫助。
1. 日志框架眾多,兼容問題
我們會接觸到不同的日志框架,很多人都認為打印日志是一件簡單的事情,但不合理的日志打印會給我們排查問題帶來困擾。
常用的日志框架:Logbcak、Log4J、Log4j2、commons-logging
在使用過程中會去調用他們各自的API,完成日志信息的記錄,各種各樣的API就造成了很混亂的感覺,同時還要避免同時使用他們,會造成死循環。為了解決這個問題應該采用日志門面。
什么是日志門面?
日志門面,是門面模式的一個典型的應用。
門面模式(Facade Pattern) ,也稱之為外觀模式,其核心為:外部與一個子系統的通信必須通過一個統一的外觀對象進行, 使得子系統更易于使用。
解決方案: SLF4J(Simple Logging Facade For Java)
org.projectlombok lombok true org.slf4j slf4j-api 1.6.1
這樣做的最大好處,就是業務層的開發不需要關心底層日志框架的實現及細節,在編碼的時候也不需要考慮日后更換框架所帶來的成本。這也是門面模式所帶來的好處。
2. 日志配置復雜,容易出錯
在使用日志框架的時候,我們會根據一些定制化的不同級別的日志輸出,進行自定義的變更配置,下面整理了下我們需要注意的一些點。
(1)錯誤配置LevelFilter造成日志重復記錄
INFO
問題分析:
我們可以跟進一下源碼來定位下,為什么沒有過濾INFO的日志信息
publicAbstractMatcherFilter(){ this.onMatch=FilterReply.NEUTRAL; this.onMismatch=FilterReply.NEUTRAL; }
默認是NEUTRAL,默認交給下一個過濾器處理,否則調用onMismatch定義的處理方式處理,默認也是交給下一個過濾器處理
大概的意思就明白了,因為我們沒有配置 onMatch 和 onMismatc h,所以默認交給了下一個過濾器執行。
解決方案:
由于沒有配置 onMatch 和 onMismatch 屬性,導致一直交給下一個過濾器處理,
只要加上配置就可以解決
DENY ACCEPT
3. 日志異步亂用,導致日志錯亂
什么情況下我們會考慮使用異步,那肯定是為了提高性能瓶頸,特別是針對一些突發日志的應用程序比較有利,提高吞吐量。
AsyncAppender 顧名思義是個異步Appender,采用異步方式處理日志,在其內部維護了一個 BlockingQueue 阻塞隊列,每次處理日志時,都先嘗試把 Log4jLogEvent 事件存入隊列中,然后交由后臺線程從隊列中取出事件并處理(把日志交由 AsyncAppender 所關聯的Appender處理),但隊列長度總是有限的,且隊列默認大小是128,如果日志量過大或日志異步線程處理不及時,就很可能導致日志隊列被打滿。
官網也為我們提供的對比圖
下圖比較了同步記錄器、異步追加器和異步記錄器的吞吐量。這是所有線程的總吞吐量。在具有 64 個線程的測試中,異步記錄器比異步追加器快 12 倍,比同步記錄器快 68 倍。
異步記錄器的吞吐量隨著線程數的增加而增加,而同步記錄器和異步追加器的吞吐量或多或少是恒定的,而不管執行日志記錄的線程數如何。

(1)異步日志丟失行號、方法名等信息
false

看到前面的?,就是我們丟失的行號、方法名等信息
主要是因為includeCallerData屬性設置為false的原因
includeCallerData作用:控制是否收集調用方數據,設置為false目的是為了提高性能
true

(2) 異步日志出現丟失
在異步日志中有關鍵的三個屬性值,他決定了日志是否出現丟失的問題
模擬打印500次的INFO級別的日志信息
@GetMapping("/testPerformance")
publicvoidtestPerformance(){
StopWatchstopWatch=newStopWatch();
stopWatch.start();
IntStream.rangeClosed(1,500).forEach(val->{
log.info("{},{}",val,"writelog"+val);
});
stopWatch.stop();
log.info("result{}",stopWatch.prettyPrint());
}
執行結果:


根據圖片我們可以看到,我們進行了500次循環,但是打印結果的數據存在缺失。
分析源碼
AsyncAppender 類主要繼承了 AsyncAppenderBase類
下面我們來看一下源碼
publicclassAsyncAppenderBaseextendsUnsynchronizedAppenderBase implementsAppenderAttachable { AppenderAttachableImpl aai=newAppenderAttachableImpl(); BlockingQueue blockingQueue; publicstaticfinalintDEFAULT_QUEUE_SIZE=256; intqueueSize=256; intappenderCount=0; staticfinalintUNDEFINED=-1; intdiscardingThreshold=-1; booleanneverBlock=false; AsyncAppenderBase .Workerworker=newAsyncAppenderBase.Worker(); publicstaticfinalintDEFAULT_MAX_FLUSH_TIME=1000; intmaxFlushTime=1000; publicAsyncAppenderBase(){ } if(this.discardingThreshold==-1){ this.discardingThreshold=this.queueSize/5; }
queueSize 屬性
作用:用于控制阻塞隊列大小,防止隊列塞滿后阻塞,默認為256,內存中最多保存256條日志。
discardingThreshold 屬性
作用:控制丟棄日志的閾值,默認值-1,需要注意的是,這里的閾值是指行數,不是百分比
privatevoidput(EeventObject){
if(this.neverBlock){
this.blockingQueue.offer(eventObject);
}else{
this.putUninterruptibly(eventObject);
}
}
問題分析:
因為 queueSize 的默認為256,所以內存中最多保存256條日志,當到達 discardingThreshold 剩余總行數的五分之一時,就會進行日志丟棄的操作。
解決方案:
通過修改關鍵的屬性值,來進行日志丟失問題的解決
false 0
我們只需要將 discardingThreshold 設置為0,他表示不進行日志的丟棄操作,這樣就可以達到保證日志不丟失的目的。
(3)異步日志內存撐爆
因為異步里面主要使用 BlockingQueue 阻塞隊列,隊列都會存在的一個問題就是過大的時候肯定就會造成OOM。
所以 queueSize 設置特別大,也會造成 OOM 異常。
(4) 異步日志出現阻塞
業務場景:
a. 調用后端RPC服務超時,導致調用方大量線程阻塞
b. 輸出異常日志導致大量線程阻塞
關鍵屬性:neverBlock屬性
作用:隊列滿的時候,加入數據是否丟棄,默認不丟棄
是的時候調用 offer() 方法不阻塞,否的時候調用 put() 方法阻塞。
我們來看一下這部分的源碼
privatevoidput(EeventObject){
if(this.neverBlock){
this.blockingQueue.offer(eventObject);
}else{
this.putUninterruptibly(eventObject);
}
}
privatevoidputUninterruptibly(EeventObject){
booleaninterrupted=false;
try{
while(true){
try{
this.blockingQueue.put(eventObject);
return;
}catch(InterruptedExceptionvar7){
interrupted=true;
}
}
}finally{
if(interrupted){
Thread.currentThread().interrupt();
}
}
}
在默認情況下,就會調用putUninterruptibly阻塞方法,拋出 OOM 異常后,會一直阻塞著。
所以,當我們設置過大的隊列或者不愿意犧牲日志的情況下可能會導致線程的阻塞問題。
我們需要做好取舍的工作,看一看是性能有限還是數據安全優先

4. DefaultErrorHandler存在線程安全問題
//org.apache.logging.log4j.core.appender.DefaultErrorHandler
privatestaticfinalLoggerLOGGER=StatusLogger.getLogger();
privatestaticfinalintMAX_EXCEPTIONS=3;
//5min時間間隔
privatestaticfinallongEXCEPTION_INTERVAL=TimeUnit.MINUTES.toNanos(5);
privateintexceptionCount=0;
privatelonglastException=System.nanoTime()-EXCEPTION_INTERVAL-1;
publicvoiderror(finalStringmsg){
finallongcurrent=System.nanoTime();
//當前時間距離上次異常處理時間間隔超過5min或者異常處理數小于3次
if(current-lastException>EXCEPTION_INTERVAL
||exceptionCount++
DefaultErrorHandler 內部在處理異常日志時增加了條件限制,只有下述兩個條件任一滿足 時才會處理,從而避免大量異常日志導致的性能問題。
兩條日志處理間隔超過5min。
異常日志數量不超過3次。
lastException 用于標記上次異常的時間戳,該變量可能被多線程訪問,無法保證多線程情況下的線程安全。
exceptionCount用于統計異常日志次數,該變量可能被多線程訪問,無法保證多線程情況下的線程安全。
5. 需要禁止的一些操作
【強制】ERROR 級別日志需打印堆棧,而非 ERROR 級別日志則不需要。
【強制】禁止日志打印內容中僅打印特殊字符或數字的情況。
【強制】禁止使用 Logback/Log4j2 等的 API,應使用 SLF4J 的 API。
【強制】禁止日志不能打印客戶敏感信息,如身份證號,銀行卡號。
6. 需要注意的一些操作
【建議】日志內容中應包含關鍵特征類信息,例如:用戶標識或流水號。
【建議】應采用異步打印模式,且打印時建議關閉打印位置信息。
【建議】日志打印若出現堵塞,建議至少丟棄 INFO 級別以上的日志。
【建議】每條日志在語義上可獨立被理解,減少上下文關聯理解。
【建議】打印異常堆棧信息,調用方法log.error(Object message, Throwable e) ,正確寫法:log.error("訂單【"+orderId+"】詳情查詢異常:, e);
【強制】在接口/方法的入口/出口處,打印請求及響應參數日志。
7. 系統異常處理原則和實踐
異常處理原則
(1)具體明確的原則。具體而不是泛化地拋出異常,明確捕獲哪種類型的異常,而不是泛化地捕獲Exception類型的異常??梢詫ν籺ry塊定義多個catch塊。
(2)更泛化的異常類型放在最后的catch塊,如IOException。
(3)提早拋出的原則。提早拋出異常(又稱"快速失敗"),異常得以清晰又準確。
(4)延遲捕獲的原則,在合適的層面捕獲異常。如在web前端捕獲、處理異常,可以有效通知用戶并提供處理意見。
異常處理實踐
(1)在堆棧跟蹤中包含引起異常的原因 。
(2)檢查型異常轉為運行時異常。如throw new RuntimeException("查詢失敗",sqlException)。
(3)禁止catch塊為空。
異常處理建議
(1)catch塊中,ex.printStacktrace()只是將異常輸出到控制臺,沒有任何意義。而且這里出現了異常并沒有中斷程序,進而調用代碼繼續執行,導致更多的異常。
(2)不要在PC網頁、H5、APP界面上顯示異常類名或者打印異常堆棧信息,這種東西對用戶沒有幫助。
(3)不要將異常包含在循環語句塊中(特別注意循環代碼塊中調用方法中包含異常處理),異常處理占用系統資源。
(4)多層次打印異常,會導致異常日志重復累贅。在合適的處理層打印異常日志信息和處理異常。
(5)不要在 finally 內部使用 return 語句。它不僅會影響函數的正確返回值,而且它可能還會導致一些異常處理過程的意外終止,最終導致某些異常的丟失。
總結
關于日志,確實是我們日常中使用最多,但卻最容易忽視的地方,只要線上一出現問題我們只能通過日志來復現問題,
只有規范的輸出日志才能讓我們的排查做到事半功倍,主要從日志的兼容性、異步日志問題、需要禁止和注意的一些操作,
在之后的輸出日志的時候,保持著更嚴謹的態度。

作者小郭的技術筆記,在此特別鳴謝!
-
JAVA
+關注
關注
20文章
3001瀏覽量
116419 -
API
+關注
關注
2文章
2368瀏覽量
66752 -
日志
+關注
關注
0文章
146瀏覽量
11063
原文標題:從阿里來個技術大佬,入職就給我們分享Java打日志的幾大神坑!
文章出處:【微信號:芋道源碼,微信公眾號:芋道源碼】歡迎添加關注!文章轉載請注明出處。
發布評論請先 登錄
日志框架簡介-Slf4j+Logback入門實踐
ArkUI-X框架LogInterface使用指南
Java入門需要學習什么?
JAVA字符集主要包括以下幾個方面
Java學習過程中需要注意的25個要點
java 日志框架Spring Boot分析
對于大規模系統日志的日志模式提煉算法的優化
基于時間卷積網絡的通用日志序列異常檢測框架
Java日志框架中的王者是誰
log4j日志框架分析
Spring Boot的日志框架使用
java日志框架 java日志配置等需要注意的幾個方面
評論