浅谈线上CPU100%排查思路

不念不忘少年蓝@ 2023-01-10 05:24 20阅读 0赞

# 问题介绍 #

最近公司的项目出现了一次惊险的崩溃，用户只要点击审批归档就会发生服务器cpu飙升，继而OOM的现象，最后解决了是因为历史错误数据未及时清理，导致时间值不满足现在的判断条件导致的问题，上一下源代码：

Date date = application.getStartTime();
            List<Date> dateList = Lists.newArrayList(date);
            while (!DateUtils.isSameDay(date, application.getEndTime())) { 
                date = DateUtils.addDays(date, 1);
                dateList.add(date);
            }

代码如上，表面上看来意思是从申请起始时间到申请结束时间的所有日期加入到 dateList 中，但是由于起始时间比结束时间大无限循环了。

# 问题还原 #

首先模拟一下当时的情况，编写一个controller如下:

@GetMapping(value = "/oom")
        public String index() throws ParseException { 
            SimpleDateFormat sdf = new SimpleDateFormat("yyyy-mm-dd");
            Date startTime = sdf.parse("2019-01-22");
            Date endTime = sdf.parse("2019-01-21");
            List<Date> dateList = new ArrayList<Date>();
            dateList.add(startTime);
            while(!isSameDay(startTime, endTime)){ 
                startTime = addDays(startTime, 1);
                dateList.add(startTime);
            }
            return "success";
        }

详细源码见我的github： https://github.com/yzuwangfeng/dealWithProblem  
首先我们将项目打包并运行：

java -Xmx2048m -Xms512m -XX:+HeapDumpOnOutOfMemoryError -jar dealWithProblem-0.0.1-SNAPSHOT.jar

之后访问 localhost:8080/oom  
此时会发现浏览器迟迟无法访问成功，等待没多久，我们就可以看到OOM异常了：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70]  
由于启动的时候，我加上了打印堆栈信息的参数，因而我们可以使用 JProfile 分析 OOM 时的内存信息：  
![在这里插入图片描述][2021012516053045.png]  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 1]  
通过这两张图片我们可以明显的分析出来是dateList的内容过多了！  
到这一步，貌似这个问题已经解决完了，但是实际处理线上问题时，远不止这么简单，示例代码中我只写了一个list， 一个循环，实际情况比这复杂许多，因而，我们需要更详细的信息进行分析。

# 整体排查思路 #

> 查消耗cpu最高的进程Pid  
> 根据Pid查出消耗cpu最高的线程号  
> 根据线程号查出对应的java线程，进行处理

## 查消耗Cpu最高的进程PID ##

执行命令  
执行top -c ，显示进程运行信息列表。按下P，进程按照Cpu使用率排序。  
通过分析得到进程号为25968的进程占用cpu非常大  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 2]

## 根据Pid查出消耗cpu最高的线程号 ##

找到进程号之后，我们需要分析其中的线程，即通过 top -Hp 25968，得到线程分析列表：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 3]

## 根据线程号查出对应的java线程，进行处理 ##

在列表中看到，25970，25971，25972，25973 这四个线程占用cpu最高，且非常相近，将这些线程号转换为16进制后分别为6572，6573，6574，6575

**通过jstack命令查看当前25968 进程中的所有线程**: jstack 25968，通过查找,可以发现这四个线程对应的是内存回收线程，如图：  
![在这里插入图片描述][20210125160839804.png]  
显然这不是我们需要分析的线程，回过头再看分析表，可以看到**25990相对占用cpu的时间也是比较多，转换为16进制为6586，这时可以在jstack中找到对应的线程信息：**  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 4]  
**打印堆栈信息**，我们可以看到：  
![在这里插入图片描述][20210125160945613.png]  
线程仍然执行在条件循环中，这一点已经显而易见了！

这篇博客写的也不错，推荐下  
[谈谈线上CPU100%排查套路][CPU100]

**参考文章**  
https://blog.csdn.net/wf3155/article/details/100546704  
https://blog.csdn.net/A\_\_\_B\_\_\_C/article/details/107769289  
https://blog.csdn.net/u011277123/article/details/101673372  
https://blog.csdn.net/schaffer\_w/article/details/111504299  
https://www.cnblogs.com/rjzheng/p/10315250.html

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70]: /images/20221119/be5b4b67b4a64f94bd87f16c1ec02aa5.png
[2021012516053045.png]: /images/20221119/e728013eb7334ba58e9f02ba3bc9c5ee.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 1]: /images/20221119/170ee7bb68374c9e92e02b024c28f7b3.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 2]: /images/20221119/3982869eaeaf4d95a1458adc57bfef2b.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 3]: /images/20221119/819d04ecd95c4d06af6f7487322a73bc.png
[20210125160839804.png]: /images/20221119/70280f7c0919458fae29f02099ce3f4b.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2ppa2UxMTIzMQ_size_16_color_FFFFFF_t_70 4]: /images/20221119/c9e2ad94ddaa4ce8a56e2eaffe8481fc.png
[20210125160945613.png]: /images/20221119/68b6e91d94994eafb45f375561e10b34.png
[CPU100]: https://www.cnblogs.com/rjzheng/p/10315250.html