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秒后踢了（在我的情况下）。

您的日志中是否缺少这些时间戳记行？