Log4j2 同步打印日志导致线程阻塞问题剖析

背景

快看服务端开发使用 Java 语言和 Spring Boot Web 框架，在一次配置变更中由于配置参数错误导致服务解析异常，代码逻辑中对异常做了捕获处理，理论上不会对服务产生影响，但实际情况是服务响应时间变长，并发处理能力出现急剧下降。

问题复现

为什么在异常已处理的情况下依然会产生这么严重的问题呢？对代码逻辑和日志再次分析确认，异常处理是生效的，但会同步打印大量的异常栈日志。因此怀疑是打印日志导致服务性能下降。为了确认这个问题，接下来通过压测来复现和对比。准备如下 4 个压测条件：

1、配置正常下压测；

2、配置异常下压测；

3、配置异常下不打印异常栈压测；

4、配置异常下使用异步打印日志压测。

在测试环境中使用相同服务部署上面 4 个容器服务，容器 CPU 和内存配置均相同。在同一个机器使用wrk对 4 个服务的相同接口进行压测。压测命令：

wrk -t8 -c50 -d60 --latency --timeout 10 $URL。

使用 8 个线程，50 个并发连接，持续压测 60s 并打印响应延迟信息。

压测结果如下：

通过以上结果可以得出结论：

1、同步打印异常栈会导致服务性能急剧下降；

2、异步打印异常栈性能有所下降，但好于同步打日志。

问题分析

为什么同步打印异常栈会导致性能急剧下降？

排查思路如下：压测复现问题现场，使用诊断利器Arthas进行现场诊断，确认出问题的代码；然后通过断点调试出问题的代码逻辑，确认最终原因。

压测

由于业务代码依赖比较多，模拟了一个简化项目，使用此项目进行实验。项目代码参考：log4j2-demo。

项目主要依赖

• JDK: Oracle 1.8.0_191.jdk

• Spring Boot: 2.5.2

• Log4j2: 2.14.1

本地测试环境

• Mac 8CPU 16GB

压测命令

• wrk -t8 -c50 -d60 --latency --timeout 10 http://127.0.0.1:8080/bad
  

压测条件

1、业务逻辑正常；

2、业务逻辑打印异常栈信息。

压测结果

使用 Arthas 现场诊断

1、查看阻塞线程状态统计，执行 thread --state BLOCKED

2、查看阻塞的线程，执行 thread -b。

3、使用 trace 追踪方法的耗时，执行 trace com.kuaikan.log4j2demo.TestController indexException -n10 '#cost > 50'，一步一步 trace 追踪，最终定位到 trace org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader loadClass -n10 '#cost > 50'。

其中 TomcatEmbeddedWebappClassLoader.loadClass 代码如下：

public Class<?> loadClass(String name, boolean resolve) throws ClassNotFoundException {    synchronized (JreCompat.isGraalAvailable() ? this : getClassLoadingLock(name)) {        Class<?> result = findExistingLoadedClass(name);        result = (result != null) ? result : doLoadClass(name);        if (result == null) {            throw new ClassNotFoundException(name);        }        return resolveIfNecessary(result, resolve);    }}

结合以上信息和代码分析：压测中线程阻塞在org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:70)，这个方法的代码中包含synchronized同步区域。trace分析这个方法也花费时间最长，但这个方法内并没有其他调用花费较多时间，也验证是同步区域发生了阻塞，等待花费了大部分的时间。TomcatEmbeddedWebappClassLoader这个类是用来加载类，那么是什么类需要这么长的时间呢？接下来通过代码断点调试进行分析。

使用 VSCode 代码断点调试

在TomcatEmbeddedWebappClassLoader.java文件第70行设置断点，这个断点之前的调用可以在 VSCode 左侧控制栏的调用堆栈中看到，这样可以很方便查看之前的调用方法来了解整个调用过程。断点信息如下：

断点调试过程比较复杂曲折，为了方便大家理解，整个过程整理成如下 4 个阶段：

第一阶段 Tomcat + Spring Boot

这个阶段是 Spring Boot 接收到一个 Http 请求到进入业务代码之前。Spring Boot 把收到的 Http 请求转发到业务代码，这个过程使用Method.invoke反射。在sun.reflect包中Method.invoke使用代理类，代理类有如下 2 种方式实现：

• NativeMethodAccessorImpl
  

• GeneratedMethodAccessorXX
  

这 2 个代理类都包含invoke方法，都能完成对反射类方法的调用。不同点是：1、NativeMethodAccessorImpl 通过new方法生成，invoke方法底层调用native方法；2、GeneratedMethodAccessorXX 通过bytecode动态生成。前 16 次调用使用NativeMethodAccessorImpl，从 17 次调用开始使用GeneratedMethodAccessorXX，这种方式称为Inflation机制。

为什么这设计呢？源码注释如下：

