Excessive minor garbage collection time

Question

We are having a problem with excessive minor GC time in our, at some point of the day, the the GC start increasing his CPU time the used eden space decreases and it keeps that way for a few hours. So,my question is, why could it be that the GC keeps working after a while if the eden space has already decreased and old gen is not full?

Also these are the gc logs:

35654.202: [GC (Allocation Failure) [PSYoungGen: 6927699K->158760K(9188864K)] 21881289K->15119270K(31558656K), 0.0641987 secs] [Times: user=0.46 sys=0.01, real=0.06 secs] 
35657.351: [GC (Allocation Failure) [PSYoungGen: 7265320K->106449K(9102336K)] 22225830K->15079895K(31472128K), 0.0558687 secs] [Times: user=0.42 sys=0.01, real=0.06 secs] 
35660.587: [GC (Allocation Failure) [PSYoungGen: 7213009K->50739K(9340928K)] 22186455K->15024184K(31710720K), 0.0533427 secs] [Times: user=0.37 sys=0.01, real=0.05 secs] 
35663.747: [GC (GCLocker Initiated GC) [PSYoungGen: 7475251K->118288K(9268224K)] 22448729K->15091765K(31638016K), 0.0565819 secs] [Times: user=0.43 sys=0.00, real=0.06 secs] 
35666.948: [GC (GCLocker Initiated GC) [PSYoungGen: 7542800K->133088K(9520128K)] 22516282K->15106571K(31889920K), 0.0579453 secs] [Times: user=0.42 sys=0.00, real=0.06 secs] 
35670.235: [GC (GCLocker Initiated GC) [PSYoungGen: 7898080K->460400K(9429504K)] 22871565K->15433884K(31799296K), 0.1234615 secs] [Times: user=0.92 sys=0.00, real=0.12 secs] 
35673.803: [GC (GCLocker Initiated GC) [PSYoungGen: 8225392K->333992K(9727488K)] 23215700K->15324301K(32097280K), 0.1232548 secs] [Times: user=0.70 sys=0.01, real=0.12 secs] 
35677.285: [GC (Allocation Failure) [PSYoungGen: 8493736K->772444K(9616896K)] 23484049K->15762757K(31986688K), 0.1639453 secs] [Times: user=1.27 sys=0.00, real=0.16 secs] 
35680.764: [GC (Allocation Failure) [PSYoungGen: 8932188K->553685K(9745920K)] 23922501K->15543997K(32115712K), 0.1294150 secs] [Times: user=0.89 sys=0.01, real=0.13 secs] 
35684.199: [GC (Allocation Failure) [PSYoungGen: 8804053K->867273K(9117696K)] 23794365K->15857586K(31487488K), 0.1873880 secs] [Times: user=1.31 sys=0.00, real=0.19 secs] 
35687.809: [GC (Allocation Failure) [PSYoungGen: 9115716K->1159141K(9382400K)] 24106029K->16163478K(31752192K), 0.2832391 secs] [Times: user=1.76 sys=0.01, real=0.29 secs] 
35691.288: [GC (Allocation Failure) [PSYoungGen: 9041381K->1305357K(9187840K)] 24045718K->16322144K(31557632K), 0.3632827 secs] [Times: user=2.19 sys=0.01, real=0.36 secs] 
35694.966: [GC (Allocation Failure) [PSYoungGen: 9187597K->1337198K(9070080K)] 24204389K->16391907K(31439872K), 0.2874729 secs] [Times: user=2.04 sys=0.01, real=0.29 secs] 
35695.275: [GC (GCLocker Initiated GC) [PSYoungGen: 1397874K->1025280K(9216000K)] 16452582K->16408831K(31585792K), 0.2539362 secs] [Times: user=1.84 sys=0.02, real=0.25 secs] 
35698.760: [GC (Allocation Failure) [PSYoungGen: 8272640K->1150789K(9151488K)] 23675376K->16558057K(31521280K), 0.2800219 secs] [Times: user=1.89 sys=0.02, real=0.28 secs] 
35699.180: [GC (GCLocker Initiated GC) [PSYoungGen: 1532509K->1257911K(8444928K)] 16939777K->16687262K(30814720K), 0.2502664 secs] [Times: user=1.81 sys=0.01, real=0.25 secs] 
35702.612: [GC (GCLocker Initiated GC) [PSYoungGen: 8444855K->2057201K(8287744K)] 23876741K->17717124K(30657536K), 0.4627608 secs] [Times: user=3.33 sys=0.01, real=0.46 secs] 
35705.765: [GC (GCLocker Initiated GC) [PSYoungGen: 8287729K->2316857K(8547840K)] 23973785K->18662968K(30917632K), 0.5713870 secs] [Times: user=4.35 sys=0.01, real=0.57 secs] 
35708.983: [GC (GCLocker Initiated GC) [PSYoungGen: 8547385K->1506000K(8211968K)] 24907890K->19799823K(30581760K), 0.7879174 secs] [Times: user=5.61 sys=0.05, real=0.78 secs] 
35712.170: [GC (Allocation Failure) [PSYoungGen: 7081168K->1507860K(8379904K)] 25385299K->20667366K(30749696K), 0.5480324 secs] [Times: user=3.84 sys=0.05, real=0.55 secs] 
35712.848: [GC (GCLocker Initiated GC) [PSYoungGen: 1827913K->78655K(8356352K)] 20987420K->20739404K(30726144K), 0.3986930 secs] [Times: user=2.84 sys=0.00, real=0.40 secs] 
35713.246: [Full GC (Ergonomics) [PSYoungGen: 78655K->0K(8356352K)] [ParOldGen: 20660749K->3040778K(22369792K)] 20739404K->3040778K(30726144K), [Metaspace: 221552K->221548K(258048K)], 1.8512788 secs] [Times: user=11.76 sys=0.03, real=1.85 secs] 
35717.558: [GC (Allocation Failure) [PSYoungGen: 5581312K->1725693K(7307264K)] 8661604K->4805985K(29677056K), 0.4301305 secs] [Times: user=2.80 sys=0.01, real=0.43 secs] 
35718.224: [GC (GCLocker Initiated GC) [PSYoungGen: 2387841K->238534K(8334848K)] 5468133K->5046571K(30704640K), 0.4111594 secs] [Times: user=3.21 sys=0.00, real=0.41 secs] 
35721.064: [GC (Allocation Failure) [PSYoungGen: 5701574K->1581940K(8312832K)] 10511283K->6596086K(30682624K), 0.3808009 secs] [Times: user=2.90 sys=0.00, real=0.38 secs] 
35721.784: [GC (GCLocker Initiated GC) [PSYoungGen: 2414567K->253910K(8349696K)] 7428713K->6850887K(30719488K), 0.4165103 secs] [Times: user=3.10 sys=0.00, real=0.41 secs] 
35724.563: [GC (GCLocker Initiated GC) [PSYoungGen: 5734870K->1430285K(8315904K)] 12349610K->8265856K(30685696K), 0.3546620 secs] [Times: user=2.77 sys=0.01, real=0.35 secs] 
35727.261: [GC (GCLocker Initiated GC) [PSYoungGen: 6911245K->1478134K(8395776K)] 13756073K->9453169K(30765568K), 0.5245972 secs] [Times: user=4.10 sys=0.01, real=0.53 secs] 
35730.136: [GC (GCLocker Initiated GC) [PSYoungGen: 7066614K->1547419K(8377344K)] 15070136K->10765885K(30747136K), 0.6109201 secs] [Times: user=4.32 sys=0.02, real=0.61 secs] 
35733.154: [GC (GCLocker Initiated GC) [PSYoungGen: 7135899K->1315619K(8498176K)] 16389479K->11807006K(30867968K), 0.5097489 secs] [Times: user=4.01 sys=0.01, real=0.51 secs] 
35736.104: [GC (Allocation Failure) [PSYoungGen: 7027491K->1522542K(8398336K)] 17520210K->13137985K(30768128K), 0.5651593 secs] [Times: user=4.15 sys=0.01, real=0.56 secs] 
35736.689: [GC (GCLocker Initiated GC) [PSYoungGen: 1565298K->15164K(8409088K)] 13180742K->13160418K(30778880K), 0.3819311 secs] [Times: user=2.84 sys=0.00, real=0.38 secs] 
35739.429: [GC (GCLocker Initiated GC) [PSYoungGen: 5756220K->1578503K(7320064K)] 18901477K->14735846K(29689856K), 0.3715531 secs] [Times: user=2.64 sys=0.01, real=0.37 secs] 
35742.119: [GC (GCLocker Initiated GC) [PSYoungGen: 7319559K->1281055K(8546816K)] 20496907K->15616628K(30916608K), 0.4926865 secs] [Times: user=3.79 sys=0.01, real=0.49 secs] 
35745.057: [GC (GCLocker Initiated GC) [PSYoungGen: 7085087K->1579244K(8441856K)] 21431613K->17081234K(30811648K), 0.6018703 secs] [Times: user=4.32 sys=0.01, real=0.60 secs] 
35748.080: [GC (GCLocker Initiated GC) [PSYoungGen: 7383276K->1613440K(8510976K)] 22885511K->18343626K(30880768K), 0.5818204 secs] [Times: user=4.48 sys=0.01, real=0.59 secs] 
35751.230: [GC (GCLocker Initiated GC) [PSYoungGen: 7474304K->1472378K(8522752K)] 24261077K->19432841K(30892544K), 0.5637150 secs] [Times: user=4.17 sys=0.03, real=0.57 secs] 
35754.213: [GC (GCLocker Initiated GC) [PSYoungGen: 7333242K->1598809K(8583680K)] 25293912K->20836636K(30953472K), 0.5915971 secs] [Times: user=4.50 sys=0.00, real=0.59 secs] 
35757.407: [GC (GCLocker Initiated GC) [PSYoungGen: 7573849K->1375973K(8576000K)] 26838408K->21485227K(30945792K), 0.5083576 secs] [Times: user=3.55 sys=0.00, real=0.51 secs] 
35760.359: [GC (GCLocker Initiated GC) [PSYoungGen: 7351013K->1586160K(8695808K)] 27465570K->22920840K(31065600K), 0.6046188 secs] [Times: user=4.46 sys=0.01, real=0.61 secs] 
35760.964: [Full GC (Ergonomics) [PSYoungGen: 1586160K->0K(8695808K)] [ParOldGen: 21334680K->2921003K(22369792K)] 22920840K->2921003K(31065600K), [Metaspace: 221580K->221580K(258048K)], 1.6722028 secs] [Times: user=10.73 sys=0.01, real=1.67 secs] 
35765.327: [GC (Allocation Failure) [PSYoungGen: 6193664K->1833280K(8027136K)] 9114677K->4754294K(30396928K), 0.3855252 secs] [Times: user=2.90 sys=0.00, real=0.39 secs] 
35765.769: [GC (GCLocker Initiated GC) [PSYoungGen: 2003858K->73942K(8417792K)] 4924871K->4835980K(30787584K), 0.4092414 secs] [Times: user=3.19 sys=0.01, real=0.41 secs] 
35768.720: [GC (Allocation Failure) [PSYoungGen: 5931734K->1597340K(8521216K)] 10722102K->6443313K(30891008K), 0.3837882 secs] [Times: user=2.78 sys=0.01, real=0.39 secs] 
35769.136: [GC (GCLocker Initiated GC) [PSYoungGen: 1684805K->20953K(8378368K)] 6530777K->6471287K(30748160K), 0.3673869 secs] [Times: user=2.79 sys=0.01, real=0.37 secs] 
35771.996: [GC (GCLocker Initiated GC) [PSYoungGen: 5747673K->1547724K(8455680K)] 12211551K->8023474K(30825472K), 0.3499080 secs] [Times: user=2.52 sys=0.01, real=0.35 secs] 
35774.772: [GC (Allocation Failure) [PSYoungGen: 7274444K->1582035K(8476672K)] 13750198K->9392607K(30846464K), 0.5657404 secs] [Times: user=4.46 sys=0.01, real=0.56 secs] 
35777.830: [GC (GCLocker Initiated GC) [PSYoungGen: 7342035K->1401068K(8467968K)] 15161539K->10378557K(30837760K), 0.5273704 secs] [Times: user=3.96 sys=0.01, real=0.53 secs] 
35780.768: [GC (GCLocker Initiated GC) [PSYoungGen: 7161068K->1550240K(8588288K)] 16179376K->11479317K(30958080K), 0.5158061 secs] [Times: user=3.73 sys=0.01, real=0.52 secs] 
35783.874: [GC (GCLocker Initiated GC) [PSYoungGen: 7516064K->1569631K(8562176K)] 17447661K->12875990K(30931968K), 0.5947770 secs] [Times: user=4.59 sys=0.01, real=0.59 secs] 
35787.030: [GC (GCLocker Initiated GC) [PSYoungGen: 7535455K->1585147K(8636928K)] 18841965K->13976453K(31006720K), 0.5300475 secs] [Times: user=4.16 sys=0.01, real=0.53 secs] 
35790.192: [GC (GCLocker Initiated GC) [PSYoungGen: 7650299K->1456048K(8612864K)] 20050389K->14876764K(30982656K), 0.4947915 secs] [Times: user=3.81 sys=0.02, real=0.50 secs] 

Which shows that GC is triggered mostly for allocation failures in the young gen.

Update: Here is Throughput evolution on the same time frame

Answer 1

I think that under lighter load GC was using mostly minor collections, cleaning only young and survivor spaces, while filling OldGen. At some point OldGen became full and major collection was performed, resulting the pause. At the same time GC goals were adjusted, which lead to GC using more CPU.

It's hard to match GC log timestamps to the chart times, you should try to enable pretty-printed dates in GC log with -XX:+PrintGCDateStamps. But, as you can see, "Ergonomics" in Full GC (Ergonomics) indicates that GC is adjusting its goals.

---

To summarize:

Parallel GC tries to maximize application throughput, setting collection goals and heap ratios. Under lighter load it may skip performing major GC. When load profile changes, GC behavior can also change (after some internal threshold is reached).