前言
随着业务的快速增长,日志导致的线程 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。