这是我参与更文挑战的第5天，活动详情查看： 更文挑战
最近测试服务突然出现CPU打满100%，重启服务之后有请求过来瞬间CPU又上升到100%。其实我们现在有的时候也会出现CPU100%的情况。借此机会分享一下排查类似问题的方案和步骤。就以此次CPU满载为例： 现象：突然测试伙伴说XXX服务不可用了，之后我看注册中心nacos发现服务不在可使用的列表中了，于是登录这个机器发现请求日志确实不动了。之后通过查看命令：
ps -ef | grep 'java'
发现JAVA线程还在，心里有些奇怪为啥JAVA线程是存活状态并且服务也是存活状态，为啥请求hang住呢，接着执行命令
top
发现JAVA线程CPU使用100%，为了不影响服务的正常进行首先我进行了服务重启，重启后发现CPU正常，本地用postman调用对应接口测试一切正常。之后先回复了测试伙伴让他们继续进行，之后准备查看原因，不一会测试伙伴反馈又hang住了，我再次登录服务器查看JAVA线程又把CPU跑了100%，初步看可能跟测试伙伴测试用的参数有关，因为我本地模拟请求包括用postman压测都是正常的。于是我想就验证一下这个JAVA线程没有处理业务究竟在干嘛，竟然把CPU能打满，我也好奇为啥测试的一个请求能产生这么大影响，于是就开启了以下排查问题的过程：
- 看一下此时的堆栈信息有没有什么明显的异常，通过top命令可以查到对应JAVA线程的pid。导出当前的堆栈到文件进行分析。
jstack -l pid >> statck.txt
经过排查分析堆栈信息中并没有明显的错误显示（主要查看一下是否存在死锁情况），如果存在死锁会有下图字样：
- 堆栈看不出明显异常，接着进行排查，想查出cpu过载的对应的线程id是哪个，它究竟在干嘛。于是执行命令：
top -H -p pid
可以看到以下内容
我们看见cpu满载的pid是17880，我们把这个线程进行16进制的转换。因为在堆栈中都是以十六进制进行输出的。执行命令：
printf "%x\n" 17880
之后可以得到对应的十六进制结果： 45d8 有了这个十六进制线程标识我们执行以下命令查看这个线程所执行的内容是什么：
jstack 17850 | grep 45d8 -A 30
可以看到如下内容：
在输出的内容中看见线程具体在操作数据库的一些信息和GC信息，但是从正常流程来讲，就是简单的查询应该不会把CPU打满，所以觉得可能是GC的原因导致java线程负载过高所以还得继续深入排查。于是执行以下命令：
jstat -gcutil 17850 1000
可能看到以下界面：
先说明一下各个列的含义：
- S0：幸存1区当前使用比例
- S1：幸存2区当前使用比例
- E：伊甸园区使用比例
- O：老年代使用比例
- M：元数据区使用比例
- CCS：压缩使用比例
- YGC：年轻代垃圾回收次数
- FGC：老年代垃圾回收次数
- FGCT：老年代垃圾回收消耗时间
- GCT：垃圾回收消耗总时间 可以看出每隔1s输出一下当前垃圾回收情况，经过排查发现FGC每秒都在增加持续上升，同时FGCT时间很长。S1，O区使用比例都是100%，所以可以得出结论导致CPU满载的原因是由于java进行垃圾回收触发FULL-GC而且对象还是强引用一直回收不掉。于是下个疑问出来了什么东西导致这么频繁的GC。接着排查使用大招了（dump出整个堆栈内存信息进行分析），因为导出内存信息十分耗时，使用mat软件分析需要大内存所以称之为大招。好接着来：于是执行命令：
jmap -dump:format=b,file=/tmp/e.bin pid
执行以上命令则会将内存信息导出导tmp文件夹中，文件名字叫e.bin。一般这个文件非常大，这个案例中这个文件将近5GB。通过sz命令将该文件下载到本地准备进行分析。
- 使用mat软件进行对dump的内存信息进行分析
- 安装mat软件
官网下载地址 www.eclipse.org/mat/downloa… ，根据操作系统版本下载最新的MAT。
- 配置mat软件
因为要分析dump的内存文件需要吃掉很多内存，于是我们要配置一下mat，找到安装目录下MemoryAnalyzer.ini文件，该文件里面有个Xmx参数，该参数表示最大内存占用量，默认为1024m，根据堆转储文件大小修改该参数即可。此次要调整到8GB大小。来个例子： 修改配置文件: [ MemoryAnalyzer.ini ] 路径: /Applications/mat.app/Contents/Eclipse/MemoryAnalyzer.ini 参数: -Xms2048m -Xmx2048m
-startup
../Eclipse/plugins/org.eclipse.equinox.launcher_1.5.700.v20200207-2156.jar
--launcher.library
../Eclipse/plugins/org.eclipse.equinox.launcher.cocoa.macosx.x86_64_1.1.1100.v20190907-0426
-vmargs
-Xms8192m
-Xms8192m
-Dorg.eclipse.swt.internal.carbon.smallFonts
-XstartOnFirstThread
- 使用mat进行分析
打开mat导入刚刚下载下来的近5GB的文件，可看到如下的界面：
一般用到比较多的2个功能，上图红色框区域。 1、Histogram 2、Leak Suspects Histogram 这个功能主要是查看类和对象关系，对象和对象之间的关系，用来定位哪些对象在FGC之后还活着，哪些对象占大部分内存。 1、点开Histogram，可列出每一个类的实例数，支持正则表达式查找，也可以计算出该类所有对象的retained size。
说明一下上图那几列的含义： Shallow Heap就是对象本身占用内存的大小，不包含其引用的对象内存，实际分析中作用不大。常规对象（非数组）的ShallowSize由其成员变量的数量和类型决定。数组的shallow size有数组元素的类型（对象类型、基本类型）和数组长度决定。对象成员都是些引用，真正的内存都在堆上，看起来是一堆原生的byte[], char[], int[]，对象本身的内存都很小。 Retained Heap值的计算方式是将Retained Set（当该对象被回收时那些将被GC回收的对象集合）中的所有对象大小叠加。或者说，因为X被释放，导致其它所有被释放对象（包括被递归释放的）所占的heap大小。 Retained Heap例子: 一个ArrayList对象持有100个对象，每一个占用16 bytes，如果这个list对象被回收，那么其中100个对象也可以被回收，可以回收16*100 + X的内存，X代表ArrayList的shallow大小。所以，RetainedHeap可以更精确的反映一个对象实际占用的大小。 Leak Suspects Leak Suspects 界面提示可能存在内存的泄露。
然后接着，是问题一的描述，列出了一些比较大的实例。
点击Details可以看到细节信息
通过以上的分析，发现异常都是在查询数据库导致触发FULL-GC进而将CPU打满。于是回归测试伙伴的入参本地进行debug分析，最终结果是查询数据结果集条数为120万条，进而将内存打满，触发GC，同时还没有返回前对象为强引用状态导致GC一直回收不了，进而将CPU打满。 总结：虽然导致该问题的原因很简单，但是排查过程涵盖了线上经常出现CPU打满，负载过高或者内存异常的排查顺序与方法。总结记录分享大家供参考。
