过多的次要垃圾收集时间

Question

我们遇到了一个问题，即次要 GC 时间过长，在一天中的某个时间点，GC 开始增加他的 CPU 时间，使用的伊甸园空间减少，并保持这种状态几个小时。所以，我的问题是，如果 eden 空间已经减少并且 old gen 未满，为什么 GC 会在一段时间后继续工作？

这些也是 gc 日志：

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] 

这表明 GC 主要是由于年轻一代的分配失败而触发的。

更新：这是同一时间范围内的吞吐量演变

Answer 1

我认为在较轻的负载下，GC 主要使用minor collections，只清理年轻和幸存者空间，同时填充 OldGen。在某些时候，OldGen 已满并执行了主要收集，导致暂停。同时调整了 GC 目标，导致 GC 占用更多 CPU。

很难将 GC 日志时间戳与图表时间匹配，您应该尝试使用 -XX:+PrintGCDateStamps 在 GC 日志中启用漂亮打印的日期。但是，如您所见，Full GC (Ergonomics) 中的“人体工程学”表示GC is adjusting its goals。

---

总结一下：

并行 GC 尝试最大化应用程序吞吐量，设置收集目标和堆比率。在较轻的负载下，它可能会跳过执行主要 GC。当负载配置文件发生变化时，GC 行为也会发生变化（在达到某个内部阈值之后）。