Understanding G1 GC Logs

Thepurpose of this post is to explain the meaning of GC logs generated with some tracing and diagnostic options for G1 GC. We will take a look at the output generated with PrintGCDetailswhich is a product flag and provides the most detailed level of information.  Along with that, we will also look at the output of two diagnostic flags that get enabled with -XX:+UnlockDiagnosticVMOptionsoption -G1PrintRegionLivenessInfothat prints the occupancy and the amount of space used by live objects in each region at the end of the marking cycle and G1PrintHeapRegionsthat provides detailed information on the heap regions being allocated and reclaimed.

本文讲解G1垃圾回收器产生的日志信息，这些日志常常用于诊断和追踪JVM的运行时情况，有如下几个参数需要用到：

PrintGCDetails、UnlockDiagnosticVMOptions、G1PrintRegionLivenessInfo、G1PrintHeapRegions

Wewill be looking at the logs generated with JDK 1.7.0_04 using theseoptions.

Option-XX:+PrintGCDetails

Here's a sample log of G1 collection generated with PrintGCDetails.

 0.522: [GC pause (young), 0.15877971 secs]
   [Parallel Time: 157.1 ms]
      [GC Worker Start (ms):  522.1  522.2  522.2  522.2
       Avg: 522.2, Min: 522.1, Max: 522.2, Diff:   0.1]
      [Ext Root Scanning (ms):  1.6  1.5  1.6  1.9
       Avg:   1.7, Min:   1.5, Max:   1.9, Diff:   0.4]
      [Update RS (ms):  38.7  38.8  50.6  37.3
       Avg:  41.3, Min:  37.3, Max:  50.6, Diff:  13.3]
         [Processed Buffers : 2 2 3 2
          Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]
      [Scan RS (ms):  9.9  9.7  0.0  9.7
       Avg:   7.3, Min:   0.0, Max:   9.9, Diff:   9.9]
      [Object Copy (ms):  106.7  106.8  104.6  107.9
       Avg: 106.5, Min: 104.6, Max: 107.9, Diff:   3.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 4 4 6
          Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5]
      [GC Worker End (ms):  679.1  679.1  679.1  679.1
       Avg: 679.1, Min: 679.1, Max: 679.1, Diff:   0.1]
      [GC Worker (ms):  156.9  157.0  156.9  156.9
       Avg: 156.9, Min: 156.9, Max: 157.0, Diff:   0.1]
      [GC Worker Other (ms):  0.3  0.3  0.3  0.3
       Avg:   0.3, Min:   0.3, Max:   0.3, Diff:   0.0]
   [Clear CT:   0.1 ms]
   [Other:   1.5 ms]
      [Choose CSet:   0.0 ms]
      [Ref Proc:   0.3 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   0.3 ms]
   [Eden: 12M(12M)->0B(10M) Survivors: 0B->2048K Heap: 13M(64M)->9739K(64M)]
 [Times: user=0.59 sys=0.02, real=0.16 secs]

This is the typical log of an Evacuation Pause (G1 collection) in which live objects are copied from one set of regions (young OR  young+old) to another set. It is a stop-the-world activity and all the application threads are stopped at a safepoint during this time.

G1回收器的某些阶段需要导致应用程序暂停，上面是在一个典型的暂停时间段中，GC打印出的日志信息，它展示了将Young或代者Young+Old代中还存活的对象，从一个Region集合拷贝到另一个Region集合这个过程的详细信息，在这个拷贝的时间段中，应用程序的运行线程需要在安全点暂停（stop-the-world）。

This pause is made up of several sub-tasks indicated by the indentation in the log entries. Here's is the top most line that gets printed for the Evacuation Pause.

0.522:[GC pause (young), 0.15877971 secs]

This is the highest level information telling us that it is an Evacuation Pause that started at 0.522 secs from the start of the process, in which all the regions being evacuated are Young i.e. Eden and Survivor regions. This collection took 0.15877971 secs to finish.

