记一次线上系统JVM频繁Gc排查总结

记一次线上系统JVM频繁Gc排查总结

1. 问题描述
2.  

在一个伸手不见五指的夜晚,突然发现系统CPU占用率飙升,业务jvm cpu最高占用超过300%,而且频率大概在1分钟之内,第一反应系统jvm出现问题了,于是有了下面的分析及解决过程;

1. 分析过程及解决
2.  

• CPU飙升分析过程
•  

命令:top

首先执行top命令查询占用较高的jvm进程,确认pid:125277

接着需要查询具体是jvm的哪些子进程导致的问题(也就是排查是不是存在代码如死循环的问题)

 

命令: top -Hp pid

说明:当时排查问题没有截图,下图是处理后的截图

 

通过查看,PID为125284所在子线程占用cpu300%,找的了问题进程,我要分析下这个子进程是做什么的？

 命令:  printf "%x" pid   //将10进制的pid转化为16进制,因为jstack出来的线程是16进制

 

转换后的16进制为1e964,用转换后的16进制子进程可以检索该线程对应的占用程序

命令: jstack pid grep 1e964 //注意:这里pid是线程的pid,不是子进程

 

上图可以分析,该进程是gc的的过程,到这里可以确定,是gc导致的cpu飙升,也就是发生了频繁的GC,GC我们都知道频繁的FULL GC意味着什么。但是为什么会发生频繁的full gc，下面进行分析:

• 频繁full gc分析过程
•  

命令:jstat -gcutil pid interval  // interval  打印时间间隔 单位:s

jstat -gcutil 125277 3000  输出如下

 

上图我们可以看到的问题

• 1.minor gc发生的很频繁，考虑jvm堆栈配置不合理,可能年轻代空间不足
• 2.当发生full gc时,old区内存基本不被回收,考虑存在内存泄露

带着上面两个问题,首先我们排查第二个

命令: jmap -histo:live pid | more  // live:查看当前存活对象，需要注意:执行此命令会发生异常full gc

jmap -histo:live 125277  | more

 

上图也是解决后的截图，当时是存在某个hashmap和某个grpc的类实例数非常多,而且占用很多内存空间。

关键解决过程:搜索了全局的hashmap和grpc实例,最后国志大佬定位到grpc有个channel关闭没有放在finally中,并且正常return了，导致内存泄露，最后修改了代码,这里提醒小伙伴们代码一定要相互review。

说完问题2，回头说说问题1堆栈配置不合理。

命令:ps -ef | grep pid

 

命令:jmap -heap pid

 

发现jvm只是配置了-Xmx(堆内存最大允许大小),这样配置因为是动态分配新生代/老年代空间的,因此高并发环境存在问题可能性很大,建议根据情况手动配置,常用调整参数如下:

-Xms4096m：堆内存初始大小

-Xmx4096m:  堆内存最大允许大小

-Xns1024m:年轻代内存初始大小 -XX:NewSize（-Xns）

-Xmn1024m :年轻代内存最大允许大小 -XX:MaxNewSize（-Xmn）

-XX:SurvivorRatio=8 年轻代中Eden区与Survivor区的容量比例值，默认为8，即8:1:1

-XX:NewRatio=4: 设置年轻代（包括Eden和两个Survivor区）与年老代的比值（除去持久代）。设置为4，则年轻代与年老代所占比值为1：4，年轻代占整个堆栈的1/5

注意:-Xms和-Xmx如过内存足够可以配置相同值,避免gc后的JVM重新分配内存

1. 常用命令
2.  

• top //查看cpu进程占用情况
• top -Hp pid //查看某个 pid子进程占用情况
• printf "%x" pid //pid16进制转换
• jstack pid grep 16进制的线程号 //查看该子进程占用的进程代码块
• jstat -gcutil pid interval //按interval定时打印gc情况
• jmap -histo:live pid | more //查看当前pid各个对象实例占用大小,降序排列
• jmap -heap pid // 查看当前堆栈内存分配情况
• 欢迎补充

 

1. 总结
2.  

• jvm要根据系统情况进行配置,尽量不用默认配置；
• 代码上线前要相互review,减少线上bug；
• 系统资源一定要接入监控告警,能即使受到异常信息；