《Java架構師的最佳實踐》生產環境JVM調優之空間擔保失敗引起的FullGC

沙漏喲發表於2021-05-27
Java架構JVMGC

1  問題現象

應用prod-xxx-k8s，在記憶體足夠的情況下，仍然會產生偶發FullGC的問題。

JVM配置如下：

-Xmx8192m -Dhsf.server.max.poolsize=2500 -Xms8192m -XX:MaxDirectMemorySize=1026m -XX:+UseGCLogFileRotation -XX:ParallelGCThreads=10 -XX:NewSize=3096m -XX:SurvivorRatio=8 -Xloggc:/home/admin/gc.log -XX:NumberOfGCLogFiles=1 -XX:ConcGCThreads=10 -XX:+PrintGCDateStamps -XX:MaxNewSize=3096m -XX:NewRatio=4 -XX:GCLogFileSize=1024m -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -Duser.timezone=Asia/Shanghai -Dlog4j.defaultInitOverride=false -XX:-OmitStackTraceInFastThrow -Djava.security.egd=file:/dev/./urandom

從配置可以看出，prod-user-provider-k8s使用的CMS垃圾收集器。

-Xmx8192m
-Xms8192m
-XX:MaxDirectMemorySize=1026m
-XX:NewRatio=4
-XX:NewSize=3096m
-XX:MaxNewSize=3096m
-XX:SurvivorRatio=8
-XX:+UseConcMarkSweepGC

最終生效的配置

命令：jmap -heap 1

命令：jinfo -flags 1

Non-default VM flags: -XX:CICompilerCount=3 -XX:ConcGCThreads=10 -XX:GCLogFileSize=1073741824 -XX:InitialHeapSize=8589934592 -XX:MaxDirectMemorySize=1075838976 -XX:MaxHeapSize=8589934592 -XX:MaxNewSize=3246391296 -XX:MinHeapDeltaBytes=196608 -XX:NewRatio=4 -XX:NewSize=3246391296 -XX:NumberOfGCLogFiles=1 -XX:OldPLABSize=16 -XX:OldSize=5343543296 -XX:-OmitStackTraceInFastThrow -XX:ParallelGCThreads=10 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:+UseParNewGC

2  定位過程

1）2021.05.26 21:52  檢測服務GC情況，發現最近1小時GC次數較多，且此時沒有釋出變更。

2）根據監控，縮小時間範圍到2021-05-26 21:10:00 ~ 2021-05-26 21:20:00

應用：prod-xxx-k8s

時間段：2021-05-26 21:10:00 ~ 2021-05-26 21:20:00

172.16.110.244，172.16.102.235，172.16.104.28 三臺機器的平均響應事件較長，就取樣這3臺了。

3）進入到 172.16.110.244 k8s終端，檢視 /home/admin/gc.log，找到21:14分的GC日誌（監控顯示21:14分有一次FullGC，此時Old區和新生代容量均未滿）

