6. GC 調優(工具篇) - GC參考手冊
進行GC性能調優時, 須要明白了解, 當前的GC行為對系統和用戶有多大的影響。
有多種監控GC的工具和方法, 本章將逐一介紹經常使用的工具。
您應該已經閱讀了前面的章節:
- 垃圾收集簡單介紹 - GC參考手冊
- Java中的垃圾收集 - GC參考手冊
- GC 算法(基礎篇) - GC參考手冊
- GC 算法(實現篇) - GC參考手冊
- GC 調優(基礎篇) - GC參考手冊
JVM 在程序執行的過程中, 提供了GC行為的原生數據。
那麽, 我們就能夠利用這些原生數據來生成各種報告。原生數據(raw data) 包含:
- 各個內存池的當前使用情況,
- 各個內存池的總容量,
- 每次GC暫停的持續時間,
- GC暫停在各個階段的持續時間。
能夠通過這些數據算出各種指標, 比如: 程序的內存分配率, 提升率等等。本章主要介紹怎樣獲取原生數據。 興許的章節將對重要的派生指標(derived metrics)展開討論, 並引入GC性能相關的話題。
JMX API
從 JVM 執行時獲取GC行為數據, 最簡單的辦法是使用標準 JMX API 接口. JMX是獲取 JVM內部執行時狀態信息 的標準API. 能夠編敲代碼代碼, 通過 JMX API 來訪問本程序所在的JVM，也能夠通過JMXclient執行(遠程)訪問。
最常見的 JMXclient是 JConsole 和 JVisualVM (能夠安裝各種插件,十分強大)。兩個工具都是標準JDK的一部分, 並且非常easy使用. 假設使用的是 JDK 7u40 及更高版本號, 還能夠使用還有一個工具: Java Mission Control( 大致翻譯為 Java控制中心, jmc.exe
JVisualVM安裝MBeans插件的步驟: 通過 工具(T) – 插件(G) – 可用插件 – 勾選VisualVM-MBeans – 安裝 – 下一步 – 等待安裝完畢…… 其它插件的安裝過程基本一致。
全部 JMXclient都是獨立的程序,能夠連接到目標JVM上。目標JVM能夠在本機, 也可能是遠端JVM. 假設要連接遠端JVM, 則目標JVM啟動時必須指定特定的環境變量,以開啟遠程JMX連接/以及端口號。 示比例如以下:
java -Dcom.sun.management.jmxremote.port=5432 com.yourcompany.YourApp
在此處, JVM 打開端口5432
通過 JVisualVM 連接到某個JVM以後, 切換到 MBeans 標簽, 展開 “java.lang/GarbageCollector” . 就能夠看到GC行為信息, 下圖是 JVisualVM 中的截圖:
下圖是Java Mission Control 中的截圖:
從以上截圖中能夠看到兩款垃圾收集器。
當中一款負責清理年輕代(PS Scavenge)，還有一款負責清理老年代(PS MarkSweep); 列表中顯示的就是垃圾收集器的名稱。
能夠看到 , jmc 的功能和展示數據的方式更強大。
對全部的垃圾收集器, 通過 JMX API 獲取的信息包含:
- CollectionCount : 垃圾收集器執行的GC總次數,
- CollectionTime: 收集器執行時間的累計。這個值等於全部GC事件持續時間的總和,
- LastGcInfo: 近期一次GC事件的具體信息。包含 GC事件的持續時間(duration), 開始時間(startTime) 和 結束時間(endTime), 以及各個內存池在近期一次GC之前和之後的使用情況,
- MemoryPoolNames: 各個內存池的名稱,
- Name: 垃圾收集器的名稱
- ObjectName: 由JMX規範定義的 MBean的名字,,
- Valid: 此收集器是否有效。本人僅僅見過 “
true“的情況 (^_^)
依據經驗, 這些信息對GC的性能來說,不能得出什麽結論. 僅僅有編敲代碼, 獲取GC相關的 JMX 信息來進行統計和分析。
在下文能夠看到, 一般也不怎麽關註 MBean , 但 MBean 對於理解GC的原理倒是挺實用的。
JVisualVM
JVisualVM 工具的 “VisualGC” 插件提供了主要的 JMXclient功能, 還實時顯示出 GC事件以及各個內存空間的使用情況。
Visual GC 插件經常使用來監控本機執行的Java程序, 比方開發人員和性能調優專家經常會使用此插件, 以高速獲取程序執行時的GC信息。
左側的圖表展示了各個內存池的使用情況: Metaspace/永久代, 老年代, Eden區以及兩個存活區。
在右邊, 頂部的兩個圖表與 GC無關, 顯示的是 JIT編譯時間 和 類載入時間。
以下的6個圖顯示的是內存池的歷史記錄, 每一個內存池的GC次數,GC總時間, 以及最大值。峰值, 當前使用情況。
再以下是 HistoGram, 顯示了年輕代對象的年齡分布。至於對象的年齡監控(objects tenuring monitoring), 本章不進行解說。
與純粹的JMX工具相比, VisualGC 插件提供了更友好的界面, 假設沒有其它趁手的工具, 請選擇VisualGC. 本章接下來會介紹其它工具, 這些工具能夠提供很多其它的信息, 以及更好的視角. 當然, 在“Profilers(分析器)”一節中，也會介紹 JVisualVM 的適用場景 —— 如: 分配分析(allocation profiling), 所以我們絕不會貶低哪一款工具, 關鍵還得看實際情況。
jstat
jstat 也是標準JDK提供的一款監控工具(Java Virtual Machine statistics monitoring tool),能夠統計各種指標。既能夠連接到本地JVM,也能夠連到遠程JVM. 查看支持的指標和相應選項能夠執行 “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 對於高速確定GC行為是否健康非常實用。啟動方式為: “jstat -gc -t PID 1s” , 當中,PID 就是要監視的Java進程ID。能夠通過 jps 命令查看正在執行的Java進程列表。
jps
jstat -gc -t 2428 1s
以上命令的結果, 是 jstat 每秒向標準輸出輸出一行新內容, 比方:
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
略微解釋一下上面的內容。參考 jstat manpage , 我們能夠知道:
- jstat 連接到 JVM 的時間, 是JVM啟動後的 200秒。此信息從第一行的 “Timestamp” 列得知。繼續看下一行, jstat 每秒鐘從JVM 接收一次信息, 也就是命令行參數中 “
1s” 的含義。 - 從第一行的 “YGC” 列得知年輕代共執行了34次GC, 由 “FGC” 列得知整個堆內存已經執行了 658次 full GC。
- 年輕代的GC耗時總共為
0.720 秒, 顯示在“YGCT” 這一列。 - Full GC 的總計耗時為
133.684 秒, 由“FGCT”列得知。這立刻就吸引了我們的目光, 總的JVM 執行時間僅僅有 200 秒, 但當中有 66% 的部分被 Full GC 消耗了。
再看下一行, 問題就更明顯了。
- 在接下來的一秒內共執行了 4 次 Full GC。參見 “FGC” 列.
- 這4次 Full GC 暫停占用了差點兒相同 1秒的時間(依據 FGCT列的差得知)。與第一行相比, Full GC 耗費了
928 毫秒, 即92.8%的時間。 - 依據 “OC 和 “OU” 列得知, 整個老年代的空間為
169,344.0 KB(“OC“), 在 4 次 Full GC 後依舊占用了169,344.2 KB(“OU“)。用了928ms的時間卻僅僅釋放了 800 字節的內存, 怎麽看都覺得非常不正常。
僅僅看這兩行的內容, 就知道程序出了非常嚴重的問題。
繼續分析下一行, 能夠確定問題依舊存在,並且變得更糟。
JVM差點兒全然卡住了(stalled), 由於GC占用了90%以上的計算資源。GC之後, 全部的老代空間仍然還在占用。其實, 程序在一分鐘以後就掛了, 拋出了 “java.lang.OutOfMemoryError: GC overhead limit exceeded” 錯誤。
能夠看到, 通過 jstat 能非常快發現對JVM健康極為不利的GC行為。一般來說, 僅僅看 jstat 的輸出就能高速發現以下問題:
- 最後一列 “GCT”, 與JVM的總執行時間 “Timestamp” 的比值, 就是GC 的開銷。假設每一秒內, “GCT” 的值都會明顯增大, 與總執行時間相比, 就暴露出GC開銷過大的問題. 不同系統對GC開銷有不同的容忍度, 由性能需求決定, 一般來講, 超過
10%的GC開銷都是有問題的。 - “YGC” 和 “FGC” 列的高速變化往往也是有問題的征兆。
頻繁的GC暫停會累積,並導致很多其它的線程停頓(stop-the-world pauses), 進而影響吞吐量。
- 假設看到 “OU” 列中,老年代的使用量約等於老年代的最大容量(OC), 並且不降低的話, 就表示盡管執行了老年代GC, 但基本上屬於無效GC。
GC日誌(GC logs)
通過日誌內容也能夠得到GC相關的信息。
由於GC日誌模塊內置於JVM中, 所以日誌中包含了對GC活動最全面的描寫敘述。
這就是其實的標準, 可作為GC性能評估和優化的最真實數據來源。
GC日誌一般輸出到文件之中, 是純 text 格式的, 當然也能夠打印到控制臺。有多個能夠控制GC日誌的JVM參數。
比如,能夠打印每次GC的持續時間, 以及程序暫停時間(-XX:+PrintGCApplicationStoppedTime), 還有GC清理了多少引用類型(-XX:+PrintReferenceGC)。
要打印GC日誌, 須要在啟動腳本中指定以下參數:
-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:<filename>
以上參數指示JVM: 將全部GC事件打印到日誌文件裏, 輸出每次GC的日期和時間戳。
不同GC算法輸出的內容略有不同. ParallelGC 輸出的日誌相似這樣:
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]
在 “04. GC算法:實現篇” 中具體介紹了這些格式, 假設對此不了解, 能夠先閱讀該章節。
分析以上日誌內容, 能夠得知:
- 這部分日誌截取自JVM啟動後200秒左右。
- 日誌片段中顯示, 在
780毫秒以內, 由於垃圾回收 導致了5次 Full GC 暫停(去掉第六次暫停,這樣更精確一些)。 - 這些暫停事件的總持續時間是
777毫秒, 占總執行時間的 99.6%。 - 在GC完畢之後, 差點兒全部的老年代空間(
169,472 KB)依舊被占用(169,318 KB)。
通過日誌信息能夠確定, 該應用的GC情況非常糟糕。JVM差點兒全然停滯, 由於GC占用了超過99%的CPU時間。 而GC的結果是, 老年代空間仍然被占滿, 這進一步肯定了我們的結論。
演示樣例程序和jstat 小節中的是同一個, 幾分鐘之後系統就掛了, 拋出 “java.lang.OutOfMemoryError: GC overhead limit exceeded” 錯誤, 不用說, 問題是非常嚴重的.
從此演示樣例能夠看出, GC日誌對監控GC行為和JVM是否處於健康狀態非常實用。
普通情況下, 查看 GC 日誌就能夠高速確定以下癥狀:
- GC開銷太大。
假設GC暫停的總時間非常長, 就會損害系統的吞吐量。不同的系統同意不同比例的GC開銷, 但一般覺得, 正常範圍在
10%以內。 - 極個別的GC事件暫停時間過長。
當某次GC暫停時間太長, 就會影響系統的延遲指標. 假設延遲指標規定交易必須在
1,000 ms內完畢, 那就不能容忍不論什麽超過1000毫秒的GC暫停。 - 老年代的使用量超過限制。假設老年代空間在 Full GC 之後仍然接近全滿, 那麽GC就成為了性能瓶頸, 可能是內存太小, 也可能是存在內存泄漏。這種癥狀會讓GC的開銷暴增。
能夠看到,GC日誌中的信息非常具體。但除了這些簡單的小程序, 生產系統一般都會生成大量的GC日誌, 純靠人工是非常難閱讀和進行解析的。
GCViewer
我們能夠自己編寫解析器, 來將龐大的GC日誌解析為直觀易讀的圖形信息。 但非常多時候自己敲代碼也不是個好辦法, 由於各種GC算法的復雜性, 導致日誌信息格式互相之間不太兼容。那麽神器來了: GCViewer。
GCViewer 是一款開源的GC日誌分析工具。項目的 GitHub 主頁對各項指標進行了完整的描寫敘述. 以下我們介紹最經常使用的一些指標。
第一步是獲取GC日誌文件。這些日誌文件要能夠反映系統在性能調優時的具體場景. 假若運營部門(operational department)反饋: 每周五下午,系統就執行緩慢, 無論GC是不是主要原因, 分析周一早晨的日誌是沒有多少意義的。
獲取到日誌文件之後, 就能夠用 GCViewer 進行分析, 大致會看到相似以下的圖形界面:
使用的命令行大致例如以下:
java -jar gcviewer_1.3.4.jar gc.log
當然, 假設不想打開程序界面,也能夠在後面加上其它參數,直接將分析結果輸出到文件。
命令大致例如以下:
java -jar gcviewer_1.3.4.jar gc.log summary.csv chart.png
以上命令將信息匯總到當前文件夾下的 Excel 文件 summary.csv 之中, 將圖形信息保存為 chart.png 文件。
點擊下載: gcviewer的jar包及使用演示樣例 。
上圖中, Chart 區域是對GC事件的圖形化展示。包含各個內存池的大小和GC事件。上圖中, 僅僅有兩個可視化指標: 藍色線條表示堆內存的使用情況, 黑色的Bar則表示每次GC暫停時間的長短。
從圖中能夠看到, 內存使用量增長非常快。一分鐘左右就達到了堆內存的最大值. 堆內存差點兒全部被消耗, 不能順利分配新對象, 並引發頻繁的 Full GC 事件. 這說明程序可能存在內存泄露, 或者啟動時指定的內存空間不足。
從圖中還能夠看到 GC暫停的頻率和持續時間。30秒之後, GC差點兒不間斷地執行,最長的暫停時間超過1.4秒。
在右邊有三個選項卡。
“Summary(摘要)” 中比較實用的是 “Throughput”(吞吐量百分比) 和 “Number of GC pauses”(GC暫停的次數), 以及“Number of full GC pauses”(Full GC 暫停的次數). 吞吐量顯示了有效工作的時間比例, 剩下的部分就是GC的消耗。
以上演示樣例中的吞吐量為 6.28%。
這意味著有 93.72% 的CPU時間用在了GC上面. 非常明顯系統所面臨的情況非常糟糕 —— 寶貴的CPU時間沒實用於執行實際工作, 而是在試圖清理垃圾。
下一個有意思的地方是“Pause”(暫停)選項卡:
“Pause” 展示了GC暫停的總時間,平均值,最小值和最大值, 並且將 total 與minor/major 暫停分開統計。假設要優化程序的延遲指標, 這些統計能夠非常快推斷出暫停時間是否過長。另外, 我們能夠得出明白的信息: 累計暫停時間為 634.59 秒, GC暫停的總次數為 3,938 次, 這在11分鐘/660秒的總執行時間裏那不是一般的高。
更具體的GC暫停匯總信息, 請查看主界面中的 “Event details” 標簽:
從“Event details” 標簽中, 能夠看到日誌中全部重要的GC事件匯總: 普通GC停頓 和 Full GC 停頓次數, 以及並發執行數, 非 stop-the-world 事件等。此演示樣例中, 能夠看到一個明顯的地方, Full GC 暫停嚴重影響了吞吐量和延遲, 依據是: 3,928 次 Full GC, 暫停了634秒。
能夠看到, GCViewer 能用圖形界面高速展現異常的GC行為。一般來說, 圖像化信息能迅速揭示以下癥狀:
- 低吞吐量。當應用的吞吐量下降到不能容忍的地步時, 實用工作的總時間就大量降低. 具體有多大的 “容忍度”(tolerable) 取決於具體場景。
依照經驗, 低於 90% 的有效時間就值得警惕了, 可能須要好好優化下GC。
- 單次GC的暫停時間過長。僅僅要有一次GC停頓時間過長,就會影響程序的延遲指標. 比如, 延遲需求規定必須在 1000 ms以內完畢交易, 那就不能容忍不論什麽一次GC暫停超過1000毫秒。
- 堆內存使用率過高。
假設老年代空間在 Full GC 之後仍然接近全滿, 程序性能就會大幅降低, 可能是資源不足或者內存泄漏。
這種癥狀會對吞吐量產生嚴重影響。
業界良心 —— 圖形化展示的GC日誌信息絕對是我們重磅推薦的。
不用去閱讀冗長而又復雜的GC日誌,通過easy理解的圖形, 也能夠得到相同的信息。
分析器(Profilers)
以下介紹分析器(profilers, Oracle官方翻譯是:抽樣器)。相對於前面的工具, 分析器僅僅關心GC中的一部分領域. 本節我們也僅僅關註分析器相關的GC功能。
首先警告 —— 不要覺得分析器適用於全部的場景。分析器有時確實作用非常大, 比方檢測代碼中的CPU熱點時。但某些情況使用分析器不一定是個好方案。
對GC調優來說也是一樣的。要檢測是否由於GC而引起延遲或吞吐量問題時, 不須要使用分析器. 前面提到的工具( jstat 或 原生/可視化GC日誌)就能更好更快地檢測出是否存在GC問題. 特別是從生產環境中收集性能數據時, 最好不要使用分析器, 由於性能開銷非常大。
假設確實須要對GC進行優化, 那麽分析器就能夠派上用場了, 能夠對 Object 的創建信息一目了然. 換個角度看, 假設GC暫停的原因不在某個內存池中, 那就僅僅會是由於創建對象太多了。 全部分析器都能夠跟蹤對象分配(via allocation profiling), 依據內存分配的軌跡, 讓你知道 實際駐留在內存中的是哪些對象。
分配分析能定位到在哪個地方創建了大量的對象. 使用分析器輔助進行GC調優的優點是, 能確定哪種類型的對象最占用內存, 以及哪些線程創建了最多的對象。
以下我們通過實例介紹3種分配分析器: hprof, JVisualVM 和 AProf。實際上還有非常多分析器可供選擇, 有商業產品,也有免費工具, 但其功能和應用基本上都是相似的。
hprof
hprof 分析器內置於JDK之中。 在各種環境下都能夠使用, 一般優先使用這款工具。
要讓 hprof 和程序一起執行, 須要改動啟動腳本, 相似這樣:
java -agentlib:hprof=heap=sites com.yourcompany.YourApplication
在程序退出時,會將分配信息dump(轉儲)到工作文件夾下的 java.hprof.txt 文件裏。使用文本編輯器打開, 並搜索 “SITES BEGIN” keyword, 能夠看到:
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 是依據每次創建的對象數量來排序的。第一行顯示全部對象中有 64.43% 的對象是整型數組(int[]), 在標識為 302116 的位置創建。
搜索 “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)
如今, 知道有 64.43% 的對象是整數數組, 在 ClonableClass0006 類的構造函數中, 第11行的位置, 接下來就能夠優化代碼, 以降低GC的壓力。
Java VisualVM
本章前面的第一部分, 在監控 JVM 的GC行為工具時介紹了 JVisualVM , 本節介紹其在分配分析上的應用。
JVisualVM 通過GUI的方式連接到正在執行的JVM。 連接上目標JVM之後 :
- 打開 “工具” –> “選項” 菜單, 點擊 性能分析(Profiler) 標簽, 新增配置, 選擇 Profiler 內存, 確保勾選了 “Record allocations stack traces”(記錄分配棧跟蹤)。
- 勾選 “Settings”(設置) 復選框, 在內存設置標簽下,改動預設配置。
- 點擊 “Memory”(內存) button開始進行內存分析。
- 讓程序執行一段時間,以收集關於對象分配的足夠信息。
- 單擊下方的 “Snapshot”(快照) button。
能夠獲取收集到的快照信息。
完畢上面的步驟後, 能夠得到相似這種信息:
上圖依照每一個類被創建的對象數量多少來排序。看第一行能夠知道, 創建的最多的對象是 int[] 數組. 鼠標右鍵單擊這行, 就能夠看到這些對象都在哪些地方創建的:
與 hprof 相比, JVisualVM 更加easy使用 —— 比方上面的截圖中, 在一個地方就能夠看到全部int[] 的分配信息, 所以多次在同一處代碼進行分配的情況就非常easy發現。
AProf
最重要的一款分析器,是由 Devexperts 開發的 AProf。 內存分配分析器 AProf 也被打包為 Java agent 的形式。
用 AProf 分析應用程序, 須要改動 JVM 啟動腳本,相似這樣:
java -javaagent:/path-to/aprof.jar com.yourcompany.YourApplication
重新啟動應用之後, 工作文件夾下會生成一個 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 進行排序的。能夠看出, 80.44% 的 bytes 和 68.81% 的 objects 是在 ManyTargetsGarbageProducer.newRandomClassObject() 方法中分配的。
當中, int[] 數組占用了 40.19% 的內存, 是最大的一個。
繼續往下看, 會發現 allocation traces(分配痕跡)相關的內容, 也是以 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[] 數組的分配, 在 ClonableClass0006 構造函數中繼續增大。
和其它工具一樣, AProf 揭露了 分配的大小以及位置信息(allocation size and locations), 從而能夠高速找到最耗內存的部分。在我們看來, AProf 是最實用的分配分析器, 由於它僅僅專註於內存分配, 所以做得最好。 當然, 這款工具是開源免費的, 資源開銷也最小。
請繼續閱讀下一章: 7. GC 調優(實戰篇) - GC參考手冊
原文鏈接: GC Tuning: Tooling
翻譯人員: 鐵錨 http://blog.csdn.net/renfufei
翻譯時間: 2016年02月06日
6. GC 調優(工具篇) - GC參考手冊