前序文章:

JVM性能调优(1) —— JVM内存模型和类加载运行机制

JVM性能调优(2) —— 垃圾回收器和回收策略

JVM性能调优(3) —— 内存分配和垃圾回收调优

一、JDK工具

先来看看有哪些常用的工具可以辅助我们进行性能调优和问题排查,后面再通过一个具体的示例结合工具来分析调优。

1、JDK工具

JDK自带了很多性能监控工具,我们可以用这些工具来监测系统和排查内存性能问题。

2、利用 jps 找出进程

jps(Java Virtual Machine Process Status Tool)是JDK 1.5提供的一个显示当前所有java进程pid的命令,简单实用,非常适合在linux/unix平台上简单察看当前java进程的一些简单情况。

1)查看Java进程PID

【jps -l】左边一列就是Java进程的PID。

2)输出传递给JVM的参数

【jps -vl】

3、利用 jstat 查看VM统计信息

使用 jstat 工具可以监测 Java 应用程序的实时运行情况,可以看到VM内的Eden、Survivor、老年代的内存使用情况,还有 YoungGC 和 FullGC 的执行次数以及耗时。通过这些指标,我们可以轻松的分析出当前系统的运行情况,判断当前系统的内存使用压力以及GC压力,还有内存分配是否合理。

1)查看 jstat 有哪些操作

【jstat -options】

  • -class:显示 ClassLoad 的相关信息;
  • -compiler:显示 JIT 编译的相关信息;
  • -gc:显示和 gc 相关的堆信息;
  • -gccapacity:显示各个代的容量以及使用情况;
  • -gcmetacapacity:显示 Metaspace 的大小;
  • -gcnew:显示新生代信息;
  • -gcnewcapacity:显示新生代大小和使用情况;
  • -gcold:显示老年代和永久代的信息;
  • -gcoldcapacity :显示老年代的大小;
  • -gcutil:显示垃圾收集信息;
  • -gccause:显示垃圾回收的相关信息(同 -gcutil),同时显示最后一次或当前正在发生的垃圾回收的诱因;
  • -printcompilation:输出 JIT 编译的方法信息

其中 jstat -gc 是最完整、最常用、最实用的命令,基本足够分析jvm的运行情况了。

2)显示 ClassLoad 的相关信息

【jstat -class <pid>】

3)查看内存使用和GC情况

【jstat -gc <pid> [<interval> [<count>]】

  • S0C:年轻代中 To Survivor 的容量(单位 KB);
  • S1C:年轻代中 From Survivor 的容量(单位 KB);
  • S0U:年轻代中 To Survivor 目前已使用空间(单位 KB);
  • S1U:年轻代中 From Survivor 目前已使用空间(单位 KB);
  • EC:年轻代中 Eden 的容量(单位 KB);
  • EU:年轻代中 Eden 目前已使用空间(单位 KB);
  • OC:老年代的容量(单位 KB);
  • OU:老年代目前已使用空间(单位 KB);
  • MC:Metaspace 的容量(单位 KB);
  • MU:Metaspace 目前已使用空间(单位 KB);
  • CCSC:压缩类空间大小
  • CCSU:压缩类空间使用大小
  • YGC:从应用程序启动到采样时年轻代中 gc 次数;
  • YGCT:从应用程序启动到采样时年轻代中 gc 所用时间 (s);
  • FGC:从应用程序启动到采样时 old 代(全 gc)gc 次数;
  • FGCT:从应用程序启动到采样时 old 代(全 gc)gc 所用时间 (s);
  • GCT:从应用程序启动到采样时 gc 用的总时间 (s)

4)查看垃圾回收统计

【jstat -gcutil <pid> [<interval> [<count>]】

  • S0:Survivor0 区占用百分比
  • S1:Survivor1 区占用百分比
  • E:Eden 区占用百分比
  • O:老年代占用百分比
  • M:元数据区占用百分比
  • YGC:年轻代回收次数
  • YGCT:年轻代回收耗时
  • FGC:老年代回收次数
  • FGCT:老年代回收耗时
  • GCT:GC总耗时 

4、利用 jmap 查看对象分布情况

使用 jmap 可查看堆内存初始化配置信息以及堆内存的使用情况,输出堆内存中的对象信息,包括产生了哪些对象,对象数量多少等。

1)查看堆内存情况

【jmap -heap <PID>】

这个命令会打印出堆内存相关的一些参数设置以及各个区域的情况,要查看这些信息一般使用 jstat 命令就足够了。

2)查看系统运行时对象分布

【jmap -histo[:live] <PID>】带上 live 则只统计活对象

这个命令会按照各种对象占用内存空间的大小降序排列,把占用内存最多的对象放在最上面。通过这个命令可以简单的了解下当前jvm中的对象对内存占用的情况以及当前内存里到底是哪个对象占用了大量的内存空间。

3)生成堆内存转储快照

【jmap -dump:format=b,file=<path> <pid>】

【jmap -dump:live,format=b,file=<path> <pid>】

jmap -dump 是输出堆中所有对象;jmap -dump:live 是输出堆中所有活着的对象,而且 jmap -dump:live 会触发 FullGC,线上使用要注意。format=b 是以二进制格式输出;file 是文件路径,格式为 hrpof 后缀。

这个命令会在当前目录下生成一个 dump.hrpof 文件,这是个二进制的格式,无法直接打开,可以使用MAT等工具来分析。这个命令把这一时刻VM堆内存里所有对象的快照放到文件里去了,供你后续去分析。

5、利用 jstack 分析线程栈

jstack 是一种线程堆栈分析工具,最常用的功能就是使用 jstack pid 命令查看线程的堆栈信息,通常会结合 top -Hp pid 或 pidstat -p pid -t 一起查看具体线程的状态,也经常用来排查一些死锁的异常、CPU占用高的线程等。

