調用 logback 去打印日誌的時候是會加鎖的，加鎖的位置在：
//ch.qos.logback.core.OutputStreamAppender#writeBytesprivatevoidwriteBytes(byte[]byteArray)throwsIOException{if(byteArray!=null&&byteArray.length!=0){this.lock.lock();try{this.outputStream.write(byteArray);if(this.immediateFlush){this.outputStream.flush();}}finally{this.lock.unlock();}}}這就意味着同一個appender的日誌寫是串行的，在高並發的場景下因為有鎖的爭用現象，所以看似很簡單的一行日誌，耗費的時間卻不少。接下來我們在本地簡單的模擬一下高並發的場景，並記錄打一行日誌的耗時是多少
publicstaticvoidmain(String[]args){ExecutorServicethreadPool=newThreadPoolExecutor(500,750,20,TimeUnit.MINUTES,newArrayBlockingQueue<>(1),newThreadFactoryBuilder().setNameFormat("test-log-thread").build(),newThreadPoolExecutor.CallerRunsPolicy());for(inti=0;i<750;i++){LoggerExecutorcommonExecutor=newLoggerExecutor();threadPool.submit(commonExecutor);}}staticclassLoggerExecutorimplementsRunnable{@SneakyThrows@Overridepublicvoidrun(){while(true){longstart=System.currentTimeMillis();logger.info("loginfomessageat{}",System.currentTimeMillis());longend=System.currentTimeMillis();longtime=end-start;System.out.println(time);}}}需要說明的是，現實中高並發的請求應當用一個線程池向另一個線程池反覆提交任務來模擬，這裡我們簡化了這個過程。
上圖是我記錄下來的logger.info的耗時曲線，從這張統計圖上可以看到，當並發量上來之後鎖爭用的情況加劇，僅僅是打印一行info日誌就可能花費 20-40ms(作為對比，在我的機器上單線程打印一行日誌通常是 1-2ms)，而且圖上有比較明顯的毛刺，打印日誌的耗時超過了 100ms，毛刺的原因在於OutputStream在緩存區滿了後要執行刷盤動作，但是在真正大流量應用中這種毛刺是致命的，可能導致RPC框架的線程池被吃光，正常業務服務的成功率下降。所以在高並發大流量的場景下info日誌的打印一定要謹慎。
1.2 大量異常引發性能毛刺在上一小節中我們提到，高並發場景下info日誌要謹慎打印，一般我們只記錄系統異常的日誌。我們把剛才的代碼片段做一個小的修改，改為調用logger.error打印日誌，然後再統計下這行代碼的耗時
//驅動代碼同1.1節，所以這裡省略staticclassLoggerExecutorimplementsRunnable{@SneakyThrows@Overridepublicvoidrun(){while(true){longstart=System.currentTimeMillis();//logger.info("loginfomessageat{}",System.currentTimeMillis());logger.error("log info message occurs error：{}",newRuntimeException());longend=System.currentTimeMillis();longtime=end-start;System.out.println(time);}}}
與 1.1 節相比，一個很明顯的變化就是error日誌的執行平均耗時到了 40-50ms，要比 1.1 節中的info日誌慢不少，這是為什麼呢？原因就在於調用logger.error(String, Throwable)時為了打印堆棧加載了每個調用節點的class，代碼在：
//ch.qos.logback.classic.spi.PackagingDataCalculator#computeBySTEPprivateClassPackagingDatacomputeBySTEP(StackTraceElementProxystep,ClassLoaderlastExactClassLoader){StringclassName=step.ste.getClassName();ClassPackagingDatacpd=cache.get(className);if(cpd!=null){returncpd;}//注意這行代碼Classtype=bestEffortLoadClass(lastExactClassLoader,className);Stringversion=getImplementationVersion(type);StringcodeLocation=getCodeLocation(type);cpd=newClassPackagingData(codeLocation,version,false);cache.put(className,cpd);returncpd;}在bestEffortLoadClass中則會嘗試類加載:
privateClassbestEffortLoadClass(ClassLoaderlastGuaranteedClassLoader,StringclassName){Classresult=loadClass(lastGuaranteedClassLoader,className);if(result!=null){returnresult;}ClassLoadertccl=Thread.currentThread().getContextClassLoader();if(tccl!=lastGuaranteedClassLoader){result=loadClass(tccl,className);}if(result!=null){returnresult;}try{returnClass.forName(className);}catch(ClassNotFoundExceptione1){returnnull;}catch(NoClassDefFoundErrore1){returnnull;}catch(Exceptione){e.printStackTrace();//thisisunexpectedreturnnull;}}//ch.qos.logback.classic.spi.PackagingDataCalculator#loadClassprivateClassloadClass(ClassLoadercl,StringclassName){if(cl==null){returnnull;}try{returncl.loadClass(className);}catch(ClassNotFoundExceptione1){returnnull;}catch(NoClassDefFoundErrore1){returnnull;}catch(Exceptione){e.printStackTrace();//thisisunexpectedreturnnull;}}java.lang.ClassLoader#loadClass(java.lang.String)這個方法就是我們熟知的加載類的接口，其實會在className維度加鎖。到這裡為什麼logger.error比logger.info慢多大家應該就猜到了，logger.error會打印出異常的堆棧，在高並發的場景下如果某個接口頻繁拋異常，那在打印error日誌的時候要各個線程要先去加載異常堆棧上各個類信息，產生鎖競爭，然後才會在appender維度排隊。一個常見的現實場景是下游服務限流或者直接宕機了，容易因為logback引發系統的毛刺。
二、異步日誌配置不當造成線程泄露其實在高並發的場景下，一般都會將日誌配置為異步打印，其原理大概如下圖所示：
AsyncAppender將Logging Event扔到一個隊列里，然後會有一個單獨的線程從隊列中消費LoggingEvent，並派發到具體要幹活的Appender中，因為避免了直接直接調用writeBytes，所以性能應該有非常大的提升。我們對logback的配置稍作改動，採取異步的方式打印日誌：
<appendername="FILE"class="ch.qos.logback.core.FileAppender"><file>/Users/idealism/Desktop/log.txt</file><encoder><pattern>%logger{35}-%msg%n</pattern></encoder></appender><appendername="ASYNC"class="ch.qos.logback.classic.AsyncAppender"><appender-refref="FILE"/></appender><rootlevel="DEBUG"><appender-refref="ASYNC"/></root></configuration>並採樣了每次打印日誌的耗時如下圖所示：
令人震驚的一幕出現了，在並發量比較大的場景下，異步打印日誌的的性能與同步相比竟然差了 10 倍！這是為什麼呢？上文說到，logback異步日誌的實現原理是一個生產者-消費者模型，問題在於在大流量的場景下，分配線程這個單線程的消費能力是趕不上生產能力的，最後導致所有的線程在日誌打印的阻塞隊列上排隊。此時通過arthas也可以看到線程的排隊情況，如果這是線上的業務系統，業務線程早被日誌的阻塞隊列吃光了，會引起業務響應異常
[arthas@9341]$threadThreadsTotal:780,NEW:0,RUNNABLE:13,BLOCKED:745,WAITING:4,TIMED_WAITING:3,TERMINATED:0,Internalthreads:15IDNAMEGROUPPRIORISTATE%CPUDELTA_TIMEINTERDAEMON10AsyncAppender-Workemain5RUNNAB43.010.0900:13.7falsetrue77arthas-command-execsystem5RUNNAB4.90.0100:0.02falsetrue39test-log-threadmain5BLOCKE0.750.0010:0.14falsefalse71test-log-threadmain5BLOCKE0.710.0010:0.15falsefalse37test-log-threadmain5BLOCKE0.710.0010:0.14falsefalse74test-log-threadmain5BLOCKE0.690.0010:0.15falsefalse67test-log-threadmain5BLOCKE0.690.0010:0.14falsefalse-1C2CompilerThread2--1-0.680.0010:1.68falsetrue69test-log-threadmain5BLOCKE0.660.0010:0.15falsefalse55test-log-threadmain5BLOCKE0.660.0010:0.14falsefalse38test-log-threadmain5BLOCKE0.650.0010:0.15falsefalse36test-log-threadmain5BLOCKE0.650.0010:0.14falsefalse28test-log-threadmain5BLOCKE0.650.0010:0.15falsefalse50test-log-threadmain5BLOCKE0.650.0010:0.14falsefalse36test-log-threadmain5BLOCKE0.640.0010:0.14falsefalse三、其他問題除了上面提到的幾個在高並發大流量場景下特有的坑外，還有一些其他的坑這裡列一下，因為網上的博客比較多了，這裡不再贅述
應當遵循以下幾個原則：
【最佳實踐一】日誌工具對象的logger應當聲明為private static final
【最佳實踐二】日誌字符串通過"+"拼接即占用了額外的內存，也不直觀，應當使用占位符
【最佳實踐三】日誌內容和日誌級別相符合
【最佳實踐四】高並發系統應少打或不打info日誌，且應當配置為異步日誌，當阻塞隊列滿時採取丟日誌的策略，以保證業務系統正常運行
推薦
Java面試題寶典
技術內卷群，一起來學習！！
PS：因為公眾號平台更改了推送規則，如果不想錯過內容，記得讀完點一下「在看」，加個「星標」，這樣每次新文章推送才會第一時間出現在你的訂閱列表里。點「在看」支持我們吧！
留言列表