服务日志性能调优，由log引出的巨坑

向右看齐 2024-03-02 09:39 29阅读 0赞

![7dcaff8630534f64a114dcd2825f32d2.png][]

只有被线上服务问题毒打过的人才明白日志有多重要！

谁赞成，谁反对？如果你深有同感，那恭喜你是个社会人了：）

日志对程序的重要性不言而喻，轻巧、简单、无需费脑，程序代码中随处可见，帮助我们排查定位一个有一个问题问题。但看似不起眼的日志，却隐藏着各式各样的“坑”，如果使用不当，不仅不能帮助我们，反而会成为服务“杀手”。

本文主要介绍生产环境日志使用不当导致的“坑”及避坑指北，高并发系统下尤为明显。同时提供一套实现方案能让程序与日志“和谐共处”。

**避坑指北**

本章节我将介绍过往线上遇到的日志问题，并逐个剖析问题根因。

不规范的日志书写格式

// 格式1
    log.debug("get user" + uid + " from DB is Empty!");
     
    // 格式2
    if (log.isdebugEnable()) {
        log.debug("get user" + uid + " from DB is Empty!");
    }
     
    // 格式3
    log.debug("get user {} from DB is Empty!", uid);

如上三种写法，我相信大家或多或少都在项目代码中看到过，那么他们之前有区别呢，会对性能造成什么影响？

如果此时关闭 DEBUG 日志级别，差异就出现了：

格式1 依然还是要执行字符串拼接，即使它不输出日志，属于浪费。

格式2 的缺点就是就在于需要加入额外的判断逻辑，增加了废代码，一点都不优雅。

所以推荐格式3，只有在执行时才会动态的拼接，关闭相应日志级别后，不会有任何性能损耗。

**生产打印大量日志消耗性能**

尽量多的日志，能够把用户的请求串起来，更容易断定出问题的代码位置。由于当前分布式系统，且业务庞杂，任何日志的缺失对于程序员定位问题都是极大的障碍。所以，吃过生产问题苦的程序员，在开发代码过程中，肯定是尽量多打日志。

为了以后线上出现问题能尽快定位问题并修复，程序员在编程实现阶段，就会尽量多打关键日志。那上线后是能快速定位问题了，但是紧接着又会有新的挑战：随着业务的快速发展，用户访问不断增多，系统压力越来越大，此时线上大量的 INFO 日志，尤其在高峰期，大量的日志磁盘写入，极具消耗服务性能。

那这就变成了博弈论，日志多了好排查问题，但是服务性能被“吃了”，日志少了服务稳定性没啥影响了，但是排查问题难了，程序员“苦”啊。

![688b27115a725883e22ed742e28f0970.png][]

提问：为何 INFO 日志打多了，性能会受损（此时 CPU 使用率很高）？

**根因一：同步打印日志磁盘 I/O 成为瓶颈，导致大量线程 Block**

可以想象，如果日志都输出到同一个日志文件时，此时有多个线程都往文件里面写，是不是就乱了套了。那解决的办法就是加锁，保证日志文件输出不会错乱，如果是在高峰期，锁的争抢 无疑是最耗性能的。当有一个线程抢到锁后，其他的线程只能 Block 等待，严重拖垮用户线程，表现就是上游调用超时，用户感觉卡顿。

如下是线程卡在写文件时的堆栈：

Stack Trace is:
    java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352)
    - waiting to lock <0x000000063d668298> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96)
    at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65)
    at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68)
    at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)
    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228)
    .....

那么是否线上减少 INFO 日志就没问题了呢？同样的，ERROR 日志量也不容小觑，假设线上出现大量异常数据，或者下游大量超时，瞬时会产生大量 ERROR 日志，此时还是会把磁盘 I/O 压满，导致用户线程 Block 住。

提问：假设不关心 INFO 排查问题，是不是生产只打印 ERROR 日志就没性能问题了？

**根因二：高并发下日志打印异常堆栈造成线程 Block**

