记一次线上机器CPU飙高的排查过程

        公司如今把小贷机器都整理回收了，访问量不大，基本都是用户来查看账户进行还款操作。

        现在情况是，我们把很多服务都放在了一台服务器上，那天线上环境改了auth的salt，本地这边是写死的，自动上线已经关闭了通道，没辙，手动替包手动上线，结果没多久运维就喊了，表示cpu飙高到300%。

        难得的机会，先用top找出cpu占用最多进程

如果想细看进程信息可以使用ll proc

其实运行完这里的时候，我比较吃惊的是，真正占CPU的并不是部署的几个服务，而是resin容器本身，飚到了99%，从这个角度来讲，其实大部分性能问题都是垃圾回收的锅。

然后利用ps查看到的进程pid找cpu最高线程

然后拿着线程tid在jstack找，结果在里面找不到，然后上网查JAVA线程无法在jstack里找到的原因

以上大概意思是没找到线程的跟踪栈有三种情况，就是线程启动前的预启动，以及线程退出后的cleanup，第三种就是，利用JVM TI agent运行的线程，这个线程是用来跑本地code的。

******这里面都提到了JVM TI技术，这个技术主要是用来提供虚拟机调用本地方法的接口，可以获取jvm运行情况和提供本地方法的后门一样的接口工具，一些调试和诊断工具都是基于JVM TI来实现的，很多JVM都有自己的TI实现。

当然，这个Stack Over Flow的答案针对的Java线程，我所知道的是，如果导致我们CPU飙高的并不是java线程，那么jstack -F就打不出来。

而这个jstack -m模式，在官方文档里是说，可以打印出所有Java线程和native frames的所有线程。其实到这里是不是隐隐感觉到什么了~~没错，最后真的是垃圾回收的锅。

然后jdk8利用jstack -m找到了，发现里面使用的方法是CMS垃圾回收器的方法

讲真，平时只负责上下线，JVM配置只要不出问题很少留意，这个年代了，还在使用CMS吗？嗯，jmap看了下，是CMS。而占用大多CPU也是CMS的特性之一：最小化GC中断，付出的代价便是高CPU负荷。

既然定位到了垃圾回收，那就接着排查垃圾回收吧，pid是18637

就去jstat -gc 18637 5000

jstat -gcold 18637

jstat -gcoldcapacity 18637

发现full gc非常频繁（每五秒输出，发现触发fullGC13次）

（复盘这次的排查问题，发现图片保存少之又少。。）

如此频繁，顺带gccause一下看看最近一次回收的原因

结果长这样

从这个结果来看最近一次是Metadata的GC，而触发原因是因为达到了阈值。再细看当前元空间使用率已经接近98%。

到这里不能等了，找运维拿来了jvm参数，有三个参数很亮眼

老年代的配置属于默认配置，占整个堆内存的2/3，CMS回收要达到80%才会触发，我们还没有达到这个值。

那么根据图1中的显示，metaspace我们已经达到了阈值。

这种情况产生也没毛病，想想一台机器部署了5个web服务和5个微服务的场景吧，虽然没什么人访问，但加载的class信息也足够多了。

主要就是metadata的配置，而有关metadata的配置并没有oracle的官方指导，官方指导上的意思是说metaspace的配置，主要是避免首次启动时对加载的类信息做回收，取决于应用本身，够用就行了，不要太频繁触发full gc就好

其实调大这metaspace的配置能够大概解决问题，但是最终我选择了切换为G1垃圾回收。

官方文档是这样写的

        首先戳我的点的主要原因是g1最终的目的是要取代cms垃圾回收器，它的回收范围是整个堆，紧跟潮流总不会错的。其次g1取代cms的情况官方也建议了以下几点：

1. 一个是要管理的堆内存大于6g

2. 一个是服务已使用的堆内存超过了50%

3. 一个是对象分配率过高或对象从新生代晋升到老年代速率过快（这里我查了一下资料，意思是对象分配率过高的话其实会导致Minor GC频繁，而这种情况会使对象更快地晋升到老年代，而老年代如果过快地被填充，又会触发FullGC。从设计角度来讲，之所以分代回收，是为了应对对象存活时间而使用不同的回收策略，老年代可不是为了频繁回收而产生的）

4. 垃圾回收导致服务中断时长超过0.5-1s。

这种时候官方就建议把cms换成g1了。

        最终cpu骤降，从99%降至一般运行状态下的2%左右。好了。就这样吧，虽然不希望线上出现这种问题，但一旦出问题了，搞一遍还蛮带感的。期待下一次的摸排：DDDDD

