JVM 排查问题实战

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

通过使用 JVM 自带的工具 jstack，jmap，jstat 排查java程序占用内存或cpu负载过高的问题。

理论部分

jstack - Prints Java thread stack traces for a Java process, core file, or remote debug server.

打印线程堆栈信息

命令行使用：

jstack <pid> 获取到 jvm 进程的所有堆栈信息

 

jmap - Prints shared object memory maps or heap memory details for a process, core file, or remote debug server.

打印内存中的对象以及堆内存信息

命令行使用：

jmap -heap <pid> 获取 jvm 进程的堆内存配置以及使用情况

jmap -histo <pid> 获取 jvm 进程的在内存中创建的对象数量

jmap -dump:format=b,file=heap.bin <pid> 导出内存文件，这个文件可以通过导入eclipse的MemoryAnalyzer来分析

 

jstat - Monitors Java Virtual Machine (JVM) statistics.

监控 jvm 获取一些统计信息，classloader，compiler，gc相关

命令行使用：

jstat [option] <pid>

参数列表(上面那个 option)：

-class：统计class loader行为信息 
-compile：统计编译行为信息 
-gc：统计jdk gc时heap信息 
-gccapacity：统计不同的generations（不知道怎么翻译好，包括新生区，老年区，permanent区）相应的heap容量情况 
-gccause：统计gc的情况，（同-gcutil）和引起gc的事件 
-gcnew：统计gc时，新生代的情况 
-gcnewcapacity：统计gc时，新生代heap容量 
-gcold：统计gc时，老年区的情况 
-gcoldcapacity：统计gc时，老年区heap容量 
-gcpermcapacity：统计gc时，permanent区heap容量 
-gcutil：统计gc时，heap情况

输出内容：

S0  — Heap上的 Survivor space 0 区已使用空间的百分比 
S0C：S0当前容量的大小 
S0U：S0已经使用的大小 
S1  — Heap上的 Survivor space 1 区已使用空间的百分比 
S1C：S1当前容量的大小 
S1U：S1已经使用的大小 
E   — Heap上的 Eden space 区已使用空间的百分比 
EC：Eden space当前容量的大小 
EU：Eden space已经使用的大小 
O   — Heap上的 Old space 区已使用空间的百分比 
OC：Old space当前容量的大小 
OU：Old space已经使用的大小 
P   — Perm space 区已使用空间的百分比 
OC：Perm space当前容量的大小 
OU：Perm space已经使用的大小 
YGC — 从应用程序启动到采样时发生 Young GC 的次数 
YGCT– 从应用程序启动到采样时 Young GC 所用的时间(单位秒) 
FGC — 从应用程序启动到采样时发生 Full GC 的次数 
FGCT– 从应用程序启动到采样时 Full GC 所用的时间(单位秒) 
GCT — 从应用程序启动到采样时用于垃圾回收的总时间(单位秒)，它的值等于YGC+FGC 

 

实战部分

线上环境存在一台服务器（centos 7）cpu使用率一直处于报警状态。

在使用上面3个命令的时候如果出现

Error attaching to process: sun.jvm.hotspot.runtime.VMVersionMismatchException: Supported vertion are 25.65-b01. Target VM is 25.121-b13

说明工具的版本和启动程序的jvm版本不一致，去oracle官网下载对应版本的jdk工具 传送门，我使用的是jdk1.8 红色部分是需要下载的小的版本 号 即jdk1.8_121

 

使用 top 命令查看cpu使用率

发现一个 pid 为 30996 的cpu使用率特别高，再次使用 top -Hp 30996 命令查看这个进程的线程使用情况

31036 这个就是有问题的线程，使用 printf "%x\n" 31036 转换成16进制（下面有用）

接着就可以使用 jstack 命令查看这个线程的堆栈情况 jstack 30996 | grep -A 10 793c (30996是刚才查到有问题的进程 793c为16进制线程号 grep -A 10 为查到793c那一行之后向下再打印10行)

这个 nid=0x793c 的 Thread-14 线程就是问题线程，多次执行命令查看之后发现代码一直运行在 MasterEngine.java 48行。然后就可以去查看代码了。

看上去在迭代一个map，循环删除。

再看下其他地方

执行 jmap -histo 30996 | head -n 20 看下内存中创建类top20的情况

连续调用4次发现 java.util.concurrent.ConcurrentHashMap$EntryIterator 实例数量在不断增大然后突然又变小了。猜测是实例被 gc 快速回收掉了。

那么再用 jstat -gcutil 30996 2000 20 看下 gc 执行情况 （2000 200 是指每隔2秒执行一次 一共执行20次）

看YGC这一列（从右边往左第五列），young gc 执行了 2千8百万多次。

再用 gccapacity 参数看一下堆的情况

只有Eden space （第6列）的大小在发生变化

再看下 jvm 堆的配置情况 jmap -heap 30996

配置了最大堆大小（MaxHeapSize）是 4g，Eden Space 45%， From Space 18%，To Space 0%，Old Generation 73%

再看下服务器负载情况，命令就是一个 w

最后三个数字表示服务器最近 1分钟 5分钟 15分钟 的平均负载，超过cpu核数*1（4核就是4 8核就是8）表示服务器负载非常大。现在这个数字看上去服务器负载比较小还是能够应对。

总结

结合以上各种迹象，基本可以断定问题就出在对map进行迭代删除的代码，频繁创建 ConcurrentHashMap$EntryIterator 实例，频繁触发 young gc，是导致 cpu 占用过高的原因。堆大小的占用情况还可以，负载还能接受，内存硬盘都正常（忘记截图了），full gc 次数没有特别多。更加具体的原因还需要了解代码作者的用意。

所以，只要会使用 jmap jstack jstat 这3个工具，还有一些linux的基本命令（检查磁盘 网络 等等），就可以从容应对因为 代码写得太烂 造成程序异常的情况。

 

转载于:https://my.oschina.net/u/232911/blog/2245724