惯性聚合 高效追踪和阅读你感兴趣的博客、新闻、科技资讯
阅读原文 在惯性聚合中打开

推荐订阅源

T
Threat Research - Cisco Blogs
H
Hacker News: Front Page
IT之家
IT之家
I
Intezer
GbyAI
GbyAI
MongoDB | Blog
MongoDB | Blog
博客园_首页
cs.CL updates on arXiv.org
cs.CL updates on arXiv.org
S
SegmentFault 最新的问题
D
Darknet – Hacking Tools, Hacker News & Cyber Security
T
Threatpost
Cisco Talos Blog
Cisco Talos Blog
C
Check Point Blog
P
Proofpoint News Feed
P
Privacy International News Feed
有赞技术团队
有赞技术团队
T
Tailwind CSS Blog
Scott Helme
Scott Helme
U
Unit 42
J
Java Code Geeks
W
WeLiveSecurity
H
Hackread – Cybersecurity News, Data Breaches, AI and More
C
CERT Recently Published Vulnerability Notes
小众软件
小众软件
The Hacker News
The Hacker News
L
LINUX DO - 热门话题
博客园 - 【当耐特】
G
Google Developers Blog
Latest news
Latest news
AWS News Blog
AWS News Blog
NISL@THU
NISL@THU
S
Secure Thoughts
P
Proofpoint News Feed
L
Lohrmann on Cybersecurity
F
Full Disclosure
S
Securelist
K
KPMG report finds enterprise disconnect between AI and its ROI | CIO
Engineering at Meta
Engineering at Meta
Security Archives - TechRepublic
Security Archives - TechRepublic
人人都是产品经理
人人都是产品经理
T
Tor Project blog
Recent Announcements
Recent Announcements
Security Latest
Security Latest
N
News | PayPal Newsroom
A
About on SuperTechFans
Hugging Face - Blog
Hugging Face - Blog
Y
Y Combinator Blog
大猫的无限游戏
大猫的无限游戏
博客园 - Franky
T
The Blog of Author Tim Ferriss

祈雨的笔记

安全多方计算MPC spark原理解析 kueue执行源码分析 spark on k8s执行源码分析 spark-operator源码解析 系统压测遇到的缓存击穿问题 我的世界PC与安卓联机 蚂蚁金服流量投放平台的AIG改造 G1大对象致Old区占用率高 日志打印导致接口响应率下跌分析 Groovy加载类导致OOM分析 记OceanBase死锁超时 应用发版期间服务响应超时 Ark Serverless初探 系统优化复盘一二三 The user specified as a definer does not exist Kong网关初探 API网关选型调研 CPU火焰图常用工具 配置中心选型调研 root操作Nginx导致用户组错误 基于Proxifier使用代理 FastJSON字段智能匹配踩坑 Nacos初探 记一次Nginx服务器CPU满荷载故障 基于券系统分库分表的思考 limit不参与SQL成本计算致索引失效 Linux常用性能监控命令 golang低版本http2偶现400 hostname in certificate didn't match 常见对称加密原理以及应用 tcp_tw_recycle引起的TCP握手失败 记一次mysql执行DDL导致锁表 mysql磁盘占用查看 mysql对text字段update致磁盘增长 elasticsearch报错index read-only TIME_WAIT与Http的Keep-Alive 记一次TIME_WAIT导致连接数报警 记一次生产事故OOM问题排查 redis分布式锁RedissonLock的实现细节 webservice复杂加密签名(2)java调用 webservice复杂加密签名(1)SoapUI mysql延时关联 利用中间人拦截实现APP内H5窜改 MySQL表字符集不同导致关联查询索引失效 通过SSH隧道远程办公 数据落盘方案 BeanDefinitionRegistryPostProcessor扩展 mysql空间索引 HTTPS攻击 spring循环依赖过程解析 elasticsearch性能优化 mysql IS NULL 使用索引 mysql字符集utf8mb4失效踩坑 常用加密算法 xml与javaBean转换 初探InnoDB MVCC源码实现 mysql索引原理 redis之list源码分析 redis之key过期源码分析 redis之string源码分析 redis之hash源码分析 线程池之ThreadPoolExecutor mysql数据页结构 Using temporary与Using filesort mysql回表致索引失效 springboot(28)HTTP连接池 定时任务之ScheduledThreadPoolExecutor elasticsearch常用script聚合 elasticsearch实现like查询 elasticsearch实现乐观锁 elasticsearch准实时原理 springboot(27)自定义缓存读写机制CachingConfigurerSupport optimizer tracing arthas常用命令 HTTP和HTTPS详解 redis集群选举机制 kafka消息重试 一点压力测试的经验 kafka架构概念 explain分析sql语句字段的解释 JVM问题分析处理手册 logstash过滤器(2)date logstash过滤器(3)dissect logstash编码器(1)json logstash编码器(2)multiline logstash表达式 logstash输入(1)通用选项 logstash输入(3)file logstash过滤器(1)通用选项 logstash输入(2)stdin logstash安装 记一次前端vConsole导致JSON序列化错误排查 解决多个异步操作嵌套问题 fastjson反序列化失败autoType is not support RTMP串流服务 POI自动调整列宽错误 Nginx+Lua实现动态黑名单 使用curl命令模拟POST和GET请求 ResponseEntity下载文件
ERROR日志打印导致CPU满载
祈雨的笔记 · 2021-09-04 · via 祈雨的笔记

