性能文章>6 个 Java 工具,轻松分析定位 JVM 问题!>

6 个 Java 工具,轻松分析定位 JVM 问题!转载

1月前
179322

你可能一开始会比较畏惧使用复杂的工具去排查问题,又或者是打开了工具感觉无从下手,但是随着实践越来越多,对 Java 程序和各种框架的运作越来越熟悉,你会发现使用这些工具越来越顺手。

这篇文章中介绍下如何使用 JDK 自带工具来分析和定位 Java 程序的问题。

使用 JDK 自带工具查看 JVM 情况

JDK 自带了很多命令行甚至是图形界面工具,帮助我们查看 JVM 的一些信息。比如,在我的机器上运行 ls 命令,可以看到 JDK 8 提供了非常多的工具或程序:

接下来,我会与你介绍些常用的监控工具。你也可以先通过下面这张图了解下各种工具的基本作用:

为了测试这些工具,我们先来写一段代码:启动 10 个死循环的线程,每个线程分配一个 10MB 左右的字符串,然后休眠 10 秒。可以想象到,这个程序会对 GC 造成压力:


//启动10个线程
IntStream.rangeClosed(110).mapToObj(i -> new Thread(() -> {
    while (true) {
        //每一个线程都是一个死循环,休眠10秒,打印10M数据
        String payload = IntStream.rangeClosed(110000000)
                .mapToObj(__ -> "a")
                .collect(Collectors.joining("")) + UUID.randomUUID().toString();
        try {
            TimeUnit.SECONDS.sleep(10);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println(payload.length());
    }
})).forEach(Thread::start);


TimeUnit.HOURS.sleep(1);

修改 pom.xml,配置 spring-boot-maven-plugin 插件打包的 Java 程序的 main 方法类:


<plugin>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-maven-plugin</artifactId>
    <configuration>
        <mainClass>org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication
        </mainClass>
    </configuration>
</plugin>

然后使用 java -jar 启动进程,设置 JVM 参数,让堆最小最大都是 1GB:

java -jar common-mistakes-0.0.1-SNAPSHOT.jar -Xms1g -Xmx1g

完成这些准备工作后,我们就可以使用 JDK 提供的工具,来观察分析这个测试程序了。

jps

首先,使用 jps 得到 Java 进程列表,这会比使用 ps 来的方便:


➜  ~ jps
12707
22261 Launcher
23864 common-mistakes-0.0.1-SNAPSHOT.jar
15608 RemoteMavenServer36
23243 Main
23868 Jps
22893 KotlinCompileDaemon

jinfo

然后,可以使用 jinfo 打印 JVM 的各种参数:


➜  ~ jinfo 23864
Java System Properties:
#Wed Jan 29 12:49:47 CST 2020
...
user.name=zhuye
path.separator=\:
os.version=10.15.2
java.runtime.name=Java(TM) SE Runtime Environment
file.encoding=UTF-8
java.vm.name=Java HotSpot(TM) 64-Bit Server VM
...


VM Flags:
-XX:CICompilerCount
=4 -XX:ConcGCThreads=2 -XX:G1ConcRefinementThreads=8 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=268435456 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=4294967296 -XX:MaxNewSize=2576351232 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=5835340 -XX:NonProfiledCodeHeapSize=122911450 -XX:ProfiledCodeHeapSize=122911450 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC


VM Arguments:
java_command: common-mistakes-0.0.1-SNAPSHOT.jar -Xms1g -Xmx1g
java_class_path (initial): common-mistakes-0.0.1-SNAPSHOT.jar
Launcher Type: SUN_STANDARD

查看第 15 行和 19 行可以发现,我们设置 JVM 参数的方式不对,-Xms1g 和 -Xmx1g 这两个参数被当成了 Java 程序的启动参数,整个 JVM 目前最大内存是 4GB 左右,而不是 1GB。

因此,当我们怀疑 JVM 的配置很不正常的时候,要第一时间使用工具来确认参数。除了使用工具确认 JVM 参数外,你也可以打印 VM 参数和程序参数:


System.out.println("VM options");
System.out.println(ManagementFactory.getRuntimeMXBean().getInputArguments().stream().collect(Collectors.joining(System.lineSeparator())));
System.out.println("Program arguments");
System.out.println(Arrays.stream(args).collect(Collectors.joining(System.lineSeparator())));

把 JVM 参数放到 -jar 之前,重新启动程序,可以看到如下输出,从输出也可以确认这次 JVM 参数的配置正确了:

➜  target git:(master) ✗ java -Xms1g -Xmx1g -jar common-mistakes-0.0.1-SNAPSHOT.jar test
VM options
-Xms1g
-Xmx1g
Program arguments
test

jvisualvm

然后,启动另一个重量级工具 jvisualvm 观察一下程序,可以在概述面板再次确认 JVM 参数设置成功了:

继续观察监视面板可以看到,JVM 的 GC 活动基本是 10 秒发生一次,堆内存在 250MB 到 900MB 之间波动,活动线程数是 22。我们可以在监视面板看到 JVM 的基本情况,也可以直接在这里进行手动 GC 和堆 Dump 操作:

jconsole如果希望看到各个内存区的 GC 曲线图,可以使用 jconsole 观察。jconsole 也是一个综合性图形界面监控工具,比 jvisualvm 更方便的一点是,可以用曲线的形式监控各种数据,包括 MBean 中的属性值:

jstat

同样,如果没有条件使用图形界面(毕竟在 Linux 服务器上,我们主要使用命令行工具),又希望看到 GC 趋势的话,我们可以使用 jstat 工具。

jstat 工具允许以固定的监控频次输出 JVM 的各种监控指标,比如使用 -gcutil 输出 GC 和内存占用汇总信息,每隔 5 秒输出一次,输出 100 次,可以看到 Young GC 比较频繁,而 Full GC 基本 10 秒一次:


➜  ~ jstat -gcutil 23940 5000 100
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
  0.00 100.00   0.36  87.63  94.30  81.06    539   14.021    33    3.972   837    0.976   18.968
  0.00 100.00   0.60  69.51  94.30  81.06    540   14.029    33    3.972   839    0.978   18.979
  0.00   0.00   0.50  99.81  94.27  81.03    548   14.143    34    4.002   840    0.981   19.126
  0.00 100.00   0.59  70.47  94.27  81.03    549   14.177    34    4.002   844    0.985   19.164
  0.00 100.00   0.57  99.85  94.32  81.09    550   14.204    34    4.002   845    0.990   19.196
  0.00 100.00   0.65  77.69  94.32  81.09    559   14.469    36    4.198   847    0.993   19.659
  0.00 100.00   0.65  77.69  94.32  81.09    559   14.469    36    4.198   847    0.993   19.659
  0.00 100.00   0.70  35.54  94.32  81.09    567   14.763    37    4.378   853    1.001   20.142
  0.00 100.00   0.70  41.22  94.32  81.09    567   14.763    37    4.378   853    1.001   20.142
  0.00 100.00   1.89  96.76  94.32  81.09    574   14.943    38    4.487   859    1.007   20.438
  0.00 100.00   1.39  39.20  94.32  81.09    575   14.946    38    4.487   861    1.010   20.442

其中,S0 表示 Survivor0 区占用百分比,S1 表示 Survivor1 区占用百分比,E 表示 Eden 区占用百分比,O 表示老年代占用百分比,M 表示元数据区占用百分比,YGC 表示年轻代回收次数,YGCT 表示年轻代回收耗时,FGC 表示老年代回收次数,FGCT 表示老年代回收耗时。

jstat 命令的参数众多,包含 -class、-compiler、-gc 等。Java 8、Linux/Unix 平台 jstat 工具的完整介绍,你可以查看这里。jstat 定时输出的特性,可以方便我们持续观察程序的各项指标。

继续来到线程面板可以看到,大量以 Thread 开头的线程基本都是有节奏的 10 秒运行一下,其他时间都在休眠,和我们的代码逻辑匹配:

点击面板的线程 Dump 按钮,可以查看线程瞬时的线程栈:

jstack

通过命令行工具 jstack,也可以实现抓取线程栈的操作:


➜  ~ jstack 23940
2020-01-29 13:08:15
Full thread dump Java HotSpot(TM) 64-Bit Server VM (11.0.3+12-LTS mixed mode):

...

"main" #1 prio
=5 os_prio=31 cpu=440.66ms elapsed=574.86s tid=0x00007ffdd9800000 nid=0x2803 waiting on condition  [0x0000700003849000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
  at java.lang.Thread.sleep(java.base@11.0.3/Native Method)
  at java.lang.Thread.sleep(java.base@11.0.3/Thread.java:339)
  at java.util.concurrent.TimeUnit.sleep(java.base@11.0.3/TimeUnit.java:446)
  at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication.main(CommonMistakesApplication.java:41)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.3/Native Method)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.3/NativeMethodAccessorImpl.java:62)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.3/DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(java.base@11.0.3/Method.java:566)
  at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
  at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
  at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
  at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)

