JDK-7022456 : G1: Significant memory footprint increase compared to other collectors during application startup
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: hs21
  • Priority: P4
  • Status: Closed
  • Resolution: Other
  • OS: generic
  • CPU: generic
  • Submitted: 2011-02-25
  • Updated: 2020-06-18
  • Resolved: 2020-06-18
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.
Other
tbdResolved
Related Reports
Relates :  
JDK-8058952 - G1 sizing policy increases heap according to gc time ratio too aggressively
Relates :  
JDK-6929868 - G1: introduce min / max young gen size bounds
Relates :  
JDK-5049299 - (process) Use posix_spawn, not fork, on S10 to avoid swap exhaustion
Description
Application fails to start with G1 on particular machine with a crash. The machine has 5G of memory and java is run with -Xmx2621440K (2560M). 

The failure appears to be caused by combination of two factors: 
1. Increase in footprint for G1: although live objects never occupy more than 350M, the heap quickly grows to 2.4G (see attached gc_g1.log). Compared with Serial GC and CMS, it is 5x, compared with Parallel GC, it is ~2x.

The process size as reported by top is 2.6G. Here is the progress:
$ grep '\-\>' gc_g1.log 
   [ 1023K->470K(80M)]
   [ 11M->3016K(80M)]
   [ 21M->8512K(80M)]
   [ 29M->15M(80M)]
   [ 24M->19M(80M)]
   [ 42M->29M(160M)]
   [ 51M->37M(320M)]
   [ 49M->38M(640M)]
   [ 64M->40M(1024M)]
   [ 89M->44M(1332M)]
   [ 107M->46M(1578M)]
   [ 125M->54M(1775M)]
   [ 122M->65M(1932M)]
   [ 149M->78M(2058M)]
   [ 151M->79M(2159M)]
   [ 209M->93M(2240M)]
   [ 157M->105M(2304M)]
   [ 202M->121M(2356M)]
   [ 209M->128M(2397M)]
   [ 273M->152M(2430M)]
   [ 214M->158M(2456M)]
   [ 314M->161M(2477M)]

See below for other collectors data.

2. the fact that application spawns child processes during startup, essentially doubling the process size and it causes swap exhaustion (see 5049299).

Logs for other GCs for comparison:

Serial GC (max old gen ~220M, process size ~500M)
...
47.138: [GC 47.138: [DefNew: 65528K->3095K(66240K), 0.1228152 secs] 193276K->135631K(212688K), 0.1232398 secs] [Times: user=0.16 sys=0.00, real=0.12 secs] 
48.050: [GC 48.051: [DefNew: 61975K->5073K(66240K), 0.1061452 secs] 194511K->137609K(212688K), 0.1066077 secs] [Times: user=0.20 sys=0.00, real=0.11 secs] 
48.895: [GC 48.895: [DefNew: 63953K->4899K(66240K), 0.1189718 secs] 196489K->138745K(212688K), 0.1194711 secs] [Times: user=0.24 sys=0.00, real=0.12 secs] 
49.697: [GC 49.697: [DefNew: 63779K->4996K(66240K), 0.1143990 secs] 197625K->140077K(212688K), 0.1148809 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] 