"Inflation" mechanism. Loading bytecodes to implement Method.invoke() and Constructor.newInstance() currently costs 3-4x more than an invocation via native code for the first invocation (though subsequent invocations have been benchmarked to be over 20x faster). Unfortunately this cost increases startup time for certain applications that use reflection intensively (but only once per class) to bootstrap themselves. To avoid this penalty we reuse the existing JVM entry points for the first few invocations of Methods and Constructors and then switch to the bytecode-based implementations.

对于第一次Method.invoke调用，使用GeneratedMethodAccessorXX会比NativeMethodAccessorImpl时间多 3-4 倍，这对于密集使用反射（每个类只有一次）作为引导启动的应用来说，增加了应用的启动时间。因此前几次会使用NativeMethodAccessorImpl，之后会切换到GeneratedMethodAccessorXX。这个次数可以通过 JVM 参数-Dsun.reflect.inflationThreshold 进行配置，默认是 15。

GeneratedMethodAccessorXX动态生成的类具体是什么呢，在 Arthas 中通过jad sun.reflect.GeneratedMethodAccessor27可以看到：

[arthas@50006]$ jad sun.reflect.GeneratedMethodAccessor27ClassLoader:+-sun.reflect.DelegatingClassLoader@51c78264  +-sun.misc.Launcher$AppClassLoader@18b4aac2    +-sun.misc.Launcher$ExtClassLoader@3551a94
Location:
/* * Decompiled with CFR. * * Could not load the following classes: *  com.kuaikan.log4j2demo.TestController */package sun.reflect;
import com.kuaikan.log4j2demo.TestController;import java.lang.reflect.InvocationTargetException;import sun.reflect.MethodAccessorImpl;
public class GeneratedMethodAccessor27extends MethodAccessorImpl {    /*     * Loose catch block     */    public Object invoke(Object object, Object[] objectArray) throws InvocationTargetException {        TestController testController;        block5: {            if (object == null) {                throw new NullPointerException();            }            testController = (TestController)object;            if (objectArray == null || objectArray.length == 0) break block5;            throw new IllegalArgumentException();        }        try {            return testController.bad();        }        catch (Throwable throwable) {            throw new InvocationTargetException(throwable);        }        catch (ClassCastException | NullPointerException runtimeException) {            throw new IllegalArgumentException(super.toString());        }    }}

这个类主要作用就是调用testController.bad()。注意ClassLoader是sun.reflect.DelegatingClassLoader，这个我们会在第四阶段讲。

第二阶段 Custom Code

这个阶段是 Http 请求进入业务逻辑代码到调用log.error之前。在这个阶段代码中抛出Exception，Exception继承自Throwable，可以查到异常栈StackTrace信息，我们将这个变量传递给log.error。

第三阶段 LoggerConfig Appender Layout

这个阶段是调用log.error方法到异常栈开始类加载之前。调用log.error方法后，Log4j2 会根据log4j2.xml配置信息关联相关的LoggerConfig、Append和Layout。Layout 配置是<PatternLayout pattern="[%-5p %d{yyyy-MM-dd HH:mm:ss.SSS}] [%t] [%X{SessionId}] %l [%m]%n"/>，Log4j2 会解析为多个LogEventPatternConverter，在上面的图中显示共解析 15 个Convert。在log4j2.xml配置中我们第 15 个其实是个空，但为什么会产生ExtendedThrowablePatternConverter呢？

If the pattern string does not contain a specifier to handle a Throwable being logged, parsing of the pattern will act as if the "%xEx" specifier had be added to the end of the string. To suppress formatting of the Throwable completely simply add "%ex{0}" as a specifier in the pattern string.

摘自 Log4j2 Pattern Layout

如果模式串不包含处理Throwable的标识符，那么会将%xEx添加到模式串的末尾进行解析。%xEx与%throwable相同，但还包括类的包信息。

在 Log4j2 中ExtendedThrowablePatternConverter是%xEx的类实现，所以会用它来进行转换。在转换中会获取每个调用栈的 Class 信息，这个逻辑我们进入第四阶段查看。

第四阶段 Classloader

这个阶段是在ExtendedThrowablePatternConverter加载类信息开始到加载结束。在分析之前我们先了解下类加载的相关概念。

• JVM 类加载机制

JVM 把描述类的数据从.class文件加载到内存，并对数据进行校验、转换解析和初始化，最终形成可以被 JVM 直接使用的 Java 类型（Java.lang.Class 对象），这就是 JVM 的类加载机制。JVM 的类加载是通过 ClassLoader 及其子类来完成的，类的层次关系和加载顺序可以由下图来描述：

JVM 在加载类时默认采用的是双亲委派机制，即一个类收到加载类的请求时，它并不会自己先去加载，而是把加载任务委托给父类加载器依次递归，所有的加载请求最终都应该传送到顶层的启动类加载器中。如果父类加载器可以完成这个类加载请求，就成功返回；当父类加载器无法完成此加载请求时，子加载器才会尝试自己去加载。通过这种层级关系可以避免类的重复加载，同时保障核心类不被篡改。

• 线程上下文类加载器（ThreadContextClassLoader 即 TCCL）

