6 個(gè) Java 工具，輕松分析定位 JVM 問(wèn)題！

大家好，我是小富~

你可能一開始會(huì)比較畏懼使用復(fù)雜的工具去排查問(wèn)題，又或者是打開了工具感覺無(wú)從下手，但是隨著實(shí)踐越來(lái)越多，對(duì) Java 程序和各種框架的運(yùn)作越來(lái)越熟悉，你會(huì)發(fā)現(xiàn)使用這些工具越來(lái)越順手。

這篇文章中介紹下如何使用 JDK 自帶工具來(lái)分析和定位 Java 程序的問(wèn)題。

使用 JDK 自帶工具查看 JVM 情況

JDK 自帶了很多命令行甚至是圖形界面工具，幫助我們查看 JVM 的一些信息。比如，在我的機(jī)器上運(yùn)行 ls 命令，可以看到 JDK 8 提供了非常多的工具或程序：

接下來(lái)，我會(huì)與你介紹些常用的監(jiān)控工具。你也可以先通過(guò)下面這張圖了解下各種工具的基本作用：

為了測(cè)試這些工具，我們先來(lái)寫一段代碼：?jiǎn)?dòng) 10 個(gè)死循環(huán)的線程，每個(gè)線程分配一個(gè) 10MB 左右的字符串，然后休眠 10 秒?？梢韵胂蟮?，這個(gè)程序會(huì)對(duì) GC 造成壓力：