这是一个最顶层的日志信息，表示在进程启动0.522秒后，开始了一次对Young代的垃圾回收，这次垃圾回收所消耗的时间为0.15877971秒，也就是说，应用程序在这次垃圾回收阶段至少暂停了0.15877971秒。

Evacuation Pauses can be mixed as well. In which case the set of regions selected include all of the young regions as well as some old regions.

在某些情况下，在这个暂停的时间段中，在对Young代进行回收的同时，还有可能对Old代进行回收，因此还会产生如下形式的日志：

1.730:[GC pause (mixed), 0.32714353 secs]

Let's take a look at all the sub-tasks performed in this Evacuation Pause.

[Parallel Time: 157.1 ms]

Parallel Time is the total elapsed time spent by all the parallel GC worker threads. The following lines correspond to the parallel tasks performed by these worker threads in this total parallel time, whichin this case is 157.1 ms. 

Parallel Time表示所有并行的GC工作线程(如果没有特殊说明，本文后续的所有线程均表示GC的工作线程)从第一个线程启动到最后一个线程结束这个阶段所经历的时间，从上面的日志中可以看出，从第一个参与并行的线程开始启动到最后一个参与并行的线程退出所花费的时间为157.1毫秒。

[GC Worker Start (ms): 522.1 522.2 522.2 522.2
Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1]

The first line tells us the start time of each of the worker thread in milliseconds. The start times are ordered with respect to the worker thread ids – thread 0 started at 522.1ms and thread 1started at 522.2ms from the start of the process. The second line tells the Avg, Min, Max and Diff of the start times of all of theworker threads.

上面日志的第一行表示各个线程开始启动的时刻(以毫秒为单位)，对线程ID排序的结果决定了这些时刻的显示顺序，在上面的日志中，0号线程的启动时刻为进程启动后522.1毫秒处，1号线程的启动时刻为进程启动后522.2毫秒处，以此类推。上面日志的第二行显示了这些线程启动时刻的一些统计信息，比如Avg、Min、Max、Diff，就拿上面的日志来说，四个线程启动的平均时间点为进程启动后522.2毫秒处，最小的启动时刻为522.1毫秒处，最大的启动时刻为522.2毫秒处，最大启动时间和最小启动时间的差值为0.1毫秒。

[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4]

This gives us the time spent by each worker thread scanning the roots(globals, registers, thread stacks and VM data structures). Here,thread 0 took 1.6ms to perform the root scanning task and thread 1 took 1.5 ms. The second line clearly shows the Avg, Min, Max and Diff of the times spent by all the worker threads.

上面的日志信息表示各个线程对roots信息进行扫描所花费的时间，roots信息包括全局信息globals、寄存器信息registers、线程的栈信息thread  stacks、虚拟机的数据结构信息VM data structures，从上面的日志可以看出，0号GC工作线程在扫描这些信息的时候花费了1.6ms，1号工作线程在扫描这些信息的时候，花费了1.5ms，以此类推。第二行是根据第一行的日志信息所计算出的统计信息，比如各个线程扫描roots信息所花费时间的平均值Avg，最小值Min，最大值Max，最大值Max与最小值Min的差值Diff。

本文后续有很多的日志信息的第二行都是对第一行日志信息的统计值，因此，后续日志的这些统计值，本文不再进行讲解。

[Update RS (ms): 38.7 38.8 50.6 37.3
Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3]

Update RS gives us the time each thread spent in updating the Remembered Sets. Remembered Sets are the data structures that keep track of the references that point into a heap region. Mutator threads keep changing the object graph and thus the references that point into a particular region. We keep track of these changes in buffers called Update Buffers.The Update RS sub-task processes the update buffers that were not able to be processed concurrently, and updates the corresponding remembered sets of all regions.

上面的日志显示了各个工作线程在更新Remembered Sets所花费的时间，Remembered Set是一个数据结构，简写为RS，每个Region都有一个RS与之关联，Region A所关联的RS中记录了其它Region中对Region A中对象的引用，也就是说，如果在其它Region中存在对Region A中对象的引用（用C/C++来说，就是其它Region中有指针指向了Region A中的对象），那么Region A中的RS都会将这些引用记录下来。

