Flink FullGC 优化（jdk8）

总结

优化办法

• 降低频率： 提高Young区的占比（占60%）、合理的Eden:From:To比例，保证对象被晋升老年代前回收掉。

  • env.java.opts.taskmanager: -XX:-UseAdaptiveSizePolicy -Xmn15000m

• 缩短时间： 调高cpu大小，保证更充分的利用cpu，避免多线程cpu切换、cpu阻塞造成的。

  • cpu尽量>1，以保证有足够线程处理gc（针对FullGC严重作业）。

    • 当作业tm cpu使用率确实低于1的情况。如果cpu利用率比较低，可以降低整体作业的并行度（tm个数） ，提高tm slot的数量，提高tm cpu的数量，这样每个cpu分到的工作更多了，也可以保证cpu使用率的同时。

明确优化目标

域内Flink1.11 版本默认使用 jdk1.8版本，垃圾回收器默认为并行垃圾回收器。

明确应用程序的需求目标是 FullGC 优化的基础，例如：

• 高可用，与响应速度相关，可用性达到几个9
• 低延迟，即响应速度，请求必须多少毫秒内完成响应。
• 高吞吐，即吞吐量，每秒完成多少次事务。

因为，上述性能指标之前可能存在冲突，比如通常情况下，缩小延迟的代价是降低吞吐量或者消耗更多的内存或者两者同时发生。

吞吐量是指应用程序所花费的时间和系统总运行时间的比值。我们可以按照这个公式来计算 GC 的吞吐量：系统总运行时间 = 应用程序耗时 +GC 耗时。如果系统运行了 100 分，GC 耗时 1 分钟，则系统吞吐量为 99%。GC 的吞吐量一般不能低于 95%。

分析验证

GC会产生STW，进而影响进程执行业务逻辑，可以从 GC 时间长、频率高两类现象入手 。

缩短 FullGC 时间

影响 FullGC 时间的因素，无非是gc 线程 数（CPU数）、要清理的内存大小。

GC 时间语义

• real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成），一般会以real当做gc时间。
• user：进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
• sys： 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间。

总结及建议

• 针对case1 和case2，现象明显是cpu不够用，大部分时间其他 线程 阻塞。需要增加CPU，给cpu更多的工作（降低并行度、避免更多的线程切换）。

处理建议：

• cpu尽量>1，以保证有足够线程处理gc（针对FullGC严重作业）。

  • 当作业tm cpu使用率确实低于1的情况。如果cpu利用率比较低，可以降低整体作业的并行度（tm个数） ，提高tm slot的数量，提高tm cpu的数量，这样每个cpu分到的工作更多了，也可以保证cpu使用率的同时。

case1：cpu低

问题描述

作业资源配置： 25个TM，cpu 0.4，mem 6G，slot 4。

gc日志如下：

2022-08-09T14:29:30.647+0000: 41501.527: [GC (Allocation Failure) [PSYoungGen: 1047123K->74867K(1072640K)] 3385832K->2418640K(3444224K), 0.2586030 secs] [Times: user=0.24 sys=0.01, real=0.26 secs] 
2022-08-09T14:29:34.987+0000: 41505.867: [GC (Allocation Failure) [PSYoungGen: 1037427K->100969K(1063936K)] 3381200K->2444751K(3435520K), 0.3137596 secs] [Times: user=0.29 sys=0.01, real=0.31 secs] 
2022-08-09T14:29:44.203+0000: 41515.083: [GC (Allocation Failure) [PSYoungGen: 1063529K->86016K(1073664K)] 3407311K->2441192K(3445248K), 0.2904001 secs] [Times: user=0.27 sys=0.02, real=0.29 secs] 
2022-08-09T14:29:44.494+0000: 41515.374: [Full GC (Ergonomics) [PSYoungGen: 86016K->0K(1073664K)] [ParOldGen: 2355175K->965897K(2371584K)] 2441192K->965897K(3445248K), [Metaspace: 110398K->110391K(1150976K)], 19.3472607 secs] [Times: user=7.96 sys=0.64, real=19.34 secs] 

FullGC时间 [Times: user=7.96 sys =0.64, real=19.34 secs]

现象分析

初步分析：

