|
級別: 初級
Jack Shirazi, 董事, JavaPerformanceTuning.com
Kirk Pepperdine, 首席技術(shù)官, JavaPerformanceTuning.com
2004 年 5 月 01 日
您的應(yīng)用程序是否經(jīng)常出現(xiàn) out-of-memory 錯誤？用戶是否感受到響應(yīng)時間有些不穩(wěn)定？應(yīng)用程序是否在相當(dāng)長的時間內(nèi)變得沒有響應(yīng)？應(yīng)用程序的性能是否顯得遲緩了？如果對任何一個問題的回答是肯定的，那么您很可能遇到了垃圾收集的問題了。先別進(jìn)行優(yōu)化，且聽聽 JavaPerformanceTuning.com 的 Jack Shirazi 和 Kirk Pepperdine 來解釋如何識別垃圾收集問題，并由此幫助您回答這個問題：您知道垃圾收集器在干什么嗎？
許多開發(fā)人員認(rèn)為，內(nèi)存管理至多是開發(fā)業(yè)務(wù)邏輯的主要任務(wù)之外的一項(xiàng)不重要的工作 —— 直到業(yè)務(wù)邏輯不能像預(yù)期的或者測試時那樣執(zhí)行得好。出現(xiàn)這種情況時，就需要知道哪里出錯了及其原因，這意味著要理解應(yīng)用程序如何與底層計(jì)算資源（特別是內(nèi)存）進(jìn)行交互。理解應(yīng)用程序如何利用內(nèi)存的最好方式是觀察垃圾收集器的行動。
為什么我的應(yīng)用程序不連貫了？
Java 虛擬機(jī)中最大的一個性能問題是應(yīng)用程序線程與同時運(yùn)行的 GC 的互斥性。垃圾收集器要完成其工作，需要在一段時間內(nèi)防止所有其他線程訪問它正在處理的堆空間（內(nèi)存）。按 GC 的術(shù)語，這段時間稱為“stop-the-world”，并且，正如其名字所表明的，在垃圾收集器努力工作時，應(yīng)用程序有一個急剎車。幸運(yùn)的是，這種暫停通常是很短的，很難察覺到，但是很容易想像，如果應(yīng)用程序在隨機(jī)的時刻出現(xiàn)隨機(jī)且較長時間的暫停，對應(yīng)用程序的響應(yīng)性和吞吐能力會有破壞性的影響。
不過 GC 只是應(yīng)用程序出現(xiàn)不連貫和停頓的一個原因。那么如何確定 GC 對產(chǎn)生這些問題是否負(fù)有責(zé)任呢？要回答這個問題，我們需要測量垃圾收集器的工作強(qiáng)度，并當(dāng)在系統(tǒng)中進(jìn)行改變時繼續(xù)這些測量，以定量地確定所做的改變是否有所期望的效果。
我需要多少內(nèi)存？
普遍接受的信念是，在系統(tǒng)中添加內(nèi)存將解決許多性能問題。雖然這個原則對于 JVM 來說經(jīng)常是正確的，但是太多好東西可能對性能是有害的。因此技巧在于 Java 應(yīng)用程序需要多少內(nèi)存就給它多少，但是絕不多給。問題是，應(yīng)用程序需要多少內(nèi)存？對于應(yīng)用程序不連貫的情況，我們需要觀察垃圾收集行為以了解看它做的是否比所需要的更多。這些觀察將告訴我們所做的改變是否有所期望的效果。
測量 GC 的活動
生成 GC 日志的標(biāo)準(zhǔn)方式是使用 -verbose:gc 旗標(biāo)，設(shè)置這個旗標(biāo)后，垃圾收集器會在每次運(yùn)行時生成它所做的事情的匯總，一般是寫入到控制臺（通過標(biāo)準(zhǔn)輸出或者標(biāo)準(zhǔn)錯誤）。許多 VM 支持一個允許 verbose GC 輸出轉(zhuǎn)向到一個文件的選項(xiàng)。例如，在 Sun 的 1.4 JVM 中，可以使用開關(guān) -Xloggc:filename 將 GC 輸出寫到文件中。對于 HP JVM，要使用 -Xverbosegc=file 開關(guān)。在本文中，我們將分析 Sun 1.4.2 和 IBM 1.4.1 JVM 捕獲的 verbose GC 輸出。
使用這個方法監(jiān)視內(nèi)存使用的一個最大好處是它對應(yīng)用程序的性能的影響很小。不幸的是，這個解決方案并不完美，因?yàn)檫@些日志文件可能變得特別大，而維護(hù)它們可能需要重新啟動 JVM。盡管如此，這種技術(shù)在生產(chǎn)環(huán)境中仍然是可行的，因?yàn)樗梢詭椭\斷只在這種環(huán)境中才列出的性能問題。
更深入觀察 GC
-verbose:gc 旗標(biāo)生成的輸出根據(jù) JVM 廠商而不同，不同的垃圾收集器選項(xiàng)會報告特定于該實(shí)現(xiàn)的信息。例如，由 IBM JVM 生成的輸出比由 Sun JVM 生成的輸出冗長得多，而 Sun 的輸出更適合于由工具讀取。就是說，每一個 GC 日志傳達(dá)基本信息 —— 使用了多少內(nèi)存、恢復(fù)了多少內(nèi)存、GC 周期用了多少時間，以及在收集期間是否采取了其他行動。從這些基本測量中，我們可以推斷出有助于更好地理解所發(fā)生的事情的細(xì)節(jié)。我們要計(jì)算的統(tǒng)計(jì)如下所示：
- 考慮的運(yùn)行時的持續(xù)時間
- 收集總數(shù)
- 收集頻率
- 收集所用最長時間
- 收集所用總時間
- 收集所用平均時間
- 收集的平均間隔
- 分配的字節(jié)總數(shù)
- 每次收集每秒分配的字節(jié)數(shù)
- 恢復(fù)的字節(jié)總數(shù)
- 每次收集每秒恢復(fù)的字節(jié)總數(shù)
理解了暫停時間，我們就可以理解 GC 對應(yīng)用程序不響應(yīng)是否負(fù)有部分或者全部責(zé)任了。一種實(shí)現(xiàn)這一任務(wù)的方法是將詳細(xì)（verbose） GC 日志中的 GC 活動與系統(tǒng)采集的其他日志（如 Web 服務(wù)器日志中的請求 backlog）相對應(yīng)。幾乎可以肯定最長的 GC 暫停會導(dǎo)致整個系統(tǒng)響應(yīng)可感覺的下降，所以知道什么時候響應(yīng)下降是很有用的，這樣就可以將 GC 活動與應(yīng)用程序吞吐相關(guān)聯(lián)起來。
另一種可能的競爭因素是堆內(nèi)存分配和恢復(fù)的比率，稱為 churn。產(chǎn)生大量立即釋放的對象的應(yīng)用程序通常會受到 churn 的拖累。更高的 churn 比率對垃圾收集器加以很大壓力，創(chuàng)造了更多的內(nèi)存資源競爭，這又可導(dǎo)致更長的暫停或者可怕的 OutOfMemoryError 。
了解應(yīng)用程序是否遭遇這些問題的一個方法是測量所考慮的整個運(yùn)行時期間 GC 所占用的總時間。有了這種計(jì)算，我們就可以了解 GC 做的是否比它所應(yīng)該做的更多。讓我們推導(dǎo)出進(jìn)行這種判斷所需要的公式。
Sun GC 日志記錄
清單 1 是由 Sun 1.4.2_03 JVM 以 -Xloggc:filename 運(yùn)行默認(rèn)的標(biāo)記-清除收集器所生成的日志記錄的例子。可以看到，日志項(xiàng)非常精確地記錄了每次所做的事情。
清單 1. 使用 -Xloggc:filename 旗標(biāo)的 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]
|
首先注意到的可能是每一項(xiàng)日志記錄是寫在一組方括號內(nèi)的。其他 GC 算法，如并發(fā)收集器， 可能將一些值分解為更細(xì)的信息。如果是這種情況，這些被分解的值會由包圍在嵌入的一組方括號中的細(xì)節(jié)所替代，這使工具可以更容易地處理詳細(xì) GC 輸出。
我們的研究首先從分析清單 1 中標(biāo)記為 69.713 的記錄開始。這個標(biāo)記是 JVM 開始后的秒數(shù)和毫秒數(shù)的時間戳。在這個例子中，JVM 在這個 GC 周期開始之前運(yùn)行了 69.713 秒。從左到右的字段為：執(zhí)行的收集的類型、GC 之前的堆使用、總的堆能力和 GC 事件的持續(xù)時間。從這個描述中我們可以看出第一個 GC 事件是一個小的收集。在 GC 開始之前，使用了 11536 Kb 的堆空間。在完成時，使用了 11044 Kb，堆能力為 12016 Kb，而整個收集用了 .0032621 秒。下一個事件，一個完全的 GC，在 69.717 秒時或者上一個小 GC 事件之后 0.003 秒時開始。注意，如果將小 GC 事件的持續(xù)時間加到其開始時間上，就會看到它在完全的 GC 開始之前不到 1毫秒結(jié)束。因此我們可以得出結(jié)論：小收集沒有恢復(fù)足夠的空間，這種失敗觸發(fā)了完全的 GC。對應(yīng)用程序來說，這像是一個持續(xù)了 0.1462319 秒的事件。讓我們繼續(xù)確定如何計(jì)算其他值。
GC 日志記錄的參數(shù)確定
我們通過確定每個 GC 日志記錄中的值的參數(shù)來開始分析：
R(n) = T(n): [ <GC> HB->HE(HC), D]
n |
清單中記錄的索引，1 是第一個，m 是最后一個 |
R(n) |
GC 記錄 |
T(n) |
第 n 個 GC 發(fā)生的時間 |
HB |
GC 之前堆的數(shù)量 |
HE |
GC 之后使用的堆數(shù)量 |
HC |
堆空間的總量 |
D |
GC 周期的持續(xù)時間 |
有了這些定義，我們現(xiàn)在可以推導(dǎo)出用于計(jì)算前面描述的值的公式。
基本值
我們要計(jì)算的第一個值是日志所覆蓋的運(yùn)行時整個持續(xù)時間。如果要考慮每一項(xiàng)記錄，那么就要分析最后一項(xiàng)記錄的時間戳。因?yàn)榍鍐?1 只表示全部日志記錄的一部分，我們需要從最后一項(xiàng)中提取出第一個時間戳。盡管對這個例子來說，這個數(shù)字足夠精確，但是為了絕對準(zhǔn)確，需要加上最后 GC 的持續(xù)時間。其原因是時間戳是在 GC 開始時記錄的，而記錄表示在記錄了時間戳以后發(fā)生的事情。
剩余值是取記錄中相應(yīng)的值的總和計(jì)算的。值得注意的是恢復(fù)的字節(jié)可以通過分析記錄中測量的關(guān)系而計(jì)算，而分配的字節(jié)可以通過分析前后記錄測量之間的關(guān)系計(jì)算。例如，如果考慮在時間戳 69.872 和 69.878 之間發(fā)現(xiàn)的記錄對，可以用第一個記錄中 GC 之后占用的內(nèi)存數(shù)量減去第二個記錄在 GC 之前占用的字節(jié)數(shù)量計(jì)算在新的一代（generation）中分配的字節(jié)數(shù)量： 6248 Kb - 5418 Kb = 830 Kb 。下面表 1 展示了其他值的公式。
要找出最長的 GC 暫停，我們只需要查看持續(xù)時間并尋找 D(n) （記錄 n 的持續(xù)時間）的最大值。
表 1. 統(tǒng)計(jì)公式
| 統(tǒng)計(jì) |
計(jì)算（時間單位調(diào)整為秒） |
| 運(yùn)行時持續(xù)時間 |
RT = (T(M) + D(M)) - T(1) |
| 小收集的總數(shù) |
TMC = Sum( R(n)) 其中 GC(n) = GC |
| 完全收集的總數(shù) |
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 |
| 小收集的時間（總數(shù)） |
TTMC = Sum(D(n)) for all n 其中 GC(n) = GC |
| 完全收集的時間（總數(shù)） |
TTFC Sum(D(n)) for all n 其中 GC(n) = Full |
| 收集的時間（總數(shù)） |
TTC = TTMC + TTFC |
| 小收集的時間（平均） |
ATMC = TTMC / RT |
| 完全收集的時間（平均） |
ATFC = TTFC / RT |
| 收集的時間（平均） |
ATC = TTC / RT |
| 收集間隔（平均） |
Sum( T(n+1) - T(n)) / (TMC + TFC) for all n |
| 分配的字節(jié)（總數(shù)） |
TBA = Sum(HB(n+1) - HE(n)) 對于所有 n |
| 分配的字節(jié)（每秒） |
TBA / RT |
| 分配的字節(jié)（每次收集） |
TBA / (TMC + TFC) |
| 小收集恢復(fù)的字節(jié)（總數(shù)） |
BRM = Sum(HB(n) - HE(n)) 其中 GC(n) = GC |
| 完全收集恢復(fù)的字節(jié)（總數(shù)） |
BRF = Sum(HB(n) - HE(n)) 其中 GC(n) = Full |
| 恢復(fù)的字節(jié)（總數(shù)） |
BRT = BRM + BRF |
| 恢復(fù)的字節(jié)（每次小收集） |
BRPM = BRM / TMC |
| 恢復(fù)的字節(jié)（每次完全收集） |
BRPF = BRF / TMF |
| 恢復(fù)的字節(jié)（小收集每秒） |
BRP = BRM / TTMC |
| 恢復(fù)的字節(jié)（完全收集每秒） |
BRF = BRF / TTFC |
可以從公式中看出，我們經(jīng)常需要分別考慮完全 GC 和小 GC。小 GC 與完全 GC 有根本性的不同，一般來說前者至少比后者要快一個數(shù)量級。我們可以通過快速分析清單 1 看出這一點(diǎn) —— 最長的小收集比完全收集快 50 倍。
下面表 2 顯示對清單 1 中的值使用表 1 中的公式的結(jié)果。
表 2. Sun GC 日志分析
| 統(tǒng)計(jì) |
計(jì)算（時間單位調(diào)整為秒） |
| 運(yùn)行時持續(xù)時間 |
(69.886 + 0.0017877) - 69.713 = 0.1747877 |
| 小收集總數(shù) |
5 |
| 完全收集總數(shù) |
1 |
| 收集頻率（小收集） |
5 / 0.1747877 = 28.6 per second |
| 收集頻率（完全） |
1 / 0.1747877 = 5.27 per second |
| 收集時間（最長的小收集） |
0.0032621 |
| 收集時間（最長的完全收集） |
0.1429698 |
| 小收集的時間（總數(shù)） |
0.0123469 |
| 完全收集的時間（總數(shù)） |
0.1429698 |
| 收集的時間（總數(shù)） |
0.1553167 |
| 小收集的時間（平均） |
7.1% |
| 完全收集的時間（平均） |
81.8% |
| 收集的時間（平均） |
88.9% |
| 收集間隔（平均） |
.173/5=0.0346 |
| 分配的字節(jié)（總數(shù)） |
3292 |
| 分配的字節(jié)（每秒） |
18834 Kb/second |
| 分配的字節(jié)（每次收集） |
549 Kb |
| 小收集恢復(fù)的字節(jié)（總數(shù)） |
3270 Kb |
| 完全收集恢復(fù)的字節(jié)（總數(shù)） |
5901 Kb |
| 恢復(fù)的字節(jié)（總數(shù)） |
5901 + 3270 = 9171 Kb |
| 恢復(fù)的字節(jié)（每次小收集） |
3270/5 = 654 |
| 恢復(fù)的字節(jié)（每次完全收集） |
5901/1 = 5901 |
| 恢復(fù)的字節(jié)（小收集每秒） |
3270/0.0123469 = 264843 Kb/second |
| 恢復(fù)的字節(jié)（完全收集每秒） |
5901/0.1429698 = 41274K/second |
表 2 包含從這些看來簡單的日志中推算出的大量信息。取決于所關(guān)注的問題，可能不需要計(jì)算所有這些值，因?yàn)槠渲幸恍┲当攘硪恍└杏谩τ趹?yīng)用程序長時間不響應(yīng)的情況，要關(guān)注的是 GC 持續(xù)時間和計(jì)數(shù)。
IBM GC 日志記錄
與 Sun 日志不同，IBM 日志特別冗長。即使這樣，仍然需要一個指導(dǎo)以完全理解所提供的信息。清單 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 中有三項(xiàng) GC 日志記錄。我將不會提供完全的說明，而是推薦一篇由 Sam Borman 所寫的很好的文章“Sensible Sanitation”（請參閱 參考資料）。對于我們的目的，需要與像對 Sun JVM 的日志那樣推算出同樣類型的信息。好的方面是有一些計(jì)算結(jié)果已經(jīng)是現(xiàn)成的了。例如，如果分析 AF[31] （事件 31 分配失敗），將會看到 GC 之間的間隔、恢復(fù)的內(nèi)存數(shù)量、事件的持續(xù)時間。我們可以根據(jù)這些數(shù)字計(jì)算其他所需要的值。
這些數(shù)字有什么意義
如何看待這些數(shù)字取決于所要得到的結(jié)果。在許多服務(wù)器應(yīng)用程序中，它歸結(jié)為縮短暫停時間，這又歸結(jié)為減少所發(fā)生的完全收集的持續(xù)時間和次數(shù)。下個月，我們將探討如何用這些信息調(diào)優(yōu)曾經(jīng)受這個問題困擾的一個真實(shí)應(yīng)用程序。
參考資料
作者簡介
 |
|
|
Kirk Pepperdine 是 Java Performance Tuning.com 的首席技術(shù)官，并且在過去 15 年一直關(guān)注對象技術(shù)和性能調(diào)優(yōu)。Kirk 是 Ant Developer's Handbook （MacMillan）一書的合著者。 | |