有次线上下游出现大量超时，异常都被我们的服务捕获了，庆幸的是容灾设计时预计到会有这种问题发生，做了兜底值逻辑，本来庆幸没啥影响是，服务器开始“教做人”了。线上监控开始报警， CPU 使用率增长过快，CPU 一路直接增到 90%+ ，此时紧急扩容止损，并找一台拉下流量，拉取堆栈。

Dump 下来的线程堆栈查看后，结合火焰退分析，大部分现成都卡在如下堆栈位置：

Stack Trace is:
    java.lang.Thread.State: BLOCKED (on object monitor)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
    - waiting to lock <0x000000064c514c88> (a java.lang.Object)
    at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:205)
    at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:112)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.(ThrowableProxy.java:112)
    at org.apache.logging.log4j.core.impl.ThrowableProxy.(ThrowableProxy.java:96)
    at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629)
    ...

此处堆栈较长，大部分现场全部 Block 在 java.lang.ClassLoader.loadClass，而且往下盘堆栈发现都是因为这行代码触发的

at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)
     
    // 对应的业务代码为
    log.error("ds fetcher get error", e);

啊这。。。就很离谱，你打个日志为何会加载类呢？加载类为何会 Block 这么多线程呢？

一番查阅分析后，得出如下结论：

使用 Log4j 的 Logger.error 去打印异常堆栈的时候，为了打印出堆栈中类的位置信息，需要使用 Classloader 进行类加载；  
Classloader加载是线程安全的，虽然并行加载可以提高加载不同类的效率，但是多线程加载相同的类时，还是需要互相同步等待，尤其当不同的线程打印的异常堆栈完全相同时，就会增加线程 Block 的风险，而 Classloader 去加载一个无法加载的类时，效率会急剧下降，使线程Block的情况进一步恶化；  
因为反射调用效率问题，JDK 对反射调用进行了优化，动态生成 Java 类进行方法调用，替换原来的 native 调用，而生成的动态类是由 DelegatingClassLoader 进行加载的，不能被其他的 Classloader 加载，异常堆栈中有反射优化的动态类，在高并发的条件下，就非常容易产生线程 Block 的情况。  
结合上文堆栈，卡在此处就很明清晰了：

大量的线程涌进，导致下游的服务超时，使得超时异常堆栈频繁打印，堆栈的每一层，需要通过反射去拿对应的类、版本、行数等信息，loadClass 是需要同步等待的，一个线程加锁，导致大部分线程 block 住等待类加载成功，影响性能。  
讲道理，即使大部分线程等待一个线程 loadClass，也只是一瞬间的卡顿，为何这个报错这会一直 loadClass类呢？结合上述结论分析程序代码，得出：此处线程内的请求下游服务逻辑包含 Groovy 脚本执行逻辑，属于动态类生成，上文结论三表明，动态类在高并发情况下，无法被log4j正确反射加载到，那么堆栈反射又要用，进入了死循环，越来越多的线程只能加入等待，block 住。

**最佳实践**

**1、去掉不必要的异常堆栈打印**

明显知道的异常，就不要打印堆栈，省点性能吧，任何事+高并发，意义就不一样了：）

try {
        System.out.println(Integer.parseInt(number) + 100);
    } catch (Exception e) {
        // 改进前
        log.error("parse int error : " + number, e);
        // 改进后
        log.error("parse int error : " + number);
    }

如果Integer.parseInt发生异常，导致异常原因肯定是出入的number不合法，在这种情况下，打印异常堆栈完全没有必要，可以去掉堆栈的打印。

**2、将堆栈信息转换为字符串再打印**

public static String stacktraceToString(Throwable throwable) {
        StringWriter stringWriter = new StringWriter();
        throwable.printStackTrace(new PrintWriter(stringWriter));
        return stringWriter.toString();
    }

log.error 得出的堆栈信息会更加完善，JDK 的版本，Class 的路径信息，jar 包中的类还会打印 jar 的名称和版本信息，这些都是去加载类反射得来的信息，极大的损耗性能。

