mons-logging、JDK自帶的java.util.logging等，都是Java體系的日志框架，確實非常多。而不同的類庫，還可能選擇使用不同的日志框架。這樣一來，日志的統一管理就變得非常。為了解決這個問題，就有了SLF4J（SimpleLoggingFacadeForJava），如下圖所示：SLF4J一是提供了統一的日志門面API，即圖中紫色部分，實現了中立的日志記錄API二是橋接功能，即圖中藍色部分，用來把各種日志框架的API（圖中綠色部分）橋接到SLF4JAPIAPISLF4JAPI三是適配功能，即圖中紅色部分，可以實現SLF4JAPI（分）的綁定。SLF4J有實現SLF4JAPI，所以需要有一個前置轉換。Logback就是按照SLF4JAPI標準實現需要理清楚的是，雖然我們可以使用log4j-over-slf4j來實現Log4j橋接到SLF4J，也可slf4j-log4j12SLF4JLog4j，也把它們畫到了一列，但是它不能同時使用它們，否則就會產生死循環。jcl和jul也是同樣的道理。雖然圖中有4個灰色的日志實現框架，但我看到的業務系統使用最廣泛的是Logback和Log4j，它們是同一人開發的。Logback可以認為是Log4j的改進版本，我更推薦使用。所以，關于日志框架配置的案例，我都會圍繞Logback展開。SpringBootJavaLogback。那，為什么我們沒有手動引入Logback的包，就可以直接使用Logback了呢？SpringBootMavenspring-boot-starterspring-boot-starter-logging模塊，而spring-boot-starter-logging模塊又幫我們自動引入了logback-classic（包含了SLF4J和Logback日志框架）和SLF4J的一些適配器。其中，log4j-to-slf4j用于實現Log4j2API到SLF4J的橋接，jul-to-slf4j則是實現java.util.loggingAPI到SLF4J的橋接：LogbackLogback配置的基本結構。debug、info、warnerror123456789publicclassLoggingControllerpublicvoidlog(){}}然后，使用下面的Logback第11和12INFO，日志輸出使用CONSOLEAppender37CONSOLEAppenderConsoleAppender，也就是把日志輸出到控制臺（System.out/System.err）；然后通過PatternLayout定義了日志的輸出格式。關于格式化字符串的各種使用方式，你可以進一步查閱文檔。810LoggerDEBUG、日志輸出同樣使用CONSOLEAppender。123456789<?xmlversion="1.0"encoding="UTF-8"<appendername="CONSOLE"<layout<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<logger<appender-refmonmistakes.logging"<root<appender-ref從配置文件的第9和12行可以看到，CONSOLE這個Appender同時掛載到了兩個Logger所以同一條日志既會通過logger記錄，也會發送到root記錄，因此應用package下的日志出現了重復記錄。后來我了解到，這個同學如此配置的初衷是實現自定義的logger配置，讓應用內的日志暫時開啟DEBUG級別的日志記錄。其實，他完全不需要重復掛載Appender，去掉下掛載的Appender即可：1<loggermonmistakes.logging"如果自定義的需要把日志輸出到不同的Appender，比如將應用的日志輸出到文件app.logadditivityfalse，這樣就不會繼承的Appender了：<?xmlversion="1.0"encoding="UTF-8"<appendername="FILE"<encoder<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<appendername="CONSOLE"<layout<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<logger<appender-ref<root<appender-refref="CONSOLE"monmistakes.logging"level="DEBUG"第二個案例是，錯誤配置LevelFilter一般互聯網公司都會使用ELK三件套來統一收集日志，有一次我們發現Kibana上展示的日志有部分重復，一直懷疑是Logstash配置錯誤，但最后發現還是Logback的配置錯誤<?xmlversion="1.0"encoding="UTF-8"<propertyname="logDir"value="./logs"<propertyname=""value="common-mistakes" 78921--{

