GC輸出澄清

Question

我運行具有以下設置Java應用程序：
-XX：+ CMSParallelRemarkEnabled
-XX：+ UseConcMarkSweepGC
-XX：+ UseParNewGC
-XX：+ PrintGCApplicationStoppedTime
-XX ：+ PrintGCApplicationConcurrentTime
-XX：+ PrintGCDetails
-XX：+ PrintGCTimeStamps
-XX：+ PrintGCDateStamps
-XX：+ PrintHeapAtGC
-XX：+ PrintTenuringDistribution

我不知道如何解釋相關的gc日誌（如下）。特別是：

• 堆後GC調用= 31（滿3）：這是否意味着有31個小的選區，和3個完整的GC？

• 什麼觸發了該應用程序的線程被停止和應用時間的總時間的連續數行？是否有可能得到與每一行相關的時間戳？

GC日誌：

 
Total time for which application threads were stopped: 0.0046910 seconds 
Application time: 0.7946670 seconds 
Total time for which application threads were stopped: 0.0002900 seconds 
Application time: 1.0153640 seconds 
Total time for which application threads were stopped: 0.0002780 seconds 
Application time: 1.0161890 seconds 
Total time for which application threads were stopped: 0.0002760 seconds 
Application time: 1.0145990 seconds 
Total time for which application threads were stopped: 0.0002950 seconds 
Application time: 0.9999800 seconds 
Total time for which application threads were stopped: 0.0002770 seconds 
Application time: 1.0151640 seconds 
Total time for which application threads were stopped: 0.0002730 seconds 
Application time: 0.9996590 seconds 
Total time for which application threads were stopped: 0.0002880 seconds 
Application time: 0.9624290 seconds 

{Heap before GC invocations=30 (full 3): 
par new generation total 131008K, used 130944K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000) 
    eden space 130944K, 100% used [0x00000000eac00000, 0x00000000f2be0000, 0x00000000f2be0000) 
    from space 64K, 0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000) 
    to space 64K, 0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000) 
concurrent mark-sweep generation total 131072K, used 48348K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000) 
concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000) 

2010-05-11T09:30:13.888+0100: 384.955: [GC 384.955: [ParNew 
Desired survivor size 32768 bytes, new threshold 0 (max 0) 
: 130944K->0K(131008K), 0.0052470 secs] 179292K->48549K(262080K), 0.0053030 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

Heap after GC invocations=31 (full 3): 
par new generation total 131008K, used 0K [0x00000000eac00000, 0x00000000f2c00000, 0x00000000f2c00000) 
    eden space 130944K, 0% used [0x00000000eac00000, 0x00000000eac00000, 0x00000000f2be0000) 
    from space 64K, 0% used [0x00000000f2be0000, 0x00000000f2be0000, 0x00000000f2bf0000) 
    to space 64K, 0% used [0x00000000f2bf0000, 0x00000000f2bf0000, 0x00000000f2c00000) 
concurrent mark-sweep generation total 131072K, used 48549K [0x00000000f2c00000, 0x00000000fac00000, 0x00000000fac00000) 
concurrent-mark-sweep perm gen total 30000K, used 19518K [0x00000000fac00000, 0x00000000fc94c000, 0x0000000100000000) 
} 

Total time for which application threads were stopped: 0.0056410 seconds 
Application time: 0.0475220 seconds 
Total time for which application threads were stopped: 0.0001800 seconds 
Application time: 1.0174830 seconds 
Total time for which application threads were stopped: 0.0003820 seconds 
Application time: 1.0126350 seconds 
Total time for which application threads were stopped: 0.0002750 seconds 
Application time: 1.0155910 seconds 
Total time for which application threads were stopped: 0.0002680 seconds 
Application time: 1.0155580 seconds 
Total time for which application threads were stopped: 0.0002880 seconds 
Application time: 1.0155480 seconds 
Total time for which application threads were stopped: 0.0002970 seconds 
Application time: 0.9896810 seconds 

Answer 1

沒有時間戳的那些行不是gc事件，它們記錄了安全點出現的時間和持續的時間。在6月21日前，他們有點不可靠。

Answer 2

是的，那是次要的和主要收藏數量在一起。有28個小型GC和3個主要GC。

次要集合會觸發您引用的那些行。如果沒有時間戳，我認爲你不能強迫他們修改JVM。然而，我的理解是，「應用程序時間」是應用程序自上次次要收集（暫停）以來運行的時間，因此可能會給你想要的。我相信，自上次輸出以來，至少有一個時間增量。

Answer 3

您將擁有與每個條目對應的時間戳。

從我的服務器日誌的例子說明

124951.831: [GC 1915727K->1295438K(1994752K), 0.1964641 secs] 
Total time for which application threads were stopped: 0.1983187 seconds 
125015.262: [GC 1909838K->1302111K(1994752K), 0.2037094 secs] 
Total time for which application threads were stopped: 0.2055489 seconds 

的124951.831和125015.262在這種情況下是以來的JVM經過秒的數量已經開始。

124951.831對應JVM運行時間34小時，42分鐘，31秒。

125015.262對應JVM運行時間34小時，43分鐘，35秒。

您必須將此向後關聯到服務器啓動時間，因此您可以獲取時間戳。

區別很重要（125015 - 124951）表明小型GC在64秒後踢了（在我的情況下）。

您的日誌中是否缺少這些時間戳記行？