進(jìn)行GC性能調(diào)優(yōu)時(shí), 需要明確了解, 當(dāng)前的GC行為對(duì)系統(tǒng)和用戶(hù)有多大的影響。有多種監(jiān)控GC的工具和方法, 本章將逐一介紹常用的工具。

JVM 在程序執(zhí)行的過(guò)程中, 提供了GC行為的原生數(shù)據(jù)。那么, 我們就可以利用這些原生數(shù)據(jù)來(lái)生成各種報(bào)告。原生數(shù)據(jù)(raw data) 包括:

• 各個(gè)內(nèi)存池的當(dāng)前使用情況,
• 各個(gè)內(nèi)存池的總?cè)萘?
• 每次GC暫停的持續(xù)時(shí)間,
• GC暫停在各個(gè)階段的持續(xù)時(shí)間。

可以通過(guò)這些數(shù)據(jù)算出各種指標(biāo), 例如: 程序的內(nèi)存分配率, 提升率等等。本章主要介紹如何獲取原生數(shù)據(jù)。 后續(xù)的章節(jié)將對(duì)重要的派生指標(biāo)(derived metrics)展開(kāi)討論, 并引入GC性能相關(guān)的話(huà)題。

1，JMX API

從 JVM 運(yùn)行時(shí)獲取GC行為數(shù)據(jù), 最簡(jiǎn)單的辦法是使用標(biāo)準(zhǔn) JMX API 接口. JMX是獲取 JVM內(nèi)部運(yùn)行時(shí)狀態(tài)信息 的標(biāo)準(zhǔn)API. 可以編寫(xiě)程序代碼, 通過(guò) JMX API 來(lái)訪(fǎng)問(wèn)本程序所在的JVM，也可以通過(guò)JMX客戶(hù)端執(zhí)行(遠(yuǎn)程)訪(fǎng)問(wèn)。

最常見(jiàn)的 JMX客戶(hù)端是 JConsole 和 JVisualVM (可以安裝各種插件,十分強(qiáng)大)。兩個(gè)工具都是標(biāo)準(zhǔn)JDK的一部分, 而且很容易使用. 如果使用的是 JDK 7u40 及更高版本, 還可以使用另一個(gè)工具: Java Mission Control( 大致翻譯為 Java控制中心, jmc.exe)。

JVisualVM安裝MBeans插件的步驟: 通過(guò) 工具(T) — 插件(G) — 可用插件 — 勾選VisualVM-MBeans — 安裝 — 下一步 — 等待安裝完成…… 其他插件的安裝過(guò)程基本一致。

所有 JMX客戶(hù)端都是獨(dú)立的程序,可以連接到目標(biāo)JVM上。目標(biāo)JVM可以在本機(jī), 也可能是遠(yuǎn)端JVM. 如果要連接遠(yuǎn)端JVM, 則目標(biāo)JVM啟動(dòng)時(shí)必須指定特定的環(huán)境變量,以開(kāi)啟遠(yuǎn)程JMX連接/以及端口號(hào)。 示例如下:

java -Dcom.sun.management.jmxremote.port=5432 com.yourcompany.YourApp

在此處, JVM 打開(kāi)端口5432以支持JMX連接。

通過(guò) JVisualVM 連接到某個(gè)JVM以后, 切換到 MBeans 標(biāo)簽, 展開(kāi) “java.lang/GarbageCollector” . 就可以看到GC行為信息, 下圖是 JVisualVM 中的截圖:

下圖是Java Mission Control 中的截圖:

從以上截圖中可以看到兩款垃圾收集器。其中一款負(fù)責(zé)清理年輕代(PS Scavenge)，另一款負(fù)責(zé)清理老年代(PS MarkSweep); 列表中顯示的就是垃圾收集器的名稱(chēng)?？梢钥吹?, jmc 的功能和展示數(shù)據(jù)的方式更強(qiáng)大。

對(duì)所有的垃圾收集器, 通過(guò) JMX API 獲取的信息包括:

• CollectionCount : 垃圾收集器執(zhí)行的GC總次數(shù),
• CollectionTime: 收集器運(yùn)行時(shí)間的累計(jì)。這個(gè)值等于所有GC事件持續(xù)時(shí)間的總和,
• LastGcInfo: 最近一次GC事件的詳細(xì)信息。包括 GC事件的持續(xù)時(shí)間(duration), 開(kāi)始時(shí)間(startTime) 和 結(jié)束時(shí)間(endTime), 以及各個(gè)內(nèi)存池在最近一次GC之前和之后的使用情況,
• MemoryPoolNames: 各個(gè)內(nèi)存池的名稱(chēng),
• Name: 垃圾收集器的名稱(chēng)
• ObjectName: 由JMX規(guī)范定義的 MBean的名字,,
• Valid: 此收集器是否有效。本人只見(jiàn)過(guò) “true“的情況 (^_^)

