g1gc logs - Ergonomics -how to print and how to understand

Introduction

Ever wondered how g1 decide which regions should be included in the collection set, when to trigger the concurrent marking cycle, or why stops mixed gc?  You can get that information from -XX:+PrintAdaptiveSizePolicy

The Parameters:

In addition to the basic parameters -XX:+PrintGCTimeStamps -XX:+PrintGCDetails mentioned in previous blog how to print and how to understand - basic, add -XX:+PrintAdaptiveSizePolicy

The Outputs:

The output from basic gc details is skipped here. Please refer to blog how to print and how to understand - basic.

Young GC

Here I posted the Ergonomic output for a young gc. At the end of this gc, g1 requests the concurrent marking cycle.

135.210: [GC pause (G1 Evacuation Pause) (young) 135.210: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 42639, predicted base time: 20.23 ms, remaining time: 79.77 ms, target pause time: 100.00 ms]

135.210: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 140 regions, survivors: 20 regions, predicted young region time: 805.95 ms]

135.210: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 140 regions, survivors: 20 regions, old: 0 regions, predicted pause time: 826.18 ms, target pause time: 100.00 ms]

136.332: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 45.64 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]

136.332: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 48586817536 bytes, allocation request: 0 bytes, threshold: 48318382080 bytes (45.00 %), source: end of GC]

The 1st line prints out the number of cards to be processed: 42639, predicted time to process those cards: 20.23 ms, since target pause time is 100.00ms, there is 79.77ms left

The 2nd line shows the number of regions in the young gen added to the collection set: eden: 140 regions, survivors: 20 regions, old: 0 regions, predicted pause time: 826.18 ms, target pause time: 100.00 ms

The 4th line shows g1 tries to expand the heap, since gc overhead(45.64 %) is over the threshold(10.00%)

The 5th line shows that the concurrent marking cycle is requested, since the heap occupancy (48586817536 bytes) is higher than the threshold 45% of the total heap (48318382080 bytes)

After the marking cycles are done, sometimes, young gc has a line like this:

252.240: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 498 regions, reclaimable: 14269425416 bytes (13.29 %), threshold: 10.00 %]

This indicates mixed gcs will be started, as the reclaimable heap 13.29% is higher than the threshold 10%

Mixed GC

Mixed gc has additional information about how old regions are included in the CSet

2014-07-16T11:18:36.296-0700: 252.374: [GC pause (G1 Evacuation Pause) (mixed) 252.374: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 40891, predicted base time: 13.74 ms, remaining time: 86.26 ms, target pause time: 100.00 ms]

252.374: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 28 regions, survivors: 4 regions, predicted young region time: 222.55 ms]

252.374: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 2.62 ms, remaining time: 0.00 ms, old: 63 regions, min: 63 regions]

252.374: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 63 regions, expensive: 63 regions, min: 63 regions, remaining time: 0.00 ms]

252.374: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 28 regions, survivors: 4 regions, old: 63 regions, predicted pause time: 387.05 ms, target pause time: 100.00 ms]

253.028: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 43.76 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]

253.028: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 435 regions, reclaimable: 12312176992 bytes (11.47 %), threshold: 10.00 %]

The 3rd line shows g1 can not add more old regions to CSet since the predicted time is already over the target pause time. However, g1 is requested to add minimum old regions (63) to CSet.

The 4th line shows that g1 added 63 old regions to meet the minimum requirement.

The last line indicates the next gc is mixed gc as well, since the reclaimable heap after this gc is 11.47%, higher then the threshold 10%.

Thresholds and Parameters:

We mentioned a lot of thresholds. Here we will explain what those thresholds are and how to control them.  The numbers in <> is the default value.

  • -XX:MaxGCPauseMillis=<200>
  • In the gc log, we saw some entries like: "target pause time: 100.00 ms". This is controlled by MaxGCPauseMillis.  This is a very important parameter as g1 adjusts heap generations sizes to meet this goal.
  • -XX:G1NewSizePercent=<5>  -XX:G1MaxNewSizePercent=<60>
  • Sometimes we see that g1 does not push Eden size low enough to meet the gc pause goal, or does not have big Eden though still below the pause time goal. Please check if these 2 parameters are limiting the range of Eden that g1 can control ergonomically. G1NewSizePercent defines minimum percentage young gen over the heap size. G1MaxNewSizePercent defines maximum percentage young gen over the heap size.
  • -XX:InitiatingHeapOccupancyPercent=<45>
  • This parameter defines when g1 initiate marking phase. In the gc log
    136.332: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 48586817536 bytes, allocation request: 0 bytes, threshold: 48318382080 bytes (45.00 %), source: end of GC]
    The threshold 48318382080 bytes is 45% of the heap size. Specifying this number too much lower under the live data set might waste the marking work.
  • -XX:G1HeapWastePercent=<10>
  • G1 decides starting/continue mixed gc based on allowed wasted. This parameter indicates if the reclaimable heap is below this percentage, g1 will stop collecting. You can see this threshold in gc log

    253.028: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 435 regions, reclaimable: 12312176992 bytes (11.47 %), threshold: 10.00 %]

    252.240: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 498 regions, reclaimable: 14269425416 bytes (13.29 %), threshold: 10.00 %]

  • -XX:G1MixedGCCountTarget=<8> -XX:+UnlockExperimentalVMOptions -XX:G1OldCSetRegionThresholdPercent=<10>
  • Under the mixed gc log, there is this log:
    252.374: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 63 regions, expensive: 63 regions, min: 63 regions, remaining time: 0.00 ms

    The total number of candicate regions devided by the G1MixedGCCountTarget is the minimum old regions added to CSet.

    Some times we see message like "old CSet region num reached max". G1OldCSetRegionThresholdPercent defines the percentage of the heap as the maximum number of old regions can be added to CSet.

  • -XX:+UnlockExperimentalVMOptions -XX:G1MixedGCLiveThresholdPercent=<65>
  • We do not see this reflected in the gc log, but some times this could be important, when the heap is tight. This means if a region's live data is above this percentage, g1 will not consider it as a candidate for mixed gc. If the heap is tight, you can try to increase it. However, since there are more live data, collecting this region can be more expensive.

Comments:

Post a Comment:
  • HTML Syntax: NOT allowed
About

Yu Zhang-Oracle

Search

Categories
Archives
« August 2015
SunMonTueWedThuFriSat
      
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
     
Today