2010-04-15 70 views
3

我們有一個對延遲敏感的應用程序,並且遇到了一些我們不完全瞭解的與GC有關的暫停。我們偶爾會有一個小的GC,導致應用程序暫停時間比報告的GC時間本身長得多。下面是一個例子日誌片段:什麼會導致較小的GC時間和總暫停時間之間的較大差異?

485377.257:[GC 485378.857:[ParNew:105845K-> 621K(118016K),0.0028070秒] 136492K-> 31374K(1035520K)0.0028720秒] [時間:用戶= 0.01 SYS = 0.00,實際= 1.61秒]
針對應用程序的線程被停止的總時間:1.6032830

這裏的總停留時間是數量級比報道的GC時間。這些是孤立的和偶然的事件:緊接着的前面和後面的次要GC事件不顯示這種大的差異。

該進程運行在專用機器上,擁有大量可用內存,8個內核,運行內核爲2.6.9-89.0.1EL-smp的Red Hat Enterprise Linux ES Release 4 Update 8。我們已經觀察到(32位)JVM版本1.6.0_13和1.6.0_18。

我們正在與這些標誌運行:

-server電子藝界-Xms512m -Xmx512m -XX:+ UseConcMarkSweepGC -XX:新尺寸=128米-XX:MaxNewSize =128米-XX:+ PrintGCDetails -XX: + PrintGCTimeStamps -XX:+ PrintGCApplicationStoppedTime -XX:-TraceClassUnloading

人都可以提供一些解釋,以什麼可能怎麼回事,和/或一些途徑進行進一步的調查?

回答

0

你說有「大量的可用內存」,但你的堆大小限制在512MB。您可能會比您想象的更頻繁/更早地耗盡內存。

4

你肯定你不換?通常看到:

時報:用戶= 0.01 SYS = 0.00,實際= 1.61秒

(從你的跟蹤)

表明,一些在這個過程中發生不佔用CPU,但確實需要掛鐘時間...這通常是交換或其他I/O。有點iostat可能有助於擺脫燈光...

你是否在Java堆外使用了大量本地內存? (可能通過DirectByteBuffer,nio等),這可能會侵蝕你的「大量的自由內存」聲明(很讓你意外)。 'top'或者vmstat也可能會顯示出來。

2

「時間安全點」是這類事情的廣泛原因。不幸的是,GC僅記錄從開始工作(在所有應用程序線程已經在安全點暫停之後)到完成(之後線程將從其安全點釋放)之間的時間。 -XX:+ PrintGCApplicationStoppedTime(更準確地說)報告從告訴第一個線程到安全點到最後一個線程被釋放再次運行的時間。

不幸的是,看到一個線程需要很長時間才能到達安全點,並且當發生這種情況時,所有其他的好的和禮貌的線程都會轉到一個安全點,並在被告知時暫停,直到落後者進來。這種事情的例子是長時間運行的操作。例如。克隆對象數組是在大多數JVM中沒有內部安全點機會的情況下完成的(想象克隆一個1GB數組,並且在中間需要進行GC暫停)。您自己的優化計數循環也可以在沒有內部安全點的情況下運行很長時間。

[Zing有一個內置的安全時間分析器,部分用於跟蹤和擊敗這類事情]。

相關問題