//啟動(dòng)10個(gè)線程
IntStream.rangeClosed(1,?10).mapToObj(i?->?new?Thread(()?->?{
????while?(true)?{
????????//每一個(gè)線程都是一個(gè)死循環(huán)，休眠10秒，打印10M數(shù)據(jù)
????????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 方法類：

????org.springframework.boot
????spring-boot-maven-plugin
????
????????org.geekbang.time.commonmistakes.troubleshootingtools.jdktool.CommonMistakesApplication
????????
????

然后使用 java -jar 啟動(dòng)進(jìn)程，設(shè)置 JVM 參數(shù)，讓堆最小最大都是 1GB：

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

完成這些準(zhǔn)備工作后，我們就可以使用 JDK 提供的工具，來(lái)觀察分析這個(gè)測(cè)試程序了。

jps

首先，使用 jps 得到 Java 進(jìn)程列表，這會(huì)比使用 ps 來(lái)的方便：

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

jinfo

然后，可以使用 jinfo 打印 JVM 的各種參數(shù)：

???~?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 行可以發(fā)現(xiàn)，我們?cè)O(shè)置 JVM 參數(shù)的方式不對(duì)，-Xms1g 和 -Xmx1g 這兩個(gè)參數(shù)被當(dāng)成了 Java 程序的啟動(dòng)參數(shù)，整個(gè) JVM 目前最大內(nèi)存是 4GB 左右，而不是 1GB。

因此，當(dāng)我們懷疑 JVM 的配置很不正常的時(shí)候，要第一時(shí)間使用工具來(lái)確認(rèn)參數(shù)。除了使用工具確認(rèn) JVM 參數(shù)外，你也可以打印 VM 參數(shù)和程序參數(shù)：

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 參數(shù)放到 -jar 之前，重新啟動(dòng)程序，可以看到如下輸出，從輸出也可以確認(rèn)這次 JVM 參數(shù)的配置正確了：

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

jvisualvm

然后，啟動(dòng)另一個(gè)重量級(jí)工具 jvisualvm 觀察一下程序，可以在概述面板再次確認(rèn) JVM 參數(shù)設(shè)置成功了：

繼續(xù)觀察監(jiān)視面板可以看到，JVM 的 GC 活動(dòng)基本是 10 秒發(fā)生一次，堆內(nèi)存在 250MB 到 900MB 之間波動(dòng)，活動(dòng)線程數(shù)是 22。我們可以在監(jiān)視面板看到 JVM 的基本情況，也可以直接在這里進(jìn)行手動(dòng) GC 和堆 Dump 操作：

jconsole如果希望看到各個(gè)內(nèi)存區(qū)的 GC 曲線圖，可以使用 jconsole 觀察。jconsole 也是一個(gè)綜合性圖形界面監(jiān)控工具，比 jvisualvm 更方便的一點(diǎn)是，可以用曲線的形式監(jiān)控各種數(shù)據(jù)，包括 MBean 中的屬性值：

jstat

同樣，如果沒(méi)有條件使用圖形界面（畢竟在 Linux 服務(wù)器上，我們主要使用命令行工具），又希望看到 GC 趨勢(shì)的話，我們可以使用 jstat 工具。

jstat 工具允許以固定的監(jiān)控頻次輸出 JVM 的各種監(jiān)控指標(biāo)，比如使用 -gcutil 輸出 GC 和內(nèi)存占用匯總信息，每隔 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 區(qū)占用百分比，S1 表示 Survivor1 區(qū)占用百分比，E 表示 Eden 區(qū)占用百分比，O 表示老年代占用百分比，M 表示元數(shù)據(jù)區(qū)占用百分比，YGC 表示年輕代回收次數(shù)，YGCT 表示年輕代回收耗時(shí)，F(xiàn)GC 表示老年代回收次數(shù)，F(xiàn)GCT 表示老年代回收耗時(shí)。

”

jstat 命令的參數(shù)眾多，包含 -class、-compiler、-gc 等。Java 8、Linux/Unix 平臺(tái) jstat 工具的完整介紹，你可以查看這里。jstat 定時(shí)輸出的特性，可以方便我們持續(xù)觀察程序的各項(xiàng)指標(biāo)。

繼續(xù)來(lái)到線程面板可以看到，大量以 Thread 開頭的線程基本都是有節(jié)奏的 10 秒運(yùn)行一下，其他時(shí)間都在休眠，和我們的代碼邏輯匹配：

點(diǎn)擊面板的線程 Dump 按鈕，可以查看線程瞬時(shí)的線程棧：

jstack

通過(guò)命令行工具 jstack，也可以實(shí)現(xiàn)抓取線程棧的操作：

???~?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/）這樣的在線分析工具來(lái)分析線程棧。

jcmd

最后，我們來(lái)看一下 Java HotSpot 虛擬機(jī)的 NMT 功能。

通過(guò) NMT，我們可以觀察細(xì)粒度內(nèi)存使用情況，設(shè)置 -XX:NativeMemoryTracking=summary/detail 可以開啟 NMT 功能，開啟后可以使用 jcmd 工具查看 NMT 數(shù)據(jù)。

我們重新啟動(dòng)一次程序，這次加上 JVM 參數(shù)以 detail 方式開啟 NMT：

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

在這里，我們還增加了 -XX:ThreadStackSize 參數(shù)，并將其值設(shè)置為 256k，也就是期望把線程棧設(shè)置為 256KB。我們通過(guò) NMT 觀察一下設(shè)置是否成功。

啟動(dòng)程序后執(zhí)行如下 jcmd 命令，以概要形式輸出 NMT 結(jié)果?？梢钥吹?，當(dāng)前有 32 個(gè)線程，線程?？偣脖Ａ袅瞬畈欢?4GB 左右的內(nèi)存。我們明明配置線程棧最大 256KB 啊，為什么會(huì)出現(xiàn) 4GB 這么夸張的數(shù)字呢，到底哪里出了問(wèn)題呢？

???~?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 參數(shù)運(yùn)行 jcmd：

jcmd?24404?VM.native_memory?detail

可以看到，有 16 個(gè)可疑線程，每一個(gè)線程保留了 262144KB 內(nèi)存，也就是 256MB（通過(guò)下圖紅框可以看到，使用關(guān)鍵字 262144KB for Thread Stack from 搜索到了 16 個(gè)結(jié)果）：

其實(shí)，ThreadStackSize 參數(shù)的單位是 KB，所以我們?nèi)绻O(shè)置線程棧 256KB，那么應(yīng)該設(shè)置 256 而不是 256k。重新設(shè)置正確的參數(shù)后，使用 jcmd 再次驗(yàn)證下：

除了用于查看 NMT 外，jcmd 還有許多功能。我們可以通過(guò) help，看到它的所有功能：

jcmd?24781?help

除了 jps、jinfo、jcmd、jstack、jstat、jconsole、jvisualvm 外，JDK 中還有一些工具，你可以通過(guò)官方文檔查看完整介紹。

“

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

”

文章來(lái)源：https://time.geekbang.org/column/article/224816

我是小富～，如果對(duì)你有用在看、關(guān)注支持下，咱們下期見~