1)jstack参数

  • -l:长列表. 打印关于锁的附加信息,例如属于 java.util.concurrent 的 ownable synchronizers 列表。
  • -F:当 jstack [-l] pid 没有响应的时候强制打印栈信息
  • -m:打印 java 和 native c/c++ 框架的所有栈信息.
  • -h | -help:打印帮助信息

2)查看线程堆栈信息

【jstack <pid> > stack.log】

这个命令可以把程序的线程堆栈dump下来。每个线程堆栈的信息中,都可以查看到线程 ID、线程状态(wait、sleep、running 等状态)以及是否持有锁等。

  • pool-11-thread-6:线程名称
  • #1920:线程编号
  • prio=5:线程的优先级别
  • os_prio=0:系统级别的线程优先级
  • tid=0x00007f87e028c000:线程ID
  • nid=0x6724:native线程的id,通过 printf "%x\n" <pid> 命令转换线程ID
  • waiting on condition [0x00007f87b97d2000]:线程当前的状态

二、Linux 命令行工具

1、top 命令

top 命令是我们在 Linux 下最常用的命令之一,它可以实时显示正在执行进程的 CPU 使用率、内存使用率以及系统负载等信息。其中上半部分显示的是系统的统计信息,下半部分显示的是进程的使用率统计信息。

看第一行:主要展示了CPU的负载情况

  • 23:22:23:指的是当前时间
  • up 12 days, 12::18:指的是机器已经运行了多长时间
  • 1 user:当前机器有一个用户在使用
  • load average: 0.19, 0.27, 0.30:指 CPU 在1分钟、5分钟、15分钟内的负载情况。

最重要的就是看 load average,比如机器是4核CPU,那么 0.19、0.27、0.30,说明4核中连一个核都没用满,4核CPU基本很空闲。如果CPU负载是1,说明有1个核被使用的比较繁忙了。如果负载是4,说明4核CPU都跑满了;如果超过4,说明4核CPU被繁忙的使用还不够处理当前的任务,很多进程可能一直在等待CPU去执行自己的任务。

② 查看具体线程使用系统资源情况

2、vmstat 命令

vmstat 是 Virtual Meomory Statistics(虚拟内存统计)的缩写,可对操作系统的虚拟内存、进程、CPU活动进行监控。

命令格式:【vmstat [ 选项 ] [ <时间间隔> ] [ <次数> ]】

字段说明:
  • Procs(进程):
    • r:等待运行的进程数
    • b:处于非中断睡眠状态的进程数
  • Memory(内存,单位Kb):
    • swpd:虚拟内存使用情况
    • free:空闲的内存
    • buff:用来作为缓冲的内存数
    • cache:用作缓存的内存大小
  • Swap(交换区):
    • si:从磁盘交换到内存的交换页数量
    • so:从内存交换到磁盘的交换页数量
  • IO:(现在的Linux版本块的大小为1024bytes)
    • bi:发送到块设备的块数
    • bo:从块设备接收到的块数
  • System(系统):
    • in:每秒中断数,包括时钟中断。【interrupt】
    • cs:每秒上下文切换数。【count/second】
  • CPU(以百分比表示):
    • us:用户 CPU 使用时间(user time)
    • sy:内核 CPU 系统使用时间 (system time)
    • id:空闲时间(包括IO等待时间),中央处理器的空闲时间 。以百分比表示。
    • wa:等待IO时间
判断指标:
  • 如果 r 经常大于4,id 经常少于40,表示cpu的负荷很重。
  • 如果 bi,bo 长期不等于0,表示内存不足。
  • 如果 disk 经常不等于0,且在 b 中的队列大于3,表示io性能不好。
  • 通过 cs 观察 Java 程序运行过程中系统的上下文切换频率。过高说明程序创建了过多的线程导致频繁的上下文切换。

3、pidstat 命令

如果是监视某个应用的上下文切换,可以使用 pidstat 命令监控指定进程的上下文切换。

pidstat 是 Sysstat 中的一个组件,也是一款功能强大的性能监测工具,我们可以通过命令:yum install sysstat 安装该监控组件。top 和 vmstat 两个命令都是监测进程的内存、CPU 以及 I/O 使用情况,而 pidstat 命令则是深入到线程级别。

命令格式:【pidstat [ 选项 ] [ <时间间隔> ] [ <次数> ]】

1)常用的选项:

  • -u:默认的参数,显示各个进程的 cpu 使用情况
  • -r:显示各个进程的内存使用情况
  • -d:显示各个进程的 I/O 使用情况
  • -p:指定进程号
  • -w:显示每个进程的上下文切换情况
  • -t:显示进程中线程的统计信息
  • -T { TASK | CHILD | ALL }
    • TASK表示报告独立的task,CHILD关键字表示报告进程下所有线程统计信息。ALL表示报告独立的task和task下面的所有线程。
    • 注意:task和子线程的全局的统计信息和pidstat选项无关。这些统计信息不会对应到当前的统计间隔,这些统计信息只有在子线程kill或者完成的时候才会被收集。
  • -V:版本号
  • -h:在一行上显示了所有活动,这样其他程序可以容易解析。
  • -I:在SMP环境,表示任务的CPU使用率/内核数量
  • -l:显示命令名和所有参数

2)查看所有进程的 CPU 使用情况

【pidstat】、【pidstat -u -p ALL】

  • PID:进程ID
  • %usr:进程在用户空间占用cpu的百分比
  • %system:进程在内核空间占用cpu的百分比
  • %guest:进程在虚拟机占用cpu的百分比
  • %CPU:进程占用cpu的百分比
  • CPU:处理进程的cpu编号
  • Command:当前进程对应的命令

