【事故复盘】吐血整理一场线上事故——CPU飙升200%

&＃x1f50d; 经验使你在第二次犯相同错误时及时发现。 —— 琼斯

&＃x1f516; 事故时间&＃xff1a;12.7日 17:43 ~ 21:03

&＃x1f516; 事故影响&＃xff1a;服务接口查询慢&＃xff0c;用户查看数据转圈

&＃x1f516; 事故过程&＃xff1a;

那是一个宛如平静的下午&＃xff0c;一群程序员像往常一样工作着....
突然&＃xff0c;在17:43时&＃xff0c;运营和运维反馈我们的产品转圈了&＃xff0c;且监控发现大量异常发生。
随后我去APM上看了监控&＃xff0c;发现service请求响应时间激增。
第一时间怀疑是数据库TiDB的问题&＃xff08;因为就在前几天有个TiDB问题&＃xff0c;且还没有修复上线&＃xff09;。
17:50 为了防止大量请求堆积把服务打挂&＃xff0c;于是我便进行了服务的重启。
17:55 重启完发现响应时间确实降下来了。
18:20 观察了一阵&＃xff0c;发现接口查询已经缓解&＃xff0c;于是便先通知了运营。
此时已经算是松了一口气&＃xff0c;随后&＃xff0c;后端同学便开始排查问题原因。
最开始的排查思路&＃xff0c;是这样的&＃xff1a;
因为17:30 时突然有大量请求&＃xff0c;怀疑是大量查询造成了DB压力&＃xff0c;然后造成了查询超时。
于是开始逐一排查激增时间段的这些请求接口。
&＃xff08;我认为这里有一个误区&＃xff0c;就当服务整体不可用时&＃xff0c;单看某一个或者某几个接口很难排查到问题原因&＃xff0c;
应尽量先从全局共享资源去考虑&＃xff0c;例如&＃xff1a;数据库、缓存、服务CPU、服务内存、网络等&＃xff09;
期间有一个schedule问题&＃xff0c;也怀疑过是这个问题造成的&＃xff0c;但最终分析不是主要原因。
随着时间的流逝&＃xff0c;发现服务每半小时还是有抖动。
不料&＃xff0c;20:14 运维和运营同学又相继反馈大量异常和查询慢问题。
20:31&＃xff0c;后端同学发现service服务CPU自从12.6发版后异常的高&＃xff0c;比平常要翻一倍多。且GC次数也异常增多。
20:33&＃xff0c;拉上其他同学&＃xff0c;召开紧急会议&＃xff0c;确定回退服务对超级店长没有影响时&＃xff0c;便进行了版本回滚。
20:49&＃xff0c;把服务回滚完毕&＃xff0c;继续观察。回滚完CPU果然回到了正常&＃xff0c;一切恢复平静&＃xff0c;总算松了一口气。
随后&＃xff0c;便反馈给运营同学。
12.8 ~ 12.11号&＃xff0c;后端同学耗费了大量时间和人力&＃xff0c;终于排查到问题根因&＃xff0c;以此文章记录事故发生过程及问题排查思路。


&＃x1f516; 结果根因

根本原因是由于DevOps平台的maven构建近期可能进行了更新&＃xff0c;后端同学在构建时发现报错&＃xff0c;于是在pom中指定了maven-plugin的版本为项目的springboot版本&＃xff0c;也就是2.3.2-RELEASE&＃xff0c;怎料spring-boot-loader在2.3.2-REALEASE版本&＃x1f449;&＃x1f449;&＃x1f449;&＃x1f449;&＃x1f449;存在BUG&＃xff1a;

当加载不存在类时&＃xff0c;会产生大量JarFile对象实例未被引用&＃xff0c;从而产生内存泄露&＃xff0c;引发服务进行频繁GC而抢占大量的CPU资源&＃xff0c;从而引发CPU占用激增&＃xff0c;造成服务整体卡顿。
https://github.com/spring-projects/spring-boot/issues/22991
https://github.com/spring-projects/spring-boot/issues/28042

&＃x1f516; 排查方式

我们花了四天时间&＃xff0c;从各个角度对服务进行了问题排查&＃xff0c;希望对以后排查问题的同学能有前车之鉴。
下面是不同角度的排查思路&＃xff1a;

1.代码

用了一天的时间进行了新发代码的Review&＃xff0c;发现除了有个interface版本不一致问题&＃xff08;后来验证该问题不影响主要逻辑&＃xff09;&＃xff0c;其他业务代码并没有致命问题。
&＃xff08;但最终问题还是因为一行代码引发的血泪事故&＃xff0c;这告诫我们——不要忽略任何一行不起眼的代码&＃xff09;

2.日志

除了零碎的几个NPM异常&＃xff0c;并没有其他的大量错误日志。

3.JVM&＃xff08;调试三件套&＃xff1a;IDEA &＃43; arthas &＃43; jProfiler&＃xff09;