根據(jù)經(jīng)驗(yàn), 這些信息對(duì)GC的性能來(lái)說(shuō),不能得出什么結(jié)論. 只有編寫(xiě)程序, 獲取GC相關(guān)的 JMX 信息來(lái)進(jìn)行統(tǒng)計(jì)和分析。 在下文可以看到, 一般也不怎么關(guān)注 MBean , 但 MBean 對(duì)于理解GC的原理倒是挺有用的。

2，JVisualVM

JVisualVM 工具的 “VisualGC” 插件提供了基本的 JMX客戶(hù)端功能, 還實(shí)時(shí)顯示出 GC事件以及各個(gè)內(nèi)存空間的使用情況。

Visual GC 插件常用來(lái)監(jiān)控本機(jī)運(yùn)行的Java程序, 比如開(kāi)發(fā)者和性能調(diào)優(yōu)專(zhuān)家經(jīng)常會(huì)使用此插件, 以快速獲取程序運(yùn)行時(shí)的GC信息。

左側(cè)的圖表展示了各個(gè)內(nèi)存池的使用情況: Metaspace/永久代, 老年代, Eden區(qū)以及兩個(gè)存活區(qū)。

在右邊, 頂部的兩個(gè)圖表與 GC無(wú)關(guān), 顯示的是 JIT編譯時(shí)間 和 類(lèi)加載時(shí)間。下面的6個(gè)圖顯示的是內(nèi)存池的歷史記錄, 每個(gè)內(nèi)存池的GC次數(shù),GC總時(shí)間, 以及最大值，峰值, 當(dāng)前使用情況。

再下面是 HistoGram, 顯示了年輕代對(duì)象的年齡分布。至于對(duì)象的年齡監(jiān)控(objects tenuring monitoring), 本章不進(jìn)行講解。

與純粹的JMX工具相比, VisualGC 插件提供了更友好的界面, 如果沒(méi)有其他趁手的工具, 請(qǐng)選擇VisualGC. 本章接下來(lái)會(huì)介紹其他工具, 這些工具可以提供更多的信息, 以及更好的視角. 當(dāng)然, 在“Profilers(分析器)”一節(jié)中，也會(huì)介紹 JVisualVM 的適用場(chǎng)景 —— 如: 分配分析(allocation profiling), 所以我們絕不會(huì)貶低哪一款工具, 關(guān)鍵還得看實(shí)際情況。

3，jstat

jstat 也是標(biāo)準(zhǔn)JDK提供的一款監(jiān)控工具(Java Virtual Machine statistics monitoring tool),可以統(tǒng)計(jì)各種指標(biāo)。既可以連接到本地JVM,也可以連到遠(yuǎn)程JVM. 查看支持的指標(biāo)和對(duì)應(yīng)選項(xiàng)可以執(zhí)行 “jstat -options” 。例如:

+-----------------+---------------------------------------------------------------+
|     Option      |                          Displays...                          |
+-----------------+---------------------------------------------------------------+
|class            | Statistics on the behavior of the class loader                |
|compiler         | Statistics  on  the behavior of the HotSpot Just-In-Time com- |
|                 | piler                                                         |
|gc               | Statistics on the behavior of the garbage collected heap      |
|gccapacity       | Statistics of the capacities of  the  generations  and  their |
|                 | corresponding spaces.                                         |
|gccause          | Summary  of  garbage collection statistics (same as -gcutil), |
|                 | with the cause  of  the  last  and  current  (if  applicable) |
|                 | garbage collection events.                                    |
|gcnew            | Statistics of the behavior of the new generation.             |
|gcnewcapacity    | Statistics of the sizes of the new generations and its corre- |
|                 | sponding spaces.                                              |
|gcold            | Statistics of the behavior of the old and  permanent  genera- |
|                 | tions.                                                        |
|gcoldcapacity    | Statistics of the sizes of the old generation.                |
|gcpermcapacity   | Statistics of the sizes of the permanent generation.          |
|gcutil           | Summary of garbage collection statistics.                     |
|printcompilation | Summary of garbage collection statistics.                     |
+-----------------+---------------------------------------------------------------+