调用 stacktraceToString 将异常堆栈转换为字符串，相对来说，确实了一些版本和 jar 的元数据信息，此时需要你自己决策取舍，到底是否有必要打印出这些信息（比如类冲突排查基于版本还是很有用的）。

**3、禁用反射优化**

使用 Log4j 打印堆栈信息，如果堆栈中有反射优化生成的动态代理类，这个代理类不能被其它的Classloader加载，这个时候打印堆栈，会严重影响执行效率。但是禁用反射优化也会有副作用，导致反射执行的效率降低。

**4、异步打印日志**

生产环境，尤其是 QPS 高的服务，一定要开启异步打印，当然开启异步打印，有一定丢失日志的可能，比如服务器强行“杀死”，这也是一个取舍的过程。

**5、日志的输出格式**

我们看戏日志输出格式区别

// 格式1
    [%d{yyyy/MM/dd HH: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

官网也有明确的性能对比提示，如果使用了如下字段输出，将极大的损耗性能

%C or $class, %F or %file, %l or %location, %L or %line, %M or %method

![17eddad87326455d55008d9021956e78.png][]

log4j 为了拿到函数名称和行号信息，利用了异常机制，首先抛出一个异常，之后捕获异常并打印出异常信息的堆栈内容，再从堆栈内容中解析出行号。而实现源码中增加了锁的获取及解析过程，高并发下，性能损耗可想而知。

如下是比较影响性能的参数配置，请大家酌情配置：

%C - 调用者的类名(速度慢,不推荐使用)  
%F - 调用者的文件名(速度极慢,不推荐使用)  
%l - 调用者的函数名、文件名、行号(极度不推荐，非常耗性能)  
%L - 调用者的行号(速度极慢,不推荐使用)  
%M - 调用者的函数名(速度极慢,不推荐使用)

**解决方案——日志级别动态调整**

项目代码需要打印大量 INFO级别日志，以支持问题定位及测试排查等。但这些大量的 INFO日志对生产环境是无效的，大量的日志会吃掉 CPU 性能，此时需要能动态调整日志级别，既满足可随时查看 INFO日志，又能满足不需要时可动态关闭，不影响服务性能需要。

方案：结合 Apollo 及 log4j2 特性，从 api层面，动态且细粒度的控制全局或单个 Class 文件内的日志级别。优势是随时生效，生产排查问题，可指定打开单个 class 文件日志级别，排查完后可随时关闭。

限于本篇篇幅，具体实现代码就不贴出了，其实实现很简单，就是巧妙的运用 Apollo 的动态通知机制去重置日志级别，如果大家感兴趣的话，可以私信或者留言我，我开一篇文章专门来详细讲解如何实现。

**总结与展望**

本篇带你了解了日志在日常软件服务中常见的问题，以及对应的解决方法。切记，简单的东西 + 高并发 = 不简单！要对生产保持敬畏之心！

**最后感谢每一个认真阅读我文章的人，礼尚往来总是要有的，虽然不是什么很值钱的东西，如果你用得到的话可以直接拿走：**

#### ![在这里插入图片描述][492d7612ecf9402ca45f3dad0b4d69e3.png_pic_center] ####

这些资料，对于【软件测试】的朋友来说应该是最全面最完整的备战仓库，这个仓库也陪伴上万个测试工程师们走过最艰难的路程，希望也能帮助到你！

[7dcaff8630534f64a114dcd2825f32d2.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/02/4f5a531357244869bcc8d331c355609e.png
[688b27115a725883e22ed742e28f0970.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/02/241f3b14803d40a7b01fc51911d83ae6.png
[17eddad87326455d55008d9021956e78.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/02/b0a2cbf5244c448a975010bb895f3149.png
[492d7612ecf9402ca45f3dad0b4d69e3.png_pic_center]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/02/4c630cbdfd554cac9006bd4e185f13e2.png