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

推荐订阅源

S
Securelist
C
Cybersecurity and Infrastructure Security Agency CISA
cs.AI updates on arXiv.org
cs.AI updates on arXiv.org
S
Security Affairs
Hacker News: Ask HN
Hacker News: Ask HN
L
Lohrmann on Cybersecurity
PCI Perspectives
PCI Perspectives
Threat Intelligence Blog | Flashpoint
Threat Intelligence Blog | Flashpoint
C
Cyber Attacks, Cyber Crime and Cyber Security
Recent Commits to openclaw:main
Recent Commits to openclaw:main
OSCHINA 社区最新新闻
OSCHINA 社区最新新闻
MyScale Blog
MyScale Blog
月光博客
月光博客
W
WeLiveSecurity
T
Threat Research - Cisco Blogs
Martin Fowler
Martin Fowler
CTFtime.org: upcoming CTF events
CTFtime.org: upcoming CTF events
Recorded Future
Recorded Future
The GitHub Blog
The GitHub Blog
Webroot Blog
Webroot Blog
Security Archives - TechRepublic
Security Archives - TechRepublic
TaoSecurity Blog
TaoSecurity Blog
P
Proofpoint News Feed
Google DeepMind News
Google DeepMind News
F
Full Disclosure
U
Unit 42
Jina AI
Jina AI
博客园 - 司徒正美
阮一峰的网络日志
阮一峰的网络日志
L
LINUX DO - 最新话题
宝玉的分享
宝玉的分享
大猫的无限游戏
大猫的无限游戏
The Hacker News
The Hacker News
The Last Watchdog
The Last Watchdog
T
Troy Hunt's Blog
腾讯CDC
T
Threatpost
H
Hacker News: Front Page
P
Palo Alto Networks Blog
博客园 - 聂微东
Last Week in AI
Last Week in AI
有赞技术团队
有赞技术团队
Help Net Security
Help Net Security
L
LINUX DO - 热门话题
N
News and Events Feed by Topic
人人都是产品经理
人人都是产品经理
让小产品的独立变现更简单 - ezindie.com
让小产品的独立变现更简单 - ezindie.com
奇客Solidot–传递最新科技情报
奇客Solidot–传递最新科技情报
Application and Cybersecurity Blog
Application and Cybersecurity Blog
Spread Privacy
Spread Privacy

祈雨的笔记

安全多方计算MPC spark原理解析 kueue执行源码分析 spark on k8s执行源码分析 spark-operator源码解析 系统压测遇到的缓存击穿问题 我的世界PC与安卓联机 蚂蚁金服流量投放平台的AIG改造 G1大对象致Old区占用率高 Groovy加载类导致OOM分析 ERROR日志打印导致CPU满载 记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下载文件
日志打印导致接口响应率下跌分析
祈雨的笔记 · 2021-12-15 · via 祈雨的笔记

背景

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

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

最近同事遇到类似的问题,虽然现象有所区别,他们系统的现象是CPU使用率始终在24%,业务接口响应耗时变长,但本质上和我原先在开发环境遇到的问题一直,都是异步打印日志堆积导致的问题。

复现

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

image

分析

类加载器

我们复现的应用是SofaArk应用,SofaArk设计了多个类加载器,因此这里首先要聊一聊SofaArk的类加载机制:SofaArk中有两种类加载器:PluginClassLoader和BizClassLoader。SofaArk为了提供模块瘦身的能力,提前将大量的常用依赖jar包已经加载到SofaArk中,开发者就不需要再将这些依赖包再打包到运行jar包中,从而显著降低了运行包的体积。

image

当前设计PluginClassLoader除了会加载SofaArk相关的类,还会加载plugin管控的依赖的类,但不会加载也无法加载业务代码的类和非plugin管控的类。而BizClassLoader则加载以下类:

  1. 业务代码的类
  2. 业务代码中引用的非plugin管控的依赖的类
  3. 业务代码中通过配置排除plugin管控的类

日志打印流程

通过火焰图可见日志打印消耗了绝大多数CPU资源,因此同样需要理解日志打印的流程。当业务代码中打印异常栈时,就会触发如下的流程。由于log4j的包是通过plugin管控的依赖,因此log4j的类加载器并不是BizClassLoader而是PluginClassLoader。由于项目配置了日志格式为异常栈需要打印jar包名称和版本号,因此当log4j打印异常栈时会通过log4j的类加载器即PluginClassLoader尝试加载每行异常栈的类,用于获取其所在的jar包名称和版本号。

image