3)显示每个进程的上下文切换情况

【pidstat -w -p <PID> <时间间隔>  <次数>】

  • PID:进程id
  • Cswch/s:每秒主动任务上下文切换数量
  • Nvcswch/s:每秒被动任务上下文切换数量
  • Command:命令名

4)显示进程中线程的统计信息

【pidstat -p <PID> -t】

三、可视化工具

下面简单介绍几款常用的可视化分析工具,一般我们需要将GC日志文件、堆转储文件dump下来,然后就可以通过这些工具来分析。如果是线上分析一般直接使用上面的那些JDK命令行工具就足够了,这些可视化工具可以做一些辅助性的分析。

1、jvisualvm — JVM监控

jvisualvm 是 jdk 提供的监控工具,位于 %JAVA_HOME%/bin/jvisualvm.exe,双击运行即可。

VisualVM 提供了一个可视界面,用于查看JVM上运行的基于 Java 技术的应用程序的详细信息。VisualVM 能够监控线程,内存情况,方法的CPU时间和内存中的对象,已被GC的对象,反向查看分配的堆栈(如100个String对象分别由哪几个对象分配出来的)等。

更详细的一些使用方式可以参考这篇文章:https://zhuanlan.zhihu.com/p/30837957

1)插件安装

VisualVM 基于NetBeans平台开发工具,它具备通过插件扩展功能的能力,有了插件扩展支持,VisualVM可以做到:

  • 显示虚拟机进程以及进程的配置、环境信息(jps、jinfo)
  • 监视应用程序的处理器、垃圾收集、堆、方法区以及线程的信息(jstat、jstack)
  • dump以及分析堆转储快照(jmap、jhat)
  • 方法级的程序运行性能分析,找出被调用最多、运行时间最长的方法
  • 离线程序快照:收集程序的运行时配置、线程dump、内存dump等信息建立一个快照,可以将快照发送开发者处进行Bug反馈
  • 其他插件带来的无限可能性

可以从工具选项中打开插件面板安装所需的插件:

2)监视面板

在左边选择需要监控的程序,右边就可以可查看CPU、堆、线程等波动情况,也可以直接在这里进行手动 GC 和堆 Dump 操作。

3)线程面板

可看到所有的线程,以及线程的运行状态。点击面板的线程 Dump 按钮,可以查看线程瞬时的线程栈。(通过 jstack 也可以抓取线程栈)

4)GC面板

可以很方便的看到GC趋势图。(也可使用 jstat 工具监控)

5)分析堆转储快照

通过左上角装入快照按钮打开 dump 的堆转储文件,就可以分析堆转储快照了。

3、GCViewer — 离线分析GC日志

GCViewer 可以离线查看GC日志,下载地址为 https://github.com/chewiebug/GCViewer。下载下来之后执行 [mvn clean install -Dmaven.test.skip=true] 命令打包编译,编译完成后在target目录下会看到jar包,然后在命令行运行这个jar包就可以启动 GCViewer。

然后通过 File 打开GC日志文件,就可以看到GC统计图和GC情况。通过工具,我们可以看到吞吐量、停顿时间以及 GC 的频率等信息,从而可以非常直观地了解到 GC 的性能情况。

4、GCeasy — 在线分析GC日志

GCeasy 是一款在线版的非常直观的 GC 日志分析工具,我们可以将日志文件压缩之后,上传到 GCeasy 官网即可看到非常清楚的 GC 日志分析结果。

5、FastThread — 分析线程栈

线程栈使用 jstack 命令 dump 下来后,可以使用 FastThread 在线工具分析线程栈信息,可以直观的看到有多少线程、线程池、线程的状态、是否有死锁等信息。

6、MAT — 分析堆转储文件

我们使用 jmap 命令 dump 下来的堆转储文件可以使用 MAT 来分析,可以分析创建了哪些对象,然后分析对象的引用链,找出问题所在。MAT 下载地址:http://www.eclipse.org/mat/downloads.php

MAT 主要功能:

  • 找出内存泄漏的原因
  • 找出重复引用的类和jar
  • 分析集合的使用
  • 分析类加载器

7、性能调优工具

1)在线工具地址

线程 Dump 分析(FastThread):https://fastthread.io/

线程 Dump 分析(PerfMa):https://thread.console.perfma.com/

内存 Dump 分析(PerfMa):https://memory.console.perfma.com/

JVM 参数分析(PerfMa):https://opts.console.perfma.com/

GC 日志分析(GCEasy):https://www.gceasy.io/

GC 日志分析(GCViewer):https://github.com/chewiebug/GCViewer

Java 诊断(Arthas):https://alibaba.github.io/arthas/

MAT:http://www.eclipse.org/mat/downloads.php

2)调优工具选择

调优的工具很多,一般对于线上系统,使用 jstat 工具足以分析出JVM的运行情况,如果有GC日志,也可以使用GCeasy快速分析JVM的运行情况。

遇到CPU负载过高,可以使用 top + pidstat 找出负载高的线程,或者直接使用 jstat 观察是不是在频繁FullGC。

遇到死锁、OOM等问题,可以用 jstack 把线程栈dump下来分析,还可以结合 FastThread 在线工具,分析线程栈、哪些线程阻塞等待等。

遇到OOM问题,使用 jmap 把堆转储快照dump下来,用MAT来分析创建了哪些大量的对象。

8、JVM监控平台

系统上线后,如果不部署可视化的监控平台,我们一般就通过上面的这些工具来分析JVM的内存运转模型、GC情况等,可以在机器上运行jstat,让其把监控信息写入一个文件,每天定时检查—下。

监控平台则可以通过可视化的界面看到JVM各个区域的内存变化,GC次数和GC耗时等信息,以及出现性能问题时能及时报警。