想要了解RS和CS的详细信息，可以参考：Oracle官方的G1指南 和 一篇详细介绍G1收集器的日志

[Processed Buffers : 2 2 3 2
Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1]

This tells us the number of Update Buffers (mentioned above) processed by each worker thread.

[Scan RS (ms): 9.9 9.7 0.0 9.7
Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9]

These are the times each worker thread had spent in scanning theRemembered Sets. Remembered Set of a region contains cards thatcorrespond to the references pointing into that region. This phasescans those cards looking for the references pointing into all theregions of the collection set.

[Object Copy (ms): 106.7 106.8 104.6 107.9
Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3]

These are the times spent by each worker thread copying live objectsfrom the regions in the Collection Set to the other regions.

[Termination (ms): 0.0 0.0 0.0 0.0
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]

Termination time is the time spent by the worker thread offering toterminate. But before terminating, it checks the work queues of otherthreads and if there are still object references in other workqueues, it tries to steal object references, and if it succeeds instealing a reference, it processes that and offers to terminateagain.

[Termination Attempts : 1 4 4 6
Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5]

This gives the number of times each thread has offered to terminate.

[GC Worker End (ms): 679.1 679.1 679.1 679.1
Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1]

These are the times in milliseconds at which each worker threadstopped.

[GC Worker (ms): 156.9 157.0 156.9 156.9
Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1]

These are the total lifetimes of each worker thread.

[GC Worker Other (ms): 0.3 0.3 0.3 0.3
Avg: 0.3, Min: 0.3, Max: 0.3, Diff: 0.0]

These are the times that each worker thread spent in performing someother tasks that we have not accounted above for the total ParallelTime.

[Clear CT: 0.1 ms]

This is the time spent in clearing the Card Table. This task isperformed in serial mode.

[Other: 1.5 ms]

Timespent in the some other tasks listed below. Thefollowing sub-tasks (which individually may be parallelized) areperformed serially.

[Choose CSet: 0.0 ms]

Time spent in selecting the regions for the Collection Set.

[Ref Proc: 0.3 ms]

Total time spent in processing Reference objects.

[Ref Enq: 0.0 ms]

Time spent in enqueuing references to the ReferenceQueues.

[Free CSet: 0.3 ms]

Time spent in freeing the collection set data structure.

[Eden: 12M(12M)->0B(13M) Survivors: 0B->2048K Heap:14M(64M)->9739K(64M)]

Thisline gives the details on the heap size changes with the EvacuationPause. This shows that Eden had the occupancy of 12M and its capacitywas also 12M before the collection. After the collection, itsoccupancy got reduced to 0 since everything is evacuated/promotedfrom Eden during a collection, and its target size grew to 13M.Thenew Eden capacity of 13M is not reserved at this point. This value isthe target size of the Eden. Regions are added to Eden as the demandis made and when the added regions reach to the target size, we startthe next collection.

Similarly,Survivors had the occupancy of 0 bytes and it grew to 2048K after thecollection. The total heap occupancy and capacity was 14M and 64Mreceptively before the collection and it became 9739K and 64M afterthe collection.

Apart from the evacuation pauses, G1 also performs concurrent-markingto build the live data information of regions.

1.416: [GC pause (young) (initial-mark), 0.62417980 secs]
…....
2.042: [GC concurrent-root-region-scan-start]
2.067: [GC concurrent-root-region-scan-end, 0.0251507]
2.068: [GC concurrent-mark-start]
3.198: [GC concurrent-mark-reset-for-overflow]
4.053: [GC concurrent-mark-end, 1.9849672 sec]
4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
4.090: [GC concurrent-cleanup-start]
4.091: [GC concurrent-cleanup-end, 0.0002721] 

The first phase of a marking cycle is Initial Marking where all theobjects directly reachable from the roots are marked and this phaseis piggy-backed on a fully young Evacuation Pause.

