前言
处理过线上问题的同学基本上都会遇到系统突然运行缓慢,CPU 100%,以及 Full GC 次数过多的问题。当然,这些问题的最终导致的直观现象就是系统运行缓慢,并且有大量的报警。给一个系统定位问题的时候,知识、经验是关键基础,数据是依据,工具是运用处理数据的手段。这里说的数据包括:运行日志、异常堆栈、GC 日志、线程快照(threaddump/javacore 文件)、堆转侟快照(heapdump/hprof 文件)等。经常使用适当的虚拟机监控和分析的工具可以加快我们分析数据、定位解决问题的速度。
对于线上系统突然产生的运行缓慢问题,如果该问题导致线上系统不可用,那么首先需要做的就是,导出 jstack 和内存信息,然后重启系统,尽快保证系统的可用性。本文主要针对 JDK 的命令行工具,主要包括用于监视虚拟机和故障处理的工具。根据 JDK 的命令行工具提供解决问题的排查思路,从而定位出问题的代码点,进而提供解决该问题的思路。
JDK 命令行工具
名称 | 主要作用 |
---|---|
jps | JVM Process Status Tool,显示指定系统内所有 HotSpot 虚拟机进程 |
jstat | JVM Statistics Monitoring Tool,用于收集 HotSpot 虚拟机各方面的运行数据 |
jinfo | Configuration Info For Java,显示虚拟机配置信息 |
jmap | Memory Map for Java,生成虚拟机的内存转储快照(heapdump 文件) |
jhat | JVM Heap Dump Browser,用于分析 heapdump 文件,它会建立一个 HTTP/HTML 服务器,让用于可以在游览器上查看分析结果 |
jstack | Stack Trace for Java,显示虚拟机的线程快照 |
这些命令行工具大多数是 jdk/lib/tools.jar 类库的一层薄包装而已,它们主要的功能代码是在 tools 类库中实现的。接来下介绍的 JDK 命令行工具大多都是基于 JDK 1.6,因此会存在个别参数在新版本 JDK 被淘汰的情况出现。所有的 JDK 工具都可以在 Oracle 官网的 Java Tools Reference 文档中找到使用说明,这是主要参考,包括命令格式、参数内容、输出信息等等。
jps:虚拟机进程状况工具
jps 可以列出正在运行的虚拟机进程,并显示虚拟机执行主类(Main Class,main() 函数所在的类)名称以及这些进程的本地虚拟机唯一 ID(Local Virtual Machine Identifier,LVMID)。
查看 jps 的帮助信息:
1 | [root@VM_24_98_centos jvm]# jps -help |
jps 命令格式:
1 | λ jps -lv |
选项 | 作用 |
---|---|
-q | 只输出 LVMID,省略主类的名称 |
-m | 输出虚拟机进程启动时传递给主类 main() 函数的参数 |
-l | 输出主类的全名,如果进程执行的是 Jar 包,输出 Jar 路径 |
-v | 输出虚拟机进程启动时 JVM 参数 |
jstat:虚拟机统计信息监视工具
jstat(JVM Statistics Monitoring Tool)是用于监视虚拟机各种运行状态信息的命令行工具,它可以显示本地或者远程虚拟机进程中的类装载、内存、垃圾收集、JIT 编译等运行数据。
查看 jstat 的帮助信息:
1 | [root@VM_24_98_centos jvm]# jstat -help |
jstat 命令格式:
1 | // 每 250 毫秒查询一次进程 2764 垃圾收集状态,一共查询 20 次 |
选项 | 作用 |
---|---|
-class | 监视类装载、卸载数量、总空间以及类装载所耗费的时间 |
-gc | 监视 Java 堆状况,包括 Eden 区、两个 survivor 区、老年代、永久代等的容量、已用空间、GC 空间合计等信息 |
-gccapacity | 监视内容与 -gc 基本相同,但输出主要关注 Java 堆各个区域使用到的最大、最小空间 |
-gcutil | 监视内容与 -gc 基本相同,但输出主要关注已使用空间占总空间的百分比 |
-gccause | 与 -gcutil 功能一样,但是会额外输出导致上一次 GC 产生的原因 |
-gcnew | 监视新生代 GC 状况 |
-gcnewcapacity | 监视内容与 -gcnew 基本相同,但输出主要关注使用到的最大、最小空间 |
-gcold | 监视老年代 GC 状况 |
-gcoldcapacity | 监视内容与 -gcold 基本相同,但输出主要关注使用到的最大、最小空间 |
-gcpermcapacity | 输出永久代使用到的最大、最小空间(JDK1.8 已废弃) |
-gcmetacapacity | 输出元数据空间使用到的最大、最小空间(JDK1.8 已废弃) |
-compiler | 输出 JIT 编译器编译过的方法、耗时等信息 |
-printcompilation | 输出已经被 JIT 编译的方法 |
特别说明:jstat 监视选项众多,由于版本原因无法逐一演示,感兴趣的朋友可以参考博客 《jvm 性能调优工具之 jstat》
jinfo:Java 配置信息工具
jinfo(Configuration Info for Java)的作用是实时地查看和调整虚拟机各项参数。使用 jps 命令的 -v 参数可以查看虚拟机启动时显示指定的参数列表,但如果想知道未被显示指定的参数的系统默认值,就只能使用 jinfo 的 -flag 选项进行查询了。
查看 jinfo 的帮助信息:
1 | [root@VM_24_98_centos jvm]# jinfo -help |
jinfo 命令格式:
1 | // jinfo 查询进程 2764 虚拟机各项参数 |
jmap:Java 内存映像工具
jmap(Memory Map for Java)命令用于生成堆转储快照(一般称为 heapdump 或者 dump 文件)。如果不使用 jmap 命令,可以使用 -XX:+HeapDumpOnOutOfMemoryError 参数,让虚拟机在 OOM 异常出现之后自动生成 dump 文件。
jmap 的作用并不仅仅是为了获取 dump 文件,它还可以查询 finalize 执行队列、Java 堆和永久代的详细信息,如空间使用率、当前用的是哪种收集器等。
查看 jmap 的帮助信息:
1 | [root@VM_24_98_centos ~]# jmap -help |
jmap 命令格式:
1 | // jinfo 查询进程 2764 Java 堆详细信息 |
选项 | 作用 |
---|---|
-dump | 生成 Java 堆转储快照。格式为:-dump:[live,]format=b,file=<filename>,其中 live 子参数说明是否只 dump 出存活的对象 |
-finalizerinfo | 显示在 F-Queue 中等待 Finalizer 线程执行 finalize 方法的对象。只有在 Linux/Solaris 平台下有效 |
-heap | 显示 Java 堆详细信息,如使用哪种回收器、参数配置、分代状况等。只有在 Linux/Solaris 平台下有效 |
-histo | 显示堆中对象统计信息,包括类、实例数量、合计容量 |
-histo:live | 与 -histo:live 功能一样,在统计之前 JVM 会先触发一次 FULL GC,线上慎用 |
-permstat | 以 ClassLoader 为统计口径显示永久代内存状态。只有在 Linux/Solaris 平台下有效 |
-F | 当虚拟机进程对 -dump 选项没有响应时,可使用这个选项强制生成 dump 快照。只有在 Linux/Solaris 平台下有效 |
jhat:虚拟机堆转储快照分析工具
Sun JDK 提供 jhat(JVM Heap Analysis Tool)命令与 jmap 搭配使用,来分析 jmap 生成的堆转快照。jhat 内置了一个微型的 HTTP/HTML 服务器,生成 dump 文件的分析结果后,可以在游览器中查看。
jhat 的分析功能相对来说比较简陋,在现实工作中,我们一般会使用 VisualVM、Eclipse Memory Analyzer、IBM HeapAnalyzer 等专业用于分析 dump 文件的工具。
查看 jhat 的帮助信息:
1 | [root@VM_24_98_centos ~]# jhat -help |
jmap 命令格式:
1 | // jhat 分析 file.dump,屏幕显示“Server is ready”的提示后,用户在游览器输入 http://localhost:7000/ 就可以看到分析结果 |
jstack:Java 堆栈跟踪工具
jstack(Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照(一般称为 threaddump 或者 javacore 文件)。线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待都是导致线程长时间停顿的常见原因。
查看 jstack 的帮助信息:
1 | [root@VM_24_98_centos ~]# jstack -help |
jstack 命令格式:
1 | // jstack 查看进程 2764 线程快照 |
选项 | 作用 |
---|---|
-F | 当正常输出的请求不被响应时,强制输出线程堆栈 |
-l | 除堆栈外,显示关于锁的附加信息 |
-m | 如果调用本地方法的话,可以显示 C/C++ 的堆栈 |
JDK 可视化工具
JDK 中除了提供大量的命令行工具外,还有两个功能强大的可视化工具:JConsole 和 VisualVM。
JConsole:Java 监视与管理控制台
JConsole(Java Monitoring and Management Console)是一种基于 JMX 的可视化监视、管理工具,它管理部分的功能是针对 JMX MBean 进行管理。
特殊说明:要对 Java 进程进行远程监控,在启动它的时候需要启用 JMX,对于 Java 进程开启远程调试可以参考博客《Java - jmx远程调优》
VisualVM:多合一故障处理工具
VisualVM(All-in-One Java Troubleshooting Tool)是到目前为止随 JDK 发布的功能最强大的运行监视和故障处理程序。VisualVM 除了运行监视、故障处理外,还提供了很多其他方面你的功能,如性能分析(Profiling)。VisualVM 的性能分析功能甚至比起 Jprofiler、YourKit 等专业且收费的 Profiling 工具都不会逊色多少,而且 VisualVM 不需要被监视的程序基于特殊 Agent 运行,因此它对对应用程序的实际性能的影响很小,使得它可以直接应用在生产环境中。
调优案例分析与实战
模拟环境:Centos7 1 核 2GB,Java 8
JVM 调优之 jstack 找出最耗 CPU 的线程并定位代码
笔者之前在一家互联网公司从事爬虫业务,在解析 HTML 时,经常由于网站返回的 HTML 网页结构不完整而导致解析框架死循环,从而导致 CPU 飚高,系统运行缓慢。
场景模拟
场景模拟:在线上的环境中,一般 CPU 飙高极大的可能性是出现了死循环了。因此我们通过模拟死循环的方式模拟 CPU 飚高的情况,然后通过 jstack 找出最耗 CPU 的线程并定位代码。启动程序后,发现该程序 CPU 直线飙高,直接到达 100% 根本没有要下降的趋势,并且系统平均负载也直线飙高至 3.79,导致系统缓慢。
1 | public class ExceptionHandler { |
排查思路
(1) jstack 找出最耗 CPU 的线程并定位代码
① 通过 top 命令找到占用 CPU 最高的 pid[进程 ID],定位到 pid 是 12870
② 通过 top -Hp pid 查看该进程中占用 CPU 过高的 tid[线程 id],定位到 tid 分别为 12894、12895、12896
③ 通过 printf “0x%x\n” tid 把线程 id 转化为十六进制,转换后的十六进制 tid 分别为 0x325e、0x325f、0x3260
④ 通过 jstack pid |grep tid -A 30 定位线程堆栈信息,这里的 tid 指的是转换后的十六进制 tid,定位到导致 CPU 飚高的代码为 ExceptionHandler 类 27 行处,发现里面有一个死循环。
(2) 通过在线可视化分析工具分析 threaddump
fastthread.io 是一个在线线程日志分析网站,科学上网打开速度会更快。定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待都是导致线程长时间停顿的常见原因。比较好的是它会提供一些优化的建议,可以作为参考,而且各个部分的分析也比较详细。
① 通过 top 命令找到占用 CPU 最高的 pid[进程 ID],定位到 pid 是 12870
② 通过 jstack -l pid > file-path 抓取 thread dump 文件,即 jstack -l 12870 > threaddump-1576050339106.tdump
③ 将 thread dump 文件上传至 fastthread 网站,查看分析结果
JVM 调优之 jstack 找出死锁线程并定位代码
Deadlock:死锁线程,一般指多个线程调用间,进入相互资源占用,导致一直等待无法释放的情况。由于锁使用不当,导致多个线程进入死锁状态,从而导致系统整体比较缓慢。
场景模拟
1 | public class ExceptionHandler { |
排查思路
(1) jstack 分析线程运行状况,找出死锁线程并定位代码
① 通过 top 命令找到占用 需要分析的 pid[进程 ID],定位到 pid 是 7120
② 通过 jstack pid 定位线程堆栈信息,通过分析线程快照,可以很轻松的发现死锁状况
(2) 通过在线可视化分析工具分析 threaddump
① 通过 top 命令找到占用 CPU 最高的 pid[进程 ID],定位到 pid 是 7120
② 通过 jstack -l pid > file-path 抓取 thread dump 文件,即 jstack -l 7120 > threaddump-1576050339106.tdump
③ 将 thread dump 文件上传至 fastthread 网站,查看分析结果
JVM 调优之 jstack 找出 Full GC 次数过多并定位代码
Full GC 次数过多,这种情况是最容易出现的,尤其是新功能上线时。对于 Full GC 较多的情况,其主要有如下两个特征:1、线上多个线程的 CPU 都超过了 100%,通过 jstack 命令可以看到这些线程主要是垃圾回收线程;2、通过 jstat 命令监控 GC 情况,可以看到 Full GC 次数非常多,并且次数在不断增加。
排查思路
(1) jstack 分析线程运行状况,找出 Full GC 次数过多原因并定位代码
① 首先我们通过 top 命令查看当前 CPU 消耗过高的进程是哪个,从而得到进程 id;然后通过 top -Hp <pid> 来查看该进程中有哪些线程 CPU 过高,一般超过 80% 就是比较高的,80% 左右是合理情况。这样我们就能得到 CPU 消耗比较高的线程 id。接着通过该线程 id 的十六进制表示在 jstack 日志中查看当前线程具体的堆栈信息
② 通过 jstack pid |grep tid -A 30 定位线程堆栈信息,这里的 tid 指的是转换后的十六进制 tid,定位到导致 CPU 飚高的线程为 “VM Thread”,而 VM Thread 指的就是垃圾回收的线程。这里我们基本上可以确定,当前系统缓慢的原因主要是垃圾回收过于频繁,导致 GC 停顿时间较长
③ 通过 jstat -gcutil pid 1000 10 查看 GC 的情况,可以看到,这里 FGC 指的是 Full GC 数量,若 FGC 过高,可能是由于内存溢出导致的系统缓慢,也可能是代码或者第三方依赖的包中有显示的 System.gc() 调用
④ 通过分析 dump 文件,确定由于内存溢出导致 Full GC 次数过多还是由于代码或者第三方依赖的包中有显示的 System.gc() 调用导致 Full GC 次数过多
(2) 通过在线可视化分析工具分析 gc.log
gceasy.io 是一个在线 GC 日志分析工具,科学上网打开速度会更快。gceasy 可帮助您可帮助您分析程序运行时 GC 情况,您可以根据分析结果及时优化程序。
① 通过 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log 命令获取 gc 日志
② 将 gc.log 文件上传至 gceasy 网站,查看分析结果
总结
对于 Full GC 次数过多,主要有以下两种原因:
- 代码中一次获取了大量的对象,导致内存溢出,此时可以通过 eclipse 的 mat 工具查看内存中有哪些对象比较多。
- 内存占用不高,但是 Full GC 次数还是比较多,此时可能是显示的 System.gc() 调用导致 GC 次数过多,这可以通过添加 - XX:+DisableExplicitGC 来禁用 JVM 对显示 GC 的响应。
JVM 调优之 jmap 找出内存泄漏并定位代码
同样是笔者之前所在的爬虫业务,有个网站改版后,登录时采用 RSA 加密方式,笔者根据网站的加密方式改版后项目重新上线后,发现项目内存使用率每天都会增加一点,对于一个长期稳定运行 Java 项目而言,出现这种情况一般都有可能是出现了内存泄露。
场景模拟
场景模拟:在线上的环境中,一个长期稳定运行的项目,内存使用率每天都增加,一般情况就是出现了内存泄露。而笔者所说的场景就是,网站采用 RSA 对网站的登录账号、密码进行加密,Java 默认的 RSA 实现是 “RSA/None/PKCS1Padding”(即 Cipher cipher = Cipher.getInstance(“RSA”););而该网站采用的 RSA 实现是 “RSA/None/NoPadding”(即 Cipher cipher = Cipher.getInstance(“RSA”, new org.bouncycastle.jce.provider.BouncyCastleProvider());)。项目长时间运行,就会出现 JceSecurity 占用的内存越来越多,而且不会释放。
1 | public class ExceptionHandler { |
排查思路
(1) MAT 找出内存泄漏并定位代码
Eclipse Memory Analyzer Tool(MAT)是一个强大的基于 Eclipse 的内存分析工具,可以帮助我们找到内存泄露,减少内存消耗。MAT 是有两种安装方式的:一种安装方式是将 MAT 当做 eclipse 的插件进行安装:启动 Eclipse –> Help –> Eclipse Marketplace,然后搜索 Memory Analyzer,安装,重启 eclipse 即可;另外一种安装方式是将 MAT 作为一个独立的软件进行安装:去 官网,根据操作系统版本下载最新的 MAT。下载后解压就可以运行了。
① 通过 top 命令找到占用内存使用率持续增加的 pid[进程 ID],定位到 pid 是 12870
② 通过 jmap -dump:[live,]format=b,file=<filename> <pid> 获取堆转储文件,即 jmap -dump:live,format=b,file=heapdump-1576054225319.hprof 12870
③ 将 heap dump 文件导入 MAT,查看分析结果
④ 加载后首页如下图,在首页上比较有用的是 Histogram 和 Leak Suspects。由下图看出这个类 javax.crypto.JceSecurity 占用 896.3 MB,表示这其中很多不能够被回对象的对象
⑤ 根据 Leak Suspects 快速查看泄露的可疑点,在 Leak Suspects 页面会给出可能的内存泄露,点击 Details 进入详情页面。在详情页面 Shortest Paths To the Accumulation Point 表示 GC root 到内存消耗聚集点的最短路径,如果某个内存消耗聚集点有路径到达 GC root,则该内存消耗聚集点不会被当做垃圾被回收。由下图可以看到大量的 BouncyCastleProvider 对象没有被垃圾回收器回收,占用了大量内存空间。
(3) 通过在线可视化分析工具分析 heaphero
heaphero.io 是一个在线内存分析工具,科学上网打开速度会更快。heaphero 可帮助您查找内存泄漏并减少内存消耗,运行报告以自动提取泄漏嫌疑者,主要展示项有:堆统计,大对象,字符串重复,低效率对象,线程数,及优化建议等。
① 通过 top 命令找到占用内存使用率持续增加的 pid[进程 ID],定位到 pid 是 12870
② 通过 jmap -dump:[live,]format=b,file=<filename> <pid> 获取堆转储文件,即 jmap -dump:live,format=b,file=heapdump-1576054225319.hprof 12870
③ 将 heap dump 文件上传至 heaphero 网站,查看分析结果
解决方式
(1)修改 provider 指定方式:Security.addProvider(new BouncyCastleProvider())
1 | public class ExceptionHandler { |
(2)把 BouncyCastleProvider 改成单例模式
1 | public class ExceptionHandler { |
参考博文
[1]. jvm 性能调优工具之 jstat
[2]. JDK的可视化工具系列 (四) JConsole、VisualVM
[3]. 使用Eclipse Memory Analyzer Tool(MAT)分析线上故障(一) - 视图&功能篇
[4]. 一道必备面试题:系统CPU飙高和GC频繁,如何排查?
深入理解 Java 虚拟机系列
- 深入理解 Java 虚拟机(一):Java 内存区域与内存溢出异常
- 深入理解 Java 虚拟机(二):JVM 垃圾收集器
- 深入理解 Java 虚拟机(三):内存分配与回收策略
- 深入理解 Java 虚拟机(四):Jvm 性能监控与调优