CPU使用率100%的故障排查记录_系统中断cpu占用100%

1. 背景

合作方反馈他们的系统rmeet偶尔出现CPU 100%的问题，每次出现都只能重启系统，但没过多久就又会出现，所以希望能协助一起排查。

注：出问题的服务器是一个java写的后台服务，业务包括会议安排、组织通讯录、消息通知等。

果然没过几天，合作方的运维同事就在微信里报 问题又出现了 。这次没有重启，而是委托相关同事抓了一些信息下来。本文就将整个排查和分析过程记录下来，以备以后翻阅，也供有兴趣的同行参考。

2. 资源分析

首先，我们尝试用 top 命令找出具体是哪些线程占用了CPU，命令用法如下：

top -H -p 7975

-H：该选项表示在进程列表中显示线程，而不仅仅是进程。
-p：指定进程ID，表示只显示指定进程ID的信息。

得到此java进程内相关线程的资源占用情况，截图如下：

jstack -l -F 7975

-l：此选项用于打印线程在等待的锁信息，常用于分析死锁和资源竞争问题。

-F: 此选项表示 强制 执行，这里表示即使JVM不响应也会打印线程堆栈信息， 常用于调试陷入死锁或严重性能问题的应用程序。

上面截图中的nid是用16进制表示的线程ID，和前面top命令截图中的pid是能一一对应上的。第一个nid 0x1f26 换算成10进制为 7974 ，正好是上面top命令截图中的第4个线程。

截图显示，这些 问题线程 全部是GC线程，通过这两个命令的截图分析，基本能推测是垃圾回收器的13个线程占满了CPU。

与此同时，相关同事也对机器资源占用情况进行了监控，CPU和内存资源在问题时间段内的截图分别如下：

垃圾回收器占满CPU说明JVM基本已经没有可分配的内存，结合内存的突增现象大概推测： 是突发的异常逻辑分配了大量内存，达到了JVM可用的Heap上限，无内存可分配，导致垃圾回收器不得不全负荷工作所以占满了CPU 。

接下来要排查的就是： 找到具体是哪个异常情况导致了内存占用的突增 。

3. 日志分析

导致服务器内存突增的情况，个人想到的大概两种：

1. 短时间内突增请求量；
2. 某个异常的逻辑分配了大量内存；

筛选过一遍Nginx日志，按时间段分组统计后，没发现流量有什么变化，第一种情况基本排除。

所以尝试从业务日志中看看有没有查询条数很多的SQL，从编号137机器的日志中过滤14:00~15:00期间所有DB 查询条数大于1000 的SQL，得到如下几个信息：

• cn.com.systec.system.user.dao.ViewUserMapper.selectList ， 只执行一次，查询了 694726 条数据
• cn.com.systec.umeet.dao.RoomMapper.selectByLocationExe ， 执行16次，共查询 27824 条数据，平均一条SQL查询1739条数据
• cn.com.systec.umeet.dao.MeetingMapper.selectList ， 执行153次， 共查询 260902条数据，平均一条SQL查询1705条数据
• cn.com.systec.umeet.dao.RoomMapper.selectList ， 只执行一次，查询 1375 条数据

最明显的异常是第一个场景， 一条SQL查询了将近70万条数据 。

从日志中可以看出第一条SQL执行了全表扫描，没有带任何条件和数量限制，如下：

2022-08-0914:27:48:048 DEBUG 297103317---[http-nio-8080-exec-6] org.mybatis.spring.transaction.SpringManagedTransaction : JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@5d21dfec] will not be managed by Spring
2022-08-0914:27:48:048 DEBUG 297103317---[http-nio-8080-exec-6] cn.com.systec.util.mybatis.MyTenantSqlParser : Original SQL: SELECT * FROM v_user
2022-08-0914:27:48:048 DEBUG 297103317---[http-nio-8080-exec-6] cn.com.systec.util.mybatis.MyTenantSqlParser : parser sql: SELECT * FROM v_user
2022-08-0914:27:48:048 DEBUG 297103317---[http-nio-8080-exec-6] cn.com.systec.system.user.dao.ViewUserMapper.selectList :==> Preparing: SELECT * FROM v_user
2022-08-0914:27:48:048 DEBUG 297103317---[http-nio-8080-exec-6] cn.com.systec.system.user.dao.ViewUserMapper.selectList :==> Parameters:2022-08-0914:29:15:015 DEBUG 297190006---[http-nio-8080-exec-6] cn.com.systec.system.user.dao.ViewUserMapper.selectList :<== Total:694726