2.042:[GC concurrent-root-region-scan-start]

This marks the start of aconcurrent phase that scans the set of root-regions which aredirectly reachable from the survivors of the initial markingphase.

2.067:[GC concurrent-root-region-scan-end, 0.0251507]

End of the concurrent root region scan phase and it lasted for 0.0251507 seconds.

2.068:[GC concurrent-mark-start]

Start of the concurrent marking at 2.068 secs from the start of theprocess.

3.198:[GC concurrent-mark-reset-for-overflow]

This indicates that the global marking stack had became full andthere was an overflow of the stack. Concurrent marking detected thisoverflow and had to reset the data structures to start the markingagain.

4.053:[GC concurrent-mark-end, 1.9849672 sec]

End of the concurrent marking phase and it lasted for 1.9849672seconds.

4.055:[GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs]

This corresponds to the remark phase which is a stop-the-world phase.It completes the left over marking work (SATB buffers processing)from the previous phase. In this case, this phase took 0.0030184 secsand out of which 0.0000254 secs were spent on Reference processing.

4.088:[GC cleanup 117M->106M(138M), 0.0015198 secs]

Cleanup phase which is again a stop-the-world phase. It goes throughthe marking information of all the regions, computes the live datainformation of each region, resets the marking data structures andsorts the regions according to their gc-efficiency. In this example,the total heap size is 138M and after the live data counting it wasfound that the total live data size dropped down from 117M to 106M.

4.090:[GC concurrent-cleanup-start]