2021-05-26T21:13:46.971+0800: 110332.313: [GC (Allocation Failure) 2021-05-26T21:13:46.972+0800: 110332.313: [ParNew: 2560944K->42868K(2853312K), 0.0163553 secs] 7265031K->4749630K(8071616K), 0.0171585 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:13:50.840+0800: 110336.181: [GC (Allocation Failure) 2021-05-26T21:13:50.840+0800: 110336.182: [ParNew: 2579188K->49558K(2853312K), 0.0157663 secs] 7285950K->4758763K(8071616K), 0.0165931 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2021-05-26T21:13:54.591+0800: 110339.933: [GC (Allocation Failure) 2021-05-26T21:13:54.592+0800: 110339.933: [ParNew: 2585878K->51614K(2853312K), 0.0163846 secs] 7295083K->4761839K(8071616K), 0.0171867 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:13:58.559+0800: 110343.900: [GC (Allocation Failure) 2021-05-26T21:13:58.560+0800: 110343.901: [ParNew: 2587934K->54453K(2853312K), 0.0152570 secs] 7298159K->4765092K(8071616K), 0.0160738 secs] [Times: user=0.13 sys=0.00, real=0.01 secs]
2021-05-26T21:14:02.507+0800: 110347.848: [GC (Allocation Failure) 2021-05-26T21:14:02.507+0800: 110347.848: [ParNew: 2590773K->52962K(2853312K), 0.0158836 secs] 7301412K->4763945K(8071616K), 0.0168485 secs] [Times: user=0.10 sys=0.03, real=0.01 secs]
2021-05-26T21:14:06.253+0800: 110351.594: [GC (Allocation Failure) 2021-05-26T21:14:06.253+0800: 110351.595: [ParNew: 2589282K->53375K(2853312K), 0.0166401 secs] 7300265K->4764793K(8071616K), 0.0175633 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:14:10.035+0800: 110355.376: [GC (Allocation Failure) 2021-05-26T21:14:10.035+0800: 110355.377: [ParNew: 2589695K->56544K(2853312K), 0.0160937 secs] 7301113K->4768240K(8071616K), 0.0168443 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:14:13.680+0800: 110359.021: [GC (Allocation Failure) 2021-05-26T21:14:13.681+0800: 110359.022: [ParNew: 2592864K->57174K(2853312K), 0.0160996 secs] 7304560K->4769381K(8071616K), 0.0169435 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2021-05-26T21:14:17.332+0800: 110362.673: [GC (Allocation Failure) 2021-05-26T21:14:17.332+0800: 110362.674: [ParNew: 2593494K->53500K(2853312K), 0.0166459 secs] 7305701K->4766029K(8071616K), 0.0174705 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:14:21.113+0800: 110366.454: [GC (Allocation Failure) 2021-05-26T21:14:21.114+0800: 110366.455: [ParNew: 2589820K->50429K(2853312K), 0.0164917 secs] 7302349K->4763507K(8071616K), 0.0173216 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:14:25.024+0800: 110370.365: [GC (Allocation Failure) 2021-05-26T21:14:25.024+0800: 110370.365: [ParNew: 2586749K->56649K(2853312K), 0.0171138 secs] 7299827K->4770415K(8071616K), 0.0179706 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2021-05-26T21:14:28.679+0800: 110374.020: [GC (Allocation Failure) 2021-05-26T21:14:28.679+0800: 110374.020: [ParNew: 2592969K->50028K(2853312K), 0.0167487 secs] 7306735K->4764476K(8071616K), 0.0175809 secs] [Times: user=0.13 sys=0.01, real=0.02 secs]
2021-05-26T21:14:32.439+0800: 110377.780: [GC (Allocation Failure) 2021-05-26T21:14:32.440+0800: 110377.781: [ParNew: 2586348K->56920K(2853312K), 0.0160964 secs] 7300796K->4772346K(8071616K), 0.0168883 secs] [Times: user=0.11 sys=0.04, real=0.02 secs]
2021-05-26T21:14:36.294+0800: 110381.636: [GC (Allocation Failure) 2021-05-26T21:14:36.295+0800: 110381.636: [ParNew: 2593240K->52929K(2853312K), 0.0163589 secs] 7308666K->4770160K(8071616K), 0.0172542 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:14:40.177+0800: 110385.518: [GC (Allocation Failure) 2021-05-26T21:14:40.177+0800: 110385.518: [ParNew: 2589249K->51830K(2853312K), 0.0157497 secs] 7306480K->4771515K(8071616K), 0.0166224 secs] [Times: user=0.11 sys=0.02, real=0.01 secs]
2021-05-26T21:14:44.009+0800: 110389.350: [GC (Allocation Failure) 2021-05-26T21:14:44.010+0800: 110389.351: [ParNew (promotion failed): 2588150K->2572606K(2853312K), 0.7510010 secs]2021-05-26T21:14:44.761+0800: 110390.102: [CMS: 4721703K->375449K(5218304K), 2.8244875 secs] 7307835K->375449K(8071616K), [Metaspace: 151787K->151787K(1189888K)], 3.5763945 secs] [Times: user=3.78 sys=0.16, real=3.57 secs]
2021-05-26T21:14:51.530+0800: 110396.871: [GC (Allocation Failure) 2021-05-26T21:14:51.531+0800: 110396.872: [ParNew: 2536320K->56158K(2853312K), 0.0890703 secs] 2911769K->431607K(8071616K), 0.0908828 secs] [Times: user=0.25 sys=0.00, real=0.09 secs]
2021-05-26T21:14:54.328+0800: 110399.670: [GC (Allocation Failure) 2021-05-26T21:14:54.330+0800: 110399.671: [ParNew: 2592478K->71256K(2853312K), 0.0873448 secs] 2967927K->446705K(8071616K), 0.0897922 secs] [Times: user=0.19 sys=0.06, real=0.09 secs]
2021-05-26T21:14:57.343+0800: 110402.685: [GC (Allocation Failure) 2021-05-26T21:14:57.345+0800: 110402.686: [ParNew: 2607576K->69383K(2853312K), 0.0773853 secs] 2983025K->444833K(8071616K), 0.0800916 secs] [Times: user=0.18 sys=0.00, real=0.08 secs]
2021-05-26T21:15:00.700+0800: 110406.041: [GC (Allocation Failure) 2021-05-26T21:15:00.701+0800: 110406.042: [ParNew: 2605703K->61466K(2853312K), 0.0252316 secs] 2981153K->436916K(8071616K), 0.0275881 secs] [Times: user=0.13 sys=0.05, real=0.03 secs]
2021-05-26T21:15:04.246+0800: 110409.587: [GC (Allocation Failure) 2021-05-26T21:15:04.247+0800: 110409.588: [ParNew: 2597786K->67316K(2853312K), 0.0226887 secs] 2973236K->442765K(8071616K), 0.0248441 secs] [Times: user=0.11 sys=0.04, real=0.02 secs]
2021-05-26T21:15:07.806+0800: 110413.147: [GC (Allocation Failure) 2021-05-26T21:15:07.808+0800: 110413.149: [ParNew: 2603636K->67948K(2853312K), 0.0245455 secs] 2979085K->443398K(8071616K), 0.0269191 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]
2021-05-26T21:15:11.406+0800: 110416.748: [GC (Allocation Failure) 2021-05-26T21:15:11.408+0800: 110416.749: [ParNew: 2604268K->68840K(2853312K), 0.0241876 secs] 2979718K->444289K(8071616K), 0.0264560 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2021-05-26T21:15:15.156+0800: 110420.498: [GC (Allocation Failure) 2021-05-26T21:15:15.158+0800: 110420.499: [ParNew: 2605160K->69215K(2853312K), 0.0227253 secs] 2980609K->444665K(8071616K), 0.0249052 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2021-05-26T21:15:19.106+0800: 110424.447: [GC (Allocation Failure) 2021-05-26T21:15:19.108+0800: 110424.449: [ParNew: 2605535K->74786K(2853312K), 0.0254132 secs] 2980985K->450235K(8071616K), 0.0277919 secs] [Times: user=0.10 sys=0.05, real=0.02 secs]
2021-05-26T21:15:22.948+0800: 110428.289: [GC (Allocation Failure) 2021-05-26T21:15:22.949+0800: 110428.291: [ParNew: 2611106K->80542K(2853312K), 0.0218103 secs] 2986555K->455991K(8071616K), 0.0241225 secs] [Times: user=0.11 sys=0.04, real=0.02 secs]
2021-05-26T21:15:26.765+0800: 110432.106: [GC (Allocation Failure) 2021-05-26T21:15:26.766+0800: 110432.107: [ParNew: 2616862K->71036K(2853312K), 0.0240100 secs] 2992311K->446485K(8071616K), 0.0266076 secs] [Times: user=0.12 sys=0.04, real=0.03 secs]
2021-05-26T21:15:30.429+0800: 110435.770: [GC (Allocation Failure) 2021-05-26T21:15:30.430+0800: 110435.771: [ParNew: 2607356K->76947K(2853312K), 0.0225847 secs] 2982805K->452397K(8071616K), 0.0247116 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2021-05-26T21:15:34.262+0800: 110439.604: [GC (Allocation Failure) 2021-05-26T21:15:34.264+0800: 110439.605: [ParNew: 2613267K->77856K(2853312K), 0.0243191 secs] 2988717K->453306K(8071616K), 0.0266642 secs] [Times: user=0.13 sys=0.04, real=0.03 secs]

找到產生FullGC的原因

2021-05-26T21:14:44.009+0800: 110389.350: [GC (Allocation Failure) 2021-05-26T21:14:44.010+0800: 110389.351: [ParNew (promotion failed): 2588150K->2572606K(2853312K), 0.7510010 secs]2021-05-26T21:14:44.761+0800: 110390.102: [CMS: 4721703K->375449K(5218304K), 2.8244875 secs] 7307835K->375449K(8071616K), [Metaspace: 151787K->151787K(1189888K)], 3.5763945 secs] [Times: user=3.78 sys=0.16, real=3.57 secs]

4）進入到 172.16.102.235 k8s終端，檢視 /home/admin/gc.log，找到21:12分的GC日誌（監控顯示21:12分有一次FullGC，此時Old區和新生代容量均未滿）

2021-05-26T21:11:42.043+0800: 109432.176: [GC (Allocation Failure) 2021-05-26T21:11:42.043+0800: 109432.177: [ParNew: 2589307K->53332K(2853312K), 0.0164383 secs] 7215117K->4679657K(8071616K), 0.0173807 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:11:45.802+0800: 109435.935: [GC (Allocation Failure) 2021-05-26T21:11:45.803+0800: 109435.936: [ParNew: 2589652K->54762K(2853312K), 0.0164353 secs] 7215977K->4682611K(8071616K), 0.0173651 secs] [Times: user=0.11 sys=0.02, real=0.02 secs]
2021-05-26T21:11:49.585+0800: 109439.719: [GC (Allocation Failure) 2021-05-26T21:11:49.586+0800: 109439.719: [ParNew: 2591082K->57472K(2853312K), 0.0174578 secs] 7218931K->4685876K(8071616K), 0.0185110 secs] [Times: user=0.12 sys=0.03, real=0.02 secs]
2021-05-26T21:11:53.458+0800: 109443.591: [GC (Allocation Failure) 2021-05-26T21:11:53.458+0800: 109443.592: [ParNew: 2593792K->58786K(2853312K), 0.0160802 secs] 7222196K->4687560K(8071616K), 0.0171554 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:11:57.343+0800: 109447.476: [GC (Allocation Failure) 2021-05-26T21:11:57.343+0800: 109447.477: [ParNew: 2595106K->45118K(2853312K), 0.0165340 secs] 7223880K->4674610K(8071616K), 0.0175619 secs] [Times: user=0.11 sys=0.02, real=0.02 secs]
2021-05-26T21:12:01.340+0800: 109451.474: [GC (Allocation Failure) 2021-05-26T21:12:01.341+0800: 109451.474: [ParNew: 2581438K->54049K(2853312K), 0.0161339 secs] 7210930K->4684058K(8071616K), 0.0171423 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:12:04.939+0800: 109455.072: [GC (Allocation Failure) 2021-05-26T21:12:04.940+0800: 109455.073: [ParNew: 2590369K->51755K(2853312K), 0.0170289 secs] 7220378K->4682596K(8071616K), 0.0181071 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:12:08.828+0800: 109458.962: [GC (Allocation Failure) 2021-05-26T21:12:08.829+0800: 109458.962: [ParNew: 2588075K->52764K(2853312K), 0.0166489 secs] 7218916K->4684232K(8071616K), 0.0176064 secs] [Times: user=0.12 sys=0.03, real=0.02 secs]
2021-05-26T21:12:12.611+0800: 109462.745: [GC (Allocation Failure) 2021-05-26T21:12:12.612+0800: 109462.745: [ParNew: 2589084K->53194K(2853312K), 0.0170641 secs] 7220552K->4686304K(8071616K), 0.0181306 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:12:16.430+0800: 109466.564: [GC (Allocation Failure) 2021-05-26T21:12:16.431+0800: 109466.564: [ParNew: 2589514K->51266K(2853312K), 0.0167824 secs] 7222624K->4685881K(8071616K), 0.0178142 secs] [Times: user=0.12 sys=0.03, real=0.02 secs]
2021-05-26T21:12:20.065+0800: 109470.198: [GC (Allocation Failure) 2021-05-26T21:12:20.065+0800: 109470.199: [ParNew: 2587586K->54790K(2853312K), 0.0166928 secs] 7222201K->4690718K(8071616K), 0.0177029 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2021-05-26T21:12:23.599+0800: 109473.732: [GC (Allocation Failure) 2021-05-26T21:12:23.599+0800: 109473.733: [ParNew: 2591110K->51765K(2853312K), 0.0167703 secs] 7227038K->4689793K(8071616K), 0.0176183 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:12:27.446+0800: 109477.579: [GC (Allocation Failure) 2021-05-26T21:12:27.446+0800: 109477.580: [ParNew (promotion failed): 2588085K->2572281K(2853312K), 0.7663931 secs]2021-05-26T21:12:28.213+0800: 109478.346: [CMS: 4640288K->371552K(5218304K), 3.1407107 secs] 7226113K->371552K(8071616K), [Metaspace: 151608K->151608K(1189888K)], 3.9082575 secs] [Times: user=4.20 sys=0.02, real=3.91 secs]
2021-05-26T21:12:34.333+0800: 109484.466: [GC (Allocation Failure) 2021-05-26T21:12:34.334+0800: 109484.467: [ParNew: 2536320K->51706K(2853312K), 0.0863266 secs] 2907872K->423258K(8071616K), 0.0885574 secs] [Times: user=0.24 sys=0.00, real=0.09 secs]
2021-05-26T21:12:37.520+0800: 109487.653: [GC (Allocation Failure) 2021-05-26T21:12:37.522+0800: 109487.655: [ParNew: 2588026K->69050K(2853312K), 0.0886567 secs] 2959578K->440602K(8071616K), 0.0912379 secs] [Times: user=0.18 sys=0.05, real=0.09 secs]
2021-05-26T21:12:40.813+0800: 109490.947: [GC (Allocation Failure) 2021-05-26T21:12:40.815+0800: 109490.948: [ParNew: 2605370K->57953K(2853312K), 0.0218886 secs] 2976922K->429505K(8071616K), 0.0241126 secs] [Times: user=0.15 sys=0.00, real=0.03 secs]
2021-05-26T21:12:44.672+0800: 109494.806: [GC (Allocation Failure) 2021-05-26T21:12:44.674+0800: 109494.807: [ParNew: 2594273K->64711K(2853312K), 0.0221487 secs] 2965825K->436264K(8071616K), 0.0244422 secs] [Times: user=0.15 sys=0.00, real=0.03 secs]
2021-05-26T21:12:48.212+0800: 109498.345: [GC (Allocation Failure) 2021-05-26T21:12:48.213+0800: 109498.347: [ParNew: 2601031K->70579K(2853312K), 0.0224411 secs] 2972584K->442132K(8071616K), 0.0249537 secs] [Times: user=0.15 sys=0.00, real=0.03 secs]
2021-05-26T21:12:51.897+0800: 109502.030: [GC (Allocation Failure) 2021-05-26T21:12:51.899+0800: 109502.032: [ParNew: 2606899K->63975K(2853312K), 0.0224915 secs] 2978452K->435527K(8071616K), 0.0248375 secs] [Times: user=0.11 sys=0.04, real=0.02 secs]
2021-05-26T21:12:55.565+0800: 109505.698: [GC (Allocation Failure) 2021-05-26T21:12:55.566+0800: 109505.700: [ParNew: 2600295K->56871K(2853312K), 0.0219563 secs] 2971847K->428424K(8071616K), 0.0243490 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2021-05-26T21:12:59.372+0800: 109509.505: [GC (Allocation Failure) 2021-05-26T21:12:59.373+0800: 109509.507: [ParNew: 2593191K->71798K(2853312K), 0.0220514 secs] 2964744K->443350K(8071616K), 0.0242666 secs] [Times: user=0.12 sys=0.03, real=0.03 secs]
2021-05-26T21:13:03.271+0800: 109513.404: [GC (Allocation Failure) 2021-05-26T21:13:03.272+0800: 109513.406: [ParNew: 2608118K->68230K(2853312K), 0.0238549 secs] 2979670K->439782K(8071616K), 0.0262654 secs] [Times: user=0.12 sys=0.04, real=0.03 secs]
2021-05-26T21:13:07.241+0800: 109517.375: [GC (Allocation Failure) 2021-05-26T21:13:07.243+0800: 109517.376: [ParNew: 2604550K->64696K(2853312K), 0.0215880 secs] 2976102K->436248K(8071616K), 0.0237131 secs] [Times: user=0.13 sys=0.03, real=0.03 secs]
2021-05-26T21:13:11.029+0800: 109521.162: [GC (Allocation Failure) 2021-05-26T21:13:11.030+0800: 109521.163: [ParNew: 2601016K->70471K(2853312K), 0.0234303 secs] 2972568K->442023K(8071616K), 0.0256151 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
2021-05-26T21:13:14.892+0800: 109525.025: [GC (Allocation Failure) 2021-05-26T21:13:14.893+0800: 109525.026: [ParNew: 2606791K->71421K(2853312K), 0.0230224 secs] 2978343K->442973K(8071616K), 0.0252567 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
2021-05-26T21:13:18.581+0800: 109528.715: [GC (Allocation Failure) 2021-05-26T21:13:18.583+0800: 109528.716: [ParNew: 2607741K->72586K(2853312K), 0.0263737 secs] 2979293K->444139K(8071616K), 0.0288899 secs] [Times: user=0.18 sys=0.00, real=0.03 secs]
2021-05-26T21:13:22.684+0800: 109532.817: [GC (Allocation Failure) 2021-05-26T21:13:22.685+0800: 109532.818: [ParNew: 2608906K->74840K(2853312K), 0.0236628 secs] 2980459K->446393K(8071616K), 0.0260311 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]

5）進入到 172.16.104.28 k8s終端，檢視 /home/admin/gc.log，找到21:15分的GC日誌（監控顯示21:15分有一次FullGC，此時Old區和新生代容量均未滿）

2021-05-26T21:15:20.903+0800: 110014.884: [GC (Allocation Failure) 2021-05-26T21:15:20.904+0800: 110014.885: [ParNew: 2589822K->54329K(2853312K), 0.0167040 secs] 7317732K->4783565K(8071616K), 0.0176035 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2021-05-26T21:15:24.701+0800: 110018.681: [GC (Allocation Failure) 2021-05-26T21:15:24.701+0800: 110018.682: [ParNew: 2590649K->55465K(2853312K), 0.0157971 secs] 7319885K->4786089K(8071616K), 0.0166526 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:15:28.267+0800: 110022.248: [GC (Allocation Failure) 2021-05-26T21:15:28.267+0800: 110022.248: [ParNew: 2591785K->55649K(2853312K), 0.0150188 secs] 7322409K->4788248K(8071616K), 0.0159535 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:15:31.926+0800: 110025.907: [GC (Allocation Failure) 2021-05-26T21:15:31.927+0800: 110025.907: [ParNew: 2591969K->51991K(2853312K), 0.0159596 secs] 7324568K->4787457K(8071616K), 0.0169736 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:15:35.708+0800: 110029.689: [GC (Allocation Failure) 2021-05-26T21:15:35.708+0800: 110029.689: [ParNew: 2588311K->53429K(2853312K), 0.0157338 secs] 7323777K->4790565K(8071616K), 0.0165723 secs] [Times: user=0.10 sys=0.04, real=0.02 secs]
2021-05-26T21:15:39.516+0800: 110033.497: [GC (Allocation Failure) 2021-05-26T21:15:39.517+0800: 110033.498: [ParNew: 2589749K->54436K(2853312K), 0.0160738 secs] 7326885K->4794339K(8071616K), 0.0170658 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2021-05-26T21:15:43.199+0800: 110037.180: [GC (Allocation Failure) 2021-05-26T21:15:43.200+0800: 110037.181: [ParNew: 2590756K->57292K(2853312K), 0.0159270 secs] 7330659K->4798809K(8071616K), 0.0168558 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2021-05-26T21:15:46.988+0800: 110040.969: [GC (Allocation Failure) 2021-05-26T21:15:46.988+0800: 110040.969: [ParNew (promotion failed): 2593612K->2564826K(2853312K), 0.7399372 secs]2021-05-26T21:15:47.728+0800: 110041.709: [CMS: 4742263K->373610K(5218304K), 2.7994206 secs] 7335129K->373610K(8071616K), [Metaspace: 151862K->151862K(1191936K)], 3.5403439 secs] [Times: user=3.78 sys=0.06, real=3.54 secs]
2021-05-26T21:15:53.651+0800: 110047.632: [GC (Allocation Failure) 2021-05-26T21:15:53.653+0800: 110047.634: [ParNew: 2536320K->58807K(2853312K), 0.0264674 secs] 2909930K->432417K(8071616K), 0.0283920 secs] [Times: user=0.18 sys=0.05, real=0.03 secs]
2021-05-26T21:15:56.649+0800: 110050.630: [GC (Allocation Failure) 2021-05-26T21:15:56.651+0800: 110050.632: [ParNew: 2595127K->47916K(2853312K), 0.0848130 secs] 2968737K->421526K(8071616K), 0.0875758 secs] [Times: user=0.14 sys=0.04, real=0.09 secs]
2021-05-26T21:16:00.098+0800: 110054.078: [GC (Allocation Failure) 2021-05-26T21:16:00.099+0800: 110054.080: [ParNew: 2584236K->51428K(2853312K), 0.0205768 secs] 2957846K->425038K(8071616K), 0.0226130 secs] [Times: user=0.11 sys=0.03, real=0.02 secs]
2021-05-26T21:16:03.974+0800: 110057.955: [GC (Allocation Failure) 2021-05-26T21:16:03.975+0800: 110057.956: [ParNew: 2587748K->52190K(2853312K), 0.0220049 secs] 2961358K->425800K(8071616K), 0.0240968 secs] [Times: user=0.11 sys=0.04, real=0.02 secs]
2021-05-26T21:16:07.644+0800: 110061.625: [GC (Allocation Failure) 2021-05-26T21:16:07.645+0800: 110061.626: [ParNew: 2588510K->55537K(2853312K), 0.0201972 secs] 2962120K->429147K(8071616K), 0.0223194 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2021-05-26T21:16:11.246+0800: 110065.227: [GC (Allocation Failure) 2021-05-26T21:16:11.247+0800: 110065.228: [ParNew: 2591857K->55768K(2853312K), 0.0217514 secs] 2965467K->429378K(8071616K), 0.0237536 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 

3  根本原因

1）空間分配擔保

在發生 Minor GC 之前，虛擬機器先檢查老年代最大可用的連續空間是否大於新生代所有物件總空間，如果條件成立的話，那麼 Minor GC 可以確認是安全的。

如果不成立的話虛擬機器會檢視 HandlePromotionFailure 的值是否允許擔保失敗，如果允許那麼就會繼續檢查老年代最大可用的連續空間是否大於歷次晉升到老年代物件的平均大小，如果大於，將嘗試著進行一次 Minor GC；如果小於，或者 HandlePromotionFailure 的值不允許冒險，那麼就要進行一次 Full GC。

2）空間分配擔保失敗

使用複製演算法的 Minor GC 需要老年代的記憶體空間作擔保，如果擔保失敗會執行一次 Full GC。

3）樣例分析

172.16.110.244 進行FullGC時，Old區此時佔用為4.5G，實際配置Old區最大可用記憶體為8G，GC日誌顯示Old區最大可用記憶體為5218304K ~= 4.9765625G，即Old區只省約0.5G~= 512M的記憶體可用。

若這512M記憶體存在記憶體碎片，則可能誘發空間擔保失敗，執行一次Full GC。

2021-05-26T21:14:44.009+0800: 110389.350: [GC (Allocation Failure)

2021-05-26T21:14:44.010+0800: 110389.351: [ParNew (promotion failed): 2588150K->2572606K(2853312K), 0.7510010 secs]

2021-05-26T21:14:44.761+0800: 110390.102: [CMS: 4721703K->375449K(5218304K), 2.8244875 secs]

7307835K->375449K(8071616K),

[Metaspace: 151787K->151787K(1189888K)], 3.5763945 secs]

[Times: user=3.78 sys=0.16, real=3.57 secs]

4  解決方案

1）修改垃圾收集器為G1，觀察效果。

-Xmx8192m -Xms8192m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/admin/heapdump.hprof -XX:+UseGCLogFileRotation -Xloggc:/home/admin/gc.log -XX:NumberOfGCLogFiles=1 -XX:+PrintGCDateStamps -XX:GCLogFileSize=1024m -XX:+PrintGC -XX:+PrintGCDetails -Duser.timezone=Asia/Shanghai -Dlog4j.defaultInitOverride=false -XX:-OmitStackTraceInFastThrow -XX:NativeMemoryTracking=detail -XX:+UseG1GC -XX:MaxGCPauseMillis=200

 

相關文章