jstat 對(duì)于快速確定GC行為是否健康非常有用。啟動(dòng)方式為: “jstat -gc -t PID 1s” , 其中,PID 就是要監(jiān)視的Java進(jìn)程ID?？梢酝ㄟ^(guò) jps 命令查看正在運(yùn)行的Java進(jìn)程列表。

jps
jstat -gc -t 2428 1s

以上命令的結(jié)果, 是 jstat 每秒向標(biāo)準(zhǔn)輸出輸出一行新內(nèi)容, 比如:

Timestamp  S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
200.0       8448.0 8448.0 8448.0  0.0   67712.0  67712.0   169344.0   169344.0  21248.0 20534.3 3072.0 2807.7     34    0.720  658   133.684  134.404
201.0      8448.0 8448.0 8448.0  0.0   67712.0  67712.0   169344.0   169343.2  21248.0 20534.3 3072.0 2807.7     34    0.720  662   134.712  135.432
202.0      8448.0 8448.0 8102.5  0.0   67712.0  67598.5   169344.0   169343.6  21248.0 20534.3 3072.0 2807.7     34    0.720  667   135.840  136.559
203.0      8448.0 8448.0 8126.3  0.0   67712.0  67702.2   169344.0   169343.6  21248.0 20547.2 3072.0 2807.7     34    0.720  669   136.178  136.898
204.0      8448.0 8448.0 8126.3  0.0   67712.0  67702.2   169344.0   169343.6  21248.0 20547.2 3072.0 2807.7     34    0.720  669   136.178  136.898
205.0      8448.0 8448.0 8134.6  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  671   136.234  136.954
206.0      8448.0 8448.0 8134.6  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  671   136.234  136.954
207.0      8448.0 8448.0 8154.8  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  673   136.289  137.009
208.0      8448.0 8448.0 8154.8  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  673   136.289  137.009

稍微解釋一下上面的內(nèi)容。參考 jstat manpage , 我們可以知道:

• jstat 連接到 JVM 的時(shí)間, 是JVM啟動(dòng)后的 200秒。此信息從第一行的 “Timestamp” 列得知。繼續(xù)看下一行, jstat 每秒鐘從JVM 接收一次信息, 也就是命令行參數(shù)中 “1s“ 的含義。
• 從第一行的 “YGC” 列得知年輕代共執(zhí)行了34次GC, 由 “FGC” 列得知整個(gè)堆內(nèi)存已經(jīng)執(zhí)行了 658次 full GC。
• 年輕代的GC耗時(shí)總共為 0.720 秒, 顯示在“YGCT” 這一列。
• Full GC 的總計(jì)耗時(shí)為 133.684 秒, 由“FGCT”列得知。 這立馬就吸引了我們的目光, 總的JVM 運(yùn)行時(shí)間只有 200 秒, 但其中有 66% 的部分被 Full GC 消耗了。

再看下一行, 問(wèn)題就更明顯了。

• 在接下來(lái)的一秒內(nèi)共執(zhí)行了 4 次 Full GC。參見(jiàn) “FGC“ 列.
• 這4次 Full GC 暫停占用了差不多 1秒的時(shí)間(根據(jù) FGCT列的差得知)。與第一行相比, Full GC 耗費(fèi)了928 毫秒, 即 92.8% 的時(shí)間。
• 根據(jù) “OC 和 “OU” 列得知, 整個(gè)老年代的空間為 169,344.0 KB (“OC“), 在 4 次 Full GC 后依然占用了 169,344.2 KB (“OU“)。用了 928ms 的時(shí)間卻只釋放了 800 字節(jié)的內(nèi)存, 怎么看都覺(jué)得很不正常。

只看這兩行的內(nèi)容, 就知道程序出了很?chē)?yán)重的問(wèn)題。繼續(xù)分析下一行, 可以確定問(wèn)題依然存在,而且變得更糟。

JVM幾乎完全卡住了(stalled), 因?yàn)镚C占用了90%以上的計(jì)算資源。GC之后, 所有的老代空間仍然還在占用。事實(shí)上, 程序在一分鐘以后就掛了, 拋出了 “java.lang.OutOfMemoryError: GC overhead limit exceeded” 錯(cuò)誤。

可以看到, 通過(guò) jstat 能很快發(fā)現(xiàn)對(duì)JVM健康極為不利的GC行為。一般來(lái)說(shuō), 只看 jstat 的輸出就能快速發(fā)現(xiàn)以下問(wèn)題:

