本文讲述了关于Talos GC性能调优的实践过程。
往期文章回顾：小米数据收集利器:AgentSource
背景
Talos作为小米自研的消息队列，在公司内部已经有了较为广泛的应用，支持了多个重点的离线和在线业务，随之而来的是业务对性能更高的要求。而对消息队列来说，最关键的性能指标不外乎吞吐和延时。对于吞吐，因为Talos的设计思想就是面向吞吐型的消息队列，再加上前文(Talos网卡负载优化：基于个性化一致性哈希的负载均衡)中所述Talos对网卡负载的优化，吞吐性能已经不是Talos的瓶颈。在高吞吐的场景下，Talos仍待解决的是GC问题对延时的影响，前文（万亿级消息背后：小米在消息队列的实践）中介绍了Talos在GC问题上经历的三个阶段，本文将详细介绍各阶段遇到的问题和解法。
>>>>
CMS中的重要概念
1.分代回收
目前主流的垃圾回收都采用“分代回收“的思路，CMS虽然是一款针对老年代的垃圾收集器，但仍免不了和年轻代打交道，因此这里简单描述一下”分代回收“思想。
年轻代：包含一个Eden区和两个Survivor区，其中Eden区是对象产生的区域，Survivor区主要存储存活着但还不能晋升到老年代的对象
老年代：存放常驻内存对象的区域
分代回收：当Eden区满时，会发生一次年轻代回收（Young GC），将仍存活的对象复制到一个Survivor区，当这个Survivor区满时，存活但没有达到晋升条件的对象全部被复制到另一个Survivor区中，达到晋升条件的对象则被放入老年代；当老年代空间使用率达到阈值，触发一次老年代回收（Old GC），将老年代中已经”死掉“的对象清理掉。需要注意的是，常说的Full GC是包含年轻代回收和老年代回收的。
2. CMS原理简述
CMS(Concurrent Mark Sweep)，是一种以牺牲吞吐量为代价来缩短应用停顿时间的、垃圾收集过程中的大部分线程可以和应用线程并发执行的、面向老年代的、采用并发标记-清除算法的垃圾收集器，一次CMS GC的主要过程如下（灰色代表应用线程，黑色代表GC线程，其中Initial-mark和Remark阶段会暂停应用进程的执行，称为Stop the world(STW)）：
Initial-mark：标记老年代中所有能被年轻代和GC Root直接引用的对象（GC Root可以理解为本次GC时肯定不会被回收的部分对象，例如静态变量）
Marking/Pre-cleaning：Marking表示在应用程序运行的同时遍历Initial-mark阶段标记出来的对象，并递归扫描这些对象可达的所有对象（标记出老年代中所有存活的对象）；Pre-cleaning表示清理应用程序并发执行时出现的引用关系变化，例如刚晋升的对象和直接分配在老年代的对象
Remark：暂停所有应用线程，重新扫描堆中的对象，在开始清理之前保持标记的正确性，查找在并发标记阶段漏掉的对象
Concurrent Sweeping：回收被标记为不可达的对象，这一阶段存活的对象并没有发生移动
3.内存碎片问题
了解”标记-清除“算法的同学应该知道这种方法将会产生大量的内存碎片，这是因为：CMS将内存空间划分成一个个的网格，内存是连续分配的，但回收时只收集”死亡“的对象，不关心仍存活的对象。因此当应用程序执行一段时间后，必然会出现大量不连续的空闲内存碎片，导致老年代虽然还有很大剩余空间，但无法找到足够大的连续空间来分配申请的对象，触发Full GC(Promotion failed)
4.Floating Garbage 问题
在并发清理阶段，用户线程仍在运行，如果产生新的垃圾，在此次GC中无法得到处理，只能等到下次清理，这些对象称为Floating Garbage。当Floating Garbage过多导致内存空间不足，那么CMS GC过程中就会出现Full GC（Concurrent Mode Failure）
>>>>
Talos+CMS遇到的问题
了解CMS的重要概念之后，本节将重点介绍在实践中遇到的问题。Talos最初使用的垃圾收集器是CMS，在吞吐量不大的集群CMS能够很好的工作，但是在一些业务流量特别大的集群（特别是在线业务），会频繁遇到Full GC的问题，对延时造成极大影响，这里将问题分为两个阶段：
1.频繁Full GC阶段
关键参数：
堆大小为20GB，其中年轻代占7GB（survivor区896MB，Eden区5.25GB），老年代占13GB
-Xmx20480m -Xms20480m -Xmn7680m -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=3 -XX:CMSInitiatingOccupancyFraction=70 |
问题描述：
Talos 进程每隔几秒出现一次耗时4秒左右的Full GC，原因是Promotion Failed，这代表应用进程在申请内存时发生了对象晋升失败。具体来说是由于在申请空间时 Eden 区满而触发 Young GC，在 Young GC 时尝试把 Survivor 区的对象（age3 -> age4）挪到 Old 区，但是老年代已经没有空间或没有连续的大块空间，于是导致 “对象晋升失败”，即Promotion Failed，从而触发 Full GC。如下图所示，通过GC日志也可以确认，发生GC时老年代已经占满。
此时面临一个问题，为什么 CMS 没有及时清理老年代呢？
根据上面设定的参数，我们知道Old 区只有13G，而通过观察GC日志发现，Talos 进程的常驻对象大概在 10-12GB 左右。这应该就是导致频繁Full GC的根本原因：老年代实际可用的空间只有1-2G，CMS回收空间的速度跟不上申请空间的速度，从而不断触发Full GC。
解决方案：
调大堆的大小
缩小年轻代的大小，转移给老年代
因为内存资源相对比较有限，在调整堆之前，让我们先通过日志来分析一下年轻代的空间利用情况。Young GC具体细节如下：
已知年轻代大小为7G，Eden区占5.25GB，两个Survivor区各占896MB，结合上图可得：
Young 区已经使用的6GB，在本次GC结束后能回收大部分对象，空间占用由 6GB 降为 90MB
Young GC 中花在Survivor区的复制开销相对较小，每次大概在几十兆左右
Survivor 区的对象一共有90MB左右，但设定的survivor区有896MB，空间利用率较低
红框部分表示本次Young GC前后，年轻代和整堆的空间变化情况。可以计算出Survivor区晋升到Old区的对象为12.2MB（(6003686-94210) - (17375735-11478816) = 12557）
由以上结论可以看出，年轻代的空间是存在浪费的，因此可以调整一部分空间转移给老年代，调整思路为：将Survivor大小调整为200MB，并将Eden区和Survivor区的比例调大到8:1，年轻代大小调整为2GB。
这样既可以保证年轻代正常运转，又在不扩大堆的前提下将老年代空间扩大了5GB。调整后关键参数如下：
-Xmx20480m -Xms20480m -Xmn2560m -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=3 -XX:CMSInitiatingOccupancyFraction=70 |
调整后，频繁Full GC的问题得到了解决，优化效果如下：
常驻内存维持在 10-12GB 左右，但不再频繁触发 full gc
因为调小了年轻代大小，YGC 由原来的平均 90ms+ 缩减到 40ms
2.周期性Full GC阶段
问题描述：
在稳定运行一段时间后，Talos集群开始出现由CMS内存碎片问题导致的周期性Full GC，最初一个周期为30天，在Talos上线一些新功能后，加重了对内存的使用，此时周期缩减为7天，单次耗时19秒左右。从监控角度来看，Full GC时的请求堆积情况非常严重，会对延迟敏感型的线上业务造成较大的影响。
解决方案：
由于CMS使用标记-清除算法，没有整理内存空间的机会，老年代空间会随应用时间的增长而被“耗尽”（此处“耗尽”是指没有连续的空间可供分配），因此如果仍然使用CMS，周期性Full GC的问题无法得到完全的解决，所以开始转向调研其他垃圾收集器。
>>>>
G1中的重要概念
1.G1原理简述
G1是Garbage-First的缩写，与CMS相比，G1是一种有内存整理过程的、优先收集存活对象最少区域的、面向年轻代和老年代的、物理空间不必连续的垃圾收集器。
Region：整个堆空间被尽可能地划分为约2048个Region(单个Region大小为1~32MB)，每个Region都可以是Eden/Survivor/Old区的任意一个
Remembered Sets(RSets)：每个Region对应一个RSet，用来跟踪指向该区域的对象引用，避免全堆扫描
Collection Sets(CSets)：CSets是一次GC中将被回收的Region集合，GC时所有CSet区域中的存活对象都会被移动到新的区域
Humongous Object：超过Region大小一半的对象称为巨型对象，会在创建时直接被分配到Old Regions中
2.工作模式
G1是同时面向年轻代和老年代的垃圾收集器，因此包括Young GC 和 Mixed GC两种工作模式。
Young GC：
Young 区由一系列不连续的Region组成，因此可以很容易在GC过程中扩/缩容
Young GC 会将存活对象转移到Survivor和老年代
Young GC 会计算 Eden 区和 Survivor 区在下次回收之前所需的的空间，然后动态调整新生代Region个数，从而达到控制Young GC耗时的目的
Mixed GC：
当老年代使用的空间超过阈值(IHOP)，会触发 Global Concurrent Marking 统计出回收收益高的老年代Region，然后开始一系列连续的Mixed GC，这个过程称为Concurrent Marking Cycle Phases
一系列连续的Mixed GC中，GC的最大次数和单次回收的空间大小可以通过参数-XX:G1MixedGCCountTarget和-XX:G1OldCSetRegionThresholdPercent进行配置
除了GC次数超过最大值以外，如果可回收空间的比例小于参数 -XX:G1HeapWastePercent ，也会中断Mixed GC周期
Mixed GC 是面向全堆进行垃圾收集的，所以通常会伴随一次Young GC，但与Full GC不同的是，Mixed GC只能回收部分老年代的Region
Mixed GC过程中会将多个老年代Region中仍存活的小对象集中到一个Region中，也就是说Mixed GC会对老年代空间进行内存整理
G1 GC 提供了一种停顿时间预测模型，用户可以通过参数-XX:MaxGCPauseMillis设定每次GC的期望停顿时间
3.Concurrent Marking Cycle Phases：
Concurrent Marking Cycle Phases包括Global Concurrent Marking和Mixed GCs，具体步骤如下图，需要注意的是Global Concurrent Marking不是GC过程，并不会和Mixed GC同时发生，它只负责标记、统计出收集收益高的老年代region
Initial-mark：标记所有能直接可达的根对象，当达到IHOP阈值时并不会直接触发，而是等待下一次Young GC，利用其STW时间完成初始标记
Concurrent Marking：和应用程序线程并发的执行，从GC Roots开始对堆中的对象标记，标记出各个region中存活的对象
Remark：暂停所有应用线程，重新扫描堆中的对象，标记在并发标记阶段发生变化的对象；
Clean：统计有存活对象和没有存活对象的region，更新RSet，把完全空闲的region收集到可分配队列
Evacuation Reclaim：拷贝整理老年代存活对象的过程，需要暂停应用程序
>>>>
为什么选择G1GC
根据以上简述可以得出几个结论：
G1在停顿时间上添加了预测机制，用户可以设置期望停顿时间，Stop The World时间相对可控
G1的年轻代和老年代空间并不是固定的，当现有年轻代分区占满时，JVM会分配新的空闲Region加入到年轻代空间，老年代也是如此。还记得在CMS中出现的年轻代空间有大量浪费的情况吗？那将不再是问题。另一方面，由于Talos无法保证每台机器的吞吐完全一致，不同机器的GC压力也是不一样的，该特性使得Talos进程可以根据情况自行调整年轻代和老年代的空间大小，以应对不同的GC压力
G1 GC的回收过程中有内存整理，理论上不会产生内存碎片！
第三点是Talos目前最需要的特性，这也是之前CMS无法解决的问题，因此我们开始调研和尝试使用G1 GC。
>>>>
Talos+G1遇到的问题
在测试集群模拟线上压力，验证使用G1后的效果是否符合预期
1.测试环境
保持和线上一致的读写压力：单机写入流量 150MB/s，读取300MB/s
根据调研和CMS的使用经验，参数设置如下：
2.GC日志分析
在稳定运行一段时间后，测试集群开始出现由GC引起的请求堆积，通过gc_log_visualizer工具将GC日志可视化后进行分析，结果如下图：
对上图中的曲线做一些说明：
截取了某天0点-11点的数据，横轴代表时间，纵轴代表内存使用情况，单位是MB
在12~14G浮动的绿色曲线代表老年代使用的内存空间，可以看到老年代常驻内存对象长时间超过IHOP(20*65%=13GB)
在200MB~2G浮动的紫色曲线代表年轻代使用的内存情况，年轻代非常小可能会导致Young GC非常频繁
在13~16G浮动的黄色曲线代表整个堆的使用情况，可以看到堆空间还存在一定浪费，有大约4G左右的空间没有被合理利用
蓝色的圆点代表发生了一次to-space exhausted，表示的意思是没有足够的空间复制对象，对象复制到survivor区和晋升老年代可能出现to-space exhausted
在2G左右浮动的黄色方块代表一次Mixed GC回收的空间，可以看到每次回收的空间都比较小
下图表示GC在整个程序执行时间的占比，可以看到最高已经达到15%左右（CMS中该值为6%左右）：
下图表示年轻代和老年代GC的停顿时间，可以看到：
Young GC最长达到了4.5秒
7点前没有Mixed GC，之后Mixed GC非常频繁，一个小时大概出现60次并发标记周期，每个周期只发生2次MixedGC
3.调整思路
根据上述分析，调整思路如下：
这里在初始设置时存在一个误解，和CMS不同的是，IHOP是老年代空间占堆的比例，而不是老年代中的使用率，因此将IHOP阈值调大为70%
Mixed GC太频繁，每次回收的内存又比较少，因此减小-XX:G1OldCSetRegionThresholdPercent为3%，并调大-XX:G1HeapWastePercent为10%，以此达到控制 Mixed GC 频率和单次耗时的目的
年轻代太小，将-XX:G1MaxNewSizePercent调整为30%
调整后再使用gc_log_visualizer进行绘图，结果如下：
调整后的效果非常明显：
gc耗时有了显著下降，平均时间在70ms左右，减少了GC对Talos读写请求的影响
年轻代大小在不断调整，说明Young区压力适中，自适应性良好（若压力过大，STW耗时较长，则Young区会一直减小至G1NewSizePercent 附近；若压力太小，则young区会一直扩大至G1MaxNewSizePercent 附近）
40分钟左右触发1次并发标记周期，周期内发生8次Mixed GC，一共回收5G左右内存，说明此时old区和Mixed GC压力较小，大部分对象都在Young区得到了回收
GC耗时在应用程序执行时间中的占比为[0.1%~3.4%]，吞吐性能良好
4.长达4秒的 Young GC
此时G1的性能已经基本满足Talos的需求了，但是还有一个隐患没有得到解决，就是长达4秒的Young gc还没有定位到原因。通过查看日志可以发现：这些4秒左右的GC其实都是Full GC(Allocation Failure)
-
2020-01-02T00:32:07.042+0800: 222101.087: [GC pause (G1 Evacuation Pause) (young)
-
Desired survivor size 33554432 bytes, new threshold 3 (max 3)
-
- age 1: 8913160 bytes, 8913160 total
-
- age 2: 3161912 bytes, 12075072 total
-
- age 3: 1664776 bytes, 13739848 total
-
222101.087: [G1Ergonomics (CSet Construction)
start choosing CSet, _pending_cards:
37632, predicted base
time:
32.03 ms, remaining
time:
57.97 ms, target pause
time:
90.00 ms]
-
222101.087: [G1Ergonomics (CSet Construction)
add young regions
to CSet, eden:
0 regions, survivors:
1 regions, predicted young region
time:
2.34 ms]
-
222101.087: [G1Ergonomics (CSet Construction)
finish choosing CSet, eden:
0 regions, survivors:
1 regions,
old:
0 regions, predicted pause
time:
34.37 ms, target pause
time:
90.00 ms]
-
222101.089: [G1Ergonomics (
Heap Sizing) attempt
heap expansion, reason: region allocation request
failed, allocation request:
509312
bytes]
-
222101.089: [G1Ergonomics (
Heap Sizing) expand the
heap, requested expansion amount:
509312
bytes, attempted expansion amount:
16777216
bytes]
-
222101.089: [G1Ergonomics (
Heap Sizing) did
not expand the
heap, reason:
heap already fully expanded]
-
222101.376: [G1Ergonomics (
Concurrent Cycles) request
concurrent
cycle initiation, reason: occupancy higher
than threshold, occupancy:
21474836480
bytes, allocation request:
0
bytes, threshold:
13958643660
bytes (
65.00 %),
source:
end
of GC]
-
(
to-
space exhausted),
0.2899120 secs]
-
2020
-01
-02T00:
32:
07.431+
0800:
222101.476: [
Full GC (Allocation
Failure)
15G->
13G(
20G),
4.4796644 secs]
-
[Eden:
0.0B(
400.0M)->
0.0B(
400.0M) Survivors:
0.0B->
0.0B
Heap:
15.5G(
20.0G)->
13.5G(
20.0G)], [Metaspace:
59784K->
59784K(
1103872K)]
-
Heap
after GC invocations=
376434 (
full
561):
-
garbage-
first
heap total
20971520K, used
14140603K [
0x00000002c0000000,
0x00000002c1002800,
0x00000007c0000000)
-
region
size
16384K,
0 young (
0K),
0 survivors (
0K)
-
Metaspace used
59784K,
capacity
60254K, committed
61056K, reserved
1103872K
-
class
space used
6020K,
capacity
6153K, committed
6272K, reserved
1048576K
-
}
-
[Times:
user=
5.55
sys=
0.00,
real=
4.48 secs]
这里有一个非常诡异的现象，occupancy: 21474836480 bytes 表示堆空间已经使用了20G，但是下一条日志中Heap: 15.5G(20.0G)->13.5G(20.0G)又显示堆空间只用了15.5G，难道是G1 GC计算错误导致的Full GC？
Google一下发现了这个Bug[https://bugs.openjdk.java.net/browse/JDK-8140597]，JDK版本和Talos的使用场景都吻合，Talos使用的是OpenJDK_1.8.0，并且进程在处理读写请求时会不断产生巨型对象，这可能会强制中断Mixed GC，导致老年代完全没有被收集，直到触发Full GC，因此可以通过升级JDK解决。
5.监控打点
在测试和调优阶段，我们是通过绘图工具将GC日志转换为曲线图来分析的，但是在线上环境，不可能每次下载日志到本地再用工具绘图，因此 Talos 使用JMX（提供进程运行时获取堆使用情况、GC次数和GC耗时的方法）对进程的内存使用情况、GC次数和GC耗时进行了监控打点，效果如下：
这样一来，我们不仅解决了 CMS 周期性 Full GC 的问题，也填补了Talos在GC监控上的空白。
小结
将G1上线到线上集群运行7天后，读请求堆积情况如下，可以看出，G1 GC已经完全消除了周期性Full GC对读写请求的影响。
至此，Talos 在GC问题上经历的三个阶段就全部说完了，希望大家能够得到一些解决GC问题的思路，有任何问题都可以互相交流，欢迎吐槽 : )
参考文献
[1]Getting Started with the G1 Garbage Collector
[2]Garbage-First Garbage Collector Tuning
[3]G1: One Garbage Collector To Rule Them All
[4]HBase原理与实践-G1GC性能调优
[5]A generational Mostly-concurrent Garbage Collector
[6]Garbage-First Garbage Collection
我就知道你“在看”
转载：https://blog.csdn.net/pengzhouzhou/article/details/103917893