Log4j2打印异常日志(AsyncAppender)导致线程Block

前言

随着业务的快速增长，日志导致的线程 Block 问题愈发频繁。比如调用后端 RPC 服务超时，导致调用方大量线程 Block；再比如，业务内部输出异常日志导致服务大量线程 Block 等，这些问题严重影响着服务的稳定性。

AsyncAppender 导致线程 Block

通过监控平台查看线程监控指标，从 Blocked 线程堆栈不难看出是跟日志打印相关，由于是 ERROR 级别日志，查看具体报错日志，发现有两种业务异常。

从 Blocked 线程堆栈中可以看出，线程阻塞在类加载流程上，发现加载类时确实会根据类名来加 synchronized 同步块，因此初步猜测是类加载导致线程 Block。

注意：

1、项目代码里只是普通地输出一条 ERROR 日志而已，为何会触发类加载？

2、通常情况下类加载几乎不会触发线程 Block，不然一个项目要加载成千上万个类，如果因为加载类就导致 Block，那项目就没法正常运行了。

为什么会触发类加载？

从 Blocked 线程堆栈着手分析，查看堆栈中的 ThrowableProxy 相关代码，发现其构造函数会遍历整个异常堆栈中的所有堆栈元素，最终获取所有堆栈元素类所在的 JAR 名称和版本信息。

具体流程如下：

1、首先获取堆栈元素的类名称。

2、再通过 loadClass 的方式获取对应的 Class 对象。

3、进一步获取该类所在的 JAR 信息，从 CodeSource 中获取 JAR 名称，从Package 中获取 JAR 版本。

当前问题已在2.11.1版本中修复，通过让 get/put 方法使用同一个 key 来修复缓存的有效性问题，但由于 ThrowableProxy 对每个 Throwable 都会创建一个全新的 Map，而不是使用全局 Map，因此其缓存也仅仅对单个 Throwable 生效。

上述问题从源码中可以看到，ThrowableProxy#toExtendedStackTrace 方法通过 Map缓存当前堆栈元素类对应的 CacheEntry，来避免重复解析 CacheEntry，但是由于Map 缓存 put 操作使用的 key 来自于 StackTraceElement.toString 方法，而 get操作使用的 key 却来自于 StackTraceElement.getClassName 方法，即使对于同一个 StackTraceElement 而言，其 toString 和 getClassName 方法对应的返回结果也不一样，所以此 map 形同虚设。

通常情况下一个类加载器对于一个类只会加载一次，类加载器内部保存有类缓存，无需重复加载，但目前的现象却是由于类加载而导致线程大量 Block，因此必然是有些类加载不了，且不断重复尝试加载，那到底是什么类无法加载呢

到底什么类加载不了？(分析业务异常的具体堆栈)

两份堆栈基本相似，且大多数类都是很普通的类，但是唯一不同的地方在于：

1、sun.reflect.NativeMethodAccessorImpl

2、sun.reflect.GeneratedMethodAccessor261

从字面信息中不难猜测出这与反射调用相关，但问题是这两份堆栈对应的其实是同一份业务代码，查阅相关资料得知，这与 JVM 反射调用相关.

JVM 对反射调用分两种情况：

1、默认使用 native 方法进行反射操作。

2、一定条件下会生成字节码进行反射操作，即生成 sun.reflect.GeneratedMethodAccessor<N> 类，它是一个反射调用方法的包装类，代理不同的方法，类后缀序号递增。

从源码的 MethodAccessorGenerator#generateName 方法可以看到，字节码生成的类名称规则是 sun.reflect.GeneratedConstructorAccessor<N>，其中 N 是从 0 开始的递增数字，且生成类是由 DelegatingClassLoader 类加载器定义，所以其他类加载器无法加载该类，也就无法生成类缓存数据，从而导致每次加载类时都需要遍历JarFile，极大地降低了类查找速度，且类加载过程是 synchronized 同步调用，在高并发情况下会更加恶化，从而导致线程 Block。

JVM 反射调用为什么要做这么做？

这是 JVM 对反射调用的一种优化手段，在 sun.reflect.ReflectionFactory 的文档注释里对此做了解释，这是一种“Inflation”机制，加载字节码的调用方式在第一次调用时会比 Native 调用的速度要慢 3~4 倍，但是在后续调用时会比 Native 调用速度快 20 多倍。为了避免反射调用影响应用的启动速度，所以在反射调用的前几次通过 Native 方式调用，当超过一定调用次数后使用字节码方式调用，提升反射调用性能。

普通通地打印一条 ERROR 日志，为何会导致解析、加载异常堆栈类？

AsyncAppender 在生成 LogEvent 的快照 Log4jLogEvent 时，会先对 LogEvent序列化处理统一转换为 LogEventProxy。

此时不同类型的 LogEvent 的处理情况稍有差异：

● Log4jLogEvent 类型，先执行 Log4jLogEvent#getThrownProxy 方法，触发创建 ThrowableProxy 实例。

● MutableLogEvent 类型，先创建 LogEventProxy 实例，在构造函数内执行 MutableLogEvent#getThrownProxy 方法，触发创建 ThrowableProxy实例。

不管 LogEvent 的实际类型是 MutableLogEvent 还是 Log4jLogEvent，最终都会触发创建 ThrowableProxy 实例，并在 ThrowableProxy 构造函数内触发了解析、加载异常堆栈类。

问题小结

Log4j2 打印异常日志时，AsyncAppender 会先创建日志事件快照，并进一步触发解析、加载异常堆栈类。JVM 通过生成字节码的方式优化反射调用性能，但该动态生成的类无法被 WebAppClassLoader 类加载器加载，因此当大量包含反射调用的异常堆栈被输出到日志时，会频繁地触发类加载，由于类加载过程是 synchronized同步加锁的，且每次加载都需要读取文件，速度较慢，从而导致线程 Block。