《架构师最佳实践》生产环境JVM调优之空间担保失败引起的FullGC
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
版权声明：本文为yeahwell原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。