此处涉及大量的底层知识&＃xff0c;如果有些你看不懂&＃xff0c;证明你该学习了。


3.1 堆内存

起初的堆内存配置是这样的&＃xff1a;

java -jar
-Dcom.sun.management.jmxremote.authenticate&＃61;false
-Dcom.sun.management.jmxremote.port&＃61;1899
-Dcom.sun.management.jmxremote.ssl&＃61;false
-Xms1024m -Xmx6144m -Xmn2048m -Xss2048K
-XX:MetaspaceSize&＃61;128m -XX:MaxMetaspaceSize&＃61;512m


通过Arthas的memory命令监控得到&＃xff1a;

持续监控&＃xff0c;发现堆内存的survivor区域持续100%&＃xff0c;也就是新生代在不停的进行ParaNewGC&＃xff0c;以至于大对象会随着GC次数的增加逐渐进入老年代&＃xff0c;而老年代用CSM收集器再会进行回收。

我画了一下此时的JVM内存结构图&＃xff1a;

这里的话&＃xff0c;有一个问题就是初始堆内存分配的1024M&＃xff08;-Xms1024m&＃xff09;&＃xff0c;有点小的其实。既然Pod已经分配了4~8个g内存&＃xff0c;干脆直接把起始内存分配的大一些。通过实践&＃xff0c;发现确实有所改善&＃xff0c;但并不是引发事故的主要原因。

-Xms4096m -Xmx8000m -Xmn2048m -Xss2048K -XX:MetaspaceSize&＃61;128m -XX:MaxMetaspaceSize&＃61;512m

3.2 线程

通过arthas的thread --state BLOCKED命令查看阻塞线程&＃xff0c;发现确实每隔几秒钟就有几个线程处于BLOCKED阻塞状态&＃xff0c;其中占用CPU资源最大的就是Finalizer线程。

那么什么是Finalizer线程&＃xff1f;它都做了什么事情&＃xff1f;
https://binkery.com/archives/362.html

其实通过这里&＃xff0c;其实已经可以定位到是由于GC大量消耗CPU造成的资源紧张了。

顺着上面的思路&＃xff0c;我们生成几份JVM堆内存快照&＃xff0c;拷贝下来进行分析&＃xff1a;
arthas生成内存快照命令&＃xff1a;

heapdump --live /root/jvm.hprof


这里有一个Tips&＃xff0c;就是如果你拉下来了大量不同间隔时间内存快照&＃xff0c;怎么知道优先分析哪个&＃xff1f;
原则是——优先选择文件最大的那个
因为文件越大&＃xff0c;证明占用内存越多&＃xff0c;越容易得到更多的信息。


通过JProfiler利器可以对快照进行分析&＃xff1a;
异常Pod和正常Pod的快照实例数对比&＃xff0c;发现异常Pod的Finalizer类很多&＃xff0c;相差数倍&＃xff1a;

继续分析Finalizer这个对象&＃xff0c;发现它大量都与JarFile这个类相关联&＃xff0c;而JarFile是做什么的呢&＃xff1f;
它是spring boot 对JDK的JarFile的一种拓展&＃xff0c;用于我们的spring boot Jar包运行时&＃xff0c;把包中的依赖包加载到内存中&＃xff0c;通过spring boot的类加载器进行加载。

在这里拓展一些知识&＃xff1a;
就是spring boot 打包后的结构(你可以自己解压一个jar包试试)&＃xff1a;

project/
├── BOOT-INF/
│ ├── classes # 当前项目结果文件放置在 classes 路径下
│ │ │ └── application.properties # 项目中配置文件
│ │ ├── org/ # 项目中 java 路径下&＃xff0c;编译成 class 文件路径
│ │ ├── static/ # 项目中 resources 路径下的静态文件夹
│ │ └── templates/ # 项目中 resources 路径下的模板文件夹
│ └── lib/ # 项目所依赖的第三方 jar&＃xff08;Tomcat&＃xff0c;SpringBoot 等&＃xff09;
├── META-INF/
│ └── MANIFEST.MF # 清单文件&＃xff0c;用于描述可执行 jar 的一些基本信息
└── org/springframework/boot/loader/ # jar 包启动相关的引导
├── archive/
├── data
├── ExectableArchiveLauncher.class
├── jar/
├── JarLauncher.class
├── LaunchedURLClassLoader.class
├── LaunchedURLClassLoader$UseFastConnectionExceptionsEnumeration.class
├── Launcher.class
├── MainMethodRunner.class
├── PropertiesLauncher.class
├── PropertiesLauncher$1.class
├── PropertiesLauncher$ArchiveEntryFilter.class
├── PropertiesLauncher$PrefixMatchingArchiveFilter.class
├── PropertiesLauncher$ArchiveEntryFilter.class
├── util/
└── WarLauncher.class


MANIFEST.MF结构&＃xff1a;

