在平时开发过程中,经常会碰到Java进程占用cpu过高的现象,本篇将简单记录一下自己分析该类问题的步骤。
1.使用 top -p <pid> 命令(<pid>为Java进程的id号)查看Java进程的cpu占用:
该Java进程占用cpu达到92.2%。
2.使用 top -Hp <pid> 命令(<pid>为Java进程的id号)查看该Java进程内所有线程的资源占用情况(按shft+p按照cpu占用进行排序,按shift+m按照内存占用进行排序)此处按照cpu排序:
可以看到,有两个线程号为97243,97912的线程占用cpu分别达到了69.2%和22.0%
3.使用 printf "%x " <tid> 命令(tid指线程的id号)将以上10进制的线程号转换为16进制:
转换后的结果分别为17bdb,17e78,由于16进制以0x开头,所以对应的16进制的线程号为0x17bdb和0x17e78。
4.使用dk自带命令jstack获取此时的线程快照并输入到文件中: jstack -l <pid> > ./jstack_result.txt 命令(<pid>为Java进程的id号)来获取线程快照结果并输入到指定文件。
5.查看第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日志,可参考http://www.importnew.com/15722.html),可以看到日志内容:
gc.log中频繁的打印垃圾回收,不过我们看到的基本都是Minor GC,即新生代的垃圾回收。
为了更清晰的查看各个区的垃圾回收情况,可以使用jstat命令 jstat -gc <pid> <period> <count> (pid为Java进程的id,period指每次监控之间的时间间隔,count指监控次数)来监控垃圾回收,打印内容如下:
可以看到,虚拟机在进行频繁的Full GC,每次耗时均在增长。
总结:
分析Java进程占用cpu过高问题时候,基本都可以按照如下步骤进行分析:
(1)使用 top -Hp <pid> 命令找出进程中占用cpu最高的前几个线程
(2)使用jstack获取线程快照,然后使用线程id搜索分析快照文件
(3)如果线程调用了业务相关代码,则分析是否是代码问题导致的cpu占用过高,如果线程是VM Thread,则应该监控检查垃圾回收活动频率,看是否是因为频繁进行垃圾回收导致的。