这个问题并不是必现，至于什么情况会执行全表扫描，需要结合代码逻辑分析。

4. 代码分析

代码执行位置及全表扫描原因归纳如下：
接口 ：/history/export/{id} ，用于导出单场历史会议的数据；
代码文件 ：

at cn.com.systec.umeet.service.HistoryMeetingService.exportHistoryMeeting(HistoryMeetingService.java:954)

代码行 ：

List<ViewUser> userList = viewUserMapper.selectList(newQueryWrapper<ViewUser>().in("id",ObjectUtil.isNotNull(historyMeeting.getUserIds())? historyMeeting.getUserIds():CollUtil.newArrayList(1L)));

原因 ：当historyMeeting.getUserIds()为空集合时，QueryWrapper不会拼接in条件，进而导致用户表全表扫描，共69万条数据，查询DB花了1分27秒。

注：这些数据在内存里持续了很长时间，SQL执行时间是在14:27分，但到合作方的运维同事抓jstack堆栈的14:47分时，线程仍然处于Runnable状态，说明这些数据已经在内存里常驻了至少20分钟以上。

从线程堆栈来看，这个线程当时在做的事情看起来是把近70万条用户数据写到Excel中，见下面ExcelExportTool.setSheet函数调用。

"http-nio-8080-exec-6" #93 daemon prio=5 os_prio=0 tid=0x00007f2ce8008800 nid=0x1f9a runnable [0x00007f2cdeef4000]java.lang.Thread.State: RUNNABLE
    at java.lang.Object.notify(NativeMethod)
    at org.apache.xmlbeans.impl.common.Mutex.release(Mutex.java:79)- locked <0x000000070b929788>(a org.apache.xmlbeans.impl.common.Mutex)
    at org.apache.xmlbeans.impl.common.GlobalLock.release(GlobalLock.java:29)
    at org.apache.xmlbeans.impl.values.XmlObjectBase.set(XmlObjectBase.java:2070)- locked <0x00000007ae330620>(a org.apache.xmlbeans.impl.store.Locale)- locked <0x000000070a12f340>(a org.apache.xmlbeans.impl.store.Locale)
    at org.apache.poi.xssf.model.SharedStringsTable.addEntry(SharedStringsTable.java:211)
    at org.apache.poi.xssf.model.SharedStringsTable.addSharedStringItem(SharedStringsTable.java:234)
    at org.apache.poi.xssf.usermodel.XSSFCell.setCellValueImpl(XSSFCell.java:427)
    at org.apache.poi.xssf.usermodel.XSSFCell.setCellValueImpl(XSSFCell.java:407)
    at org.apache.poi.ss.usermodel.CellBase.setCellValue(CellBase.java:292)
    
    at cn.com.systec.util.tools.ExcelExportTool.setSheet(ExcelExportTool.java:65)
    
    at cn.com.systec.umeet.service.HistoryMeetingService.exportHistoryMeeting(HistoryMeetingService.java:954)
    at cn.com.systec.umeet.service.HistoryMeetingService$$FastClassBySpringCGLIB$$ab77da0a.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:684)
    at cn.com.systec.umeet.service.HistoryMeetingService$$EnhancerBySpringCGLIB$$8ebcbd67.exportHistoryMeeting(<generated>)
    at cn.com.systec.umeet.web.MeetingController.exportHistoryMeeting(MeetingController.java:687)
    at cn.com.systec.umeet.web.MeetingController$$FastClassBySpringCGLIB$$864917f2.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
    at cn.com.systec.umeet.web.MeetingController$$EnhancerBySpringCGLIB$$52e634c8.exportHistoryMeeting(<generated>)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethod)
    at sun.reflect.NativeMethodAccessorImpl.invoke(UnknownSource)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(UnknownSource)