CMS (max old gen ~220M, process size 500M):
...
47.557: [GC 47.557: [ParNew: 19056K->2112K(19136K), 0.0139841 secs] 177006K->160114K(223248K), 0.0145109 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
47.761: [GC 47.762: [ParNew: 19136K->1690K(19136K), 0.0359526 secs] 177138K->161568K(223248K), 0.0364501 secs] [Times: user=0.21 sys=0.00, real=0.04 secs] 
47.986: [GC 47.986: [ParNew: 18714K->2112K(19136K), 0.0126478 secs] 178592K->161994K(223248K), 0.0131672 secs] [Times: user=0.10 sys=0.01, real=0.01 secs] 
48.193: [GC 48.194: [ParNew: 19136K->2112K(19136K), 0.0309732 secs] 179018K->163064K(223248K), 0.0316050 secs] [Times: user=0.21 sys=0.01, real=0.03 secs] 

Parallel GC (max old gen ~750M, process size 1G):
...
39.500: [GC [PSYoungGen: 411824K->30731K(501632K)] 501936K->120843K(669568K), 0.4409441 secs] [Times: user=1.42 sys=0.67, real=0.44 secs] 
45.469: [GC [PSYoungGen: 480843K->32788K(501440K)] 570955K->122900K(669376K), 0.3268305 secs] [Times: user=1.41 sys=0.51, real=0.33 secs] 
50.500: [GC [PSYoungGen: 482900K->36737K(581568K)] 573012K->126849K(749504K), 0.5064412 secs] [Times: user=1.47 sys=0.94, real=0.51 secs]
Comments
G1 has for a long time now used actual GC time ratio to drive expansion of the heap as suggested as a potential fix. There is JDK-8238687 that aims to extend this to heap shrinking. So I am closing this. If this is still an issue, please file a new bug with a reproducer to investigate.
18-06-2020
WORK AROUND Using GCTimeRatio (correctly! see Eval comment #3) can decrease the probability of G1 increasing the heap size this aggressively. If this does become a problem in some sitatuations, the max heap size can be constrained by decreasing -Xmx.
29-03-2011
EVALUATION The reason G1 increases the footprint so aggressively for this application is what I originally thought which is that the GC overhead of the app seems to be quite high early on and G1 expands the heap according to its policy (i.e. expand the heap if GC overhead > target GC overhead == 10% by default). The reason why the test that Nicolay did with GCTimeRatio=80 was not successful was my fault. Unfortunately, the GCTimeRatio parameter is interpreted as an app:GC time ratio, not as a percentage. So, GCTimeRatio=80 will dictate that the GC should take no more than 1.2%. I meant to say that this should be 20%, and the right setting for this is GCTimeRatio=4. Apologies to Nicolay! Heres's some data to back my claim. The default GC percentage target is 10%. I created an awk script that reproduces the heustic calculations that G1 does. Here's the output from this script run on a GC log that I got from this app on jtg-t2000-12c. The columns are: time stamp (sec), GC time (ms), overhead (%), committed size (K). 2.22 44.94 2.0 114688.0 2.33 35.83 3.4 114688.0 2.85 19.61 3.5 114688.0 4.13 82.65 4.3 114688.0 4.50 97.39 6.1 114688.0 4.87 86.05 7.4 114688.0 5.76 106.83 8.1 114688.0 6.49 85.39 8.5 114688.0 6.94 84.37 9.2 114688.0 7.46 18.36 8.8 114688.0 8.00 23.36 11.1 114688.0 8.55 31.23 10.2 229376.0 9.69 78.67 10.1 458752.0 10.96 233.71 12.1 917504.0 11.75 143.71 12.2 1468416.0 12.36 72.53 11.7 1908736.0 13.61 44.47 10.5 2260992.0 14.83 174.13 10.7 2543616.0 15.40 134.11 11.2 2768896.0 16.26 141.47 12.1 2949120.0 17.41 148.94 12.6 3093504.0 18.75 115.78 12.5 3209216.0 19.77 233.07 14.1 3301376.0 20.56 149.65 14.3 3375104.0 22.55 76.88 12.0 3434496.0 24.04 86.15 11.2 3481600.0 25.50 113.83 11.5 3519488.0 26.60 124.97 11.3 3550208.0 29.71 138.55 9.3 3574784.0 31.11 134.90 8.9 3574784.0 ... Note that there's a clear correlation between the overhead being > 10% (the default) and the committed space expanding (this expansion happens just after the pause is finished which is why it looks as if it happens during the next pause). Here's also the output from this script on the last G1 log that Nicolay posted: 2.12 35.22 1.6 114688.0 2.25 10.94 2.0 229376.0 2.98 34.34 2.7 458752.0 3.98 54.43 3.3 917504.0 5.13 108.12 4.6 1468416.0 5.71 141.41 6.6 1908736.0 6.28 149.03 8.3 2260992.0 7.14 123.68 9.0 2543616.0 8.07 75.58 9.0 2768896.0 8.67 70.90 9.2 2949120.0 9.75 98.67 11.3 3093504.0 ... But the target overhead was set to 1.2% which is why G1 expanded the heap at every GC. I attached a log (gc-g1-b131-XXGCTimeRatio-4.log) I got with JDK 7 b131 and GCTimeRatio=4 (i.e., a GC overhead target of 20%). The log shows that the higher GC overhead target does keep the heap smaller early on, at least compared to the other two logs. But, the heap does grow to its maximum eventually. The awk script shows us why: 1.86 36.08 1.9 114688.0 1.97 6.72 2.2 114688.0 2.89 46.23 3.0 114688.0 3.48 97.24 5.2 114688.0 4.03 106.98 7.1 114688.0 ... 12.86 16.79 15.6 114688.0 13.01 40.54 16.4 114688.0 13.15 13.94 18.6 114688.0 13.28 26.76 20.3 114688.0 13.40 41.00 21.6 229376.0 14.57 38.19 13.4 458752.0 16.35 204.60 11.5 458752.0 17.32 168.30 12.2 458752.0 18.26 122.63 12.1 458752.0 19.85 230.48 12.4 458752.0 ... 193.80 78.39 19.2 458752.0 194.11 73.41 20.1 458752.0 194.43 57.85 21.6 917504.0 194.53 116.72 24.0 1468416.0 194.70 145.68 28.0 1908736.0 195.18 34.24 26.8 2260992.0 195.36 49.50 28.4 2543616.0 195.73 53.62 26.9 2768896.0 196.10 80.69 26.3 2949120.0 196.59 80.66 25.0 3093504.0 197.54 83.59 20.7 3209216.0 198.01 97.95 20.4 3301376.0 ... At some points in time the GC overhead goes even higher than 20% which causes G1 to expand the heap.
29-03-2011
EVALUATION With -XX:GCTimeRatio=80 the picture is same (if not worse): [ 5120K->1461K(80M)] [ 4533K->2056K(160M)] [ 12M->5536K(320M)] [ 15M->8991K(640M)] [ 28M->15M(1024M)] [ 24M->19M(1332M)] [ 30M->24M(1578M)] [ 37M->30M(1775M)] [ 44M->36M(1932M)] [ 51M->41M(2058M)] [ 57M->44M(2159M)] [ 61M->46M(2240M)] [ 81M->50M(2304M)] [ 68M->53M(2356M)] [ 89M->60M(2397M)] [ 97M->68M(2430M)] [ 105M->76M(2456M)] [ 95M->80M(2477M)] [ 118M->88M(2494M)] [ 107M->90M(2508M)] [ 128M->92M(2519M)] [ 130M->94M(2528M)] [ 170M->103M(2535M)] [ 122M->106M(2540M)] [ 144M->115M(2544M)] [ 153M->124M(2548M)] [ 162M->133M(2551M)] [ 152M->138M(2553M)] [ 157M->140M(2555M)] [ 178M->142M(2556M)] [ 180M->150M(2557M)] [ 188M->158M(2558M)] [ 196M->170M(2559M)] [ 189M->175M(2560M)] [ 213M->182M(2560M)] [ 220M->185M(2560M)] ... With -XX:GCTimeRatio=60: [ 5120K->1555K(80M)] [ 4627K->2214K(160M)] [ 12M->5664K(320M)] [ 15M->9080K(640M)] [ 18M->12M(1024M)] [ 28M->18M(1332M)] [ 29M->24M(1578M)] [ 37M->29M(1775M)] [ 44M->36M(1932M)] [ 51M->41M(2058M)] [ 57M->45M(2159M)] [ 62M->48M(2240M)] [ 66M->50M(2304M)] [ 86M->56M(2356M)] [ 92M->63M(2397M)] [ 82M->67M(2430M)] [ 104M->75M(2456M)] [ 113M->83M(2477M)] [ 121M->90M(2494M)] [ 128M->92M(2508M)] [ 130M->94M(2519M)] [ 132M->98M(2528M)] [ 136M->102M(2535M)] [ 140M->109M(2540M)] [ 147M->119M(2544M)] [ 157M->127M(2548M)] [ 165M->136M(2551M)] [ 174M->141M(2553M)] [ 179M->144M(2555M)] [ 182M->152M(2556M)] [ 190M->160M(2557M)] [ 179M->165M(2558M)] [ 203M->175M(2559M)] [ 194M->181M(2560M)] [ 219M->184M(2560M)] [ 222M->186M(2560M)] [ 224M->188M(2560M)] [ 226M->190M(2560M)] [ 227M->191M(2560M)] [ 240M->194M(2560M)] ... Note: the machine is T2000 zone with 8 vcpus.
09-03-2011
WORK AROUND Setting -XX:GCTimeRatio=80 or 70 might force G1 to be less aggressive in expanding the heap.
08-03-2011
EVALUATION G1 expands the heap differently than our other GCs. It monitors its GC overhead and if it goes over a certain limit it expands the heap in an attempt to introduce more space in the heap, hopefully space out the GCs, and reduce the GC overhead. This GC overhead limit is set with the GCTimeRatio parameter which by default is set to 90 for G1 (90 meaning: 90% app / 10% GC). Does the issue remain if GCTimeRatio=80?
08-03-2011
WORK AROUND Increase swap on the machine.
25-02-2011