描述

开发环境对一台测试节点进行压测时,由于参数配置错误导致请求没有业务处理直接报错。随即停止压测后登录测试机器排查日志,以外发现虽然已经没有请求到该节点,但应用依然在打印错误日志,并且看日志时间是在打印几分钟前请求的日志。

第一反应是异步打印的日志出现堆积,于是查看了该应用所在节点的物理资源,发现CPU已经满荷载,以及JVM触发了多次Full GC和OOM。

分析

复现

该节点重启后,以50TPS的速率故意发起错误请求的压测,果然稳定复现CPU满载的问题,因此盲猜是因为CPU满载导致异步日志打印速率慢,生产速度高于消费速度而出现日志堆积的情况,最终内存耗尽触发Full GC和OOM。通过arthas打印CPU火焰图后,发现CPU资源的消耗主要分布在日志异步打印时Class类加载方面,火焰图如下:

image

CPU满载原因

到这里有点摸不到头脑,大量日志打印会消耗CPU资源能理解,但仅仅每秒50次的日志打印也能吃满CPU?以及为什么日志打印会在类加载上消耗如此多的CPU资源?火焰图中为什么会出现3个类加载执行步骤?为了清楚以上问题,通过远程Debug来翻看该场景下日志打印的源代码实现。

通过层层debug,发现问题的核心代码逻辑在org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.ClassLoader, java.lang.String)这个方法中。但打印ERROR日志的异常堆栈时,会尝试加载该异常堆栈中所有的类,类加载的代码实现如下。例如一个异常堆栈有76层,则会对这76个异常堆栈的类进行类加载,但事实上由于应用是SofaArk应用,存在多个破坏双亲委任的类加载器,导致此处逻辑虽然最多会尝试3次类加载,但始终都是使用SofaArk的PluginClassLoader对Class类进行尝试加载。

因此如果异常堆栈中出现PluginClassLoader加载不到的类,就会出现CPU火焰图中类加载3次的情况。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
private Class<?> loadClass(final ClassLoader lastLoader, final String className) {
Class<?> clazz;


if (lastLoader != null) {
try {
clazz = lastLoader.loadClass(className);
if (clazz != null) {
return clazz;
}
} catch (final Throwable ignore) {

}
}
try {


clazz = LoaderUtil.loadClass(className);
} catch (final ClassNotFoundException | NoClassDefFoundError e) {
return loadClass(className);
} catch (final SecurityException e) {
return null;
}
return clazz;
}

private Class<?> loadClass(final String className) {
try {

return Loader.loadClass(className, this.getClass().getClassLoader());
} catch (final ClassNotFoundException | NoClassDefFoundError | SecurityException e) {
return null;
}
}

那么问题来了,为什么三次类加载都是用的PluginClassLoader尝试加载Class类?有哪些类是PluginClassLoader类加载器加载不到的?这里就涉及到SofaArk的类加载机制了,SofaArk中有两种类加载器:PluginClassLoader和BizClassLoader,前者加载不到Ark业务的类,后者加载不到Ark插件的类。

而SofaArk为了提供模块瘦身的能力,提前将大量的常用依赖jar包已经加载到SofaArk中,开发者就不需要再将这些依赖包再打包到运行jar包中,从而显著降低了运行包的体积。但这个功能导致了另外的一个问题:这些依赖jar包会优先由PluginClassLoader加载。其中就包括了log4j相关依赖,因此log4j的类加载器是PluginClassLoader,所以上述三次类加载过程中,始终都是通过PluginClassLoader尝试加载Class类。最终导致当一个异常堆栈打印时,其中的业务代码的类和其他未被SofaArk管控依赖的类会出现PluginClassLoader加载失败的问题。

image

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
protected Class<?> loadClassInternal(String name, boolean resolve) throws ArkLoaderException {
Class<?> clazz = null;



if (classloaderService.isSunReflectClass(name)) {
throw new ArkLoaderException(
String
.format(
"[ArkPlugin Loader] %s : can not load class: %s, this class can only be loaded by sun.reflect.DelegatingClassLoader",
pluginName, name));
}



if (clazz == null) {
clazz = findLoadedClass(name);
}



if (clazz == null) {
clazz = resolveJDKClass(name);
}



if (clazz == null) {
clazz = resolveArkClass(name);
}


if (clazz == null) {
clazz = preLoadClass(name);
}



if (clazz == null) {
clazz = resolveExportClass(name);
}



if (clazz == null) {
clazz = resolveLocalClass(name);
}



if (clazz == null) {
clazz = resolveJavaAgentClass(name);
}


if (clazz == null) {
clazz = postLoadClass(name);
}

if (clazz != null) {
if (resolve) {
super.resolveClass(clazz);
}
return clazz;
}

throw new ArkLoaderException(String.format(
"[ArkPlugin Loader] %s : can not load class: %s", pluginName, name));
}

