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

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 220,492评论 6 513
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 94,048评论 3 396
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 166,927评论 0 358
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 59,293评论 1 295
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 68,309评论 6 397
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 52,024评论 1 308
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,638评论 3 420
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,546评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 46,073评论 1 319
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 38,188评论 3 340
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 40,321评论 1 352
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,998评论 5 347
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,678评论 3 331
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 32,186评论 0 23
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 33,303评论 1 272
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,663评论 3 375
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 45,330评论 2 358

推荐阅读更多精彩内容