• 最后一列 “GCT”, 與JVM的總運(yùn)行時(shí)間 “Timestamp” 的比值, 就是GC 的開(kāi)銷(xiāo)。如果每一秒內(nèi), “GCT“ 的值都會(huì)明顯增大, 與總運(yùn)行時(shí)間相比, 就暴露出GC開(kāi)銷(xiāo)過(guò)大的問(wèn)題. 不同系統(tǒng)對(duì)GC開(kāi)銷(xiāo)有不同的容忍度, 由性能需求決定, 一般來(lái)講, 超過(guò) 10% 的GC開(kāi)銷(xiāo)都是有問(wèn)題的。
• “YGC” 和 “FGC” 列的快速變化往往也是有問(wèn)題的征兆。頻繁的GC暫停會(huì)累積,并導(dǎo)致更多的線(xiàn)程停頓(stop-the-world pauses), 進(jìn)而影響吞吐量。
• 如果看到 “OU” 列中,老年代的使用量約等于老年代的最大容量(OC), 并且不降低的話(huà), 就表示雖然執(zhí)行了老年代GC, 但基本上屬于無(wú)效GC。

4，GC日志(GC logs)

通過(guò)日志內(nèi)容也可以得到GC相關(guān)的信息。因?yàn)镚C日志模塊內(nèi)置于JVM中, 所以日志中包含了對(duì)GC活動(dòng)最全面的描述。 這就是事實(shí)上的標(biāo)準(zhǔn), 可作為GC性能評(píng)估和優(yōu)化的最真實(shí)數(shù)據(jù)來(lái)源。

GC日志一般輸出到文件之中, 是純 text 格式的, 當(dāng)然也可以打印到控制臺(tái)。有多個(gè)可以控制GC日志的JVM參數(shù)。例如,可以打印每次GC的持續(xù)時(shí)間, 以及程序暫停時(shí)間(-XX:+PrintGCApplicationStoppedTime), 還有GC清理了多少引用類(lèi)型(-XX:+PrintReferenceGC)。

要打印GC日志, 需要在啟動(dòng)腳本中指定以下參數(shù):

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:<filename>

以上參數(shù)指示JVM: 將所有GC事件打印到日志文件中, 輸出每次GC的日期和時(shí)間戳。不同GC算法輸出的內(nèi)容略有不同. ParallelGC 輸出的日志類(lèi)似這樣:

199.879: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1473386 secs] [Times: user=0.43 sys=0.01, real=0.15 secs]
200.027: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1567794 secs] [Times: user=0.41 sys=0.00, real=0.16 secs]
200.184: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1621946 secs] [Times: user=0.43 sys=0.00, real=0.16 secs]
200.346: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1547695 secs] [Times: user=0.41 sys=0.00, real=0.15 secs]
200.502: [Full GC (Ergonomics) [PSYoungGen: 64000K->63999K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1563071 secs] [Times: user=0.42 sys=0.01, real=0.16 secs]
200.659: [Full GC (Ergonomics) [PSYoungGen: 64000K->63999K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1538778 secs] [Times: user=0.42 sys=0.00, real=0.16 secs]

在 “GC算法:實(shí)現(xiàn)篇” 中詳細(xì)介紹了這些格式, 如果對(duì)此不了解, 可以先閱讀該章節(jié)。

分析以上日志內(nèi)容, 可以得知:

• 這部分日志截取自JVM啟動(dòng)后200秒左右。
• 日志片段中顯示, 在780毫秒以?xún)?nèi), 因?yàn)槔厥?導(dǎo)致了5次 Full GC 暫停(去掉第六次暫停,這樣更精確一些)。
• 這些暫停事件的總持續(xù)時(shí)間是 777毫秒, 占總運(yùn)行時(shí)間的 99.6%。
• 在GC完成之后, 幾乎所有的老年代空間(169,472 KB)依然被占用(169,318 KB)。

通過(guò)日志信息可以確定, 該應(yīng)用的GC情況非常糟糕。JVM幾乎完全停滯, 因?yàn)镚C占用了超過(guò)99%的CPU時(shí)間。 而GC的結(jié)果是, 老年代空間仍然被占滿(mǎn), 這進(jìn)一步肯定了我們的結(jié)論。 示例程序和jstat 小節(jié)中的是同一個(gè), 幾分鐘之后系統(tǒng)就掛了, 拋出 “java.lang.OutOfMemoryError: GC overhead limit exceeded” 錯(cuò)誤, 不用說(shuō), 問(wèn)題是很?chē)?yán)重的.

從此示例可以看出, GC日志對(duì)監(jiān)控GC行為和JVM是否處于健康狀態(tài)非常有用。一般情況下, 查看 GC 日志就可以快速確定以下癥狀:

• GC開(kāi)銷(xiāo)太大。如果GC暫停的總時(shí)間很長(zhǎng), 就會(huì)損害系統(tǒng)的吞吐量。不同的系統(tǒng)允許不同比例的GC開(kāi)銷(xiāo), 但一般認(rèn)為, 正常范圍在 10% 以?xún)?nèi)。
• 極個(gè)別的GC事件暫停時(shí)間過(guò)長(zhǎng)。當(dāng)某次GC暫停時(shí)間太長(zhǎng), 就會(huì)影響系統(tǒng)的延遲指標(biāo). 如果延遲指標(biāo)規(guī)定交易必須在 1,000 ms內(nèi)完成, 那就不能容忍任何超過(guò) 1000毫秒的GC暫停。
• 老年代的使用量超過(guò)限制。如果老年代空間在 Full GC 之后仍然接近全滿(mǎn), 那么GC就成為了性能瓶頸, 可能是內(nèi)存太小, 也可能是存在內(nèi)存泄漏。這種癥狀會(huì)讓GC的開(kāi)銷(xiāo)暴增。

可以看到,GC日志中的信息非常詳細(xì)。但除了這些簡(jiǎn)單的小程序, 生產(chǎn)系統(tǒng)一般都會(huì)生成大量的GC日志, 純靠人工是很難閱讀和進(jìn)行解析的。

5，GCViewer

我們可以自己編寫(xiě)解析器, 來(lái)將龐大的GC日志解析為直觀易讀的圖形信息。 但很多時(shí)候自己寫(xiě)程序也不是個(gè)好辦法, 因?yàn)楦鞣NGC算法的復(fù)雜性, 導(dǎo)致日志信息格式互相之間不太兼容。那么神器來(lái)了: GCViewer。

GCViewer 是一款開(kāi)源的GC日志分析工具。項(xiàng)目的 GitHub 主頁(yè)對(duì)各項(xiàng)指標(biāo)進(jìn)行了完整的描述. 下面我們介紹最常用的一些指標(biāo)。

第一步是獲取GC日志文件。這些日志文件要能夠反映系統(tǒng)在性能調(diào)優(yōu)時(shí)的具體場(chǎng)景. 假若運(yùn)營(yíng)部門(mén)(operational department)反饋: 每周五下午,系統(tǒng)就運(yùn)行緩慢, 不管GC是不是主要原因, 分析周一早晨的日志是沒(méi)有多少意義的。

獲取到日志文件之后, 就可以用 GCViewer 進(jìn)行分析, 大致會(huì)看到類(lèi)似下面的圖形界面:

使用的命令行大致如下:

java -jar gcviewer_1.3.4.jar gc.log

當(dāng)然, 如果不想打開(kāi)程序界面,也可以在后面加上其他參數(shù),直接將分析結(jié)果輸出到文件。

命令大致如下:

java -jar gcviewer_1.3.4.jar gc.log summary.csv chart.png

以上命令將信息匯總到當(dāng)前目錄下的 Excel 文件 summary.csv 之中, 將圖形信息保存為 chart.png 文件。

點(diǎn)擊下載: gcviewer的jar包及使用示例 。

上圖中, Chart 區(qū)域是對(duì)GC事件的圖形化展示。包括各個(gè)內(nèi)存池的大小和GC事件。上圖中, 只有兩個(gè)可視化指標(biāo): 藍(lán)色線(xiàn)條表示堆內(nèi)存的使用情況, 黑色的Bar則表示每次GC暫停時(shí)間的長(zhǎng)短。

從圖中可以看到, 內(nèi)存使用量增長(zhǎng)很快。一分鐘左右就達(dá)到了堆內(nèi)存的最大值. 堆內(nèi)存幾乎全部被消耗, 不能順利分配新對(duì)象, 并引發(fā)頻繁的 Full GC 事件. 這說(shuō)明程序可能存在內(nèi)存泄露, 或者啟動(dòng)時(shí)指定的內(nèi)存空間不足。

從圖中還可以看到 GC暫停的頻率和持續(xù)時(shí)間。30秒之后, GC幾乎不間斷地運(yùn)行,最長(zhǎng)的暫停時(shí)間超過(guò)1.4秒。

在右邊有三個(gè)選項(xiàng)卡。“Summary(摘要)” 中比較有用的是 “Throughput”(吞吐量百分比) 和 “Number of GC pauses”(GC暫停的次數(shù)), 以及“Number of full GC pauses”(Full GC 暫停的次數(shù)). 吞吐量顯示了有效工作的時(shí)間比例, 剩下的部分就是GC的消耗。