一般可以部署 Zabbix、Ganglia、Open-Falcon、Prometheus 之类的可视化监控平台,把线上系统接入到这些平台,就可以直接图形化看到JVM的表现。

四、利用工具分析JVM运行情况

要想合理地分配内存、优化GC,通过前一篇的性能调优过程可以发现,我们至少需要知道如下的一些信息:新生代对象增长的速率,YoungGC的触发频率,YoungGC的耗时,每次YoungGC后存活对象大小,每次YoungGC过后有多少对象进入了老年代,老年代对象增长的速率,FullGC的触发频率,FullGC的耗时等。前面我们是通过分析GC日志或者粗略估算的方式来调优的,现在就利用 jstat 工具来分析下。

1、运行示例程序

1)如下示例代码

这段代码模拟每秒钟在新生代创建20M对象,1秒之后就变为垃圾对象了。

 1 public class GCMain {
 2     static final int _1M = 1024 * 1024;
 3 
 4     public static void main(String[] args) {
 5         sleep(20);
 6 
 7         for (int i = 0; i < 100; i++) {
 8             loadData(i);
 9         }
10     }
11 
12     // loadData 每次请求产生20M对象,每次请求耗时1秒
13     public static void loadData(int index) {
14         System.out.println("load data: " + index);
15         byte[] data1 = new byte[_1M * 10];
16         byte[] data2 = new byte[_1M * 10];
17 
18         sleep(1);
19     }
20 
21     public static void sleep(long seconds) {
22         try {
23             Thread.sleep(seconds * 1000);
24         } catch (InterruptedException e) {
25             e.printStackTrace();
26         }
27     }
28 }

2)设置JVM参数

运行示例程序前设置如下的JVM参数:新生代、老年代各100M,Eden区80M,Survivor区10M,大对象阀值20M。

-Xms200M
-Xmx200M
-Xmn100M
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=5
-XX:PretenureSizeThreshold=20M
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction=92
-XX:+UseCMSInitiatingOccupancyOnly
-XX:+UseCMSCompactAtFullCollection
-XX:CMSFullGCsBeforeCompaction=0
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:./gc.log 

3)估算内存运转模型

我们先根据这段业务代码以及JVM参数配置估算下JVM运行情况:

  • 这段代码每秒将在Eden区产生20M对象,大概3~4秒钟会占满Eden区触发YoungGC。
  • YoungGC 后存活的对象可能超过10M,因为可能在创建 data2 时,Eden区不够了,而 data1 还是存活的;也有可能为0,在创建 data1 的时候 Eden 区就不够了。
  • 由于 Survivor 区不足以放下YoungGC后存活的对象,那么每次大概会有10M的对象进入老年代;考虑到有可能YoungGC后没有存活对象,就估算为2次YoungGC会有10M进入老年代吧。
  • YoungGC 3~4 秒触发一次,那么大概经过18次左右YoungGC,就是60秒左右,老年代就快满了,然后存活对象无法放入老年代触发FullGC。
  • 由于CMS后台回收线程在老年代超过92%时会触发OldGC,所以60秒左右也有可能由于老年代超过92%这个阀值触发GC。

4)使用 jps 命令找出程序的 PID

将程序运行起来,首先通过 jps -l 命令找到这个程序的PID。

5)使用 jstat 命令查看GC情况