real耗时比user长，说明进程阻塞时间或者切换进程占用的时间太长，一般两种原因cpu不够用或者io负载繁重。这个作业实际上是cpu不够用（此时cpu为0.4）。

gc 日志分析： gc线程数为1（实际可用cpu0.4），老年代容量2.2G左右，每次回收1.2G左右。

下图说明 Young区分配速率高，Old晋升速率一般。

优化前后

优化操作：

优化前后对比：

case2：cpu低

问题描述

作业资源配置： 10个TM，cpu 1，mem 10G，slot 5。

gc日志如下：

2022-08-08T20:15:37.656+0000: 2282061.082: [Full GC (Ergonomics) [PSYoungGen: 14229K->0K(2295296K)] [ParOldGen: 4626248K->1648062K(4631552K)] 4640478K->1648062K(6926848K), [Metaspace: 111892K->111892K(1153024K)], 19.0460954 secs] [Times: user=17.42 sys=1.14, real=19.05 secs] 
2022-08-08T22:21:52.703+0000: 2289636.129: [GC (Allocation Failure) [PSYoungGen: 2283939K->3936K(2294784K)] 6905405K->4626402K(6926336K), 0.1368344 secs] [Times: user=0.12 sys=0.02, real=0.13 secs] 
2022-08-08T22:21:58.756+0000: 2289642.182: [GC (GCLocker Initiated GC) [PSYoungGen: 2278240K->8262K(2294784K)] 6900706K->4631632K(6926336K), 0.2015076 secs] [Times: user=0.09 sys=0.01, real=0.20 secs] 
2022-08-08T22:22:06.455+0000: 2289649.881: [GC (Allocation Failure) [PSYoungGen: 2282566K->8240K(2296320K)] 6906017K->4632315K(6927872K), 0.1150609 secs] [Times: user=0.10 sys=0.01, real=0.12 secs] 
2022-08-08T22:22:12.882+0000: 2289656.308: [GC (Allocation Failure) [PSYoungGen: 2285104K->6352K(2295808K)] 6909179K->4634307K(6927360K), 0.1163622 secs] [Times: user=0.12 sys=0.00, real=0.11 secs] 
2022-08-08T22:22:12.998+0000: 2289656.425: [Full GC (Ergonomics) [PSYoungGen: 6352K->0K(2295808K)] [ParOldGen: 4627954K->1983940K(4631552K)] 4634307K->1983940K(6927360K), [Metaspace: 112023K->112023K(1153024K)], 21.5050397 secs] [Times: user=20.48 sys=0.54, real=21.51 secs] 
2022-08-08T22:22:38.296+0000: 2289681.722: [GC (Allocation Failure) [PSYoungGen: 2276864K->18419K(2144256K)] 4260804K->2201774K(6775808K), 0.2868879 secs] [Times: user=0.24 sys=0.00, real=0.29 secs] 
2022-08-08T22:22:41.880+0000: 2289685.306: [GC (Allocation Failure) [PSYoungGen: 2144243K->94708K(2220544K)] 4327598K->2383539K(6852096K), 0.1798056 secs] [Times: user=0.11 sys=0.06, real=0.18 secs] 
2022-08-08T22:22:45.081+0000: 2289688.507: [GC (Allocation Failure) [PSYoungGen: 2220532K->94706K(1971712K)] 4509363K->2546901K(6603264K), 0.1915639 secs] [Times: user=0.14 sys=0.02, real=0.19 secs] 
2022-08-08T22:22:47.579+0000: 2289691.005: [GC (Allocation Failure) [PSYoungGen: 1971698K->151628K(2029056K)] 4423893K->2687542K(6660608K), 0.1093241 secs] [Times: user=0.11 sys=0.00, real=0.12 secs] 

FullGC时间 [Times: user=18.99 sys =0.36, real=19.73 secs]

现象分析

user时长和real时长接近，说明gc线程数为1，根本也是cpu不够用。

gc线程数为1，老年代容量4.4G左右，每次回收2.2G左右。

优化前后

优化操作：

资源概览

• 总并行度：50 -> 40

• 总内存：100G -> 90G

• 总cpu：10 -> 7.5

优化前后对比：

case3：cpu低

问题描述

【单个TM 平均 FullGC 时间 ms】 26230.0 【单个TM 平均 FullGC 次数】 20.0

第一次调整：增加cpu数

