JDK-8010780 : G1: Eden occupancy/capacity output wrong after a full GC
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: hs24,hs25
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2013-03-25
  • Updated: 2013-09-18
  • Resolved: 2013-04-11
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 7 JDK 8 Other
7u40Fixed 8Fixed hs24Fixed
Related Reports
Relates :  
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.
26-03-2013

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.
25-03-2013