如下是 jstat 输出的情况:

  1 Mechrevo@hello-world MINGW64 ~/Desktop
  2 $ jstat -gc 15488 1000 1000
  3  S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
  4 10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
  5 10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
  6 10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
  7 10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
  8 10240.0 10240.0  0.0    0.0   81920.0   4984.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
  9 10240.0 10240.0  0.0    0.0   81920.0  25464.1   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
 10 10240.0 10240.0  0.0    0.0   81920.0  45944.2   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
 11 10240.0 10240.0  0.0    0.0   81920.0  66424.2   102400.0     0.0     4480.0 786.6  384.0   76.4       0    0.000   0      0.000    0.000
 12 10240.0 10240.0  0.0   713.8  81920.0  11878.4   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
 13 10240.0 10240.0  0.0   713.8  81920.0  33961.9   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
 14 10240.0 10240.0  0.0   713.8  81920.0  54441.9   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
 15 10240.0 10240.0  0.0   713.8  81920.0  74922.0   102400.0   10242.1   4864.0 3043.9 512.0  321.7       1    0.005   0      0.000    0.005
 16 10240.0 10240.0 828.5   0.0   81920.0  22891.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
 17 10240.0 10240.0 828.5   0.0   81920.0  43371.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
 18 10240.0 10240.0 828.5   0.0   81920.0  63851.3   102400.0   10242.1   4864.0 3044.4 512.0  321.7       2    0.005   0      0.000    0.005
 19 10240.0 10240.0  0.0   964.7  81920.0  10240.0   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
 20 10240.0 10240.0  0.0   964.7  81920.0  32230.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
 21 10240.0 10240.0  0.0   964.7  81920.0  52710.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
 22 10240.0 10240.0  0.0   964.7  81920.0  73190.5   102400.0   20484.1   4864.0 3044.5 512.0  321.7       3    0.010   0      0.000    0.010
 23 10240.0 10240.0 759.6   0.0   81920.0  22035.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
 24 10240.0 10240.0 759.6   0.0   81920.0  42515.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
 25 10240.0 10240.0 759.6   0.0   81920.0  62995.2   102400.0   20484.1   4864.0 3044.5 512.0  321.7       4    0.011   0      0.000    0.011
 26 10240.0 10240.0  0.0   886.2  81920.0  10240.0   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
 27 10240.0 10240.0  0.0   886.2  81920.0  32212.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
 28 10240.0 10240.0  0.0   886.2  81920.0  52692.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
 29 10240.0 10240.0  0.0   886.2  81920.0  73172.1   102400.0   30724.1   4864.0 3044.5 512.0  321.7       5    0.016   0      0.000    0.016
 30 10240.0 10240.0  0.0    0.0   81920.0  22023.2   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
 31 10240.0 10240.0  0.0    0.0   81920.0  42503.3   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
 32 10240.0 10240.0  0.0    0.0   81920.0  62983.3   102400.0   31373.1   4864.0 3044.5 512.0  321.7       6    0.019   0      0.000    0.019
 33 10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
 34 10240.0 10240.0  0.0    0.0   81920.0  32204.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
 35 10240.0 10240.0  0.0    0.0   81920.0  52684.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
 36 10240.0 10240.0  0.0    0.0   81920.0  73164.4   102400.0   41613.1   4864.0 3044.5 512.0  321.7       7    0.024   0      0.000    0.024
 37 10240.0 10240.0  0.0    0.0   81920.0  22018.2   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
 38 10240.0 10240.0  0.0    0.0   81920.0  42498.3   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
 39 10240.0 10240.0  0.0    0.0   81920.0  62978.3   102400.0   41613.1   4864.0 3044.9 512.0  321.7       8    0.025   0      0.000    0.025
 40 10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
 41 10240.0 10240.0  0.0    0.0   81920.0  32201.1   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
 42 10240.0 10240.0  0.0    0.0   81920.0  52681.2   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
 43 10240.0 10240.0  0.0    0.0   81920.0  73161.2   102400.0   51853.2   4864.0 3044.9 512.0  321.7       9    0.030   0      0.000    0.030
 44 10240.0 10240.0  0.0    0.0   81920.0  22016.1   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
 45 10240.0 10240.0  0.0    0.0   81920.0  42496.2   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
 46 10240.0 10240.0  0.0    0.0   81920.0  62976.2   102400.0   51853.2   4864.0 3045.6 512.0  321.7      10    0.031   0      0.000    0.031
 47 10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
 48 10240.0 10240.0  0.0    0.0   81920.0  32199.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
 49 10240.0 10240.0  0.0    0.0   81920.0  52679.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
 50 10240.0 10240.0  0.0    0.0   81920.0  52679.8   102400.0   62093.2   4864.0 3045.9 512.0  321.7      11    0.036   0      0.000    0.036
 51 10240.0 10240.0  0.0    0.0   81920.0  22015.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
 52 10240.0 10240.0  0.0    0.0   81920.0  42495.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
 53 10240.0 10240.0  0.0    0.0   81920.0  62975.3   102400.0   62093.2   4864.0 3045.9 512.0  321.7      12    0.036   0      0.000    0.036
 54 10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
 55 10240.0 10240.0  0.0    0.0   81920.0  32199.2   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
 56 10240.0 10240.0  0.0    0.0   81920.0  52679.3   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
 57 10240.0 10240.0  0.0    0.0   81920.0  74797.7   102400.0   72333.2   4864.0 3045.9 512.0  321.7      13    0.041   0      0.000    0.041
 58 10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
 59 10240.0 10240.0  4.0    0.0   81920.0  22014.9   102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
 60 10240.0 10240.0  4.0    0.0   81920.0  62975.0   102400.0   72333.2   4864.0 3048.0 512.0  321.7      14    0.042   0      0.000    0.042
 61 10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
 62 10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
 63 10240.0 10240.0  0.0    2.0   81920.0  32199.0   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
 64 10240.0 10240.0  0.0    2.0   81920.0  73159.1   102400.0   82573.2   4864.0 3048.0 512.0  321.7      15    0.047   0      0.000    0.047
 65 10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
 66 10240.0 10240.0  4.0    0.0   81920.0  22014.7   102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
 67 10240.0 10240.0  4.0    0.0   81920.0  62974.8   102400.0   82573.2   4864.0 3048.0 512.0  321.7      16    0.048   0      0.000    0.048
 68 10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
 69 10240.0 10240.0  0.0    2.0   81920.0  10240.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
 70 10240.0 10240.0  0.0    2.0   81920.0  32198.9   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
 71 10240.0 10240.0  0.0    2.0   81920.0  73159.0   102400.0   10892.1   4864.0 3048.7 512.0  321.7      17    0.053   2      0.002    0.055
 72 10240.0 10240.0  2.0    0.0   81920.0  22833.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
 73 10240.0 10240.0  2.0    0.0   81920.0  22833.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
 74 10240.0 10240.0  2.0    0.0   81920.0  43313.9   102400.0   10892.1   4864.0 3049.0 512.0  321.7      18    0.054   2      0.002    0.056
 75 10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
 76 10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
 77 10240.0 10240.0  0.0    4.0   81920.0  32193.5   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
 78 10240.0 10240.0  0.0    4.0   81920.0  52673.6   102400.0   21132.1   4864.0 3049.0 512.0  321.7      19    0.056   2      0.002    0.058
 79 10240.0 10240.0  2.0    0.0   81920.0  22011.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
 80 10240.0 10240.0  2.0    0.0   81920.0  22011.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
 81 10240.0 10240.0  2.0    0.0   81920.0  42491.2   102400.0   21132.1   4864.0 3049.0 512.0  321.7      20    0.057   2      0.002    0.058
 82 10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
 83 10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
 84 10240.0 10240.0  0.0    4.0   81920.0  32196.6   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
 85 10240.0 10240.0  0.0    4.0   81920.0  52676.6   102400.0   31372.2   4864.0 3049.0 512.0  321.7      21    0.059   2      0.002    0.060
 86 10240.0 10240.0  4.0    0.0   81920.0    0.0     102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
 87 10240.0 10240.0  4.0    0.0   81920.0  22013.2   102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
 88 10240.0 10240.0  4.0    0.0   81920.0  42493.2   102400.0   31372.2   4864.0 3049.0 512.0  321.7      22    0.059   2      0.002    0.061
 89 10240.0 10240.0  0.0    4.0   81920.0    0.0     102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
 90 10240.0 10240.0  0.0    4.0   81920.0  10240.0   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
 91 10240.0 10240.0  0.0    4.0   81920.0  32197.9   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
 92 10240.0 10240.0  0.0    4.0   81920.0  52677.9   102400.0   41612.2   4864.0 3049.0 512.0  321.7      23    0.061   2      0.002    0.062
 93 10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
 94 10240.0 10240.0  0.0    0.0   81920.0  42494.1   102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
 95 10240.0 10240.0  0.0    0.0   81920.0  42494.1   102400.0   41612.2   4864.0 3049.0 512.0  321.7      24    0.061   2      0.002    0.063
 96 10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
 97 10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
 98 10240.0 10240.0  0.0    0.0   81920.0  32198.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
 99 10240.0 10240.0  0.0    0.0   81920.0  52678.5   102400.0   51852.3   4864.0 3049.8 512.0  321.7      25    0.063   2      0.002    0.065
