 |
級別: 初級
Jack Shirazi, 董事, JavaPerformanceTuning.com
Kirk Pepperdine, 首席技術官, JavaPerformanceTuning.com
2004 年 5 月 01 日
您的應用程序是否經常出現 out-of-memory 錯誤？用戶是否感受到響應時間有些不穩定？應用程序是否在相當長的時間內變得沒有響應？應用程序的性能是否顯得遲緩了？如果對任何一個問題的回答是肯定的，那么您很可能遇到了垃圾收集的問題了。先別進行優化，且聽聽 JavaPerformanceTuning.com 的 Jack Shirazi 和 Kirk Pepperdine 來解釋如何識別垃圾收集問題，并由此幫助您回答這個問題：您知道垃圾收集器在干什么嗎？
許多開發人員認為，內存管理至多是開發業務邏輯的主要任務之外的一項不重要的工作 —— 直到業務邏輯不能像預期的或者測試時那樣執行得好。出現這種情況時，就需要知道哪里出錯了及其原因，這意味著要理解應用程序如何與底層計算資源（特別是內存）進行交互。理解應用程序如何利用內存的最好方式是觀察垃圾收集器的行動。
為什么我的應用程序不連貫了？
Java 虛擬機中最大的一個性能問題是應用程序線程與同時運行的 GC 的互斥性。垃圾收集器要完成其工作，需要在一段時間內防止所有其他線程訪問它正在處理的堆空間（內存）。按 GC 的術語，這段時間稱為“stop-the-world”，并且，正如其名字所表明的，在垃圾收集器努力工作時，應用程序有一個急剎車。幸運的是，這種暫停通常是很短的，很難察覺到，但是很容易想像，如果應用程序在隨機的時刻出現隨機且較長時間的暫停，對應用程序的響應性和吞吐能力會有破壞性的影響。
不過 GC 只是應用程序出現不連貫和停頓的一個原因。那么如何確定 GC 對產生這些問題是否負有責任呢？要回答這個問題，我們需要測量垃圾收集器的工作強度，并當在系統中進行改變時繼續這些測量，以定量地確定所做的改變是否有所期望的效果。
我需要多少內存？
普遍接受的信念是，在系統中添加內存將解決許多性能問題。雖然這個原則對于 JVM 來說經常是正確的，但是太多好東西可能對性能是有害的。因此技巧在于 Java 應用程序需要多少內存就給它多少，但是絕不多給。問題是，應用程序需要多少內存？對于應用程序不連貫的情況，我們需要觀察垃圾收集行為以了解看它做的是否比所需要的更多。這些觀察將告訴我們所做的改變是否有所期望的效果。
測量 GC 的活動
生成 GC 日志的標準方式是使用 -verbose:gc 旗標，設置這個旗標后，垃圾收集器會在每次運行時生成它所做的事情的匯總，一般是寫入到控制臺（通過標準輸出或者標準錯誤）。許多 VM 支持一個允許 verbose GC 輸出轉向到一個文件的選項。例如，在 Sun 的 1.4 JVM 中，可以使用開關 -Xloggc:filename 將 GC 輸出寫到文件中。對于 HP JVM，要使用 -Xverbosegc=file 開關。在本文中，我們將分析 Sun 1.4.2 和 IBM 1.4.1 JVM 捕獲的 verbose GC 輸出。
使用這個方法監視內存使用的一個最大好處是它對應用程序的性能的影響很小。不幸的是，這個解決方案并不完美，因為這些日志文件可能變得特別大，而維護它們可能需要重新啟動 JVM。盡管如此，這種技術在生產環境中仍然是可行的，因為它可以幫助診斷只在這種環境中才列出的性能問題。
更深入觀察 GC
-verbose:gc 旗標生成的輸出根據 JVM 廠商而不同，不同的垃圾收集器選項會報告特定于該實現的信息。例如，由 IBM JVM 生成的輸出比由 Sun JVM 生成的輸出冗長得多，而 Sun 的輸出更適合于由工具讀取。就是說，每一個 GC 日志傳達基本信息 —— 使用了多少內存、恢復了多少內存、GC 周期用了多少時間，以及在收集期間是否采取了其他行動。從這些基本測量中，我們可以推斷出有助于更好地理解所發生的事情的細節。我們要計算的統計如下所示：
- 考慮的運行時的持續時間
- 收集總數
- 收集頻率
- 收集所用最長時間
- 收集所用總時間
- 收集所用平均時間
- 收集的平均間隔
- 分配的字節總數
- 每次收集每秒分配的字節數
- 恢復的字節總數
- 每次收集每秒恢復的字節總數
理解了暫停時間，我們就可以理解 GC 對應用程序不響應是否負有部分或者全部責任了。一種實現這一任務的方法是將詳細（verbose） GC 日志中的 GC 活動與系統采集的其他日志（如 Web 服務器日志中的請求 backlog）相對應。幾乎可以肯定最長的 GC 暫停會導致整個系統響應可感覺的下降，所以知道什么時候響應下降是很有用的，這樣就可以將 GC 活動與應用程序吞吐相關聯起來。
另一種可能的競爭因素是堆內存分配和恢復的比率，稱為 churn。產生大量立即釋放的對象的應用程序通常會受到 churn 的拖累。更高的 churn 比率對垃圾收集器加以很大壓力，創造了更多的內存資源競爭，這又可導致更長的暫停或者可怕的 OutOfMemoryError 。
了解應用程序是否遭遇這些問題的一個方法是測量所考慮的整個運行時期間 GC 所占用的總時間。有了這種計算，我們就可以了解 GC 做的是否比它所應該做的更多。讓我們推導出進行這種判斷所需要的公式。
Sun GC 日志記錄
清單 1 是由 Sun 1.4.2_03 JVM 以 -Xloggc:filename 運行默認的標記-清除收集器所生成的日志記錄的例子。可以看到，日志項非常精確地記錄了每次所做的事情。
清單 1. 使用 -Xloggc:filename 旗標的 GC 日志記錄
69.713: [GC 11536K->11044K(12016K), 0.0032621 secs]
69.717: [Full GC 11044K->5143K(12016K), 0.1429698 secs]
69.865: [GC 5958K->5338K(11628K), 0.0021492 secs]
69.872: [GC 6169K->5418K(11628K), 0.0021718 secs]
69.878: [GC 6248K->5588K(11628K), 0.0029761 secs]
69.886: [GC 6404K->5657K(11628K), 0.0017877 secs]
|
首先注意到的可能是每一項日志記錄是寫在一組方括號內的。其他 GC 算法，如并發收集器， 可能將一些值分解為更細的信息。如果是這種情況，這些被分解的值會由包圍在嵌入的一組方括號中的細節所替代，這使工具可以更容易地處理詳細 GC 輸出。
我們的研究首先從分析清單 1 中標記為 69.713 的記錄開始。這個標記是 JVM 開始后的秒數和毫秒數的時間戳。在這個例子中，JVM 在這個 GC 周期開始之前運行了 69.713 秒。從左到右的字段為：執行的收集的類型、GC 之前的堆使用、總的堆能力和 GC 事件的持續時間。從這個描述中我們可以看出第一個 GC 事件是一個小的收集。在 GC 開始之前，使用了 11536 Kb 的堆空間。在完成時，使用了 11044 Kb，堆能力為 12016 Kb，而整個收集用了 .0032621 秒。下一個事件，一個完全的 GC，在 69.717 秒時或者上一個小 GC 事件之后 0.003 秒時開始。注意，如果將小 GC 事件的持續時間加到其開始時間上，就會看到它在完全的 GC 開始之前不到 1毫秒結束。因此我們可以得出結論：小收集沒有恢復足夠的空間，這種失敗觸發了完全的 GC。對應用程序來說，這像是一個持續了 0.1462319 秒的事件。讓我們繼續確定如何計算其他值。
GC 日志記錄的參數確定
我們通過確定每個 GC 日志記錄中的值的參數來開始分析：
R(n) = T(n): [ <GC> HB->HE(HC), D]
n |
清單中記錄的索引，1 是第一個，m 是最后一個 |
R(n) |
GC 記錄 |
T(n) |
第 n 個 GC 發生的時間 |
HB |
GC 之前堆的數量 |
HE |
GC 之后使用的堆數量 |
HC |
堆空間的總量 |
D |
GC 周期的持續時間 |
有了這些定義，我們現在可以推導出用于計算前面描述的值的公式。
基本值
我們要計算的第一個值是日志所覆蓋的運行時整個持續時間。如果要考慮每一項記錄，那么就要分析最后一項記錄的時間戳。因為清單 1 只表示全部日志記錄的一部分，我們需要從最后一項中提取出第一個時間戳。盡管對這個例子來說，這個數字足夠精確，但是為了絕對準確，需要加上最后 GC 的持續時間。其原因是時間戳是在 GC 開始時記錄的，而記錄表示在記錄了時間戳以后發生的事情。
剩余值是取記錄中相應的值的總和計算的。值得注意的是恢復的字節可以通過分析記錄中測量的關系而計算，而分配的字節可以通過分析前后記錄測量之間的關系計算。例如，如果考慮在時間戳 69.872 和 69.878 之間發現的記錄對，可以用第一個記錄中 GC 之后占用的內存數量減去第二個記錄在 GC 之前占用的字節數量計算在新的一代（generation）中分配的字節數量： 6248 Kb - 5418 Kb = 830 Kb 。下面表 1 展示了其他值的公式。
要找出最長的 GC 暫停，我們只需要查看持續時間并尋找 D(n) （記錄 n 的持續時間）的最大值。
表 1. 統計公式
| 統計 |
計算（時間單位調整為秒） |
| 運行時持續時間 |
RT = (T(M) + D(M)) - T(1) |
| 小收集的總數 |
TMC = Sum( R(n)) 其中 GC(n) = GC |
| 完全收集的總數 |
TFC = Sum( R(n)) 其中 GC(n) = Full |
| 收集頻率（小收集） |
CFM = TMC / RT |
| 收集頻率（完全） |
CFF = TFC / RT |
| 收集的時間（最長的小收集） |
MAX(D(n)) for all n 其中 GC(n) = GC |
| 收集的時間（最長的完全收集） |
MAX(D(n)) for all n 其中 GC(n) = Full |
| 小收集的時間（總數） |
TTMC = Sum(D(n)) for all n 其中 GC(n) = GC |
| 完全收集的時間（總數） |
TTFC Sum(D(n)) for all n 其中 GC(n) = Full |
| 收集的時間（總數） |
TTC = TTMC + TTFC |
| 小收集的時間（平均） |
ATMC = TTMC / RT |
| 完全收集的時間（平均） |
ATFC = TTFC / RT |
| 收集的時間（平均） |
ATC = TTC / RT |
| 收集間隔（平均） |
Sum( T(n+1) - T(n)) / (TMC + TFC) for all n |
| 分配的字節（總數） |
TBA = Sum(HB(n+1) - HE(n)) 對于所有 n |
| 分配的字節（每秒） |
TBA / RT |
| 分配的字節（每次收集） |
TBA / (TMC + TFC) |
| 小收集恢復的字節（總數） |
BRM = Sum(HB(n) - HE(n)) 其中 GC(n) = GC |
| 完全收集恢復的字節（總數） |
BRF = Sum(HB(n) - HE(n)) 其中 GC(n) = Full |
| 恢復的字節（總數） |
BRT = BRM + BRF |
| 恢復的字節（每次小收集） |
BRPM = BRM / TMC |
| 恢復的字節（每次完全收集） |
BRPF = BRF / TMF |
| 恢復的字節（小收集每秒） |
BRP = BRM / TTMC |
| 恢復的字節（完全收集每秒） |
BRF = BRF / TTFC |
可以從公式中看出，我們經常需要分別考慮完全 GC 和小 GC。小 GC 與完全 GC 有根本性的不同，一般來說前者至少比后者要快一個數量級。我們可以通過快速分析清單 1 看出這一點 —— 最長的小收集比完全收集快 50 倍。
下面表 2 顯示對清單 1 中的值使用表 1 中的公式的結果。
表 2. Sun GC 日志分析
| 統計 |
計算（時間單位調整為秒） |
| 運行時持續時間 |
(69.886 + 0.0017877) - 69.713 = 0.1747877 |
| 小收集總數 |
5 |
| 完全收集總數 |
1 |
| 收集頻率（小收集） |
5 / 0.1747877 = 28.6 per second |
| 收集頻率（完全） |
1 / 0.1747877 = 5.27 per second |
| 收集時間（最長的小收集） |
0.0032621 |
| 收集時間（最長的完全收集） |
0.1429698 |
| 小收集的時間（總數） |
0.0123469 |
| 完全收集的時間（總數） |
0.1429698 |
| 收集的時間（總數） |
0.1553167 |
| 小收集的時間（平均） |
7.1% |
| 完全收集的時間（平均） |
81.8% |
| 收集的時間（平均） |
88.9% |
| 收集間隔（平均） |
.173/5=0.0346 |
| 分配的字節（總數） |
3292 |
| 分配的字節（每秒） |
18834 Kb/second |
| 分配的字節（每次收集） |
549 Kb |
| 小收集恢復的字節（總數） |
3270 Kb |
| 完全收集恢復的字節（總數） |
5901 Kb |
| 恢復的字節（總數） |
5901 + 3270 = 9171 Kb |
| 恢復的字節（每次小收集） |
3270/5 = 654 |
| 恢復的字節（每次完全收集） |
5901/1 = 5901 |
| 恢復的字節（小收集每秒） |
3270/0.0123469 = 264843 Kb/second |
| 恢復的字節（完全收集每秒） |
5901/0.1429698 = 41274K/second |
表 2 包含從這些看來簡單的日志中推算出的大量信息。取決于所關注的問題，可能不需要計算所有這些值，因為其中一些值比另一些更有用。對于應用程序長時間不響應的情況，要關注的是 GC 持續時間和計數。
IBM GC 日志記錄
與 Sun 日志不同，IBM 日志特別冗長。即使這樣，仍然需要一個指導以完全理解所提供的信息。清單 2 是這種 verbose:gc 日志文件的一部分。
清單 2. IBM JVM verbose:gc 輸出
<AF[31]: Allocation Failure. need 528 bytes, 969 ms since last AF>
<AF[31]: managing allocation failure, action=1 (0/97133320) (1082224/1824504)>
<GC(31): GC cycle started Wed Feb 25 23:08:41 2004
<GC(31): freed 36259000 bytes, 37% free (37341224/98957824), in 569 ms>
<GC(31): mark: 532 ms, sweep: 37 ms, compact: 0 ms>
<GC(31): refs: soft 0 (age >= 32), weak 0, final 2, phantom 0>
<AF[31]: managing allocation failure, action=3 (37341224/98957824)>
<GC(31): need to expand mark bits for 116324864-byte heap>
<GC(31): expanded mark bits by 270336 to 1818624 bytes>
<GC(31): need to expand alloc bits for 116324864-byte heap>
<GC(31): expanded alloc bits by 270336 to 1818624 bytes>
<GC(31): need to expand FR bits for 116324864-byte heap>
<GC(31): expanded FR bits by 544768 to 3637248 bytes>
<GC(31): expanded heap by 17367040 to 116324864 bytes, 47% free, ratio:0.417>
<AF[31]: completed in 812 ms>
<AF[32]: Allocation Failure. need 528 bytes, 1765 ms since last AF>
<AF[32]: managing allocation failure, action=1 (0/115394264) (930600/930600)>
<GC(32): GC cycle started Wed Feb 25 23:08:43 2004
<GC(32): freed 54489184 bytes, 47% free (55419784/116324864), in 326 ms>
<GC(32): mark: 292 ms, sweep: 34 ms, compact: 0 ms>
<GC(32): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[32]: completed in 328 ms>
<AF[33]: Allocation Failure. need 528 bytes, 1686 ms since last AF>
<AF[33]: managing allocation failure, action=1 (0/115510592) (814272/814272)>
<GC(33): GC cycle started Wed Feb 25 23:08:45 2004
<GC(33): freed 56382392 bytes, 49% free (57196664/116324864), in 323 ms>
<GC(33): mark: 285 ms, sweep: 38 ms, compact: 0 ms>
<GC(33): refs: soft 0 (age >= 32), weak 0, final 18, phantom 0>
<AF[33]: completed in 324 ms>
|
清單 2 中有三項 GC 日志記錄。我將不會提供完全的說明，而是推薦一篇由 Sam Borman 所寫的很好的文章“Sensible Sanitation”（請參閱 參考資料）。對于我們的目的，需要與像對 Sun JVM 的日志那樣推算出同樣類型的信息。好的方面是有一些計算結果已經是現成的了。例如，如果分析 AF[31] （事件 31 分配失敗），將會看到 GC 之間的間隔、恢復的內存數量、事件的持續時間。我們可以根據這些數字計算其他所需要的值。
這些數字有什么意義
如何看待這些數字取決于所要得到的結果。在許多服務器應用程序中，它歸結為縮短暫停時間，這又歸結為減少所發生的完全收集的持續時間和次數。下個月，我們將探討如何用這些信息調優曾經受這個問題困擾的一個真實應用程序。
參考資料
作者簡介
|
|
|
Kirk Pepperdine 是 Java Performance Tuning.com 的首席技術官，并且在過去 15 年一直關注對象技術和性能調優。Kirk 是 Ant Developer's Handbook （MacMillan）一書的合著者。 | |