这篇文章中介绍下如何使用 JDK 自带工具来分析和定位 Java 程序的问题。
使用 JDK 自带工具查看 JVM 情况
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 提供的工具,来观察分析这个测试程序了。如果您正在学习Spring Cloud,推荐一个经典教程(含Spring Cloud Alibaba):https://blog.didispace.com/spring-cloud-learning/
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。最近整理了一份最新的面试资料,里面收录了2021年各个大厂的面试题,打算跳槽的小伙伴不要错过,点击领取吧!
因此,当我们怀疑 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 定时输出的特性,可以方便我们持续观察程序的各项指标。如果您正在学习Spring Cloud,推荐一个经典教程(含Spring Cloud Alibaba):https://blog.didispace.com/spring-cloud-learning/
继续来到线程面板可以看到,大量以 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:
jcmd24404 VM.native_memory detail
可以看到,有 16 个可疑线程,每一个线程保留了 262144KB 内存,也就是 256MB(通过下图红框可以看到,使用关键字 262144KB for Thread Stack from 搜索到了 16 个结果):
其实,ThreadStackSize 参数的单位是 KB,所以我们如果要设置线程栈 256KB,那么应该设置 256 而不是 256k。重新设置正确的参数后,使用 jcmd 再次验证下:
除了用于查看 NMT 外,jcmd 还有许多功能。我们可以通过 help,看到它的所有功能:
jcmd24781 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
关注后端面试那些事,回复【JAVA宝典】
获取最新免费Java资料大全