This concurrent cleanup phase frees up the regions that were found tobe empty (didn't contain any live data) during the previousstop-the-world phase.

4.091:[GC concurrent-cleanup-end, 0.0002721]

Concurrent cleanup phase took 0.0002721 secs to free up the emptyregions.

Option-XX:G1PrintRegionLivenessInfo

Now, let's look at the output generated with the flagG1PrintRegionLivenessInfo. This is a diagnostic option and getsenabled with -XX:+UnlockDiagnosticVMOptions.G1PrintRegionLivenessInfo prints the live data information of eachregion during the Cleanup phase of the concurrent-markingcycle.

26.896:[GC cleanup
###PHASE Post-Marking @ 26.896
###HEAP committed: 0x02e00000-0x0fe00000 reserved:0x02e00000-0x12e00000 region-size: 1048576

Cleanup phase of the concurrent-marking cycle started at 26.896 secsfrom the start of the process and this live data information isbeing printed after the marking phase. Committed G1 heap ranges from0x02e00000 to 0x0fe00000 and the total G1 heap reserved by JVM isfrom 0x02e00000 to 0x12e00000. Each region in the G1 heap is of size1048576 bytes.

### type address-range used prev-live next-live gc-eff
### (bytes) (bytes) (bytes) (bytes/ms)

This is the header of the output that tells us about the type of theregion, address-range of the region, used space in the region, livebytes in the region with respect to the previous marking cycle, livebytes in the region with respect to the current marking cycle and theGC efficiency of that region.

### FREE 0x02e00000-0x02f00000 0 0 0 0.0

This is a Free region.

### OLD 0x02f00000-0x03000000 1048576 1038592 1038592 0.0

Old region with address-range from 0x02f00000 to 0x03000000. Totalused space in the region is 1048576 bytes, live bytes as per theprevious marking cycle are 1038592 and live bytes with respect to thecurrent marking cycle are also 1038592. The GC efficiency has beencomputed as 0.

### EDEN 0x03400000-0x03500000 20992 20992 20992 0.0

This is an Eden region.

### HUMS 0x0ae00000-0x0af00000 1048576 1048576 1048576 0.0
### HUMC 0x0af00000-0x0b000000 1048576 1048576 1048576 0.0
### HUMC 0x0b000000-0x0b100000 1048576 1048576 1048576 0.0
### HUMC 0x0b100000-0x0b200000 1048576 1048576 1048576 0.0
### HUMC 0x0b200000-0x0b300000 1048576 1048576 1048576 0.0
### HUMC 0x0b300000-0x0b400000 1048576 1048576 1048576 0.0
### HUMC 0x0b400000-0x0b500000 1001480 1001480 1001480 0.0

These are the continuous set of regions called Humongous regions forstoring a large object. HUMS (Humongous starts) marks the start ofthe set of humongous regions and HUMC (Humongous continues) tags thesubsequent regions of the humongous regions set.

### SURV 0x09300000-0x09400000 16384 16384 16384 0.0

This is a Survivor region.

###SUMMARY capacity: 208.00 MB used: 150.16 MB / 72.19 % prev-live:149.78 MB / 72.01 % next-live: 142.82 MB / 68.66 %

At the end, a summary is printed listing the capacity, the used spaceand the change in the liveness after the completion of concurrentmarking. In this case, G1 heap capacity is 208MB, total used space is150.16MB which is 72.19% of the total heap size, live data in theprevious marking was 149.78MB which was 72.01% of the total heap sizeand the live data as per the current marking is 142.82MB which is68.66% of the total heap size.

Option-XX:+G1PrintHeapRegions

G1PrintHeapRegions optionlogs the regions related events when regions are committed, allocatedinto or are reclaimed.

COMMIT/UNCOMMIT events

G1HR COMMIT[0x6e900000,0x6ea00000]
G1HR COMMIT [0x6ea00000,0x6eb00000]

Here, the heap is being initialized or expanded and theregion (with bottom: 0x6eb00000 and end: 0x6ec00000) is being freshlycommitted. COMMIT events are always generated in order i.e. the nextCOMMIT event will always be for the uncommitted region with thelowest address.

G1HR UNCOMMIT[0x72700000,0x72800000]
G1HR UNCOMMIT [0x72600000,0x72700000]

Opposite to COMMIT. The heap got shrunk at the end of aFull GC and the regions are being uncommitted. Like COMMIT, UNCOMMITevents are also generated in order i.e. the next UNCOMMIT event willalways be for the committed region with the highest address.

GC Cycle events

G1HR #StartGC 7
G1HR CSET0x6e900000
G1HR REUSE 0x70500000
G1HR ALLOC(Old)0x6f800000
G1HR RETIRE 0x6f800000 0x6f821b20
G1HR #EndGC 7

This shows start and end of an Evacuation pause. Thisevent is followed by a GC counter tracking both evacuation pauses andFull GCs. Here, this is the 7th GC since the start of the process.

G1HR #StartFullGC 17
G1HRUNCOMMIT [0x6ed00000,0x6ee00000]
G1HR POST-COMPACTION(Old)0x6e800000 0x6e854f58
G1HR #EndFullGC 17

Shows start and end of a Full GC. This event is alsofollowed by the same GC counter as above. This is the 17th GC sincethe start of the process.

ALLOC events

G1HR ALLOC(Eden) 0x6e800000

The region with bottom 0x6e800000 just started beingused for allocation. In this case it is an Eden region and allocatedinto by a mutator thread.

G1HR ALLOC(StartsH) 0x6ec000000x6ed00000
G1HR ALLOC(ContinuesH) 0x6ed00000 0x6e000000

Regions being used for the allocation of Humongousobject. The object spans over two regions.

G1HR ALLOC(SingleH) 0x6f9000000x6f9eb010

Single region being used for the allocation ofHumongous object.

G1HR COMMIT[0x6ee00000,0x6ef00000]
G1HR COMMIT [0x6ef00000,0x6f000000]
G1HRCOMMIT [0x6f000000,0x6f100000]
G1HR COMMIT[0x6f100000,0x6f200000]
G1HR ALLOC(StartsH) 0x6ee000000x6ef00000
G1HR ALLOC(ContinuesH) 0x6ef00000 0x6f000000
G1HRALLOC(ContinuesH) 0x6f000000 0x6f100000
G1HR ALLOC(ContinuesH)0x6f100000 0x6f102010

Here, Humongous object allocation request could not besatisfied by the free committed regions that existed in the heap, sothe heap needed to be expanded. Thus new regions are committed andthen allocated into for the Humongous object.

G1HR ALLOC(Old) 0x6f800000

Old region started being used for allocation during GC.

G1HR ALLOC(Survivor) 0x6fa00000

Region being used for copying old objects into during aGC.

Note that Eden and Humongous ALLOC events are generatedoutside the GC boundaries and Old and Survivor ALLOC events aregenerated inside the GC boundaries.

Other Events

G1HR RETIRE 0x6e800000 0x6e87bd98

Retire and stop using the region having bottom0x6e800000 and top 0x6e87bd98 for allocation.

Note that most regions are full when they are retiredand we omit those events to reduce the output volume. A region isretired when another region of the same type is allocated or we reachthe start or end of a GC(depending on the region). So for Edenregions:

For example:

1. ALLOC(Eden) Foo
2. ALLOC(Eden) Bar
3. StartGC

At point 2, Foo has just been retired and it was full.At point 3, Bar was retired and it was full. If they were not fullwhen they were retired, we will have a RETIRE event:

1. ALLOC(Eden) Foo
2. RETIRE Foo top
3.ALLOC(Eden) Bar
4. StartGC

G1HR CSET 0x6e900000

Region (bottom: 0x6e900000) is selected for theCollection Set. The region might have been selected for thecollection set earlier (i.e. when it was allocated). However, wegenerate the CSET events for all regions in the CSet at the start ofa GC to make sure there's no confusion about which regions are partof the CSet.

G1HR POST-COMPACTION(Old)0x6e800000 0x6e839858

POST-COMPACTION event is generated for each non-emptyregion in the heap after a full compaction. A full compaction movesobjects around, so we don't know what the resulting shape of the heapis (which regions were written to, which were emptied, etc.). To dealwith this, we generate a POST-COMPACTION event for each non-emptyregion with its type (old/humongous) and the heap boundaries. At thispoint we should only have Old and Humongous regions, as we havecollapsed the young generation, so we should not have eden andsurvivors.

POST-COMPACTION events are generated within the Full GCboundary.

G1HR CLEANUP 0x6f400000
G1HRCLEANUP 0x6f300000
G1HR CLEANUP 0x6f200000

These regions were found empty after remark phase ofConcurrent Marking and are reclaimed shortly afterwards.

G1HR #StartGC 5
G1HR CSET0x6f400000
G1HR CSET 0x6e900000
G1HR REUSE 0x6f800000

At the end of a GC we retire the old region we areallocating into. Given that its not full, we will carry on allocatinginto it during the next GC. This is what REUSE means. In the abovecase 0x6f800000 should have been the last region with an ALLOC(Old)event during the previous GC and should have been retired before theend of the previous GC.

G1HR ALLOC-FORCE(Eden) 0x6f800000

A specialization of ALLOC which indicates that we havereached the max desired number of the particular region type (in thiscase: Eden), but we decided to allocate one more. Currently it's onlyused for Eden regions when we extend the young generation because wecannot do a GC as the GC-Locker is active.

G1HR EVAC-FAILURE 0x6f800000

During a GC, we have failed to evacuate an object fromthe given region as the heap is full and there is no space left tocopy the object. This event is generated within GC boundaries andexactly once for each region from which we failed to evacuateobjects.

When Heap Regions are reclaimed?

It is also worth mentioning when the heap regions inthe G1 heap are reclaimed.

• All regions that are inthe CSet (the ones that appear in CSET events) are reclaimed at theend of a GC. The exception to that are regions with EVAC-FAILUREevents.

• All regions withCLEANUP events are reclaimed.

• After a Full GC some regions get reclaimed (theones from which we moved the objects out). But that is not shownexplicitly, instead the non-empty regions that are left in the heapare printed out with the POST-COMPACTION events.

Oracle 官网有很多好的Blog，欢迎大家前去阅读：https://blogs.oracle.com

本文来自：https://blogs.oracle.com/poonam/entry/understanding_g1_gc_logs