<filter<encoder<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<appendername="ERROR_FILE"<filter<encoder<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<root<appender-refref="CONSOLE"<appender-ref<appender-ref第31到35行定義的root了三個Appender第5到9行是第一個ConsoleAppender第10到19行定義了一個FileAppender，用于記錄文件日志，并定義了文件名、記錄日志的格式和編碼等信息。最關鍵的是，第12到14行定義的LevelFilter過濾日志，將過濾級別設置為INFO，目的是希望_info.log文件中可以記錄INFO級別的日志。第20到30行定義了一個類似的FileAppender，并使用ThresholdFilter來過濾日志，過濾級別設置為WARN，目的是把WARN以上級別的日志記錄到另一個_error.log可以看到，_info.log中包含了INFO、WARN和ERROR三個級別的日志，不符合我們的預期；error.log包含了WARN和ERROR兩個級別的日志。因此，造成了日志的重復收你可能會問，這么明顯的日志重復為什么沒有及時發現？一些公司使用自動化的ELK方案的日志，而在測試和生產環境又因為開發人員沒有服務器權限，所以原始日志文件中的 下ThresholdFilter和LevelFilter的配置方式代publicclassThresholdFilter代publicclassThresholdFilterextends{publicFilterReplydecide(ILoggingEventevent)3(!isStarted())4return5}678{return9}elsereturn}}13在這個案例中，把ThresholdFilter設置為WARN，可以記錄WARN和ERROR級別的日LevelFilter用來比較日志級別，然后進行相應處理：如果匹配就調用onMatch定義的處理 MatcherFilter基類中定義的默認值）；否則，調用onMismatch定義的處理方式，默認也是交給下一個過濾器處理。2FilterReplydecide(ILoggingEventevent)3(!isStarted())4return5}679return}elsereturn}14}ThresholdFilterLevelFilterlevel由于沒有配置onMatch和onMismatchINFO以定位到問題后，修改方式就很明顯了：配置LevelFilter的onMatch屬性為ACCEPT，表示接收INFO級別的日志；配置onMismatch屬性為DENY，表示除了INFO級別都不記<appendername="INFO_FILE"<filter這樣修改后，_info.log文件中只會有INFO用的性能瓶頸。這可以幫助我們解決，磁盤（比如機械磁盤）IO性能較差、日志量又很大FILE是一個FileAppenderCONSOLE是一個ConsoleAppendertime<?xmlversion="1.0"encoding="UTF-8"<appendername="FILE"<encoder<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<appendername="CONSOLE"<layout<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<filter<evaluator<root<appender-ref<appender-refEvaluatorFilter（求值過濾器），用于判斷日志結果也混在其中的話，就很難找到那條日志。所以，這里我們使用EvaluatorFilter對日志試結果的那條日志上做了time標記。配合使用標記和EvaluatorFilter，實現日志的按過濾，是一個不錯的小技巧123123publicvoidperformance(@RequestParam(name="count",defaultValue="1000")longbegin=6789.collect(Collectors.joining(""))+UUID.randomUUID().toString();IntStream.rangeClosed(1,count).forEach(i->("{}{}",i,payload)MarkertimeMarker=MarkerFactory.getMarker("time");(timeMarker,"took{}ms",System.currentTimeMillis()-}4payload=)5 ->執行程序后可以看到，記錄1000次日志和100006.344.5FileAppender繼承自OutputStreamAppender，查看OutputStreamAppender源碼的第30到33行發現，在追加日志的時候，是直接把日志寫入OutputStream中，屬于同publicclassOutputStreamAppender<E>extendsUnsynchronizedAppenderBase<E>privateOutputStreambooleanimmediateFlush=protectedvoidappend(EeventObject)if(!isStarted()) protectedvoidsubAppend(E{if(!isStarted())}trybyte[]byteArray=}catch(IOExceptionioe)}}privatevoidwriteBytes(byte[]byteArray)throws{if(byteArray==null||byteArray.length==tryif(immediateFlush)}}finally}}41辦法當然有了，使用Logback提供的AsyncAppender即可實現異步的日志記錄。AsyncAppendeAsyncAppenderAppenderAppenderASYNCFILEFileAppender，1<appendername="ASYNCFILE"<appender-ref<appender-ref<root<appender-ref<appender-ref測試一下可以發現，記錄1000次日志和10000735668性能居然這么好，你覺得其中有什么問題嗎？異步日志真的如此神奇和萬能嗎？當然不是，因為這樣并沒有記錄下所有日志。我之前就遇到過很多關于AsncAppndr異步日志的坑，這些坑可以歸結為三類：ConsoleAppenderMySlowAppender，作為記錄到控制臺的輸出器，寫入日志時休眠1秒。publicclassMySlowAppenderextendsConsoleAppenderprotectedvoidsubAppend(Objectevent)try//}catch(InterruptedExceptione) 12然后，在配置文件中使用AsyncAppender，將MySlowAppender123456789<?xmlversion="1.0"encoding="UTF-8"<appendername="CONSOLE"<layout<pattern>[%d{yyyy-MM-ddHH:mm:ss.SSS}][%thread][%-5level]<appendername="ASYNC"<appender-refref="CONSOLE"<root<appender-refref="ASYNC"123456publicvoidmanylog(@RequestParam(name="count",defaultValue="1000")intclongbegin=System.currentTimeMillis();IntStream.rangeClosed(1,count).forEach(i->("log-{}",i));System.out.println("took"+(System.currentTimeMillis()-begin)+"ms")}執行方法后發現，耗時很短但出現了日志丟失：我們要記錄1000條日志，最終控制臺只能搜索到215出現這個問題的原因在于，AsyncAppenderincludeCallerDatafalse，此時方法行號、方法名等信息將不能顯示（源碼第2行以及7到11行）。1517），256256discardingThreshold是控制丟棄日志的閾值，主要是防止隊列滿后阻塞。默認情況下，隊列剩余量低于隊列長度的20%，就會丟棄TRACE、DEBUG和INFO級別的日志。（361819262733344042neverBlock用于控制隊列滿的時候，加入的數據是否直接丟棄，不會阻塞等待，默認是false（4468）offerput滿的時候offer方法不阻塞，而put方阻塞；neverBlock為true時，使用offerpublicclassAsyncAppenderextendsAsyncAppenderBase<ILoggingEvent>booleanincludeCallerData=false;//protectedbooleanisDiscardable(ILoggingEventevent)Levellevel=returnlevel.toInt()<=Level.INFO_INT;//丟棄<=INFO protectedvoidpreprocess(ILoggingEventeventObject)if 1213publicclassAsyncAppenderBase<E>extendsUnsynchronizedAppenderBase<E>BlockingQueue<E>blockingQueue;//publicstaticfinalintDEFAULT_QUEUE_SIZE=256;//intqueueSize=staticfinalintUNDEFINED=-intdiscardingThreshold=booleanneverBlock=false;//publicvoidstart()blockingQueue=newif(discardingThreshold==discardingThreshold=queueSize/5;// protectedvoidappend(EeventObject)if(isQueueBelowDiscardingThreshold()&&isDiscardable(eventObject)) privatebooleanisQueueBelowDiscardingThreshold()return(blockingQueue.remainingCapacity()< privatevoidput(EeventObject)if(neverBlock){//根據neverBlock決定使用不阻塞的offer還是阻塞的put}else privatevoidputUninterruptibly(EeventObject)booleaninterrupted=trywhile(true)try}catch(InterruptedExceptione)interrupted= }finallyif(interrupted)}}69}25680INFO以理解日志中為什么只有215條INFO日志了。queueSizeOOMqueueSize設置得比較小（默認值就非常小），且discardingThreshold設置為大于<=INFO的日志。這里的坑點有兩個。一是，因為discardingThreshold的存在，設置queueSize時容易踩坑。比如，本例中最大日志并發是1000，即便設置queueSize為1000同樣會導致日志丟失。二是，discardingThreshold比，而是日志條數。對于總容量10000的隊列，如果希望隊列剩余容量少于1000條的時候丟棄，需要配置為1000。neverBlock默認為false，意味著總可能會出現阻塞。如果discardingThreshold為0，那么隊列滿時再有日志寫入就會阻塞；如果discardingThreshold不為0，也只會丟棄可以看出queueSize、discardingThreshold和neverBlock這三個參數關，務必neverBlock為truediscardingThreshold0INFO級別日志也不會丟，但最好把queueSize設置大一點，畢竟默認的queueSize顯然太小，queueSize理的discardingThreshold。不知道你有沒有聽人：SLF4J的{}占位符語法，到真正記錄日志時才會獲取實際參數，為了驗證這個問題，我們寫一段測試代碼：有一個slowString方法，返回結果耗時1秒：privateStringslowString(Strings)System.out.println("slowStringcalledvia"+try}catch(InterruptedExceptione)}return8DEBUGINFO1拼接字符串方式記錄slowString；使用占位符方式記錄slowString；先判斷日志級別是否啟用DEBUGStopWatchstopWatch=newlog.debug("debug1:"+log.debug("debug2:{}",iflog.debug("debug3:{}",可以看到，前兩種方式都調用了slowString方法，所以耗時都是1使用占位符方式記錄slowString的方式，同樣需要耗時1秒，是因為這種方式雖然允許我們傳入Object，不用拼接字符串，但也只是延遲（如果日志不記錄那么就是省去）了日志參數對象.toString()和字符串拼接的耗時。在這個案例中，除非事先判斷日志級別，否則必然會調用slowString方法。回到之前提的SLF4JAPIlambdaLog4j2APILombok注解替換為@Log4j2lambdapublicclassLoggingControllerlog.debug("debug4:{}",()-像這樣調用debug方法，簽名是r<?>，參數會延真正需要記錄日志時再獲代代123456789voiddebug(Stringr<?>...publicvoidlogIfEnabled(finalr<?>...,finalLevellevel,finalMarkerrs)if(isEnabled(level,marker,message)),level,marker,message,}}protectedvoidlogMessage(finalr<?>...,finalLevellevel,finalMarkerrs)finalMessagemsg=messageFactory.newMessage(message,,level,marker,msg,}修改后再次運試，可以看到這次debug4并不會調用slowString方法Log4j2API，Logback就是SLF4J適配的一個好處。Java的日志框架眾多，SLF4J實現了這些框架記錄日志