Java 1.2 引入 TCCL，作为一个线程本地变量的和某个线程关联在一起的一个类加载器。这能够让任何包都可以在任意时候通过当前调用线程访问当前上下文加载器。这一上下文加载器能够访问负责本次调用的特定应用类加载器，然后能够对应用的类进行访问。

接下来我们分析类加载的过程：调用栈的大部分的 Class 信息可以从StackLocatorUtil.getCurrentStackTrace()中直接获取，不需要类加载。但GeneratedMethodAccessorXX无法直接获取，经过一个复杂的类加载后仍然没有加载到。这个过程代码如下，大致分为 3 次类加载：

private static Class<?> loadClass(final ClassLoader lastLoader, final String className) {    // XXX: this is overly complicated    Class<?> clazz;    if (lastLoader != null) {        try {            clazz = lastLoader.loadClass(className); // 1            if (clazz != null) {                return clazz;            }        } catch (final Throwable ignore) {            // Ignore exception.        }    }    try {        clazz = LoaderUtil.loadClass(className); // 2    } catch (final ClassNotFoundException | NoClassDefFoundError e) {        return loadClass(className);  // 3    } catch (final SecurityException e) {        return null;    }    return clazz;}
private static Class<?> loadClass(final String className) {    try {        return Loader.loadClass(className, ThrowableProxyHelper.class.getClassLoader());    } catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {        return null;    }}

• 第一次类加载

调试中lastLoader是Launcher$AppClassLoader，无法加载到类信息。

• 第二次类加载

调用LoaderUtil.loadClass，这个代码如下：

public static Class<?> loadClass(final String className) throws ClassNotFoundException {    if (isIgnoreTccl()) {        return Class.forName(className);    }    try {        ClassLoader tccl = getThreadContextClassLoader();        if (tccl != null) {            return tccl.loadClass(className);        }    } catch (final Throwable ignored) {    }    return Class.forName(className);}

使用线程上下文类加载器tccl进行类加载，通过调试tccl是TomcatEmbeddedWebappClassLoader，这个过程比较复杂，涉及到使用线程上下文类加载器和双亲委派进行类加载，但还是无法加载到类信息。

• 第三次类加载

使用ThrowableProxyHelper.class.getClassLoader()加载，这个加载器还是Launcher$AppClassLoader，无法加载到类信息。

结合以上过程以及第一阶段GeneratedMethodAccessorXX类的生成方式，无法加载到的原因如下：1、GeneratedMethodAccessorXX是动态生成的类，.class文件无法在磁盘中查找到，所以通过其他的类加载器无法进行类加载。

2、在第一阶段中可以看到GeneratedMethodAccessorXX的类加载器是DelegatingClassLoader，而 Log4j2 并没有使用此加载器来获取，所以也不会加载到。

通过以上分析，总结如下：

1、日志Layout默认使用%xEx打印异常栈的类信息，而异常栈中包含动态类GeneratedMethodAccessorXX的加载，需要类加载；

2、Log4j2 最终调用TomcatEmbeddedWebappClassLoader.loadclass进行类加载，由于是动态类和类加载器使用的原因，导致无法加载。每次日志打印都会进行类加载过程，而在上面的方法中有synchronized发生同步等待，线程阻塞后，并发能力下降。

优化

优化方式

上面原因比较清楚了，那么我们怎么来优化呢？

1、在Layout中增加标识符%ex{n}，这个不会打印类信息，不会因为类加载导致线程阻塞；n 表示打印多少行栈信息，一般只需要把业务调用栈信息打印出来即可，框架栈信息不需要。经过压测效果有提升，但还会发生其他方面的线程阻塞；

2、使用异步日志打印+Layout中增加标识符%ex{n}。因为日志打印发生在异步线程中，对业务线程没有影响，因此能够比较好的解决这个问题。

压测结果

总结

以上排查首先通过压测定位业务问题代码，然后通过Arthas和VSCode断点调试分析出问题的原因。在这过程中我们比较深入的分析了 Java 的 2 个重要的机制：反射和类加载。虽然在平时业务开发中很少用到，但在基础框架的实现、解决类冲突问题、热加载及热部署，JAR 包加密等方面有广泛的应用。熟悉这些技术背后实现的原理，能够帮助我们快速解决开发中遇到的各种疑难问题。

One more thing

快看创办于 2014 年，是中国最大的国漫平台和超新 Z 世代娱乐社区。截止到 2021 年 8 月，快看总用户超过 3.4 亿，月活接近 5000 万，超过行业第二名至第六名之和。快看作品已登陆全球近 200 个国家和地区，成为中国文化出海的代表。

公司高度重视技术投入，积极探索内容产业前沿科技。采用 AI、大数据等推动内容创作能力的拓展，提高内容行业的分发效率，加速内容产业与互联网的融合发展。

欢迎加入 KKFamily，一起做有挑战、有意思的事情，简历请投 hrzhaopin@kkworld.com。

作者：Bourne，2015 年 9 月加入快看，负责快看运维平台、基础组件和容器相关的开发工作。