100 10240.0 10240.0  0.0    0.0   81920.0    0.0     102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
101 10240.0 10240.0  0.0    0.0   81920.0  22014.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
102 10240.0 10240.0  0.0    0.0   81920.0  42494.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
103 10240.0 10240.0  0.0    0.0   81920.0  62974.4   102400.0   51852.3   4864.0 3049.8 512.0  321.7      26    0.064   2      0.002    0.065
104 10240.0 10240.0  0.0    0.0   81920.0  10240.0   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
105 10240.0 10240.0  0.0    0.0   81920.0  32198.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
106 10240.0 10240.0  0.0    0.0   81920.0  52678.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
107 10240.0 10240.0  0.0    0.0   81920.0  73158.7   102400.0   62092.3   4864.0 3049.8 512.0  321.7      27    0.065   2      0.002    0.067
108 10240.0 10240.0  0.0    0.0   81920.0  22014.5   102400.0   62092.3   4864.0 3050.1 512.0  321.7      28    0.066   2      0.002    0.068
109 10240.0 10240.0  0.0    0.0   81920.0  42494.6   102400.0   62092.3   4864.0 3050.1 512.0  321.7      28    0.066   2      0.002    0.068
View Code

首先从前面几行可以看出内存各个区域的大小,Survivor0/Survivor1 10M,Eden区80M,老年代100M 等信息。

2、新生代对象增长的速率

从 EU 这一行可以看出,新生代基本是按照每秒20M左右的对象在增长。

3、YoungGC的触发频率和耗时

从 Eden 区的内存变化可以看出,基本是每隔3秒或4秒就会触发一次 YoungGC,比如第一次Eden区增长到66424.2时,经过一次 YoungGC后只剩下11878.4。从 YGC 这列也大致可以看出YoungGC的频率。

从 YGCT 这列可以看出,每次YoungGC耗时1~5毫秒的样子,也就是说每隔3~4秒,触发一次YoungGC,一次YoungGC系统卡顿1~5毫秒。这也可以看出 YoungGC 其实是很快的,就算新生代800M也才10几毫秒,对系统几乎没什么影响。

4、YoungGC后存活对象大小以及有多少对象进入了老年代

从 S0U、S1U 这两列的变化可以看出,每次YoungGC后有800K左右的对象进入 Survivor 区。

从 OU 这列的变化可以看出,每次进入老年代的对象在10M左右,所以一次YoungGC后可能有10M的存活对象进入老年代。

5、FullGC的触发频率和耗时

从 OU 这列的变化可以看出,在老年代达到 82573.2 时,触发了 FullGC,回收后老年代大小为 10892.1。从整体的时间线上看,刚好60秒就触发了一次FullGC。

从 FGCT 可以看出,一次FullGC 耗时2毫秒,

为什么在老年代 82573.2 时就触发了FullGC呢,我们从GC日志中来看:

可以看出这一秒内,实际上这次YoungGC导致有10M的对象进入老年代,老年代实际有92815K对象,因而应该是CMS超过了 92% 的阀值之后触发了老年代GC。

6、使用GCeasy查看GC日志

至此,其实已经基本上分析出整个JVM的运转情况了。这里总结下:

  • 新生代、老年代 100M,Eden区80M,Survivor区10M;
  • Eden区每秒产生20M左右对象,每隔3~4秒触发一次YoungGC;
  • YoungGC后存活对象在0~10M左右,由于无法放入Survivor区会进入老年代,每次进入老年代对象10M左右;
  • 在经过16次左右YoungGC后,也就是60秒左右老年代会接近占满,超过设置的阀值,触发一次 FullGC。

从上面的分析可以看出,jstat 监控的输出结果基本是符合前面估算的结果的。但是粗略估算需要熟悉系统核心的业务,而且其它未知因素也比较多,粗略估算一般用于系统刚上线阶段来设置JVM参数。而通过 jstat 来监控一般就可以比较准确的摸清JVM的运行情况,然后进行性能调优。

接下来再通过GC日志来看下是否符合分析的情况,GC日志就不再一行一行分析了,我们直接通过在线工具 GCeasy 来看看内存变化和GC的情况。将输出的GC日志直接拷贝到 GCeasy 上,就可以看到分析的结果。

1)GC总体情况

从这张图可以得到如下信息:

  • 垃圾回收器的吞吐率为 99.937%;
  • 平均GC停顿时间:2毫秒
  • 最长GC停顿时间:10毫秒
  • 80% 的GC耗时 0~1毫秒
  • 20% 的GC耗时 9~10毫秒