以上示例中的吞吐量為 6.28%。這意味著有 93.72% 的CPU時(shí)間用在了GC上面. 很明顯系統(tǒng)所面臨的情況很糟糕 —— 寶貴的CPU時(shí)間沒(méi)有用于執(zhí)行實(shí)際工作, 而是在試圖清理垃圾。

下一個(gè)有意思的地方是“Pause”(暫停)選項(xiàng)卡:

“Pause” 展示了GC暫停的總時(shí)間,平均值,最小值和最大值, 并且將 total 與minor/major 暫停分開(kāi)統(tǒng)計(jì)。如果要優(yōu)化程序的延遲指標(biāo), 這些統(tǒng)計(jì)可以很快判斷出暫停時(shí)間是否過(guò)長(zhǎng)。另外, 我們可以得出明確的信息: 累計(jì)暫停時(shí)間為 634.59 秒, GC暫停的總次數(shù)為 3,938 次, 這在11分鐘/660秒的總運(yùn)行時(shí)間里那不是一般的高。

更詳細(xì)的GC暫停匯總信息, 請(qǐng)查看主界面中的 “Event details” 標(biāo)簽:

從“Event details” 標(biāo)簽中, 可以看到日志中所有重要的GC事件匯總: 普通GC停頓和 Full GC 停頓次數(shù) 以及并發(fā)執(zhí)行數(shù)等。此示例中, 可以看到一個(gè)明顯的地方, Full GC 暫停嚴(yán)重影響了吞吐量和延遲, 依據(jù)是: 3,928 次 Full GC 暫停了634秒。

可以看到, GCViewer 能用圖形界面快速展現(xiàn)異常的GC行為。一般來(lái)說(shuō), 圖像化信息能迅速揭示以下癥狀:

• 低吞吐量。當(dāng)應(yīng)用的吞吐量下降到不能容忍的地步時(shí), 有用工作的總時(shí)間就大量減少. 具體有多大的 “容忍度”(tolerable) 取決于具體場(chǎng)景。按照經(jīng)驗(yàn), 低于 90% 的有效時(shí)間就值得警惕了, 可能需要好好優(yōu)化下GC。
• 單次GC的暫停時(shí)間過(guò)長(zhǎng)。只要有一次GC停頓時(shí)間過(guò)長(zhǎng),就會(huì)影響程序的延遲指標(biāo). 例如, 延遲需求規(guī)定必須在 1000 ms以?xún)?nèi)完成交易, 那就不能容忍任何一次GC暫停超過(guò)1000毫秒。
• 堆內(nèi)存使用率過(guò)高。如果老年代空間在 Full GC 之后仍然接近全滿(mǎn), 程序性能就會(huì)大幅降低, 可能是資源不足或者內(nèi)存泄漏。這種癥狀會(huì)對(duì)吞吐量產(chǎn)生嚴(yán)重影響。

業(yè)界良心 —— 圖形化展示的GC日志信息絕對(duì)是我們重磅推薦的。不用去閱讀冗長(zhǎng)而又復(fù)雜的GC日志,通過(guò)容易理解的圖形, 也可以得到同樣的信息。

6，分析器(Profilers)

下面介紹分析器(profilers, Oracle官方翻譯是:抽樣器)。相對(duì)于前面的工具, 分析器只關(guān)心GC中的一部分領(lǐng)域. 本節(jié)我們也只關(guān)注分析器相關(guān)的GC功能。

首先警告 —— 不要認(rèn)為分析器適用于所有的場(chǎng)景。分析器有時(shí)確實(shí)作用很大, 比如檢測(cè)代碼中的CPU熱點(diǎn)時(shí)。但某些情況使用分析器不一定是個(gè)好方案。

對(duì)GC調(diào)優(yōu)來(lái)說(shuō)也是一樣的。要檢測(cè)是否因?yàn)镚C而引起延遲或吞吐量問(wèn)題時(shí), 不需要使用分析器. 前面提到的工具( jstat 或 原生/可視化GC日志)就能更好更快地檢測(cè)出是否存在GC問(wèn)題. 特別是從生產(chǎn)環(huán)境中收集性能數(shù)據(jù)時(shí), 最好不要使用分析器, 因?yàn)樾阅荛_(kāi)銷(xiāo)非常大。

