线上问题分析

排查线上java程序高CPU占比代码

线上问题分析

Posted by John Doe on 2022-07-14
Words 1.3k and Reading Time 5 Minutes
Viewed Times

java程序CPU占比过高分析

一、Arthas分析高CPU占比代码

Arthas官方文档地址:https://arthas.aliyun.com/doc/quick-start.html

1.1 启动Arthas

在命令行下面执行（使用和目标进程一致的用户启动，否则可能attach失败）：

1
2
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar

执行该程序的用户需要和目标进程具有相同的权限。比如以admin用户来执行：sudo su admin && java -jar arthas-boot.jar 或 sudo -u admin -EH java -jar arthas-boot.jar。
如果attach不上目标进程，可以查看~/logs/arthas/ 目录下的日志。
如果下载速度比较慢，可以使用aliyun的镜像：java -jar arthas-boot.jar --repo-mirror aliyun --use-http java -jar arthas-boot.jar -h 打印更多参数信息。

1.2 模拟CPU飙升代码

1
2
3
4
5
6
7
fun cpuHigh() {
    Thread {
        while (true) {
            println("cpu飙升中～")
        }
    }.start()
}

1.3 运行项目运行Arthas,找到自己当前项目对应的PID进行监听

1.3 输入dashboard仪表盘显示当前进程相关信息

1.4 使用 thread 命令，排查当前项目中的各个运行中方法的CPU占用率情况

可见图中，ID=11的线程CPU占用率很高，达到66.09%

1.5 使用 thread -[id] 命令，继续查看这个线程具体是哪个方法所导致的CPU占用率过高

由图可见，id=11的任务处于RUNNABLE状态，且CPU占用率高的主要原因是因为一直进行FileOutputStream操作，也就是输出流操作，并且定位代码在 TestMain.kt 中的第28行执行了这个高CPU占用率的方法，而导致的，再来看下代码

二、jstack获取线程快照分析CPU占比代码

  1. 查找高占比进程pid,使用ps -ef|grep java 、 jps查找对应java进程pid

或使用top`top -p <pid> 查看Java进程的cpu占用：

该Java进程占用cpu达到92.2%。

  1. 使用 top -Hp 命令（为Java进程的id号）查看该Java进程内所有线程的资源占用情况（按shft+p按照cpu占用进行排序，按shift+m按照内存占用进行排序）此处按照cpu排序

可以看到，有两个线程号为97243，97912的线程占用cpu分别达到了69.2%和22.0%

  1. 使用 printf “%x “ 命令（tid指线程的id号）将以上10进制的线程号转换为16进制：

转换后的结果分别为17bdb，17e78，由于16进制以0x开头，所以对应的16进制的线程号为0x17bdb和0x17e78。

  1. 使用jdk自带命令jstack获取此时的线程快照并输入到文件中： jstack -l > ./jstack_result.txt 命令（为Java进程的id号）来获取线程快照结果并输入到指定文件。

  2. 查看第4步生成的txt文件，在其中搜索tid为0x17bdb的线程：

可以看到线程号为0x17bdb（10进制线程号97243）对应的是一个”VM Thread”即虚拟机线程，这个不是与我们代码相关的线程，所以暂时忽略。

　　再看0x17e78线程：

该线程的堆栈较深，且很明显有调用我们自己代码的逻辑，并且提示了具体的代码行数，我们查看该处代码：

发现此处是在一个死循环里边重复的拼接字符串导致的，我们知道，String类使用contact方法拼接字符串其实是创建新的对象并返回，看到这里，似乎可以和占用cpu最高的”VM Thread”联系起来了，因此作出假设：由于代码一直循环创建对象，导致不断有不再被引用的对象产生，虚拟机检测到对象不再被引用之后，就进行垃圾回收，垃圾回收占用了很大一部分cpu资源。

　　为了证明该假设，设置jvisualvm监控，经过一段时间允许，cpu资源监控结果如下：

可以看到cpu总占用达到88.5%，而垃圾回收活动占用cpu达到84.0%，因此证明了上述假设。

　　知道了该问题的原因后，我们还想知道此时垃圾回收的频率，耗时等信息，于是可以设置JVM参数 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc.log （或者使用jinfo命令动态设置GC日志，可以看到日志内容：

　　

gc.log中频繁的打印垃圾回收，不过我们看到的基本都是Minor GC，即新生代的垃圾回收。

　　为了更清晰的查看各个区的垃圾回收情况，可以使用jstat命令 jstat -gc （pid为Java进程的id，period指每次监控之间的时间间隔，count指监控次数）来监控垃圾回收，打印内容如下：

　　

可以看到，虚拟机在进行频繁的Full GC，每次耗时均在增长。

　　总结：

　　分析Java进程占用cpu过高问题时候，基本都可以按照如下步骤进行分析：

　　（1）使用 top -Hp 命令找出进程中占用cpu最高的前几个线程

　　（2）使用jstack获取线程快照，然后使用线程id搜索分析快照文件

　　（3）如果线程调用了业务相关代码，则分析是否是代码问题导致的cpu占用过高，如果线程是VM Thread，则应该监控检查垃圾回收活动频率，看是否是因为频繁进行垃圾回收导致的。

This is copyright.

...

...

00:00
00:00
FEATURED TAGS
线上问题分析
FRIENDS