2)YoungGC频率

从 Young Gen 这个统计图可以看出,YoungGC的频率在3~4秒的样子。

3)老年代GC频率

从这张统计图可以看出,老年代是每两次YoungGC增长一次,每次增长10M左右,在60秒左右触发一次OldGC。

4)CMS回收情况

这张图展示了CMS各个阶段的统计情况

7、性能优化

从上面的分析可以看出,这个JVM最大的问题在于 Survivor 区没起作用,Survivor 区只有10M,而YoungGC后存活对象大于10M,导致无法放进Survivor区而直接进入老年代了,进而触发FullGC。因此我们可以增大新生代大小或者调整Eden区和Survivor区比例,来让对象进入Survivor区。

比如改为如下配置:新生代给150M,比例调整为6,这样Eden区90M,Survivor区各30M,这样Survivor区足以放下YoungGC后存活的对象,也基本上能避免动态年龄判断导致对象进入老年代。

-Xms200M
-Xmx200M
-Xmn150M
-XX:SurvivorRatio=6

再看这时的GC情况,首先从 S0U、S1U 的变化可以看出,Survivor 区在起作用了,每次YoungGC后存活对象都进入Survivor区了。

然后从 OU、YGC的变化可以看出,有部分长期存活的对象在YoungGC次数超过设置的GC年龄阀值(设置的5岁)后,进入了老年代。

从 FGC 这列可以看出,Survivor 区合理设置后,再没有发生过 FullGC 了。

五、使用 MAT 分析OOM问题

对于排查 OOM 问题、分析程序堆内存使用情况,最好的方式就是分析堆转储,堆转储,包含了堆现场全貌和线程栈信息。这节就来看看如何使用MAT分析OOM问题。

1、运行示例程序