根据case1、case2调大单个tm进程cpu，如下：

第二次调整：调大年轻代

第一次调整后FullGC 频率降低，但是FullGC 时长还是在20s左右。

分析下堆内存和gc日志。

活跃数据是指运行时长期存活对象在堆中占用的空间大小，也就是Full GC后堆中老年代占用空间的大小。

根据gc日志查看，活跃数据的大小为 2G 左右，年轻代空间为6G左右，老年代空间为10GB左右，所以大致判断，年轻代较小，导致一些对象快速晋升到老年代。

根据堆内存分析，大部分内存被state cache占用，每次回收时间长，

综上，先调整年轻代大小6G -> 10G，所以老年代 10G -> 6G。

操作如下：

效果如下：

调整后gc日志

2022-08-22T21:06:30.340+0000: 37378.970: [GC (Allocation Failure) [PSYoungGen: 8721504K->1064448K(8960000K)] 15310058K->7704282K(15665152K), 2.5922697 secs] [Times: user=2.51 sys=0.02, real=2.59 secs] 
2022-08-22T21:06:32.933+0000: 37381.563: [Full GC (Ergonomics) [PSYoungGen: 1064448K->0K(8960000K)] [ParOldGen: 6639833K->2631293K(6705152K)] 7704282K->2631293K(15665152K), [Metaspace: 102771K->102617K(1144832K)], 20.0011797 secs] [Times: user=19.92 sys=0.04, real=20.01 secs] 

说明上述调整只是降低了Full GC 的频率，时长还是在20s左右。

此时老年代6G左右，活跃对象2G左右，1个垃圾回收线程，要回收4G数据，耗时20s。

所以还是要增大cpu以增加 gc 线程 数。

第三次调整：cpu 1->2

GC时间减半，20s ->10s

2022-08-24T05:39:03.312+0000: 7322.425: [GC (Allocation Failure) [PSYoungGen: 8809196K->1172479K(8960000K)] 15344111K->7750419K(15665152K), 1.5925591 secs] [Times: user=2.99 sys=0.14, real=1.59 secs] 
2022-08-24T05:39:04.905+0000: 7324.017: [Full GC (Ergonomics) [PSYoungGen: 1172479K->0K(8960000K)] [ParOldGen: 6577939K->2430285K(6705152K)] 7750419K->2430285K(15665152K), [Metaspace: 103728K->103690K(1144832K)], 10.4834331 secs] [Times: user=19.50 sys=1.00, real=10.48 secs] 

降低 FullGC 频率

单天每个 FullGC次数 100次，意味着大部分 tm 15分钟做一次FullGC，。 理论上讲，进行FullGC是由于内存不足，增大内存可以直接的降低Full GC频率。

case1 对象过早晋升

过早晋升的定义

在大流量场景下，会有大量的对象快速创建，可能产生对象过早晋升。

一般来说过早提升的症状表现为以下形式：

• 短时间内频繁地执行 Full GC
• 每次 Full GC 后老年代的使用率都很低，在 10~20% 或以下
• 晋升速率接近于分配速率

现象分析

gc日志如下：