继续翻找日志打印源码发现,log4j之所以对异常堆栈中每一个类尝试类加载,实际上是为了获取该类所在的jar包名称和版本号,用于日志打印。而对于类加载失败时,则jar包名称和版本号均以?表示,最终输出的异常堆栈日志格式如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
java.lang.RuntimeException: null
at com.wakzz.service.ContentManageFacadeImpl.queryByIds(ContentManageFacadeImpl.java:105) ~[?:?]
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at com.alicp.jetcache.anno.aop.JetCacheInterceptor.invoke(JetCacheInterceptor.java:42) ~[?:?]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at com.alicp.jetcache.anno.aop.JetCacheInterceptor.invoke(JetCacheInterceptor.java:42) ~[?:?]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.14.RELEASE.jar!/:5.1.14.RELEASE]
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]
at java.lang.Thread.run(Thread.java:858) [?:1.8.0_232]

通过jar包名称和版本号均为?判断该类为3次类加载失败的情况,如果异常堆栈中有13个类加载失败,该场景下一次异常堆栈打印需要执行39次类加载过程。因此复现步骤中虽然是以50TPS的低频率进行请求,但实际上导致了每秒近2000次的类加载。而复现步骤中抛出异常的位置是业务代码入口,因此涉及到的Ark业务类较少,试想一下,如果异常从比较深的路径上抛,一次请求中多次打印的异常堆栈,那么甚至可能出现每秒十几次甚至几次的持续错误请求就足够将该应用的CPU打垮而发生线上事故。

解决

通过分析得知,异常堆栈打印之所以导致CPU满载,是因为SofaArk应用多个ClassLoader实现的类隔离和瘦身能力导致异常堆栈日志打印时频繁执行无效的类加载过程,而通过CPU火焰图发现PluginClassLoader的resolveLocalClass方法对CPU资源消耗严重。

分析出问题引起的导火索是日志打印异常堆栈时输出jar包名称和版本号,因此盲猜涉及到了日志的输出格式。应用中使用的还是log4j作为日志输出工具,因此翻找log4j的日志格式文档。文档中详细记录了异常堆栈的三种输出格式:

  1. ex|exception|throwable: 输出完整的异常堆栈,输出格式和Throwable.printStackTrace()相同
  2. rEx|rException|rThrowable: 异常堆栈从第一个引发的异常开始打印(实测也打印类所在目录的jar包名称)
  3. xEx|xException|xThrowable: 除了输出ex|exception|throwable的信息外,还输出类所在的包信息,例如类所在目录的jar包名称

然后查看应用的日志输出配置,发现部分日志的输出格式没有表明异常堆栈的输出格式,如下:

1
<PatternLayout pattern="%d %-5p %c{2} - %m%n" charset="UTF-8"/>

通过log4j源码org.apache.logging.log4j.core.pattern.PatternParser#parse(java.lang.String, boolean, boolean, boolean)可得,异常堆栈的默认输出格式为xEx|xException|xThrowable。即未配置异常输出格式时,默认会通过类加载获取异常堆栈中每个类的包名和版本号。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
for (final PatternConverter converter : converters) {
if (converter instanceof NanoTimePatternConverter) {


if (config != null) {
config.setNanoClock(new SystemNanoClock());
}
}
LogEventPatternConverter pc;
if (converter instanceof LogEventPatternConverter) {
pc = (LogEventPatternConverter) converter;
handlesThrowable |= pc.handlesThrowable();
} else {
pc = new LiteralPatternConverter(config, Strings.EMPTY, true);
}

FormattingInfo field;
if (fieldIter.hasNext()) {
field = fieldIter.next();
} else {
field = FormattingInfo.getDefault();
}
list.add(new PatternFormatter(pc, field));
}

if (alwaysWriteExceptions && !handlesThrowable) {
final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, null);
list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
}

因此解决方案就很简单了,修改log4j的日志配置,强制指定每个日志文件的异常堆栈格式为ex|exception|throwable,修改如下:

1
2
3
4
5

<PatternLayout pattern="%d %-5p %c{2} - %m%n" charset="UTF-8"/>


<PatternLayout pattern="%d %-5p %c{2} - %m%n%throwable" charset="UTF-8"/>

修改后,再对应用以50TPS的频率进行压测,CPU资源满载的问题已经解决,其CPU火焰图输出如下:

image