高并发系统谨防被一行日志击垮

　　一、同步打印日志中的坑1。1高并发场景下logback造成线程泄露
　　调用logback去打印日志的时候是会加锁的，加锁的位置在：ch。qos。logback。core。OutputStreamAppenderwriteBytesprivatevoidwriteBytes（byte〔〕byteArray）throwsIOException｛if（byteArray！nullbyteArray。length！0）｛this。lock。lock（）；try｛this。outputStream。write（byteArray）；if（this。immediateFlush）｛this。outputStream。flush（）；｝｝finally｛this。lock。unlock（）；｝｝｝
　　这就意味着同一个appender的日志写是串行的，在高并发的场景下因为有锁的争用现象，所以看似很简单的一行日志，耗费的时间却不少。接下来我们在本地简单的模拟一下高并发的场景，并记录打一行日志的耗时是多少publicstaticvoidmain（String〔〕args）｛ExecutorServicethreadPoolnewThreadPoolExecutor（500，750，20，TimeUnit。MINUTES，newArrayBlockingQueue（1），newThreadFactoryBuilder（）。setNameFormat（testlogthread）。build（），newThreadPoolExecutor。CallerRunsPolicy（））；for（inti0；i750；i）｛LoggerExecutorcommonExecutornewLoggerExecutor（）；threadPool。submit（commonExecutor）；｝｝staticclassLoggerExecutorimplementsRunnable｛SneakyThrowsOverridepublicvoidrun（）｛while（true）｛longstartSystem。currentTimeMillis（）；logger。info（loginfomessageat｛｝，System。currentTimeMillis（））；longendSystem。currentTimeMillis（）；longtimeendstart；System。out。println（time）；｝｝｝
　　需要说明的是，现实中高并发的请求应当用一个线程池向另一个线程池反复提交任务来模拟，这里我们简化了这个过程。
　　上图是我记录下来的logger。info的耗时曲线，从这张统计图上可以看到，当并发量上来之后锁争用的情况加剧，仅仅是打印一行info日志就可能花费2040ms（作为对比，在我的机器上单线程打印一行日志通常是12ms），而且图上有比较明显的毛刺，打印日志的耗时超过了100ms，毛刺的原因在于OutputStream在缓存区满了后要执行刷盘动作，但是在真正大流量应用中这种毛刺是致命的，可能导致RPC框架的线程池被吃光，正常业务服务的成功率下降。所以在高并发大流量的场景下info日志的打印一定要谨慎。1。2大量异常引发性能毛刺
　　在上一小节中我们提到，高并发场景下info日志要谨慎打印，一般我们只记录系统异常的日志。我们把刚才的代码片段做一个小的修改，改为调用logger。error打印日志，然后再统计下这行代码的耗时驱动代码同1。1节，所以这里省略staticclassLoggerExecutorimplementsRunnable｛SneakyThrowsOverridepublicvoidrun（）｛while（true）｛longstartSystem。currentTimeMillis（）；logger。info（loginfomessageat｛｝，System。currentTimeMillis（））；logger。error（loginfomessageoccurserror：｛｝，newRuntimeException（））；longendSystem。currentTimeMillis（）；longtimeendstart；System。out。println（time）；｝｝｝
　　与1。1节相比，一个很明显的变化就是error日志的执行平均耗时到了4050ms，要比1。1节中的info日志慢不少，这是为什么呢？原因就在于调用logger。error（String，Throwable）时为了打印堆栈加载了每个调用节点的class，代码在：ch。qos。logback。classic。spi。PackagingDataCalculatorcomputeBySTEPprivateClassPackagingDatacomputeBySTEP（StackTraceElementProxystep，ClassLoaderlastExactClassLoader）｛StringclassNamestep。ste。getClassName（）；ClassPackagingDatacpdcache。get（className）；if（cpd！null）｛returncpd；｝注意这行代码ClasstypebestEffortLoadClass（lastExactClassLoader，className）；StringversiongetImplementationVersion（type）；StringcodeLocationgetCodeLocation（type）；cpdnewClassPackagingData（codeLocation，version，false）；cache。put（className，cpd）；returncpd；｝
　　在bestEffortLoadClass中则会尝试类加载：privateClassbestEffortLoadClass（ClassLoaderlastGuaranteedClassLoader，StringclassName）｛ClassresultloadClass（lastGuaranteedClassLoader，className）；if（result！null）｛returnresult；｝ClassLoadertcclThread。currentThread（）。getContextClassLoader（）；if（tccl！lastGuaranteedClassLoader）｛resultloadClass（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。PackagingDataCalculatorloadClassprivateClassloadClass（ClassLoadercl，StringclassName）｛if（clnull）｛returnnull；｝try｛returncl。loadClass（className）；｝catch（ClassNotFoundExceptione1）｛returnnull；｝catch（NoClassDefFoundErrore1）｛returnnull；｝catch（Exceptione）｛e。printStackTrace（）；thisisunexpectedreturnnull；｝｝
　　java。lang。ClassLoaderloadClass（java。lang。String）这个方法就是我们熟知的加载类的接口，其实会在className维度加锁。到这里为什么logger。error比logger。info慢多大家应该就猜到了，logger。error会打印出异常的堆栈，在高并发的场景下如果某个接口频繁抛异常，那在打印error日志的时候要各个线程要先去加载异常堆栈上各个类信息，产生锁竞争，然后才会在appender维度排队。一个常见的现实场景是下游服务限流或者直接宕机了，容易因为logback引发系统的毛刺。二、异步日志配置不当造成线程泄露
　　其实在高并发的场景下，一般都会将日志配置为异步打印，其原理大概如下图所示：
　　AsyncAppender将LoggingEvent扔到一个队列里，然后会有一个单独的线程从队列中消费LoggingEvent，并派发到具体要干活的Appender中，因为避免了直接直接调用writeBytes，所以性能应该有非常大的提升。我们对logback的配置稍作改动，采取异步的方式打印日志：fileUsersidealismDesktoplog。txtfileencoderpatternlogger｛35｝msgnpatternencoderappenderappenderrootlevelDEBUGrootconfiguration
　　并采样了每次打印日志的耗时如下图所示：
　　令人震惊的一幕出现了，在并发量比较大的场景下，异步打印日志的的性能与同步相比竟然差了10倍！这是为什么呢？上文说到，logback异步日志的实现原理是一个生产者消费者模型，问题在于在大流量的场景下，分配线程这个单线程的消费能力是赶不上生产能力的，最后导致所有的线程在日志打印的阻塞队列上排队。此时通过arthas也可以看到线程的排队情况，如果这是线上的业务系统，业务线程早被日志的阻塞队列吃光了，会引起业务响应异常〔arthas9341〕threadThreadsTotal：780，NEW：0，RUNNABLE：13，BLOCKED：745，WAITING：4，TIMEDWAITING：3，TERMINATED：0，Internalthreads：15IDNAMEGROUPPRIORISTATECPUDELTATIMEINTERDAEMON10AsyncAppenderWorkemain5RUNNAB43。010。0900：13。7falsetrue77arthascommandexecsystem5RUNNAB4。90。0100：0。02falsetrue39testlogthreadmain5BLOCKE0。750。0010：0。14falsefalse71testlogthreadmain5BLOCKE0。710。0010：0。15falsefalse37testlogthreadmain5BLOCKE0。710。0010：0。14falsefalse74testlogthreadmain5BLOCKE0。690。0010：0。15falsefalse67testlogthreadmain5BLOCKE0。690。0010：0。14falsefalse1C2CompilerThread210。680。0010：1。68falsetrue69testlogthreadmain5BLOCKE0。660。0010：0。15falsefalse55testlogthreadmain5BLOCKE0。660。0010：0。14falsefalse38testlogthreadmain5BLOCKE0。650。0010：0。15falsefalse36testlogthreadmain5BLOCKE0。650。0010：0。14falsefalse28testlogthreadmain5BLOCKE0。650。0010：0。15falsefalse50testlogthreadmain5BLOCKE0。650。0010：0。14falsefalse36testlogthreadmain5BLOCKE0。640。0010：0。14falsefalse三、其他问题
　　除了上面提到的几个在高并发大流量场景下特有的坑外，还有一些其他的坑这里列一下，因为网上的博客比较多了，这里不再赘述https：www。elietio。xyzpostsf6b1711c。html《低版本bug导致totalSizeCap参数不生效》logback版本过低导致SizeAndTimeBasedRollingPolicy不生效的问题四、最佳实践
　　应当遵循以下几个原则：
　　【最佳实践一】日志工具对象的logger应当声明为privatestaticfinal声明为private是为了安全性考虑，防止logger被其他类非法使用声明为static和final则是因为在类的声明周期内无需变更logger，并且占用内存也更小
　　【最佳实践二】日志字符串通过拼接即占用了额外的内存，也不直观，应当使用占位符
　　【最佳实践三】日志内容和日志级别相符合debug和trace一般是开发者调试程序使用，线上应关闭这类日志info日志应当记录重要且无风险的信息，如上下文初始化，定时任务开始执行或者远程连接建立等场合warn日志应当记录可能有风险，但是不会影响系统继续运行的错误，如系统参数配置错误，用户请求参数不正确等。或者是在一些耗时异常的场景，如一次请求超时，一次sql执行超过2秒等error日志用于程序出错打印堆栈，不应该输出程序问题之外的其他信息
　　【最佳实践四】高并发系统应少打或不打info日志，且应当配置为异步日志，当阻塞队列满时采取丢日志的策略，以保证业务系统正常运行