United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-8010780 G1: Eden occupancy/capacity output wrong after a full GC
JDK-8010780 : G1: Eden occupancy/capacity output wrong after a full GC

Details
Type:
Bug
Submit Date:
2013-03-25
Status:
Resolved
Updated Date:
2013-05-14
Project Name:
JDK
Resolved Date:
2013-04-11
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P3
Resolution:
Fixed
Affected Versions:
hs24,hs25
Fixed Versions:
hs25 (b29)

Related Reports
Backport:
Backport:
Backport:
Relates:
Relates:

Sub Tasks

Description
Received the following report from the performance team and it is hampering their tuning efforts.

In the G1 logs, the information printed for the pause following a full GC is misleading.

Here's an example from Jenny Zhang:

JDK version:
java(TM) SE Runtime Environment (build 1.8.0-ea-b78)
Java HotSpot(TM) 64-Bit Server VM (build 25.0-b19, mixed mode)

OS: Linux x64
Linux sc14ia05 2.6.39-200.24.1.el6uek.x86_64 #1 SMP Sat Jun 23 02:39:07 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux

In the gc log, sometimes I see lines like:
 [Eden: 2368.0M(1840.0M)->0.0B(1632.0M) Survivors: 0.0B->304.0M Heap: 20.7G(36.0G)->20.2G(36.0G)]

The used is larger than the capacity of the Eden.

Lines before this:
411.322: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 519 regions, reclaimable: 3980609520 bytes (10.30 %), threshold: 10.00 %]
 (to-space exhausted), 0.4279260 secs]
   [Parallel Time: 391.9 ms, GC Workers: 18]
      [GC Worker Start (ms): Min: 410894.1, Avg: 410894.5, Max: 410894.9, Diff: 0.8]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 1.2, Diff: 1.2, Sum: 3.3]
      [Update RS (ms): Min: 21.7, Avg: 22.5, Max: 22.9, Diff: 1.2, Sum: 405.0]
         [Processed Buffers: Min: 54, Avg: 78.1, Max: 98, Diff: 44, Sum: 1405]
      [Scan RS (ms): Min: 6.5, Avg: 6.5, Max: 6.6, Diff: 0.1, Sum: 117.6]
      [Object Copy (ms): Min: 361.6, Avg: 361.7, Max: 361.8, Diff: 0.3, Sum: 6511.0]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms): Min: 390.8, Avg: 391.1, Max: 391.5, Diff: 0.8, Sum: 7040.2]
      [GC Worker End (ms): Min: 411285.6, Avg: 411285.6, Max: 411285.7, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 2.9 ms]
   [Other: 33.1 ms]
      [Choose CSet: 0.3 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.3 ms]
   [Eden: 0.0B(1840.0M)->0.0B(1840.0M) Survivors: 0.0B->0.0B Heap: 36.0G(36.0G)->36.0G(36.0G)]
 [Times: user=1.13 sys=0.10, real=0.43 secs]
 411.335: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: allocation request failed, allocation request: 56 bytes]
 411.335: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 16777216 bytes, attempted expansion amount: 16777216 bytes]
 411.335: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap expansion operation failed]
411.336: [Full GC (Allocation Failure)  35G->18G(36G), 8.0471890 secs]
 [Times: user=8.50 sys=0.01, real=8.05 secs]
433.639: [GC pause (G1 Evacuation Pause) (young) 433.640: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 26203, predicted base time: 13.50 ms, remaining time: 186.50 ms, target pause time: 200.00 ms]
 433.640: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 148 regions, survivors: 0 regions, predicted young region time: 164.22 ms]
 433.640: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 148 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 177.72 ms, target pause time: 200.00 ms]
 433.895: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 21458059264 bytes, allocation request: 0 bytes, threshold: 17394617520 bytes (45.00 %), source: end of GC]
, 0.2552910 secs]
   [Parallel Time: 251.1 ms, GC Workers: 18]
      [GC Worker Start (ms): Min: 433640.7, Avg: 433640.9, Max: 433641.1, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 1.0, Diff: 1.0, Sum: 2.9]
      [Update RS (ms): Min: 6.6, Avg: 11.4, Max: 67.4, Diff: 60.8, Sum: 204.3]
         [Processed Buffers: Min: 2, Avg: 6.7, Max: 18, Diff: 16, Sum: 121]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.8]
      [Object Copy (ms): Min: 182.8, Avg: 238.8, Max: 242.7, Diff: 59.9, Sum: 4298.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.7]
      [GC Worker Total (ms): Min: 250.3, Avg: 250.5, Max: 250.7, Diff: 0.5, Sum: 4509.0]
      [GC Worker End (ms): Min: 433891.4, Avg: 433891.4, Max: 433891.5, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 3.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.3 ms]
   [Eden: 2368.0M(1840.0M)->0.0B(1632.0M) Survivors: 0.0B->304.0M Heap: 20.7G(36.0G)->20.2G(36.0G)]

The line that is misleading here is:

   [Eden: 2368.0M(1840.0M)->0.0B(1632.0M) Survivors: 0.0B->304.0M Heap: 

It looks like the occupancy of eden is much, much more than it's capacity.
                                    

Comments
Proposed output:

7.281: [Full GC (Allocation Failure)  256M->221M(256M), 13.9717389 secs]
   [Eden: 0.0B(12.0M)->0.0B(12.0M) Survivors: 0.0B->0.0B Heap: 256.0M(256.0M)->221.7M(256.0M)]
 [Times: user=16.41 sys=0.10, real=13.97 secs] 

This reuses the routine G1CollectorPolicy::print_detailed_heap_transition().

Note the output could be changed to match that suggested by Poonam in JDK-8010738 to also include perm (only for hs24) and whether the detailed info should be additional or replace the existing information.
                                     
2013-03-26
URL:   http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/71013d764f6e
User:  johnc
Date:  2013-04-11 21:12:52 +0000

                                     
2013-04-11
URL:   http://hg.openjdk.java.net/hsx/hsx25/hotspot/rev/71013d764f6e
User:  amurillo
Date:  2013-04-19 20:07:30 +0000

                                     
2013-04-19
The problem is that we have recalculated the target eden capacity after the full GC but we do not update the field, in G1CollectorPolciy, that holds the previous eden capacity. That field is only updated after an incremental pause with the new eden capacity.

Fortunately, at the start of both incremental and full GCs, the value in G1CollectorPolicy::_target_young_length, and the values in G1YoungList::_survivor_bytes, and in G1YoungList::_eden_bytes are valid. Hence the eden capacity can be calculated (and stored) at the start of a GC.

Additionally, printing out a more detailed heap size transition after a full GC would also be helpful.  
                                     
2013-03-25



Hardware and Software, Engineered to Work Together