分析定位JVM问题JDK自带工具

目录

常用的监控工具

jps

jinfo

jvisualvm

jstat

jstack

jcmd

---

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

常用的监控工具

启动10个死循环的线程，每个线程分配一个10MB左右的字符串，然后休眠10秒，程序会对GC造成压力：

//启动10个线程
IntStream.rangeClosed(1, 10).mapToObj(i -> new Thread(() -> {
    while (true) {
        //每一个线程都是一个死循环，休眠10秒，打印10M数据
        String payload = IntStream.rangeClosed(1, 10000000)
                .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进程列表

➜  ~ 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参数外，也可以打印JVM参数和程序参数

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之前，重新启动程序，看到如下输出。

➜  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/