后记：

        最近在复盘这次垃圾回收，因为这次jvm排查的经历让我对垃圾回收机制和分代回收这一块加深了印象。复盘的时候发现自己思考地还欠缺深入。这次的问题有两个地方值得深思，一个是为什么metaspace会超？如果正常进行GC，为何会超出阈值？其次是没有调大metaspace的前提下，换成G1为什么就没有再频繁FullGC过？

        为什么metaspace会超，我经过比对当时留下CMS的jstat数据和G1当前的数据，发现新生代CMS划分区域非常大，是现在G1的十倍。G1是不建议设定新老年代比例的，这样它就可以动态调整新老年代比例，达到最优实践。首先说明metaspace是存储类描述信息的，当堆上分配了对象，就会关联到metaspace里面的类信息，如果堆上的对象不回收，那么metaspace里面的类信息也不会回收。

        在配置cms时，我们会设置新生代老年代比例，新生代空间是固定的，如果新生代的空间比较大，回收间隔时间长，那就会导致metaspace里的class信息无法被释放，最终导致未进行youngGC而率先因为metaspace超了跑了FullGC。但G1的新生代空间是根据使用情况动态分配的，它的算法会去回收最有回收价值的region。

        就这次修改参数而言，使用G1比CMS时间短很多，就已经执行了717次youngGC，而CMS用了那么久，才52次，侧面也能佐证这个猜测的正确性，解释了为何在相同metaspace的配置下，G1没有产生频繁FullGC的原因：新生代对象回收加快，metaspace空间得到了尽快释放，没有达到阈值，于是不会触发FullGC。

参考文献：

* https://www.oracle.com/java/technologies/javase/hotspot-garbage-collection.html

* https://www.oracle.com/java/technologies/javase/gc-tuning-6.html

* https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/sizing.html

* https://plumbr.io/blog/garbage-collection/what-is-allocation-rate

* https://plumbr.io/blog/garbage-collection/what-is-promotion-rate

一、引子

对于互联网公司，线上CPU飙升的问题很常见（例如某个活动开始，流量突然飙升时），按照本文的步骤排查，基本1分钟即可搞定！特此整理排查方法一篇，供大家参考讨论提高。

二、问题复现

线上系统突然运行缓慢，CPU飙升，甚至到100%，以及Full GC次数过多，接着就是各种报警：例如接口超时报警等。此时急需快速线上排查问题。

三、问题排查

不管什么问题，既然是CPU飙升，肯定是查一下耗CPU的线程，然后看看GC。

3.1 核心排查步骤

1.执行“top”命令：查看所有进程占系统CPU的排序。极大可能排第一个的就是咱们的java进程（COMMAND列）。PID那一列就是进程号。

2.执行“top -Hp 进程号”命令：查看java进程下的所有线程占CPU的情况。

3.执行“printf "%x\n 10"命令 ：后续查看线程堆栈信息展示的都是十六进制，为了找到咱们的线程堆栈信息，咱们需要把线程号转成16进制。例如,printf "%x\n 10-》打印：a，那么在jstack中线程号就是0xa.

4.执行 “jstack 进程号 | grep 线程ID” 查找某进程下-》线程ID（jstack堆栈信息中的nid）=0xa的线程堆栈信息。如果“"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable”，第一个双引号圈起来的就是线程名，如果是“VM Thread”这就是虚拟机GC回收线程了

5.执行“jstat -gcutil 进程号 统计间隔毫秒 统计次数（缺省代表一致统计）”，查看某进程GC持续变化情况，如果发现返回中FGC很大且一直增大-》确认Full GC! 也可以使用“jmap -heap 进程ID”查看一下进程的堆内从是不是要溢出了，特别是老年代内从使用情况一般是达到阈值(具体看垃圾回收器和启动时配置的阈值)就会进程Full GC。

6.执行“jmap -dump:format=b,file=filename 进程ID”，导出某进程下内存heap输出到文件中。可以通过eclipse的mat工具查看内存中有哪些对象比较多。

3.2 原因分析

1.内存消耗过大，导致Full GC次数过多

执行步骤1-5：

多个线程的CPU都超过了100%，通过jstack命令可以看到这些线程主要是垃圾回收线程-》上一节步骤2

通过jstat命令监控GC情况，可以看到Full GC次数非常多，并且次数在不断增加。--》上一节步骤5

确定是Full GC,接下来找到具体原因：

生成大量的对象，导致内存溢出-》执行步骤6，查看具体内存对象占用情况。

内存占用不高，但是Full GC次数还是比较多，此时可能是代码中手动调用 System.gc()导致GC次数过多，这可以通过添加 -XX:+DisableExplicitGC来禁用JVM对显示GC的响应。

2.代码中有大量消耗CPU的操作，导致CPU过高，系统运行缓慢；

执行步骤1-4：在步骤4jstack，可直接定位到代码行。例如某些复杂算法，甚至算法BUG，无限循环递归等等。

3.由于锁使用不当，导致死锁。

执行步骤1-4：如果有死锁，会直接提示。关键字：deadlock.步骤四，会打印出业务死锁的位置。

造成死锁的原因：最典型的就是2个线程互相等待对方持有的锁。

4.随机出现大量线程访问接口缓慢。

代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的；平时消耗的CPU不多，而且占用的内存也不高。

思路：

首先找到该接口，通过压测工具不断加大访问力度，大量线程将阻塞于该阻塞点。

第一步：定位出来使用资源CPU最多的进程，不管是Windows还是linux或者Mac，这个都可以通过任务管理器很快的定位出来。

第二步：定位为什么这个进程耗费CPU资源多。通常的原因有：程序本身本身就是CPU密集型的任务，而且程序正处于工作状态；某些后台软件也有可能执行一些CPU密集型的任务，比如杀毒软件等。

第三步：解决问题。可以通过如下一些方式解决：更换硬件配置，换上更高配的硬件；软件更换，使用一些占用CPU资源更少的软件。

---