您好,登錄后才能下訂單哦!
小編給大家分享一下如何解決Java日志級別,重復記錄、丟日志的問題,相信大部分人都還不怎么了解,因此分享這篇文章給大家參考一下,希望大家閱讀完這篇文章后大有收獲,下面讓我們一起去了解一下吧!
不同類庫可能使用不同日志框架,兼容是個難題
日志配置文件通常很繁雜,很多同學習慣從其他項目或網上博客直接復制份配置文件,但卻不仔細研究如何修改。常見錯誤發生于重復記錄日志、同步日志的性能、異步記錄的錯誤配置。
比如沒考慮到日志內容獲取的代價、胡亂使用日志級別等。
Logback、Log4j、Log4j2、commons-logging、JDK自帶的java.util.logging等,都是Java體系的日志框架,確實非常多。而不同的類庫,還可能選擇使用不同的日志框架。這樣一來,日志的統一管理就變得非常困難。
SLF4J(Simple Logging Facade For Java)就為解決該問題
提供統一的日志門面API,即圖中紫色部分,實現中立的日志記錄API
橋接功能,藍色部分,把各種日志框架API(綠色部分)橋接到SLF4J API。這樣即便你的程序中使用各種日志API記錄日志,最終都可橋接到SLF4J門面API。
適配功能,紅色部分,可實現SLF4J API和實際日志框架(灰色部分)綁定。
SLF4J只是日志標準,還是需要實際日志框架。日志框架本身未實現SLF4J API,所以需前置轉換。Logback就是按SLF4J API標準實現,所以才無需綁定模塊做轉換。
雖然可用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:
比如
應用日志輸出到文件app.log
其他框架日志輸出到控制臺
可設置<logger>
的additivity屬性為false,這就不會繼承<root>
的Appender
在記錄日志到控制臺的同時,把日志記錄按照不同級別記錄到倆文件
執行結果
info.log 文件包含INFO、WARN和ERROR三級日志,不符預期
error.log包含WARN和ERROR倆級別日志,導致日志重復收集
事故問責
一些公司使用自動化ELK方案收集日志,日志會同時輸出到控制臺和文件,開發人員在本地測試不會關心文件中記錄的日志,而在測試和生產環境又因為開發人員沒有服務器訪問權限,所以原始日志文件中的重復問題難以發現。
日志到底為何重復呢?
當日志級別 ≥ 配置級別
返回NEUTRAL,繼續調用過濾器鏈上的下個過濾器
否則返回DENY,直接拒絕記錄日志
該案例我們將 ThresholdFilter 置 WARN,因此可記錄WARN和ERROR級日志。
用于比較日志級別,然后進行相應處理。
若匹配就調用onMatch定義的處理方式:默認交給下一個過濾器處理(AbstractMatcherFilter基類中定義的默認值)
否則調用onMismatch定義的處理方式:默認也是交給下一個過濾器
和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,實現日志的按標簽過濾。
測試代碼:實現記錄指定次數的大日志,每條日志包含1MB字節的模擬數據,最后記錄一條以time為標記的方法執行耗時日志:
執行程序后可以看到,記錄1000次日志和10000次日志的調用耗時,分別是5.1秒和39秒
對只記錄文件日志的代碼,這耗時過長。
FileAppender繼承自OutputStreamAppender
在追加日志時,是直接把日志寫入OutputStream中,屬同步記錄日志
所以日志大量寫入才會曠日持久。如何才能實現大量日志寫入時,不會過多影響業務邏輯執行耗時而影響吞吐量呢?
使用Logback的AsyncAppender
即可實現異步日志記錄。AsyncAppender類似裝飾模式,在不改變類原有基本功能情況下為其增添新功能。這便可把AsyncAppender附加在其他Appender,將其變為異步。
定義一個異步Appender ASYNCFILE,包裝之前的同步文件日志記錄的FileAppender, 即可實現異步記錄日志到文件
記錄1000次日志和10000次日志的調用耗時,分別是537毫秒和1019毫秒
異步日志真的如此高性能?并不,因為這并沒有記錄下所有日志。
記錄異步日志撐爆內存
記錄異步日志出現日志丟失
記錄異步日志出現阻塞。
模擬慢日志記錄場景:
首先,自定義一個繼承自ConsoleAppender的MySlowAppender,作為記錄到控制臺的輸出器,寫入日志時休眠1秒。
配置文件中使用AsyncAppender,將MySlowAppender包裝為異步日志記錄
測試代碼
耗時很短但出現日志丟失:要記錄1000條日志,最終控制臺只能搜索到215條日志,而且日志行號變問號。
原因分析
AsyncAppender提供了一些配置參數,而當前沒用對。
includeCallerData
默認false:方法行號、方法名等信息不顯示
queueSize
控制阻塞隊列大小,使用的ArrayBlockingQueue阻塞隊列,默認容量256:內存中最多保存256條日志
discardingThreshold
丟棄日志的閾值,為防止隊列滿后發生阻塞。默認隊列剩余容量 < 隊列長度的20%
,就會丟棄TRACE、DEBUG和INFO級日志
neverBlock
控制隊列滿時,加入的數據是否直接丟棄,不會阻塞等待,默認是false
隊列滿時:offer不阻塞,而put會阻塞
neverBlock為true時,使用offer
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日志。這里的坑點有兩個:
因為discardingThreshold,所以設置queueSize時容易踩坑。
比如本案例最大日志并發1000,即便置queueSize為1000,同樣會導致日志丟失
discardingThreshold參數容易有歧義,它不是百分比,而是日志條數
。對于總容量10000隊列,若希望隊列剩余容量少于1000時丟棄,需配置為1000
意味總可能會出現阻塞。
若discardingThreshold = 0,那么隊列滿時再有日志寫入就會阻塞
若discardingThreshold != 0,也只丟棄≤INFO級日志,出現大量錯誤日志時,還是會阻塞
queueSize、discardingThreshold和neverBlock三參密不可分,務必按業務需求設置:
若優先絕對性能,設置neverBlock = true
,永不阻塞
若優先絕不丟數據,設置discardingThreshold = 0
,即使≤INFO級日志也不會丟。但最好把queueSize設置大一點,畢竟默認的queueSize顯然太小,太容易阻塞。
若兼顧,可丟棄不重要日志,把queueSize設置大點,再設置合理的discardingThreshold
以上日志配置最常見兩個誤區
再看日志記錄本身的誤區。
SLF4J的{}占位符語法,到真正記錄日志時才會獲取實際參數,因此解決了日志數據獲取的性能問題。
這說法對嗎?
驗證代碼:返回結果耗時1秒
若記錄DEBUG日志,并設置只記錄>=INFO級日志,程序是否也會耗時1秒?
三種方法測試:
拼接字符串方式記錄slowString
使用占位符方式記錄slowString
先判斷日志級別是否啟用DEBUG。
前倆方式都調用slowString,所以都耗時1s。且方式二就是使用占位符記錄slowString,這種方式雖允許傳Object,不顯式拼接String,但也只是延遲(若日志不記錄那就是省去)日志參數對象.toString()和字符串拼接的耗時。
本案例除非事先判斷日志級別,否則必調用slowString。
所以使用{}占位符
不能通過延遲參數值獲取,來解決日志數據獲取的性能問題。
除事先判斷日志級別,還可通過lambda表達式延遲參數內容獲取。但SLF4J的API還不支持lambda,因此需使用Log4j2日志API,把Lombok的@Slf4j注解替換為**@Log4j2**注解,即可提供lambda表達式參數的方法:
這樣調用debug,簽名Supplier<?>,參數就會延遲到真正需要記錄日志時再獲取:
所以debug4并不會調用slowString方法
只是換成Log4j2 API,真正的日志記錄還是走的Logback,這就是SLF4J適配的好處。
SLF4J統一了Java日志框架。在使用SLF4J時,要理清楚其橋接API和綁定。若程序啟動時出現SLF4J錯誤提示,那可能是配置問題,可使用Maven的dependency:tree命令梳理依賴關系。
異步日志解決性能問題,是用空間換時間。但空間畢竟有限,當空間滿,要考慮阻塞等待or丟棄日志。如果更希望不丟棄重要日志,那么選擇阻塞等待;如果更希望程序不要因為日志記錄而阻塞,那么就需要丟棄日志。
日志框架提供的參數化日志記錄方式不能完全取代日志級別判斷。若你的日志量很大,獲取日志參數代價也很大,就要判斷日志級別,避免不記錄日志也要耗時獲取日志參數。
以上是“如何解決Java日志級別,重復記錄、丟日志的問題”這篇文章的所有內容,感謝各位的閱讀!相信大家都有了一定的了解,希望分享的內容對大家有所幫助,如果還想學習更多知識,歡迎關注億速云行業資訊頻道!
免責聲明:本站發布的內容(圖片、視頻和文字)以原創、轉載和分享為主,文章觀點不代表本網站立場,如果涉及侵權請聯系站長郵箱:is@yisu.com進行舉報,并提供相關證據,一經查實,將立刻刪除涉嫌侵權內容。