2022-08-09T14:22:15.268+0000: 559700.911: [Full GC (Ergonomics) [PSYoungGen: 29440K->0K(1654784K)] [ParOldGen: 3359802K->1079271K(3374080K)] 3389242K->1079271K(5028864K), [Metaspace: 104694K->104694K(1146880K)], 5.5284600 secs] [Times: user=8.90 sys=0.14, real=5.53 secs] 
2022-08-09T14:29:28.737+0000: 560134.380: [GC (Allocation Failure) [PSYoungGen: 1494208K->25760K(1585664K)] 4753328K->3303132K(4959744K), 0.1083258 secs] [Times: user=0.21 sys=0.01, real=0.11 secs] 
2022-08-09T14:29:33.086+0000: 560138.730: [GC (Allocation Failure) [PSYoungGen: 1506976K->28096K(1582080K)] 4784348K->3318692K(4956160K), 0.1004469 secs] [Times: user=0.16 sys=0.04, real=0.10 secs] 
2022-08-09T14:29:33.187+0000: 560138.830: [Full GC (Ergonomics) [PSYoungGen: 28096K->0K(1582080K)] [ParOldGen: 3290595K->1086420K(3374080K)] 3318692K->1086420K(4956160K), [Metaspace: 104694K->104694K(1146880K)], 5.1444650 secs] [Times: user=8.33 sys=0.04, real=5.14 secs] 
2022-08-09T14:29:40.141+0000: 560145.785: [GC (Allocation Failure) [PSYoungGen: 1481216K->84172K(1567232K)] 2567636K->1170592K(4941312K), 0.1543051 secs] [Times: user=0.24 sys=0.00, real=0.16 secs] 
2022-08-09T14:29:43.333+0000: 560148.976: [GC (Allocation Failure) [PSYoungGen: 1554636K->27104K(1578496K)] 2641056K->1138228K(4952576K), 0.1161557 secs] [Times: user=0.17 sys=0.04, real=0.12 secs] 
2022-08-09T14:29:47.555+0000: 560153.198: [GC (Allocation Failure) [PSYoungGen: 1497568K->27821K(1586176K)] 2608692K->1155745K(4960256K), 0.0940228 secs] [Times: user=0.15 sys=0.03, real=0.09 secs] 
2022-08-09T14:29:51.995+0000: 560157.639: [GC (Allocation Failure) [PSYoungGen: 1510061K->28358K(1582592K)] 2637985K->1171410K(4956672K), 0.1409153 secs] [Times: user=0.25 sys=0.00, real=0.14 secs] 
2022-08-09T14:29:56.124+0000: 560161.768: [GC (Allocation Failure) [PSYoungGen: 1510598K->27648K(1593856K)] 2653650K->1187196K(4967936K), 0.1045922 secs] [Times: user=0.18 sys=0.01, real=0.11 secs] 

满足过早晋升的现象：

• FullGC后，老年代使用率20%，3394466K->1072486K (4956160K)。

• FullGC间隔 平均12min，频繁。

下图Eden、From、To比例不为8:1:1

优化方法：

• 通过关闭Young区动态调配、提高Young区占比，降低频率。

• 使用CMS垃圾回收，默认关闭AdaptiveSizePolicy

优化前后

操作：加参数 "env.java.opts.taskmanager": "-XX:-UseAdaptiveSizePolicy -XX:NewRatio=1"

利用 G1 提升吞吐量测试

case1

dws_country_metric_video_play_finish_5min

使用 g1 默认配置 g1日志分析，吞吐量较低84%

第一次调整：放松暂停时间

放松暂停时间目标，从而提高吞吐量，-XX:MaxGCPauseMillis =1000

放松暂停时间后，吞吐量变化：84% -> 95%

gc日志中，mixed GC耗时主要在scan RS阶段，需打印详情，参数-XX:G1SummarizeRSetStatsPeriod

2022-08-24T11:47:54.334+0000: 6060.355: [GC pause (G1 Evacuation Pause) (mixed), 2.0672955 secs]
   [Parallel Time: 2053.5 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 6060360.5, Avg: 6060360.5, Max: 6060360.5, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.8, Avg: 2.3, Max: 3.1, Diff: 1.3, Sum: 9.1]
      [Update RS (ms): Min: 52.2, Avg: 53.1, Max: 53.6, Diff: 1.4, Sum: 212.5]
         [Processed Buffers: Min: 62, Avg: 85.8, Max: 130, Diff: 68, Sum: 343]
      [Scan RS (ms): Min: 1945.3, Avg: 1946.2, Max: 1947.7, Diff: 2.4, Sum: 7784.8]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Object Copy (ms): Min: 50.5, Avg: 51.6, Max: 52.2, Diff: 1.7, Sum: 206.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 104.8, Max: 150, Diff: 149, Sum: 419]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 2053.3, Avg: 2053.4, Max: 2053.4, Diff: 0.1, Sum: 8213.5]
      [GC Worker End (ms): Min: 6062413.9, Avg: 6062413.9, Max: 6062413.9, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.9 ms]
   [Other: 12.8 ms]
      [Choose CSet: 4.3 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.9 ms]
      [Humongous Register: 0.4 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 5.8 ms]
   [Eden: 592.0M(592.0M)->0.0B(600.0M) Survivors: 52.0M->44.0M Heap: 5425.7M(12.6G)->4620.3M(12.6G)]
 [Times: user=7.86 sys=0.04, real=2.06 secs]