Manifest-Version: 1.0 # 清单版本号
Start-Class: org.incoder.start.SpringbootStartApplication # 项目 main 方法所在的类
Spring-Boot-Classes: BOOT-INF/classes/ # 项目相关代码在打包后 jar 中的路径
Spring-Boot-Lib: BOOT-INF/lib/ # 项目中所依赖的第三方 jar 在打包后 jar 中的路径
Spring-Boot-Version: 2.1.6.RELEASE # 项目 SpringBoot 版本
Main-Class: org.springframework.boot.loader.JarLauncher # 当前 jar 文件的执行入口类&＃xff08;main 方法所在的类&＃xff09;
回车换行&＃xff08;在清单文件中&＃xff0c;必须有&＃xff0c;否则会出错&＃xff09;


再拓展一个知识&＃xff0c;spring boot的启动流程&＃xff1a;

要知道我们平时启动一个普通的jar都是通过jdk自带的三种类加载器进行『双亲委派』加载的&＃xff0c;
不同的内置classloader的scope 如下&＃xff1a;

• Bootstrap ClassLoader&＃xff08;加载JDK的/lib目录下的类&＃xff09;
• Extension ClassLoader&＃xff08;加载JDK的/lib/ext目录下的类&＃xff09;
• Application ClassLoader&＃xff08;程序自己classpath下的类)

但是spring-boot为了适配fatjar结构&＃xff0c;只能打破『双亲委派加载原则』&＃xff0c;通过使用spring-boot自定义的类加载器加载我们的程序依赖的Jar包。

通过对比正常和异常的service.jar包解压后的文件&＃xff0c;基本定位到该问题就是spring-boot-loader导致的了:

随后我下来了spring-boot的源码&＃xff0c;通过对比spring-boot-loader的 2.3.2 和 2.3.4&＃xff08;这个版本正常&＃xff09;版本提交记录&＃xff0c;发现了以下问题&＃xff08;可以在github 的issue中搜22991&＃xff09;&＃xff1a;

到这里基本确定是JarFile 内存泄露导致的了&＃xff0c;且spring-boot在2.3.4版本进行了修复&＃xff0c;但值得注意的是&＃xff0c;在JDK 11中仍然会存在问题&＃xff08;还好我们用的是JDK8&＃xff09;。

但你以为到这里就分析结束了吗&＃xff1f;作为一名程序员&＃xff0c;一定要有刨根问底的不懈精神&＃xff01;

于是&＃xff0c;我在本地进行了问题复现&＃xff1a;
方式也很简单&＃xff0c;在service服务中引入 spring-boot-loader源码&＃xff0c;通过JarLauncher类启动spring-boot项目&＃xff0c;然后模拟大量的请求发送&＃xff0c;观察JVM状态&＃xff0c;通过捕捉内存快照&＃xff0c;果然复现了问题。


通过github的issue得知&＃xff0c;是加载了不存在的类造成的内存泄露&＃xff0c;那我们去查查哪些类没被加载到&＃xff1a;
https://github.com/spring-projects/spring-boot/issues/28042

于是&＃xff0c;顺着思路查一下哪些类没有被加载到&＃xff1a;
通过&＃xff0c;调试源码发现&＃xff0c;spring-boot不会对类加载进行异常捕获&＃xff0c;于是我手动加上一个try cache&＃xff0c;运行。

果然发现了端倪&＃xff1a;

这个类是从阿里巴巴的druid连接池中调用的&＃xff1a;
于是跟踪到druid的源代码&＃xff0c;发现这里捕获了异常&＃xff0c;但是又不打印异常&＃xff0c;你说难受不难受&＃xff0c;要我们都没发现有报错信息呢。

于是再往上跟踪&＃xff0c;发现是这里调用的上述方法&＃xff0c;这个方法是获取最后一个包发送的时间&＃xff0c;用来判断是否需要断开与数据库的连接&＃xff0c;为了适配不同的 MySQL 版本&＃xff0c;这里先加载第一个类&＃xff0c;如果加载不到就加载第二个类。

通过调试&＃xff0c;我终于发现了这里的大坑&＃xff1a;
我们的mysql驱动是6.0.3&＃xff0c;理论上应该能找到第二个类并加载

但是&＃xff01;
6.0.3驱动包中的MysqlConnection类名称确实正确&＃xff0c;可是包路径却不一致。

至此&＃xff0c;终于定位到问题的根因&＃xff0c;解决办法是把
MySQL驱动包升到8.0.21版本&＃xff0c;同时把spring-boot-maven-plugin 升级到最新2.7.5



mysql
mysql-connector-java
8.0.21




org.springframework.boot
spring-boot-maven-plugin
2.7.5

com.hualala.report.HualalaReportServiceApplication




repackage






至此&＃xff0c;感谢运营和运维同学的及时提醒&＃xff0c;感谢每个后端小伙伴的辛苦付出&＃xff01;
希望在今后的日子里&＃xff0c;希望我们能慎重对待每一行代码&＃xff01;&＃x1f389;&＃x1f389;&＃x1f389;&＃x1f389;&＃x1f389;