线程栈对应的相关代码如下：

940行的viewUserManager.selectList是查询会议上的所有参会人用户信息，954行是把参会人信息导出到Excel中，应该是卡在了954行。

5. 内存占用分析

这将近70万条用户大概占用了多少内存呢？这里我们可以粗略估算一下。

DB中一条用户数据信息：

1136145321038234357201906910012000276  智慧空间服务部 TEST004 $2a$10$FImVykfWwOMB4b8LIrDUIuoRLgq8oFgo0DAAeFhSOTpkBwaQGBIDG    测试004   TEST004@crc.com.hk  1389075436311   NULL    2019069100010340012305477877772019-06-0513:38:48 NULL    2022-03-3011:12:02 blacklist   1136145319667085314 NULL    11136559058664984578220190691000,20190691001,201906910011000000,201906910011000012,201906910012000208,201906910012000209,201906910012000215,201906910012000276   华润集团/集团总部/华润集团总部/集团财务部/华润汇项目组/华润守正招标/守正公司项目三部/智慧空间服务部   111111111000           NULL

• 代码中这个ViewUser对象以及它继承的User和BaseEntity对象，大概数下来有56个属性，全部是封装类型（如Long)，在计算空间占用时每个属性都要按Java 对象 的内存分配来计算；
• 这56个属性，不算数据部分，单纯对象头+引用（按12个字节头+4个字节的引用来计），要占将近900个字节；
• 数据部分从DB粗略找了一条数据，去掉空白字符并把整型列按Java中定义的int/long来计算，大概占600字节；
• 单纯上面两部分一条数据在内存里要占1500字节，70万条数据大约占用1.05GB的内存空间。

这里还没考虑有些属性是数组、嵌套对象（Date）、父子对象占用的引用和对象头空间，实际情况可能比1.05GB还要大。

更进一步评估 ：上面仅仅是List这个集合占用的空间，这个集合在导出到Excel时，需要先在内存里构造整张Excel表格需要写的行列对象数据，构造完才会真正将数据刷到磁盘（构造Excel单元格对象的代码见下图）。

从上图可知，它用了双层For循环为将近70万条数据构造XSSRow、XSSCell对象，这相当于 把70万个ViewUser对象再复制一份 ，要向JVM的堆空间再申请1GB左右的内存空间

注：图中第65行代码是在给每个ViewUser对象的每个属性构造XSSCell对象。

个人推测，在setSheet这一步由于JVM没有足够的堆空间给程序分配，所以启动垃圾回收器来满负荷回收内存，所以各个核的CPU都飙升至近90%以上。

而且由于需要的空间超过了堆空间能提供的可分配内存，垃圾回收器也无法回收足够的内存，这个CPU高的状态就会长期持续下去。

6. 结论

原因 ：MybatisPlus中QueryWrapper的in条件缺少空集合参数的检查和处理，导致误走了全表扫描。

解法 ：直接将in语法拼接的判断条件由 CollUtils.isNotNull 改成 CollUtils.isNotEmpty 即可。

// 解法示例
List<ViewUser> userList = viewUserMapper.selectList(
	new QueryWrapper<ViewUser().in(CollUtil.isNotEmpty(historyMeeting.getUserIds()),"id", historyMeeting.getUserIds()));//QueryWrapper的带condition的in方法原型：
default This in(boolean condition, R column, Object... values){
    ……
}

附相关排查命令

# 查看指定进程下的线程资源占用top -H -p 7975# 查看指定进程下的线程运行堆栈
jstack -l -F 7975# 筛选返回条数大于1000的所有大数据量查询cat info_0809_14_137.log |grep -E 'Total: [0-9]{4}'# 按DB函数名分组统计每条查询执行的次数# info_0809_14_137.log是从137机器日志中切割出的14:00~15:00期间的日志文件cat info_0809_14_137.log |grep -E 'Total: [0-9]{4}'|awk'{print $7}'|sort|uniq -c |sort -nr 
# 按DB函数名分组求和每个查询场景的扫描行数之和cat info_0809_14_137.log |grep -E 'Total: [0-9]{4}'|awk'{s[$7] += $11}END{for(i in s){ print i,s[i]}}'