一次线上集群CPU占用100%的问题分析过程

765 阅读3分钟

这是我参与8月更文挑战的第16天,活动详情查看:8月更文挑战

一、前言

最近在搭建Ignite集群的过程中,突然发现线上机器运行一会儿之后CPU占用就会飙升到99%甚至100%。于是开始着手分析并解决了该问题。本文将详细讲解整个问题定位过程。

二、分析过程

1、发现问题

机器上线之后频繁收到CPU告警通知,于是通过监控系统查看集群服务器,发现所有机器CPU占用都解决100%。

随机选择一台机器登录到后台,通过Top命令发现CPU占用高的进程是一个Java进程,由此可知是咱们自己的Java程序导致了CPU占用极高。

2、问题定位

发现自己的程序导致了CPU占用高,根据经验我们有了基本的分析思路。首先打印出线程栈信息,然后找到CPU占用高的线程,再通过查看其线程栈信息,然后再根据代码具体分析其原因。

A、获取关键信息

首先我们需要获取到Java的线程栈信息。因此我们直接在后台通过jstack -l pid > log.log 就可以打印出线程栈信息。然后将线程栈信息(log.log)下载到本地。其内容如下:

然后我们需要找到该Java进程中哪些线程CPU占用高。因此我们通过在机器后台执行top -Hp pid命令,即可以看到当前进程中哪些线程占用CPU很高(下图中第一列的pid即为线程ID)。

B、问题定位

获取到线程栈信息和哪些线程占用CPU高之后,我们就可以开始我们的定位工作了。首先将任意一个占用CPU高的线程ID转换为16进制。比如上图中第一个线程708,其转换为16进制之后为2c4。

根据得到的16进制线程ID,在线程栈文件中直接搜索(即搜索0x2c4)得到如下线程信息:

通过通过类似方式查找上述其他线程,发现大部分占用CPU的线程都是执行的统一的代码:

于是我们猜测应该是这段代码执行异常导致了CPU占用高。于是我们进一步分析这段程序源码。通过源码分析大开能够看到该capTotalSize方法会定时执行,其会不断扫描日志文件是否超过配置限制。

进一步分析capTotalSize方法,发现调用了方法getFilesInPerios,大概的意思是扫描日志文件夹下的符合条件的日志文件。

进行分析发现,getFilesInPerios调用了FileFilterUtil.filesInFolderMatchingStemRegex方法。

查看FileFilterUtil.filesInFolderMatchingStemRegex实现发现,其cpu主要消耗在如下方法(file.listFiles)上。

于是我们大致分析,应该在扫描日志文件夹下的日志文件时在一直消耗CPU,接着我们尝试去打开日志文件夹,发现打不开。因此我们猜测应该是文件数太多,导致无法打开。这样就能够解释为什么日志扫描线程会hold在listFiles的位置(线程仍然在执行)。

那么为什么会有这么多的日志文件呢?我们首先想到去查看日志配置参数,查看之后发下日志文件做了如下配置。

咋眼一看上述配置文件貌似也没有什么问题啊。但是通过仔细查看我们会发现Max-size和total-size-cap都没有设置单位,如果不带单位则其默认单位是字节。这就导致日志被设置为每个文件50个字节(操作系统处理的时候是1K一个文件。)于是导致大量的日志文件生成。从而引起扫描线程由于日志文件数过多而导致扫描Hold住。

三、解决办法

分析清楚具体原因后,解决办法也就比较简单了。我们直接给Max-size和total-size-cap都设置上具体的单位即可。

修改完配置周,重新启动服务,然后查看CPU监控,此时所有CPU占用已经恢复正常。

通过一段时间的观察,发现CPU占用一直比较稳定,于是问题被解决。

四、总结

回过头来看,整个问题还是比较简单。就是因为日志文件配置错误(未配置具体单位),导致日志文件全部变成1K一个,生成大量日志文件。最终导致引起日志扫描线程在扫描日志文件的地方hold住,从而引起CPU占用100%。

五、惯例

如果你对本文有任何疑问或者高见,欢迎添加公众号共同交流探讨(添加公众号可以获得”Java高级架构“上10G的视频和图文资料哦)。