一次cpu大于100%的排查记录

1,670 阅读5分钟

1、现象

近日,在uat环境做某个操作时(大概是筛选出符合条件的用户,然后给其发送通知消息),uat的服务器cpu使用率居然大于100% 甚至达到了200% 左右,着实让我一惊,同时也让我兴奋,因为可以亲自来排查一次这面试高频的问题了。

2、排查过程

2.1 、使用top命令观察服务器

2.1.1、top命令介绍使用方法

top介绍

top命令是Linux下常用的性能分析工具,能够实时显示系统中各个进程的资源占用状况,类似于Windows的任务管理器。
top显示系统当前的进程和其他状况,是一个动态显示过程,即可以通过用户按键来不断刷新当前状态.如果在前台执行该命令,
它将独占前台,直到用户终止该程序为止. 比较准确的说,top命令提供了实时的对系统处理器的状态监视.它将显示系统中CPU
最“敏感”的任务列表.该命令可以按CPU使用.内存使用和执行时间对任务进行排序;而且该命令的很多特性都可以通过交互式命令
或者在个人定制文件中进行设定.

使用格式:

top [-] [d] [p] [q] [c] [C] [S] [s] [n]

参数说明:

d:指定每两次屏幕信息刷新之间的时间间隔。

p:通过指定监控进程ID来仅仅监控某个进程的状态。

q:该选项将使top没有任何延迟的进行刷新。如果调用程序有超级用户权限,那么top将以尽可能高的优先级运行。

S:指定累计模式。

s:使top命令在安全模式中运行。这将去除交互命令所带来的潜在危险。

i:使top不显示任何闲置或者僵死进程。

c:显示整个命令行而不只是显示命令名。

常用示例

top   //每隔5秒(默认就是5秒)显式所有进程的资源占用情况
top -d 2  //每隔2秒显式所有进程的资源占用情况
top -c  //每隔5秒显式进程的资源占用情况,并显示进程的命令行参数(默认只有进程名)
top -p 1234 -p 5678//每隔5秒显示pid是1234和pid是5678的两个进程的资源占用情况
top -d 2 -c -p 1234 //每隔2秒显示pid是1234的进程的资源使用情况,并显式该进程启动的命令行参数

2.1.1、top命令观察有问题的进程

top 命令执行结果如下图所示

image.png

可以看到进程29567的 cpu使用率是101.3%(并且居高不下) 这还属于少的,有时候会是200%多

2.2、 找到进程id后,找出该进程中的占用cpu资源的线程 (同样也是使用top命令)

找到进程id后,查看该进程中哪个线程占用的cpu高 对应命令 top H -p <占用cpu高的pid>

执行 top H -p 29567

结果: 显示PID为29574那个线程占用很高,如下图所示:

image.png

注意: 此时PID 29574 是10进制  我们需要将其转换为16进制 (因为待会jstack命令要用到)

在服务器 执行 printf "%x\n" 29574将输出29574的十16进制 即 7386

2.3、 使用jstack命令查看堆栈信息

关于jstack的各种详细命令这里不做过多介绍

jstack [option] // 打印某个进程的堆栈信息

接下来 执行 jstack 29567 |grep 7386 -A 30 (这里我们过滤一下 是7386的才展示)

image.png

从上图可以看出 nid=0x7386 (注意 nid是操作系统级别的线程id 其中0x是其固定开头)的线程是一个VM Thread 我猜测和GC有关系,再网上搜索了下确实是这么回事。于是我看了下GC情况如下

执行 sudo jstat -gcutil 29567 3000 1000

image.png

可以看出各个分区使用率非常的高

2.4、使用jmap工具dump堆转储快照文件

执行 jmap -dump:live,format=b,file=指定文件名称.log 29567

文件内容我是看不懂 如下

image.png

于是我使用了mat工具

MAT(Eclipse Memory Analyzer)是一种快速且功能丰富的Java堆分析器,它帮助查找内存泄漏。使用内存分析
器分析具有数亿个对象的高效堆转储,快速计算对象的保留大小,查看谁在阻止垃圾收集器收集对象,运行报告以自动提取泄漏嫌疑。
官网地址https://www.eclipse.org/mat,下载地址为https://www.eclipse.org/mat/downloads.php。我们可以在下载
页面看到:MAT可以独立运行,也可以通过插件的形式在Eclipse中安装使用,具体的安装过程就不再这里介绍了,我是下载的独立运行
的程序包。

下载安装后我导入了堆转储文件并执行分析,结果如下

image.png

image.png

image.png

image.png

最后通过观察分析结果可以看出有内存泄露嫌疑对象,根据报告,我大概知道哪里出问题了,修改log打印(主要本质原因是在toJson时候,内部进行大量的数组copy导致),以及去掉极光的调用(主要是连接和对象创建问题)后再观察,cpu飙升现象没有再出现过。

3、此次经验总结

  • 这是我第一次排查cpu问题,也是不断摸索,另外 什么jstack jmap 这种工具之前也没用过,只是看一些资料时候看到过(比如马士兵大佬的jvm调优资料),这次能够亲自排查,我感到很愉快,有时间会继续写下jstack和jmap的相关内容,尤其是jstack 他可以很好的看出GC情况,可以有效判断根因。

  • 当你感觉到困难时,说明你在成长; ~~~ 我是蝎子莱莱,一个咸鱼coder。