但由于SofaArk的类加载器的实现,PluginClassLoader只会加载plugin管控的依赖的类,因此如下以内容平台的一次异常栈举例,业务代码的异常栈(包路径为com.wakzz.service.*)和引入的未被plugin管控的依赖永远尝试加载失败。因此异常栈通过PluginClassLoader尝试获取其所在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]

更糟糕的是log4j会对加载失败的类尝试3次,核心代码见org.apache.logging.log4j.core.impl.ThrowableProxy#loadClass(java.lang.ClassLoader, java.lang.String),直接导致上述的类加载失败问题直接放大了3倍。

假设一次异常栈中有10个类不在PluginClassLoader管控范围内,那么一次log4j的异常栈打印就会触发30次类加载。在加上我们项目中日志文件非常多,一个异常栈打印通常会在多个日志中打印,如一个异常栈会在3个日志文件中打印,那么类加载失败问题再放大3倍,即一次log4j的异常栈打印就会触发90次类加载。那么只需要以10TPS的频率触发调用接口的异常,那么就导致了每秒近1000次的类加载。

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

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;
}
}

类加载耗时

分析完日志打印问题,接下来分析类加载问题,为何类加载会消耗这么多资源。截取类加载对CPU消耗采样的火焰图,可见大多数资源消耗在类加载器对类的查找上。另外火焰图中String.relpace方法会消耗近四分之一的CPU挺意外的,因此专门对这处逻辑的代码实现关注了一下,关键代码如下:

image

PluginClassLoader类加载器在查询类之前,会先通过全类名组装文件路径,其中replaceCurrentDir的逻辑则是将/./字符替换成/,仅此简单的逻辑,由于使用的是String.relpace,其底层使用的是正则,因此当调用频率高的场景下,会消耗相当可观的CPU资源。因此这里实际上建议通过类似于replaceParentDir方法的字段截取来实现,能有效降低CPU的资源消耗问题。

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
private String normalize(String file) {
int afterLastSeparatorIndex = file.lastIndexOf(SEPARATOR) + SEPARATOR.length();
String afterSeparator = file.substring(afterLastSeparatorIndex);
afterSeparator = replaceParentDir(afterSeparator);
afterSeparator = replaceCurrentDir(afterSeparator);
return new StringBuilder(afterLastSeparatorIndex + afterSeparator.length())
.append(file.substring(0, afterLastSeparatorIndex)).append(afterSeparator).toString();
}

private String replaceParentDir(String file) {
int parentDirIndex;
while ((parentDirIndex = file.indexOf("/../")) >= 0) {
int precedingSlashIndex = file.lastIndexOf('/', parentDirIndex - 1);
if (precedingSlashIndex >= 0) {
file = file.substring(0, precedingSlashIndex) + file.substring(parentDirIndex + 3);
} else {
file = file.substring(parentDirIndex + 4);
}
}
return file;
}

private String replaceCurrentDir(String file) {
return file.replace("/./", "/");
}

主线程耗时

另一个问题,为何启用了日志异步打印,但业务线程依然被日志打印阻塞,从而影响到接口响应耗时?关键代码涉及到log4j异步日志打印时的降级逻辑。简单描述为异步打印日志时有个日志事件队列(默认长度2^18),业务代码的日志事件全部扔到该队列中,由异步线程消费并打印日志。但当日志事件的生产速度大于消费速度,导致该队列的日志时间堆积满后,就会触发降级逻辑,由原先的异步执行降级为通过业务线程同步打印日志。

实现逻辑见com.lmax.disruptor.RingBufferorg.apache.logging.log4j.core.async.AsyncLoggerConfig#callAppenders,与上述类加载问题合并后的具体流程如下图:

image

通过流程图可见,由于ERROR日志异常栈触发的类加载需要对全类名上悲观锁,且类加载过程对CPU资源消耗较多,因此实际场景下虽然log4j有4个异步日志消费线程,但每个类同时只有1个线程在执行加载逻辑,出现传说中的一核有难八核围观的现象。这个悲观锁导致日志消费瓶颈,进一步加剧了日志事件的堆积问题。

当异步队列堆积满后,触发日志打印降级,所有日志变成同步打印后,业务线程同步打印日志会在加载类时等待锁,从而增加了接口耗时,当锁等待超时则直接导致业务接口执行超时。

image

总结

综上是因为大量的业务异常打印了非常多的异常栈日志,在加上项目中配置的异常日志格式为异常栈需要打印jar包名和版本号,导致异常堆栈日志打印时频繁执行无效的类加载过程,而通过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