简介《只有被线上服务问题打得头破血流的人，才知道日志的重要性！》先说结论，谁赞成谁反对？如果你也有同感，恭喜你，你是一个社会人：）日志对于程序的重要性不言而喻。它重量轻，简单，不需要大脑。在程序代码中随处可见，帮助我们排查和定位问题。然而，看似不起眼的日志却隐藏着各种“陷阱”。如果使用不当，它不仅不能帮助我们，反而会成为服务的“杀手”。本文主要介绍在生产环境中日志使用不当造成的“坑”以及避免坑的指南，尤其是在高并发系统中。同时提供了一套实现方案，让程序和日志“和谐共存”。本章将介绍以往在网上遇到的日志问题，并一一分析问题的根源。不规则日志写入格式场景//format1log.debug("getuser"+uid+"fromDBisEmpty!");//format2if(log.isdebugEnable()){log.debug("getuser"+uid+"fromDBisEmpty!");}//Format3log.debug("getuser{}fromDBisEmpty!",uid);以上三种写法，相信大家在项目中或多或少都在代码中看到过，那么它们之前有什么区别，对性能会有什么影响呢？如果此时关闭DEBUG日志级别，就会出现差异。Format1即使不输出日志，也需要进行字符串拼接，比较浪费。格式2的缺点是需要增加额外的判断逻辑，增加了废代码，一点都不优雅。所以推荐格式3，只有在执行的时候才会动态拼接。关闭相应的日志级别后，不会有性能损失。尽可能多地生产和打印大量消耗性能的日志，这样可以将用户请求串起来，更容易确定问题的代码位置。由于现在的分布式系统和复杂的业务，任何日志的缺失都是程序员定位问题的很大障碍。因此，遭受生产问题困扰的程序员在代码开发过程中必须尽可能多地记录日志。为了日后尽快定位和修复问题，程序员在编程实现阶段会尽量多敲击关键日志。上线后可以快速定位问题，但随之而来的是新的挑战：随着业务的快速发展，用户访问量越来越大，系统压力越来越大。此时在线有大量INFO日志，尤其是在高峰期，大量写入日志磁盘，极大地消耗了业务性能。那么这就变成了博弈论。日志越多，排查问题越容易，但服务性能却被“吃掉”了。日志少了，不影响服务稳定性，但排查难度大，程序员很“吃亏”。问题：为什么INFO日志太多，性能会受损（此时CPU占用率高）？根本原因一：日志磁盘I/O同步打印成为瓶颈，导致大量线程阻塞。可以想象，如果日志都输出到同一个日志文件，此时多个线程都在写文件，是不是乱七八糟？向上。解决方法是加锁，保证日志文件输出不会乱序。如果是在高峰期，争夺锁无疑是最耗性能的。当一个线程抢到锁后，其他线程只能在Block中等待，严重拖累了用户线程。表现为上游调用超时，用户感觉卡住了。下面是写文件卡住的线程栈。堆栈跟踪是：java.lang.Thread.State：阻塞（在对象监视器上）在org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352)-等待锁定<0x000000063d668298>(aorg.apache.logging.log4j.core.appender.rolling.RollingFileManager）在org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText（TextEncoderHelper.java:96）在org.apache.logging.log4j.core。layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65)在org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68)在org.apache。logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)atorg.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228).....然后在线是不是可以减少INFO日志吗？同样，ERROR日志的数量也不应被低估。如果线上出现大量异常数据，或者下游出现大量超时，会瞬间产生大量ERROR日志。这个时候磁盘I/O还是会满的，导致用户线程阻塞。问：假设你不关心INFO排错，生产中只打印ERROR日志就没有性能问题吗？Rootcause2：高并发下的日志打印异常栈导致线上和下游的线程阻塞大量超时。底线价值逻辑，还好没有作用，服务器开始“教人”了。在线监控开始报警，CPU占用率上升太快，一路直接上升到90%+。这时紧急扩容止损，找了一台电脑拉下流量拉栈。从dump看线程栈，结合flame回溯分析，大部分都卡在了如下栈位置：StackTraceis:java.lang.Thread.State:BLOCKED(onobjectmonitor)atjava.lang.ClassLoader.loadClass(ClassLoader.java:404)-等待锁定<0x000000064c514c88>（一个java.lang.Object）在sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)atjava.lang。ClassLoader.loadClass（ClassLoader.java：357）在org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass（ThrowableProxyHelper.java:205）在org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace（ThrowableProxyHelper.java:112)在org.apache.logging.log4j.core.impl.ThrowableProxy.(ThrowableProxy.java:112)在org.apache.logging.log4j.core.impl.ThrowableProxy.(ThrowableProxy.java:96)atorg.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629)...这里的栈很长，大部分场景块都在java.lang中。氯assLoader.loadClass,stackdown发现在org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)//对应的业务代码为log.error("dsfetchergeterror",e);啊。.太离谱了，你做日志的时候为什么要加载类？为什么加载类会阻塞这么多线程？经过一番回顾分析，得出以下结论：在使用Log4j的Logger.error打印异常栈时，为了打印出类在栈中的位置信息，需要使用Classloader进行类加载；类加载器加载是线程安全的，虽然并行加载可以提高加载不同类的效率，但是当多个线程加载同一个类时，仍然需要相互同步等待，尤其是当不同线程打印的异常栈正好是同样，会增加线程阻塞的风险，而Classloader加载一个无法加载的类时，效率会急剧下降，进一步恶化线程阻塞的情况；由于反射调用的效率，JDK对反射调用进行了优化，动态生成方法调用的Java类，替代了原有的native调用。动态类由DelegatingClassLoader加载，不能被其他Classloader加载。异常堆栈中有反射优化的动态类。在高并发的情况下，非常容易产生线程阻塞。结合上面的栈，很明显这里卡住了：大量线程涌入，导致下游服务超时，导致超时异常栈频繁打印，栈的每一层都需要通过反射获取对应的class和version，行数等信息，loadClass需要同步等待，锁住一个线程，导致大部分线程阻塞等待class加载成功，影响性能。讲道理，即使大部分线程等待一个线程加载Class，也只是一瞬间的卡顿。为什么这个错误总是报loadClass？结合以上结论分析程序代码，得出这里线程中请求下游服务逻辑包括Groovy脚本执行逻辑，属于动态类生成。以上结论三说明动态类在高并发情况下无法被log4j正确反映和加载。然后又用栈反射，进入死循环。越来越多的线程只能加入等待，block活了。Bestpractice1.Removeunnecessaryexceptionstacks打印明显的异常，不打印堆栈，节省性能，随便什么+高并发，意思不一样:)try{System.out.println(Integer.parseInt(number)+100);}catch(Exceptione){//改进前log.error("parseinterror:"+number,e);//改进后log.error("parseinterror:"+number);}如果Integer.parseInt出现异常，异常的原因肯定是输入输出的数字不合法。这样的话，就完全没有必要打印异常栈了，可以去掉栈的打印。2.将堆栈信息转换为字符串，然后打印publicstaticStringstacktraceToString(Throwablethrowable){StringWriterstringWriter=newStringWriter();throwable.printStackTrace（新的PrintWriter（stringWriter））；returnstringWriter.toString();}log.error得到的栈信息会更完整，JDK版本，Class路径信息，jar包中的类也会打印jar的名称和版本信息。这些都是加载类的反射信息，大大降低了性能。.调用stacktraceToString将异常堆栈转换为字符串。相对而言，确认了一些版本和jar元数据信息。这时候你需要决定是否有必要把这些信息打印出来（比如基于版本的类冲突排查还是很有用的）。3.禁用反射优化，使用Log4j打印堆栈信息。如果栈中有反射优化生成的动态代理类，这个代理类就无法被其他Classloader加载。这时候打印栈会严重影响执行效率。但是禁用反射优化也有副作用，导致反射执行效率降低。4、异步打印日志生产环境，尤其是QPS高的服务，必须开启异步打印。当然，如果开启了异步打印，也有一定的丢失日志的可能。比如服务器被强行“杀死”，这也是一种选择的过程。5.日志的输出格??式与播放日志的输出格??式不同//Format1[%d{yyyy/MM/ddHH:mm:ss.SSS}[%X{traceId}]%t[%p]%C{1}(%F:%M:%L)%msg%n//格式2[%d{yy-MM-dd.HH:mm:ss.SSS}][%thread][%-5p%-22c{0}-]%m%n官网也有明确的性能对比提示，如果使用下面的字段输出，性能会大打折扣%Cor$class,%For%file,%lor%location,%Lor%line,%Mor%methodlog4j使用异常机制获取函数名和行号信息，先抛出异常，然后捕获异常并打印出异常信息的栈内容，然后从堆栈内容中解析行号。但是在实现源码中加入了锁的获取和解析过程。高并发下，性能损失可想而知。以下是影响性能的参数配置，请酌情配置：%C-调用者的类名（慢，不推荐）%F-调用者的文件名（很慢，不推荐）%l-调用者的函数名，文件名，行号（极度不推荐，很耗性能）%L-调用者的行号（很慢，不推荐）%M-调用者的函数名（很慢，不推荐）解决方案——动态调整日志级别项目代码需要打印大量INFO级别的日志，以支持问题定位和测试排查。但是这些大量的INFO日志对于生产环境来说是没有效果的。大量日志会吃掉CPU性能。这时候就需要动态调整日志级别，既可以满足随时查看INFO日志的需要，又可以满足在不需要的时候动态关闭的需求。影响服务性能需求。解决方案：结合Apollo和log4j2的特性，从API层面动态细粒度地控制全局或单个Class文件中的日志级别。优点是随时生效。对于生产排错，可以指定日志级别打开单个class文件，排错后可以随时关闭。由于本文篇幅所限，具体的实现代码就不贴出来了。其实实现起来很简单，就是巧妙地利用Apollo的动态通知机制来重置日志级别。有兴趣的可以私信我或者留言，我会开一篇文章专门详细讲解如何实现的。总结与展望本文带您了解日常软件服务中日志的常见问题及相应的解决方案。记住，简单的东西+高并发=不简单！敬畏生产！