如果確實(shí)需要對(duì)GC進(jìn)行優(yōu)化, 那么分析器就可以派上用場(chǎng)了, 可以對(duì) Object 的創(chuàng)建信息一目了然. 換個(gè)角度看, 如果GC暫停的原因不在某個(gè)內(nèi)存池中, 那就只會(huì)是因?yàn)閯?chuàng)建對(duì)象太多了。 所有分析器都能夠跟蹤對(duì)象分配(via allocation profiling), 根據(jù)內(nèi)存分配的軌跡, 讓你知道 實(shí)際駐留在內(nèi)存中的是哪些對(duì)象。

分配分析能定位到在哪個(gè)地方創(chuàng)建了大量的對(duì)象. 使用分析器輔助進(jìn)行GC調(diào)優(yōu)的好處是, 能確定哪種類(lèi)型的對(duì)象最占用內(nèi)存, 以及哪些線(xiàn)程創(chuàng)建了最多的對(duì)象。

下面我們通過(guò)實(shí)例介紹3種分配分析器: hprof, JVisualVM 和 AProf。實(shí)際上還有很多分析器可供選擇, 有商業(yè)產(chǎn)品,也有免費(fèi)工具, 但其功能和應(yīng)用基本上都是類(lèi)似的。

hprof

hprof 分析器內(nèi)置于JDK之中。 在各種環(huán)境下都可以使用, 一般優(yōu)先使用這款工具。

要讓 hprof 和程序一起運(yùn)行, 需要修改啟動(dòng)腳本, 類(lèi)似這樣:

java -agentlib:hprof=heap=sites com.yourcompany.YourApplication

在程序退出時(shí),會(huì)將分配信息dump(轉(zhuǎn)儲(chǔ))到工作目錄下的 java.hprof.txt 文件中。使用文本編輯器打開(kāi), 并搜索 “SITES BEGIN” 關(guān)鍵字, 可以看到:

SITES BEGIN (ordered by live bytes) Tue Dec 8 11:16:15 2015
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 64.43% 4.43% 8370336 20121 27513408 66138 302116 int[]
2 3.26% 88.49% 482976 20124 1587696 66154 302104 java.util.ArrayList
3 1.76% 88.74% 241704 20121 1587312 66138 302115 eu.plumbr.demo.largeheap.ClonableClass0006
... 部分省略 ...
SITES END

從以上片段可以看到, allocations 是根據(jù)每次創(chuàng)建的對(duì)象數(shù)量來(lái)排序的。第一行顯示所有對(duì)象中有 64.43% 的對(duì)象是整型數(shù)組(int[]), 在標(biāo)識(shí)為 302116 的位置創(chuàng)建。搜索 “TRACE 302116” 可以看到:

TRACE 302116:
eu.plumbr.demo.largeheap.ClonableClass0006.<init>(GeneratorClass.java:11)
sun.reflect.GeneratedConstructorAccessor7.newInstance(<Unknown Source>:Unknown line)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:422)

現(xiàn)在, 知道有 64.43% 的對(duì)象是整數(shù)數(shù)組, 在 ClonableClass0006 類(lèi)的構(gòu)造函數(shù)中, 第11行的位置, 接下來(lái)就可以?xún)?yōu)化代碼, 以減少GC的壓力。

Java VisualVM

本章前面的第一部分, 在監(jiān)控 JVM 的GC行為工具時(shí)介紹了 JVisualVM , 本節(jié)介紹其在分配分析上的應(yīng)用。

JVisualVM 通過(guò)GUI的方式連接到正在運(yùn)行的JVM。 連接上目標(biāo)JVM之后 :

• 打開(kāi) “工具” —> “選項(xiàng)” 菜單, 點(diǎn)擊 性能分析(Profiler) 標(biāo)簽, 新增配置, 選擇 Profiler 內(nèi)存, 確保勾選了 “Record allocations stack traces”(記錄分配棧跟蹤)。
• 勾選 “Settings”(設(shè)置) 復(fù)選框, 在內(nèi)存設(shè)置標(biāo)簽下,修改預(yù)設(shè)配置。
• 點(diǎn)擊 “Memory”(內(nèi)存) 按鈕開(kāi)始進(jìn)行內(nèi)存分析。
• 讓程序運(yùn)行一段時(shí)間,以收集關(guān)于對(duì)象分配的足夠信息。
• 單擊下方的 “Snapshot”(快照) 按鈕?？梢垣@取收集到的快照信息。

完成上面的步驟后, 可以得到類(lèi)似這樣的信息:

上圖按照每個(gè)類(lèi)被創(chuàng)建的對(duì)象數(shù)量多少來(lái)排序?？吹谝恍锌梢灾? 創(chuàng)建的最多的對(duì)象是 int[] 數(shù)組. 鼠標(biāo)右鍵單擊這行, 就可以看到這些對(duì)象都在哪些地方創(chuàng)建的:

