log4j并发打印日志导致线程Block问题排查记录

现象:对固定接口测试环境做压测。qps保持在单机37左右,各服务未出现异常。但是压测持续30分钟左右时,突然出现大量线程block告警。

查看阻塞线程,大部分线程阻塞于ThrowableProxy.toExtendedStackTrace方法。

问题0:线程阻塞概念,一般有哪些原因?

1.锁对象有两个队列,等待队列+同步队列。线程被wait之后进入等待队列,notify之后进入同步队列,随后获取到锁进行业务操作。如果在notify之后,有多个线程竞争,线程没有获取到锁,则进入block状态,等待下次notify后重新竞争锁。

问题1:正常情况下,下游抛异常,上游日志线程是否会阻塞?

1.下游抛少量异常时,首先解析异常堆栈时是用的反射,不会生成代理类,就没有类解析这步操作。
2.即使大量反射导致生成了代理类,但如果异常较少,对于代理类的解析竞争线程少,会造成阻塞但是现象不明显。

问题2:下游短时间内抛大量异常,上游线程为什么会阻塞?

1.日志线程会通过反射获取异常类的包名,类名,行号,jar版本号等信息。反射两种方式实现,第一种jni native方法调用,第二种生成代理类GeneratorMethodAccessor,生成包含目标方法的代理类,通过DelegatingClassLoader加载后调用。默认是15次调用后通过类加载器处理反射,可通过sun.reflect.noInflation来设置。 初次调用使用native方法效率更高,代理类需要初始化。但是长期调用,代理类效率高是jni的10-40倍左右。
2.当大量异常时,jvm会优化通过类加载器来反射获取异常类信息。但是由于log4j bug,无法解析代理类,导致线程阻塞。

问题3:为什么日志线程需要去加载类?

获取异常信息的包名,类名,报错方法行号,版本号等信息。

问题4:为什么日志线程无法加载异常类?

log4j加载类有3个流程。
1.双亲委派加载。通过BootStrapClassLoader,ExtensionClassLoader,ApplicationClassLoader顺序加载,但是都没加载成功。并且由于该步骤需要sychronized(class.name),导致大量线程在此阻塞。抛异常后到第二步。


image.png

2.Class.forName()。由于没有完整的异常类class文件,导致无法正常加载。
3.使用当前类的类加载器加载。当前类加载器为UrlClassLoader,无法加载反射对应的类。只有DelegatingClassLoader能加载。
最后返回了null。


image.png

问题5:为何会一直重复加载类,而不是从缓存里取?

始终没有加载成功过,所以缓存中没有对应的类实例,每次都在ClassLoader.loadClass这个地方阻塞,同步加载,其他线程被block。

问题6:异步打印日志,为何还会出现阻塞?

log4j 2.7队列满了之后,默认的处理策略是由主线程来处理日志,同步写日志。

问题6:高并发打日志导致线程阻塞,CPU飙升。问题如何解决?

1.已知异常日志,只打印错误信息名,e.getMessage(),不打印堆栈信息。

破除问题的触发条件之一即可:
高并发打印异常栈日志(QPS>50);打日志增加限流
异常栈中包含反射相关的类(RPC中间件、aop); 异常堆栈中过滤掉反射类。MethodGeneratorAccessor,DelegatingMethodAccessor,NativeMethodAccessor

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