准备如下两个测试类:

 1 package com.lyyzoo.test.jvm;
 2 
 3 public class OomService {
 4 
 5     private List<String> data = new ArrayList<>();
 6 
 7     public void addData() {
 8         //往同一个ArrayList中不断加入大小为10KB的字符串
 9         data.add(IntStream.rangeClosed(1, 10_000)
10                 .mapToObj(__ -> "A")
11                 .collect(Collectors.joining("")));
12     }
13
 1 package com.lyyzoo.test.jvm;
 2 
 3 public class OomMain {
 4     public static void main(String[] args) {
 5         OomService service = new OomService();
 6 
 7         while (true) {
 8             service.addData();
 9         }
10     }
11 }

设置如下JVM参数:

-Xms200M
-Xmx200M
-Xmn100M
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=./dump.hprof
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:./gc.log 

运行程序后报OOM异常:

2、MAT 分析OOM问题的思路

对于线上运行的程序,如果我们不能通过日志快速定位出OOM的根源,一般就可以使用MAT来分析OOM的问题。

使用 MAT 分析 OOM 问题,一般可以按照以下思路进行:

  • 通过支配树功能或直方图功能查看消耗内存最大的类型,来分析内存泄露的大概原因;
  • 查看那些消耗内存最大的类型、详细的对象明细列表,以及它们的引用链,来定位内存泄露的具体点;
  • 配合查看对象属性的功能,可以脱离源码看到对象的各种属性的值和依赖关系,帮助我们理清程序逻辑和参数;
  • 辅助使用查看线程栈来看 OOM 问题是否和过多线程有关,甚至可以在线程栈看到 OOM 最后一刻出现异常的线程。

如果dump出来的内存快照很大,比如有几个G,务必在启动MAT之前,先在配置文件(MemoryAnalyzer.ini)里给MAT本身设置—下堆内存大小(默认为1024m),比如设置为4个G,或者8个G。

3、总览图 — 快速分析OOM问题

使用MAT打开堆转储文件 dump.hprof,打开后先进入的是概览信息界面:

从饼图可以看出,明显有对象占用了大量内存,然后再看 Problem Suspect1,已经说明了 main 线程通过局部变量占据了 99.42% 内存的对象,而且是 java.lang.Object[] 数组占据了大量内存。

点击 Details 进去查看详细的说明,从 “Accumulated Objects in Dominator Tree” 支配树可以看出,main 线程引用了 OomService 对象,OomService 引用了一个 ArrayList 对象,然后 ArrayList 存储了大量 String 对象。这里基本上就能分析出OOM的根源了。

再点击 See stacktrace 看看线程栈基本就能定位到问题代码了。

4、直方图 — 定位根源

工具栏的第二个按钮可以打开直方图,直方图按照类型进行分组,列出了每个类有多少个实例,以及占用的内存。

可以看到,char[] 字节数组占用内存最多,对象数量也很多,第二位的 String 对象数量也非常多,有 9791 个,从这大概可以猜出应该是创建了大量的 String 对象。

在 char[] 上点击右键,选择 List objects -> with incoming references,就可以列出所有的 char[] 实例,以及每个 char[] 的整个引用关系链:

随机展开一个 char[],如下图所示:

右侧框中可以看到整个引用链,左侧的框可以查看每一个实例的内部属性。

通过这个引用链可以发现是 String 对象引用了 char[] 数组(String 的内部结构就是一个 char[] 数组),说明创建了大量的 String 对象;然后 String 对象又被 ArrayList 的 Object[] 数组引用着,说明是大量 String 对象放入了 ArrayList 中,然后这个 ArrayList 又被 OomService 的 data 变量引用着。到这里就定位出了引发OOM的类了。

Retained Heap(深堆)代表对象本身和对象关联的对象占用的内存,Shallow Heap(浅堆)代表对象本身占用的内存。比如,OomService 中的 data 这个 ArrayList 对象本身只有 16 字节,但是其所有关联的对象占用了 130+MB 内存。

如果希望看到完整内容的话,可以右键选择 Copy->Value,把值复制到剪贴板或保存到文件中:

5、支配树 — 定位根源

其实,使用直方图定位 OomService,已经走了些弯路。可以点击工具栏中第三个按钮进入支配树界面。这个界面会按照对象保留的 Retained Heap 倒序直接列出占用内存最大的对象。

可以看到,第一位就是 OomService,整个路径是 OomSerice -> ArrayList -> Object[] -> String -> char[] 。

6、线程栈 — 分析代码

可以点击工具栏的第五个按钮,打开线程视图来分析 OomService 执行什么逻辑。可以看到 OomService 是 OomMain 的一个本地变量,然后 OomMain 调用了 OomService 的 addData 方法,然后 addData 方法里应该是通过 Stream 生成一个字符串放入 data 中的。

7、OQL—查询数据

点击工具栏的第四个按钮,来到 OQL 界面。在这个界面,我们可以使用类似 SQL 的语法,在 dump 中搜索数据。可以看到只创建了一个 OomService 实例,说明只有一个地方调用了 OomService 的方法。

然后可通过 List objects 功能搜索引用OomService 的对象:

可以看到其被 main 线程引用着:

六、使用 Arthas 分析高 CPU 问题

Arthas 是阿里开源的 Java 诊断工具,相比 JDK 内置的诊断工具,要更人性化,并且功能强大,可以实现许多问题的一键定位,而且可以一键反编译类查看源码,甚至是直接进行生产代码热修复,实现在一个工具内快速定位和修复问题的一站式服务。

Arthas 官方文档:https://alibaba.github.io/arthas/

1、运行示例程序

准备如下导致CPU负载高的代码:代码中创建了2个线程的线程池,提交的任务通过 BCryptPasswordEncoder 对一个长字符串加密,这个是非常消耗CPU的。

 1 package com.lyyzoo.test.jvm;
 2 
 3 import java.util.concurrent.ExecutorService;
 4 import java.util.concurrent.Executors;
 5 import java.util.concurrent.Future;
 6 import java.util.stream.Collectors;
 7 import java.util.stream.IntStream;
 8 
 9 import org.apache.commons.lang3.RandomUtils;
10 import org.springframework.security.crypto.bcrypt.BCryptPasswordEncoder;
11 
12 public class CpuService {
13     private BCryptPasswordEncoder encoder = new BCryptPasswordEncoder();
14     private ExecutorService executor = Executors.newFixedThreadPool(2);
15 
16     public void doTask() throws Exception {
17         while (true) {
18             randomEncode(RandomUtils.nextInt(0, 10000));
19         }
20     }
21 
22     private void randomEncode(Integer size) throws Exception {
23         String payload = IntStream.rangeClosed(1, size).mapToObj(__ -> "A").collect(Collectors.joining());
24         Future<String> f1 = executor.submit(() -> {
25             return encoder.encode(payload);
26         });
27         Future<String> f2 = executor.submit(() -> {
28             return encoder.encode(payload);
29         });
30 
31         f1.get();
32         f2.get();
33     }
34 }
1 public class CpuMain {
2     private static CpuService service = new CpuService();
3 
4     public static void main(String[] args) throws Exception {
5         service.doTask();
6     }
7 }

2、启动 Arthas

首先,下载 Arthas:https://arthas.aliyun.com/arthas-boot.jar

然后把程序先运行起来,再运行 arthas:java -jar arthas-boot.jar

启动后,直接找到我们要排查的 JVM 进程,然后可以看到 Arthas 附加进程成功:

输入 help 命令,可以看到所有支持的命令列表。这里主要会用到 dashboard、thread、jad、watch 等命令,来定位高CPU的问题。

3、dashboard — 展示整体情况

dashboard 命令整体展示了进程所有线程、内存、GC 等情况,可以明显看到两个CPU占用很高的线程,从线程名字来看应该是线程池的线程。

4、thread — 查看高CPU的线程

接下来,查看最繁忙的线程在执行的线程栈,可以使用 thread -n 命令。这里,我们查看下最忙的 2 个线程:从线程栈可以看出,应该就是 CpuService 的 randomEncode 方法调用 BCryptPasswordEncoder 的 encode 方法导致CPU负载高的。

5、watch — 监控参数

如果想要观察方法的入参和出参,可以用 watch 命令来观察:

6、jad — 反编译

前面已经分析出CPU负载高的位置是 CpuService 的 randomEncode 了,那么通过 jad 反编译来看看源码长什么样子,方便我们进一步定位问题。

7、redefine — 重载类

如果我们想做线上调试,又不想在本地改代码,打印日志,再提交到服务器,再重启服务测试,那我们可以结合 arthas 的 jad、mc、redefine 来动态重定义类。

① 首先用 jad 把源文件下载下来

然后修改下源码:添加了一行输出日志

② 使用 mc 命令反编译源文件

反编译后会生成对应的 class 文件:

③ 使用 redefine 重载类

就可以看到控制台已经在输出我们打印的日志了:

需要额外说明的是,由于 monitor、trace、watch 等命令是通过字节码增强技术来实现的,会在指定类的方法中插入一些切面来实现数据统计和观测,因此诊断结束要执行 shutdown 来还原类或方法字节码,然后退出 Arthas。

参考

本文是学习、参考了如下课程,再通过自己的总结和实践总结而来。如果想了解更多深入的细节,建议阅读原著。

从 0 开始带你成为JVM实战高手

极客时间:Java性能调优实战

posted on 2020-10-13 12:58  bojiangzhou  阅读(9638)  评论(1编辑  收藏  举报