cpu使用率飙高排查过程

2019独角兽企业重金招聘Python工程师标准>>>

一、背景
     最近两周伙拼其中的一台task机器每隔几天总是报警cpu利用率飙高的问题，因为一直在忙项目。所以前几次都是通过重启任务临时解决。这种情况出现两次之后，今天终于抽出时间来排查这个问题，在此分享一下，这个cpu使用率飙高的问题的排查过程，方便大家以后遇到同样的问题可以有参考。


二、排查思路和过程
1.通过top命令查看占用cpu比较高的进程id。
       如下图所示，能够看到进程为164065这个进程cpu占比很高，629.4%，只要能眼睛没毛病的都能看出来，明显164065这个进程有猫腻。




2.既然164065这个进程有猫腻，那我们就看看这个有猫腻的进程是个什么鬼。
      通过pe  -ef | grep164065 ,可以看到，这是伙拼的一个活动扫描任务。任务的执行内容就不说了。




3.既然164065这个jvm进程有问题，那么我们就需要定位到这个进程里面具体是什么线程有猫腻。
      通过top -Hp 164065,可以看到原来是164069，164070，164071，164072这四个线程的cpu占比达这么高。




4.我们再继续深入，探探这四个线程究竟是干嘛的
     那么怎么看164069，164070，164071，164072这四个线程是干嘛的呢？别急，我们先转成16进制。转换之后分别是280e5，280e6，280e7，280e8



5.转成16进制以后，再通过jstack 164065可以看到具体的线程信息。
如下图所示，哈哈，终于逮到你了，原来是GC的4个线程在搞鬼。


6.为什么GC的这四个线程的cpu使用占比一直这么高？
     既然是进行GC的线程，我们当然要来看一下堆内存的状况了。通过jmap -heap 164065  我们来简单看一下堆内存吧。WTF,新生代的空间已经用了100%，老年代的空间的使用也达到了99.87%。看到这里，估计大家都明白了。为啥GC线程会不停的占用cpu。原来是堆内存的新生代和老年代的空间不够了，需要进行fullGC和minorGC，但是每次fullGC和monorGC只能释放一点点空间，然后很快又达到了需要GC的程度。再进行GC，如此循环导致GC的线程疯狂调用。必须要强调的是，这里正好达到了即将发生OOM，但是还没有发生OOM，立马进行GC这么一个平衡。所以GC线程才能如此嚣张的占用CPU.




7. 通过jstat -GC pid，我们来查看一下GC的频率。
     咦，图呢？不好意思，当时太激动了忘了截图了，总之minorGC和fullGC执行频率之高令人咋舌。

8.我们继续来分析，为什么堆内存会这么不够用呢。
     立马想到的就是分析dump。好，我们通过jmap -dump:format=b,file=taskDump.bin 生产dump文件，然后通过zprofiler对堆内存进行分析（不要问我为什么要手动打印dump，因为这台机器上有N个jvm进程，zprofile貌似不能指定进程）。可以看到这个dump文件里面有三个对象非常大，加在一起基本上有300M。而我们这个进程的jvm 堆内存配置的最大才512M。这三个大对象都是forest包里面的，再联想到两周前才做过viewcache到forest的迁移，这两周开始出现的cpu利用率飙高的谜题终于真相大白了。





二、解决办法
      解决办法很简单，加大JVM的堆内存配置大小。同时通知一下forest那边的团队，你们的常驻堆内存的对象太大了，要不要进行优化一下。


三、总结
       因为两周之前接入了forest，结果forest的三个大对象有300M之大，而我们的JVM配置的最大可使用内存才512M.导致JVM堆内存中的新生代和老年代的使用内存达到了一个很巧妙的平衡（即将OOM，但是经过GC还能挽回），在这个平衡下，jvm的GC线程会去疯狂的进行minorGC和fullGC，从而导致CPU利用率飙高。通过仔细分析，把两个看似不相干的问题却联系到了一起。这个思路针对于一些JVM应用cpu占用飙高的问题的解决应该有所帮助，所以花了点时间记录下并分享出来。

转载于:https://my.oschina.net/u/2250599/blog/1505661