"Thread-1" #13 prio=5 os_prio=31 cpu=17851.77ms elapsed=574.41s tid=0x00007ffdda029000 nid=0x9803 waiting on condition  [0x000070000539d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
  at java.lang.Thread.sleep(java.base@11.0.3/Native Method)
  at java.lang.Thread.sleep(java.base@11.0.3/Thread.java:339)
  at java.util.concurrent.TimeUnit.sleep(java.base@11.0.3/TimeUnit.java:446)
  at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication.lambda$null$1(CommonMistakesApplication.java:33)
  at org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication$$Lambda$41/0x00000008000a8c40.run(Unknown Source)
  at java.lang.Thread.run(java.base@11.0.3/Thread.java:834)


...

抓取后可以使用类似fastthread(https://fastthread.io/)这样的在线分析工具来分析线程栈。

jcmd

最后,我们来看一下 Java HotSpot 虚拟机的 NMT 功能。

通过 NMT,我们可以观察细粒度内存使用情况,设置 -XX:NativeMemoryTracking=summary/detail 可以开启 NMT 功能,开启后可以使用 jcmd 工具查看 NMT 数据。

我们重新启动一次程序,这次加上 JVM 参数以 detail 方式开启 NMT:

-Xms1g -Xmx1g -XX:ThreadStackSize=256k -XX:NativeMemoryTracking=detail

在这里,我们还增加了 -XX:ThreadStackSize 参数,并将其值设置为 256k,也就是期望把线程栈设置为 256KB。我们通过 NMT 观察一下设置是否成功。

启动程序后执行如下 jcmd 命令,以概要形式输出 NMT 结果。可以看到,当前有 32 个线程,线程栈总共保留了差不多 4GB 左右的内存。我们明明配置线程栈最大 256KB 啊,为什么会出现 4GB 这么夸张的数字呢,到底哪里出了问题呢?


➜  ~ jcmd 24404 VM.native_memory summary
24404:


Native Memory Tracking:


Total: reserved=6635310KB, committed=5337110KB
-                 Java Heap (reserved=1048576KB, committed=1048576KB)
                            (mmap: reserved=1048576KB, committed=1048576KB)


-                     Class (reserved=1066233KB, committed=15097KB)
                            (classes #902)
                            (malloc=9465KB #908)
                            (mmap: reserved=1056768KB, committed=5632KB)


-                    Thread (reserved=4209797KB, committed=4209797KB)
                            (thread #32)
                            (stack: reserved=4209664KB, committed=4209664KB)
                            (malloc=96KB #165)
                            (arena=37KB #59)


-                      Code (reserved=249823KB, committed=2759KB)
                            (malloc=223KB #730)
                            (mmap: reserved=249600KB, committed=2536KB)


-                        GC (reserved=48700KB, committed=48700KB)
                            (malloc=10384KB #135)
                            (mmap: reserved=38316KB, committed=38316KB)


-                  Compiler (reserved=186KB, committed=186KB)
                            (malloc=56KB #105)
                            (arena=131KB #7)


-                  Internal (reserved=9693KB, committed=9693KB)
                            (malloc=9661KB #2585)
                            (mmap: reserved=32KB, committed=32KB)


-                    Symbol (reserved=2021KB, committed=2021KB)
                            (malloc=1182KB #334)
                            (arena=839KB #1)


-    Native Memory Tracking (reserved=85KB, committed=85KB)
                            (malloc=5KB #53)
                            (tracking overhead=80KB)


-               Arena Chunk (reserved=196KB, committed=196KB)
                            (malloc=196KB)            

重新以 VM.native_memory detail 参数运行 jcmd:

jcmd 24404 VM.native_memory detail

可以看到,有 16 个可疑线程,每一个线程保留了 262144KB 内存,也就是 256MB(通过下图红框可以看到,使用关键字 262144KB for Thread Stack from 搜索到了 16 个结果):

其实,ThreadStackSize 参数的单位是 KB,所以我们如果要设置线程栈 256KB,那么应该设置 256 而不是 256k。重新设置正确的参数后,使用 jcmd 再次验证下:

除了用于查看 NMT 外,jcmd 还有许多功能。我们可以通过 help,看到它的所有功能:

jcmd 24781 help

除了 jps、jinfo、jcmd、jstack、jstat、jconsole、jvisualvm 外,JDK 中还有一些工具,你可以通过官方文档查看完整介绍。

官方文档:https://docs.oracle.com/javase/8/docs/technotes/tools/

文章来源:https://time.geekbang.org/column/article/224816

往期推荐

2万字详解,彻底讲透 全文搜索引擎 Elasticsearch


Oracle官宣:腾讯 JDK 18 国内第一,贡献度!


如何解决 IDEA 占用大量 CPU 导致的卡顿问题?这顿操作猛如虎!

作者:朱晔

文章来源:微信公众号

原文链接:https://mp.weixin.qq.com/s/CwxPpnq3TdFbSxABBr_s3w

分类:
标签:
请先登录,再评论

写的真够详细

1月前

👍

1月前

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得