與 hprof 相比, JVisualVM 更加容易使用 —— 比如上面的截圖中, 在一個(gè)地方就可以看到所有int[] 的分配信息, 所以多次在同一處代碼進(jìn)行分配的情況就很容易發(fā)現(xiàn)。

AProf

最重要的一款分析器,是由 Devexperts 開(kāi)發(fā)的 AProf。 內(nèi)存分配分析器 AProf 也被打包為 Java agent 的形式。

用 AProf 分析應(yīng)用程序, 需要修改 JVM 啟動(dòng)腳本,類(lèi)似這樣:

java -javaagent:/path-to/aprof.jar com.yourcompany.YourApplication

重啟應(yīng)用之后, 工作目錄下會(huì)生成一個(gè) aprof.txt 文件。此文件每分鐘更新一次, 包含這樣的信息:

========================================================================================================================
TOTAL allocation dump for 91,289 ms (0h01m31s)
Allocated 1,769,670,584 bytes in 24,868,088 objects of 425 classes in 2,127 locations
========================================================================================================================
Top allocation-inducing locations with the data types allocated from them
------------------------------------------------------------------------------------------------------------------------
eu.plumbr.demo.largeheap.ManyTargetsGarbageProducer.newRandomClassObject: 1,423,675,776 (80.44%) bytes in 17,113,721 (68.81%) objects (avg size 83 bytes)
int[]: 711,322,976 (40.19%) bytes in 1,709,911 (6.87%) objects (avg size 416 bytes)
char[]: 369,550,816 (20.88%) bytes in 5,132,759 (20.63%) objects (avg size 72 bytes)
java.lang.reflect.Constructor: 136,800,000 (7.73%) bytes in 1,710,000 (6.87%) objects (avg size 80 bytes)
java.lang.Object[]: 41,079,872 (2.32%) bytes in 1,710,712 (6.87%) objects (avg size 24 bytes)
java.lang.String: 41,063,496 (2.32%) bytes in 1,710,979 (6.88%) objects (avg size 24 bytes)
java.util.ArrayList: 41,050,680 (2.31%) bytes in 1,710,445 (6.87%) objects (avg size 24 bytes)
... cut for brevity ...

上面的輸出是按照 size 進(jìn)行排序的?？梢钥闯? 80.44% 的 bytes 和 68.81% 的 objects 是在 ManyTargetsGarbageProducer.newRandomClassObject() 方法中分配的。 其中, int[] 數(shù)組占用了 40.19% 的內(nèi)存, 是最大的一個(gè)。

繼續(xù)往下看, 會(huì)發(fā)現(xiàn) allocation traces(分配痕跡)相關(guān)的內(nèi)容, 也是以 allocation size 排序的:

 Top allocated data types with reverse location traces
------------------------------------------------------------------------------------------------------------------------
int[]: 725,306,304 (40.98%) bytes in 1,954,234 (7.85%) objects (avg size 371 bytes)
eu.plumbr.demo.largeheap.ClonableClass0006.: 38,357,696 (2.16%) bytes in 92,206 (0.37%) objects (avg size 416 bytes)
java.lang.reflect.Constructor.newInstance: 38,357,696 (2.16%) bytes in 92,206 (0.37%) objects (avg size 416 bytes)
eu.plumbr.demo.largeheap.ManyTargetsGarbageProducer.newRandomClassObject: 38,357,280 (2.16%) bytes in 92,205 (0.37%) objects (avg size 416 bytes)
java.lang.reflect.Constructor.newInstance: 416 (0.00%) bytes in 1 (0.00%) objects (avg size 416 bytes)
... cut for brevity ...

可以看到, int[] 數(shù)組的分配, 在 ClonableClass0006 構(gòu)造函數(shù)中繼續(xù)增大。

和其他工具一樣, AProf 揭露了 分配的大小以及位置信息(allocation size and locations), 從而能夠快速找到最耗內(nèi)存的部分。在我們看來(lái), AProf 是最有用的分配分析器, 因?yàn)樗粚?zhuān)注于內(nèi)存分配, 所以做得最好。 當(dāng)然, 這款工具是開(kāi)源免費(fèi)的, 資源開(kāi)銷(xiāo)也最小。

以上就是jvm垃圾回收之GC調(diào)優(yōu)工具分析詳解的詳細(xì)內(nèi)容，更多關(guān)于jvm垃圾回收GC調(diào)優(yōu)工具的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章！

原文鏈接：https://plumbr.io/handbook/gc-tuning-measuring