此文是笔者对于 GC 系列调研的收尾。本次工作全面总结了 PS、G1 等常见 GC 的工作原理、可调参数,解析了 GC 日志读法、可观测手段,还从延迟、吞吐两个角度分别总结了调优方法论。内容覆盖从 GC 基本知识、观测手段、日志解析到调优方法,完成了 GC 诊断、定位、调优的全链路调研解析。

文章大量参考互联网资料,感谢!

基本原理与介绍

基础知识1:对于 GC,无论其具体实现和策略,都有标记-清除、复制、标记-整理等基本算法,只是不同的 GC 使用不同的基本算法。此处不再赘述,详细可以参考往期博客

基础知识2:对于大部分 GC,都会对堆内存进行分代划分,可以参考往期博客。对于更详细的 java 内存划分概念,同样可以参考往期博客

基础知识3:对于 GC,在 footprint(内存占用)、throughout(吞吐)、latency(延迟)三者不可能同时满足。最多三者满足其二。(类似 CAP 定理)

吞吐量跟低延时是无法兼得的,低延时意味着GC工作会更加频繁,相对的,会占用应用的资源,吞吐量降低。需要大吞吐量,那么GC工作就会减少,相对的,每次回收的垃圾就会多,暂停时间就会增加,延时就会增加。

我们经常遇到的情况是高吞吐的 GC 单次 stw 时间较长;而 stw 优秀的 GC 往往 GC 频率高、占用线程资源多,导致吞吐低。因此我们调优需要有的放矢,一般是针对吞吐和延迟分别调优,而不是同时追求吞吐和延迟。

G1

在 jdk 7 才推出,9 中正式作为默认 GC ,注重停顿时间。

本文主要从 oracle 官网文档和 G1 的论文进行宏观上的调研。

设计理念

【摘自官网】

G1 垃圾收集器是一个服务端的垃圾收集器,它针对的是拥有较大内存的多处理器的机器。

• 它既满足了暂停时间比较短的高性能,又满足吞吐量比较高的目标。

G1 垃圾收集器是在 Oracle 的 JDK7 update 4 及以后的版本得到了完全的支持。G1 垃圾收集器是针对这样的应用来进行设计的:

• 能够像 CMS 收集器一样跟应用线程并发的去执行。【CMS 本身就是一个并发的收集器,也就是GC线程与应用线程可以同时间执行】
• 可以压缩可用的空间,而不会让 GC 引起暂停时间过长。
• 需要更多的可预测的 GC 暂停的间隔。【也就是说 GC 暂停的时间会尽量往我们设置的暂时时间来靠】
• 不想牺牲大量吞吐性能。
• 不想需要大量 Java 的堆空间。

Oracle 官方说明:如果应用程序具有以下一个或多个特征,则当前使用 CMS 或 PS 运行的应用程序将有利于切换到 G1:

• Full GC 持续时间太长或太频繁。
• 对象分配率或提升率波动很大。
• 不需要的长时间垃圾收集或压缩暂停(超过 0.5 到 1 秒)

【笔者经验总结】

也就是说,G1 是一款相对通用,在 footprint(内存占用)、throughout(吞吐)、latency(延迟)三者达成一个较好平衡的回收器,相对更侧重 latency(延迟,或者我们常说的暂停时间)的优化。相比于 PS,G1 的 FGC 将显著减少。

因此 G1 不经过调优,实测在 IoTDB 的某些场景下,吞吐等指标不如 PS 等侧重优化吞吐的 GC

补充:CMS 被废弃的原因有部分原因是源于 G1 更可控、更易于维护、在大多数场景下有更好的表现。

参考:https://openjdk.org/jeps/291

Oracle 官网专门提到:G1 的吞吐量目标是 90% 应用 + 10% GC,而 PS 是 99% 应用 + 1% GC。因此 G1 的吞吐肯定是不如 PS 的,但是 G1 的 stw 表现比 PS 更优秀。

G1 内存模型

一般的 GC (像 serial、PS、CMS)采用分代内存模型,如下图:

image-20240401161844376

G1 在内存空间的划分上:堆被划分了一组相等大小堆区域(region),区域之间可能是离散的,但每一个区域都是连续虚拟内存的地址空间, 这就提供了内存使用当中最大的灵活性。区域大小由-XX:G1HeapRegionSize决定。一般来说,JVM 大约划分 2000 个 regions,它们的大小范围为 [1, 32] MB

但是在概念上仍采取分代内存的思想,即这些 regions 会分别映射到 eden、survivor、old。

image-20240401161859543

此外,还有一种上图没标出的 region,称为巨型区域(huge region)。 这些区域用于容纳尺寸为标准区域 50% 或更大的对象,它们存储为一组连续的区域。

G1 的 GC 过程

年轻代收集

在 YGC(Young GC) 中,live objects 被搬运(evacuated,即复制或移动)到一个或多个 survivor 区域。 如果满足老化阈值,则某些对象将被提升到老一代区域。YGC 将 stw 。

• 注意 Eden 大小和 Survivor 大小是为下一次 YGC 计算的。 相关信息会被保留以帮助计算大小。 诸如暂停时间目标(-XX:MaxGCPauseMillis)之类的事情都会被考虑在内。这种方法可以根据需要放大或缩小 Eden 和 Survivor 的大小。

image-20240401161917881

在 YGC 的末尾,live objects 已被搬运到幸存者区域或晋升到老年代区域。

image-20240401161929260

综上所述:

• 堆是划分为多个区域的单个内存空间。
• 年轻代内存由一组不连续的区域组成。这使得在需要时可以轻松调整大小。
• YGC 是 stw 的事件。 所有应用程序线程都会因该操作而停止。
• YGC 使用多个线程并行完成。
• 活动对象被复制到新的幸存者或老一代区域。

老年代收集

G1 收集器在堆的老年代执行以下阶段。

• 请注意,某些阶段是 YGC 的一部分(因为 G1 的实现里面,由 YGC 触发 mixed GC / full GC)
• Mixed GC 是 G1 特有的回收策略,在回收年轻代之余,还会回收部分收益较高的老年代区域

接下来看看这些 phase 是如何和 G1 的老年代交互的

1. Initial Marking Phase

活动对象的初始标记是在 YGC 的基础上进行的。 在日志中,这被标记为 GC pause (young)(inital-mark).

image-20240401162004224

2. Concurrent Marking Phase

如果发现空区域(如"X"所示),则在 marking 阶段立即将其删除。 此外,还计算确定 liveness 的"accounting"信息。

image-20240401162019150

3. Remark Phase

空区域被删除并回收。 所有区域的 liveness 将被计算

image-20240401162032792

4. Copying/Cleanup Phase

G1 选择"liveness"最低的区域,即可以最快收集的区域。 然后这些区域会与 YGC 同时收集。 这在日志中表示为 [GC pause (mixed)]。 所以年轻代和老年代都会同时被收集。

image-20240401162043900

5. After Copying/Cleanup Phase

所选区域已被收集并压缩为图中所示的深蓝色区域和深绿色区域。

image-20240401162055015

综上所述,关于老年代的 G1 垃圾回收:

• Concurrent Marking Phase
  • Liveness 信息是在应用程序运行时同时计算的。
  • 此 liveness 信息可识别在疏散暂停期间最适合回收的区域。
  • 没有像 CMS 那样的清理阶段。
• Remark Phase
  • 使用开始快照 (SATB) 算法,该算法比 CMS 所使用的算法(增量更新)快得多。
    • 详细介绍:对于对象关系的扫描处理(GC root 扫描),JVM 使用「三色标记算法」。然而,对于该算法,在用户线程和 GC 线程并发的情况下,存在漏标情况。CMS 和 G1 分别对漏标问题有不同的解决方案。
      • CMS 对增加引用环节进行处理(Increment Update),G1 则对删除引用环节进行处理 (SATB)
    • SATB 算法的机制是:在三色扫描时,如果用户线程断开灰色对象 A 到白色对象B 的引用,会通过写屏障机制记录当前对象状态的快照。然后在 Remark phase 中将 B 改为灰色,重新扫描一遍
      • 由于 RSet 的存在,且对象 B 在对象引用链中的深度一般较大,遍历链的扫描开销较小
    • CMS 的增量更新机制是:当黑色对象要增加指向灰色或白色对象的引用关系时,将发出引用的黑色对象改为灰色,重新扫描一遍
      • 由于黑色对象在对象引用链中的深度较小,遍历链的深度扫描开销大,所以比 G1 的 SATB 慢
  • 完全空的区域被回收。
• Copying/Cleanup Phase
  • 年轻代和老年代同时被回收。
  • 老年代区域是根据其活跃度来选择的。

PS

JDK 8 的默认 GC,又叫 throughout GC,注重吞吐

中英文互联网都没搜到特别详实的、原理层次的解析。因此这里主要参考国内 system 领域著名实验室 iPads 的论文中关于 PS 原理的论述。感兴趣的读者也可以直接阅读论文原文:

• https://ipads.se.sjtu.edu.cn/_media/publications/scissorgc-vee2019.pdf
• https://ipads.se.sjtu.edu.cn/_media/publications/yuvee.pdf
• https://ipads.se.sjtu.edu.cn/_media/publications/wuatc20.pdf

PS 的 GC 过程

对于 YGC,PS 基于标记-复制算法(copy-based),论文没有做详细的描述。

大多数对象一开始分配在 eden 区(一些大对象是例外,会直接分配到 old 区)。当 YGC 后,一些对象被移动到 survivor 区,同时一些其他年老的对象被晋升到老年代。

对于 FGC,PS 基于标记-整理算法(compaction-based)

PS 的 FGC 实现分为三个阶段,包括 marking phase, summary phase, 和 compacting phase。 这三个阶段都是 region-based: PS 将 JVM 堆划分为相等大小的连续 regions(默认大小为 512KB),并将相同 region 内的 live objects 一同整理(compact)

• 论文给出的 region 代码是:

class Region { 
 // Fields in vanilla PSGC
 int dcount;
 int live_obj_size;
 char* dest_addr;
 Region*[] src_regions;
 ...
} 

去 openjdk 源码求证了一下,论文给出的源码应该是简化过的,并不是完整、标准的源码。

• 实际对比后,论文的 class Region 应该对应:openjdk - RegionData

PS 的 FGC 可以划分为以下三阶段:

1. Marking phase:GC 线程将从已知根(GC roots),例如堆栈引用和静态变量,搜索活动对象。 所有从 GC roots 可达的对象将被标记为活着,并且它们的大小将被添加到特定 region 的 live_obj_size 中。
2. Summary phase:marking phase 结束后,PS 会为所有 region 分别根据它们的 live_obj_size 计算出一个 heap summary。
   1. Heap summary 会生成一个 source region 到 destination region 的映射,这样每个 source region 都会有 1~2 个 destination region 用于后续的对象拷贝。这些映射被保存在 src_regions 中。
   2. Summary phase 也会生成 per-region indices,即 dest_addr,GC 线程可以用它来得到 region 内 live objects的目标地址。
3. Compacting phase:Live objects 直到该阶段才会被移动或修改。该阶段是 overhead 最大的,一般占了70% 以上的 FGC 开销。
   1. Compacting phase 仍然是 region-based,每个 destination regions 即代表一个 task,GC 线程将并行地从相应的 source regions 中 fetch live objects 去填充这些 destination regions。在 copy 对象的过程中,引用关系也将被更新。
   2. 由于 destination regions 自身可能也是其他 region 的 source regions(即一个 region 可能既是 destination 又是 source,既要把自己的 live objects 拷贝到其他 region 那里,也要接受其他 region 拷贝过来的 live objects),因此 GC 线程必须等 destination regions 内的所有 live objects 都被搬运(evacuated)到它们的 destinations 后才能开始处理它们。

      • 该 process order 通过维护一个名为 dcount 或者下图所示 destination_count 的变量来保持。该变量记录了该 region 作为 source,有多少 destination regions。Summary phase 会计算该变量的值。

      • image-20240401162140442

      • 在 Compacting phase,一旦某个 GC 线程 fills up 了一个 destination region,它将相应 update 该 destination region 关联的所有 source region 的 dcount(减1)。当某个 region 的 dcount 减为 0 时,意味着它作为 source region 的职责结束,可以 serve as a destination region 了。该 region 会被 push 到 GC 线程的 working stack 中,并准备好接受其他 source regions 中的 live objects。

Compact 详细算法

image-20240401162113697

论文提供了 Figure 2 来帮助理解,下面详细解说:

1. 假设有 6 个 region,从 0 编号到 5;假设有 2 个 GC 线程,从 0 编号到 1
2. 在 Summary phase。由于 region 0 和 region 2 不包含 live objects,所以它们的 dcount 是 0(因为它们不需要将自己的 live objects 拷贝出去)。而其他 region 都有相应的 destination regions
3. 当 Compacting phase 开始时,region 0 和 region 2(dcount 为 0 的 regions)会被分配到 GC thread 0、1 的 working stack 中(如 Figure 2.a 所示)
4. 两个 GC 线程会根据 Summary phase 生成的 per-region indices 将其他 regions 中的 live objects 拷贝到 stack 中对应的 regions(如 Figure 2.a 所示)
5. 当 region 0 被 thread 0 处理后,region1 的 dcount 会减为 0,这意味着 region1 可以作为 destination region 入栈被 GC 线程处理了。
6. 由于 region 1 一开始依赖 region 0,并是 region 3、4 的 destination regions。因此它会被 push 到 thread 0 的栈中(如 Figure 2.b 所示)
7. 相反,当 thread 1 完成 region 2 的处理后,region 5 并不会被 push 到 GC 线程的栈中,因为没有 region 依赖它。
8. 相似地,当 region 1 的 task 完成后,region 3、4 不会被 push 到 GC 线程的栈中。此时所有的 live objects 都被整理完毕,compacting phase 结束。

GC 对性能的影响

受GC影响请求占比=(接口响应时间+GC时间)×ばつN/T

举例:假设单位时间T内发生一次持续25ms的GC,接口平均响应时间为50ms,且请求均匀到达,根据下图所示:

image-20240401162150663

那么有 (50ms+25ms)/T 比例的请求会受GC影响,其中GC前的 50ms 内到达的请求都会增加 25ms,GC期间的25ms 内到达的请求,会增加 0-25ms 不等,如果时间 T 内发生 N 次GC,受GC影响请求占比=(接口响应时间+GC时间)×ばつN/T 。可见无论降低单次 GC 时间还是降低 GC 次数 N 都可以有效减少 GC 对响应时间的影响。

JVM 调优参数

以下参数均来自 oracle JDK 8、11、17 官方文档 GC VM options 板块,本文档实现了对 oracle 官网的全覆盖。

很多参数背后都有 trade-off。所以 JDK 团队已经为我们选取了最合适的 default 值,大多数情况不需要修改。

• 比如说:-XX:InitiatingHeapOccupancyPercent,如果该值过小,比如 Mixed GC 周期结束后老年代使用率还是超过 IHOP,那么会再次触发全局并发标记过程,这样就会导致频繁的老年代 GC,影响应用吞吐量。如果此值太高,会导致老年代回收不及时(容易导致年轻代晋升失败而触发 Full GC) + 老年代一次回收的任务量较重(造成尖刺)

G1

PS

调优建议

我们调优的时候,通常从以下事实出发:

1. 调优目标:

• 降低停顿时间(减少 fgc)(常用)
• 提高吞吐(减少 gc 次数)(常用)
• 降低 footprint 占用

2. 根据业务需求进行调优:

• 比如对于高并发场景,大多数对象是朝生夕死的,也就是说大部分对象在新生代创建后,还没来得及晋升到老年代就死亡了。这种情况下就需要提高新生代内存,减少 fgc。

3. 调优策略

我们的终极目标是

1. 减少 ygc、fgc 的次数
2. 降低 ygc、fgc 的耗时

首先对于减少次数:我们从 GC 的成因拆解。

• ygc 的成因是新生代的空间不足以容纳对象大小 —— 因此减少 ygc 的次数可以通过增加新生代空间大小实现。常见的做法是分析 old 和 young 的空间大小,如果 old 有盈余,可以适当减少 old,增加 young
• Fgc 的成因是
  • 当新生代的 Eden 区、Survivor 区无法容纳新的对象时,会触发 ygc。如果在 ygc 后仍然没有足够的内存空间分配对象,则会触发 fgc —— 因此这里还是新生代空间大小的问题,可以通过增大新生代空间解决
  • 当老年代无法容纳新的对象时,会触发 Major GC(老年代垃圾回收)。如果在 Major GC 后仍然没有足够的内存空间分配对象,则会触发 fgc —— 1. 如果是老生代空间大小的问题,可以通过增大老生代空间解决;2. 如果是对象晋升过快的问题,可以调大 survivor 区大小,减缓对象在 from 和 to 区复制转移的速度;或者直接增大新生代空间,以减缓年龄晋升速度;3. 调整代码,尽量减少大对象和对象频繁创建行为
  • 当元空间的类加载信息、常量池等元数据无法容纳新的数据时,会触发 fgc —— 因此这里是 metapsace 空间大小的问题,可以通过增大 metaspace 空间解决

其次对于减少耗时,这里要复杂很多,我们仍然从成因分析:

• Ygc 的一个常见耗时场景:对于 PS、G1 这种标记复制算法的 gc,大多数对象需要在 survivor 区的 from 和 to 复制多次,直到晋升 —— 所以为了减少复制成本,MaxTenuringThreshold 要尽量合理,不能设置太大,否则有些长寿对象在每次 GC 时都会在两个 Survivor 区之间来回复制,无疑是增加了复制阶段的耗时
• GC log 里经常会看到 safe-point —— 遇到锁竞争时,取消锁的过程需要等待全局安全点(safe point),会导致所有线程暂停,即会发生Stop-The-World。所以在锁竞争激烈的场景下,最好提前关闭掉偏向锁。
• GC 的某个阶段耗时过长(可以从日志看出) —— 1. 调整并行线程、并发线程等参数,增加并行度,优化性能;2. 优化代码,减少大对象创建等;3. 根据实际情况减少该阶段的耗时

4. 内存参数基本策略

各分区的大小对 GC 的性能影响很大。如何将各分区调整到合适的大小,分析活跃数据的大小是很好的切入点。

活跃数据的大小是指,应用程序稳定运行时长期存活对象在堆中占用的空间大小,也就是 Full GC 后堆中老年代占用空间的大小。可以通过 GC 日志中 Full GC 之后老年代数据大小得出,比较准确的方法是在程序稳定后,多次获取 GC 数据,通过取平均值的方式计算活跃数据的大小。活跃数据和各分区之间的比例关系如下:

例如,根据GC日志获得老年代的活跃数据大小为300M,那么各分区大小可以设为:

总堆:1200MB = 300MB ×ばつ 4

新生代:450MB = 300MB ×ばつ 1.5

老年代: 750MB = 1200MB - 450MB

这部分设置仅仅是堆大小的初始值,后面的优化中,可能会调整这些值,具体情况取决于应用程序的特性和需求。

PS

Parallel GC会尽量去满足如下目标:(优先级由高到低)

• 最大停顿时间目标
• 吞吐量目标
• 最小移动目标

对 ParallelGC 的调优,其目标应尽可能避免 Full GC, 这就需要优化对象老年化的频率,

使用 ParallelGC 时,垃圾收集的资源开销应小于 5%,如果已经减少到 1% 甚至更少,基本上已经达到极限了。

吞吐优先

1. JVM 自适应调优:宏观目标:-XX:GCTimeRatio=99 。其值为1-100的整数,表示吞吐量,默认值是99,表示允许1%的垃圾回收时间占比。暂停时间越长,那么垃圾回收占用的时间比越大,可能会超过前面的设定比例。
2. 降低线程资源占用:根据实际情况适当调小-XX:ParallelGCThreads ,给用户线程让出更多的 CPU 资源
3. 想方设法降低 GC 频率(这样可能会导致每次 GC 的 stw 时间变长):包括调高-XX:MaxGCPauseMills等
   1. 如果 ygc 频率过高,可以从两个角度考虑:
      1. 尝试调高 young 区大小,推迟对象堆积的时机
      2. 根据日志:尝试调整晋升年龄,将大部分对象及时晋升,减少在 s 区来回 copy 的开销并占据 young 区
   2. 如果 fgc 频率过高,建议根据日志从以下角度考虑调优
      1. 是否 old 区内存增长速度过快——减缓对象晋升速度
         1. 可以调整 young 区
            1. 直接调大 size:-Xmn
            2. 调整 young 和 old 的比例 :-XX:NewRatio
            3. 可以调大 survivor 区,减缓对象晋升速度:-XX:SurvivorRatio
      2. 是否 young 区过小,ygc 后仍然没有足够空间——调大 young 区
         1. 直接调大 size:-Xmn
         2. 调整 young 和 old 的比例 :-XX:NewRatio
      3. Meta 区是否过小——调大 Meta 区

延迟优先

1. 宏观目标:-XX:MaxGCPauseMills=<N> ,值大于0的毫秒数。
2. 新生代(Ygc)调优: 如果发现 GC 频率过高,整体新生代又太小,可以增大新生代的大小,从而降低 YGC 的频率和占用时间。ParallelGC 可以自动调整 Survivor 空间,大部分的程序使用自动调整可以满足要求,个别应用在需要的情况下可以关闭自动调整,进行手动调整。
   1. -Xmn(设置新生代大小) 、-XX:-UseAdaptiveSizePolicy(关闭自适应调整)
   2. 一般情况下 Eden 区的大小比 Survivor 大很多,如果大量对象都在一次 YoungGC 后就会回收清理,那么新生代 Eden:From:To 为8:1:1就比较合适。如果说很大部分对象的年龄都超过 1,即需要在 Survivor 的 From,To 中来回转换几次之后才能被回收,那么此时可以调小 SurvivorRatio 的值,在整个新生代不变的情况下,会增大 Survivor 区的大小(From 和 To 同时增大)。将 Survivor 的空间使用率增大,避免对象年龄增长过快,从而被移动到老年代,造成 FullGC。
      1. -XX:SurvivorRatio 可以调整新生代中 Survivor 与 Eden 区的比例,例如 -XX:SurvivorRatio=6 表示S(From) : S(To) : Eden = 1: 1: 6 。其默认值为8
3. 老年代调优
4. 并行线程的优化:-XX:ParallelGCThreads=<N>。此参数设置年轻代并行收集器的线程数,一般与 CPU数量相等,过多的线程数量会影响垃圾回收以及整个程序的性能。

G1

无论以延迟还是吞吐为目标,Oracle 官网不建议我们显式通过-Xmn设置新生代区域大小(仅管前面 PS 我们提到过这种做法),因为这与 G1 的默认表现相悖:

• 设置新生代大小会让 G1 的停顿目标失效
• 设置新生代大小会让 G1 失去动态扩缩容新生代的能力

吞吐优先

想达到吞吐目标,建议优先考虑 PS。

如果想使用 G1 的同时优化吞吐,建议:

1. 降低线程资源占用:根据实际情况适当调小 -XX:ParallelGCThreads 和 -XX:ConcGCThreads,给用户线程让出更多的 CPU 资源
2. 想方设法降低 GC 频率(这样可能会导致每次 GC 的 stw 时间变长):包括调高XX:MaxGCPauseMillis等方法
   1. 可以参考上文 PS 片段中提到的方法
   2. 此外还可以根据日志观察程序是否有规律大小的大对象。如有,可针对性设置 regionSize,增大内存利用率。
   3. 如果上述方法都效果不大,尤其是在 space-reclaimation 阶段,根据 oracle 官网,建议调高 young 区的最小 size -XX:G1NewSizePercent 并调高 young 区的上限 size -XX:G1MaxNewSizePercent
   4. 如果 fgc 频率过高,对于 G1,可以适当提高 mixed gc 频率。调整 -XX:G1HeapWastePercent。也可以调整 -XX:InitiatingHeapOccupancyPercent,来提前开启并发标记,用更多的小代价 mixed gc 换取更少的高代价 fgc
3. 降低 concurrent work 的频率:根据 oracle 官网,并发很消耗 cpu 资源。可以调高 -XX:G1RSetUpdatingPauseTimePercent,将并发工作移到 gc pause 中。
4. 内存调优:-XX:+AlwaysPreTouch,将 -Xmx 和 -Xms 设置为同样的值以禁止堆自动扩缩容

延迟优先

1. 根据 oracle 官网的建议,对于延迟我们主要关注 XX:MaxGCPauseMillis=<N>参数,考虑将XX:MaxGCPauseMillis 设置为能满足 90% 场景需求的值。也就是说,90% 的 gc 停顿不超过 XX:MaxGCPauseMillis

2. 如果我们在日志中看到很多 Evacuation Failure,那么可以考虑下面一些方案:

   1. What is an Evacuation Failure?

      A promotion failure that happens when a JVM runs out of heap regions during the GC for either survivors and promoted objects. The heap can’t expand because it is already at max. This is indicated in the GC logs when using -XX:+PrintGCDetails by to-space overflow. This is expensive!

      • GC still has to continue, so space has to be freed up.
      • Unsuccessfully copied objects have to be tenured in place.
      • Any updates to RSets of regions in the CSet have to be regenerated.
      • All of these steps are expensive.

   2. 增加 heap size

      1. 此时最好同步增加**-XX:G1ReservePercent=n**, 默认值是 10。这样会流出更多的空间来供晋升

   3. 更早开启 marking cycle,调低 -XX:InitiatingHeapOccupancyPercent(提前开启 mixed GC)。 Evacuation Failure 的代价比多执行一些 marking cycle 周期高很多。

   4. 增加 marking 阶段的线程,设置 -XX:ConcGCThreads

3. 优化 ygc 时间。

   1. 观察大部分对象的晋升年龄和目前程序设置的 tenure threshold,将二者调为一致,保证对象在该晋升时就晋升,减少新生代 from 和 to 区来回复制的开销

4. 优化 mixed gc 时间(此段参考 oracle 官网)

   1. 通过增加 -XX:G1MixedGCCountTarget 将老年代区域回收分散到更多垃圾回收中。
   2. 降低 -XX:G1MixedGCLiveThresholdPercent ,不将花费大量时间的区域放入候选收集集中,可以避免收集这些区域。 在许多情况下,高度占用的区域需要花费大量时间来收集。
   3. 可以增加 -XX:G1HeapWastePercent,尽早停止老年代的空间回收,这样 G1 就不会收集那么多高度占用的区域。

观测 GC 的方式

日志

开启日志参数

JDK8

-Xloggc:${IOTDB_HOME}/logs/gc.log 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintHeapAtGC
-XX:+PrintReferenceGC 
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1 
-XX:+PrintTenuringDistribution 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintPromotionFailure 
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100M

JDK9 及以上 JVM 重构了日志框架。大大简化了日志参数,下面的参数基本与上面等价:

-Xlog:
gc*=debug,
heap*=debug,
age*=trace,
metaspace*=info,
safepoint*=debug,
promotion*=info:
file=${IOTDB_HOME}/logs/gc.log:time,uptime,pid,tid,level,tags:filecount=10,filesize=100M

如何读日志

默认的 JVM 日志包括:

[启动经过时间][日志级别][日志标签,可能包含多个] 日志内容

比如:

[2024-01-15T15:14:32.025+0800][278.288s][3381829][3381900][debug][gc,alloc,region ] GC(418) Mutator Allocation stats, regions: 136, wasted size: 2952B ( 0.0%)

其中一行日志,可能包含多个标签。如上面的例子里标签就有 gc、alloc、region。之后关于 JVM 日志相关的配置,也是围绕着这些标签进行配置。

gc 日志有很多标签与组合,大部分以 gc 标签为开始,混合搭配其他一些标签。一般,有如下几个标签我们会经常用到:

1. 标签gc

gc 总体描述日志,一般设置 info 级别查看 gc 的发生时间,消耗时间还有内存大小。例如:

[2024-01-15T15:14:32.112+0800][278.375s][3381829][3381900][info ][gc ] GC(418) Pause Young (Normal) (G1 Evacuation Pause) 20934M->20078M(25088M) 86.631ms

包含了 gc 类型,gc 原因,收集内存大小,持续时间等信息

目前 System 面板较好的集成了该项日志信息,也推荐直接看 System 面板。

2. 标签gc,age

gc 中 age 相关信息,age 比较高的对象会进入老年代。debug 级别只会输出最高级别的 age 以及期望大小。如果是 trace 级别,会输出:

• 每一个 age 的所有对象占用总大小
• 不大于这个 age 的所有 age 的大小。

例如:

[2024-01-15T15:14:44.595+0800][290.858s][3381829][3381900][trace][gc,age ] GC(441) Age table with threshold 15 (max threshold 15)
[2024-01-15T15:14:44.595+0800][290.858s][3381829][3381900][trace][gc,age ] GC(441) - age 1: 164913704 bytes, 164913704 total
[2024-01-15T15:14:44.595+0800][290.858s][3381829][3381900][trace][gc,age ] GC(441) - age 2: 36313680 bytes, 201227384 total

这个标签可以有效分析对象的晋升年龄情况,从而调整 -XX:MaxTenuringThreshold等选项

3. 标签gc,alloc,gc,alloc,region

这两个参数仅对 G1 gc 有效 gc,alloc 在 gc 完成的时候,打印 trace 级别日志记录触发 gc 的线程是哪一个以及返回的 gc 结果地址,一般是在 debug 调试 gc 的时候才需要看这个日志,平时开到 debug 级别即可。

[2020-02-28T02:14:02.694+0000][trace][gc,alloc ] sdk-27692-2-amqp-t-4: Successfully scheduled collection returning 0x00000007ffc00000

gc,alloc,region 统计每次 gc 的 Regions 信息,打印 debug 级别日志。

[2024-01-15T15:14:46.431+0800][292.694s][3381829][3381900][debug][gc,alloc,region ] GC(445) Mutator Allocation stats, regions: 136, wasted size: 536B ( 0.0%)

4. 标签gc,cpu 这个是大多数 gc 问题定位需要查看的日志,info 级别打印每次gc真正耗时:

注意到日志中时间分为了三块:user, sys,和 real,三者的区别和含义如下:

• real:指的是在此次 GC 事件中 CPU 实际所花费的时间,跟钟表上的时间是一致的(wall clock time);
• user:指的是 CPU 工作在用户态所花费的时间;
• sys:指的是 CPU 工作在内核态所花费的时间。

User + sys 就是 CPU 花费的实际时间,注意这个值统计了所有CPU上的时间。如果 CPU 是多核的,User + sys 可能会比自然流逝的绝对时间大

[2024-01-15T15:23:39.132+0800][825.395s][3381829][3381900][info ][gc,cpu ] GC(1449) User=1.41s Sys=0.00s Real=0.11s

一般来说,如果看到 real 所显示的时间 远 大于 User + sys,表明 GC 过程存在某些问题(等待计算资源),原因可能是下面这两种:

• 频繁的 IO 操作(让 GC 延迟)
• 缺乏 CPU 资源(GC 分配不到 CPU cycles)

如果 sys 特别高,说明虚拟机没有得到足够的 CPU,主机的负载可能太高了。可能是 io、内存分配等方面出了问题;

5. 标签gc,ergo,gc,ergo,cset,gc,ergo,ihop,gc,ergo,refine

这是 GC 自适应调节(ergonomics)相关的日志,记录了 GC 是如何自适应调节相关参数的。一般的 debug 级别信息就够了

[2024-01-15T15:23:39.439+0800][825.702s][3381829][3381900][debug][gc,ergo ] GC(1450) Running G1 Clear Card Table Task using 9 workers for 9 units of work for 538 regions.
[2024-01-15T15:23:39.343+0800][825.606s][3381829][3381900][debug][gc,ergo,cset ] GC(1450) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 68.65
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,ergo,ihop ] GC(1378) Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 12398362624B allocation request: 0B threshold: 11838003609B (45.00) source: end of GC
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,ergo,refine ] GC(1378) Updated Refinement Zones: green: 82, yellow: 246, red: 410

6. 标签gc,heap,gc,heap,region

gc,heap的 debug 级别会显示 gc 的时候堆的概况,对于 g1 gc gc,heap,region的 trace 级别,会打印每一个 region 的详细情况,这个一般供 gc 调试使用。

我们一般只需要关心gc,heap的日志就行了:关注年轻代和年老代堆回收前后的情况,观察 GC 效率、堆空间增长速度等。

目前 System 面板较好的集成了该项日志信息,也推荐直接看 System 面板。

[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][info ][gc,heap ] GC(1378) Eden regions: 251->0(229)
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][info ][gc,heap ] GC(1378) Survivor regions: 32->35(35)
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][info ][gc,heap ] GC(1378) Old regions: 1040->1148
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][info ][gc,heap ] GC(1378) Humongous regions: 334->330
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,heap ] GC(1378) Heap after GC invocations=1343 (full 36): garbage-first heap total 25690112K, used 12333688K [0x00000001e0000000, 0x0000000800000000)
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,heap ] GC(1378) region size 8192K, 35 young (286720K), 35 survivors (286720K)
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,heap ] GC(1378) Metaspace used 66936K, capacity 68918K, committed 69760K, reserved 1110016K
[2024-01-15T15:23:02.240+0800][788.503s][3381829][3381900][debug][gc,heap ] GC(1378) class space used 7554K, capacity 8389K, committed 8780K, reserved 1048576K

7. 标签gc,humongous

如果使用的是 G1 gc,并且经常出现 Evacuation Failure 或者 Humongous Allocation ,并且不知道是什么原因的话,可以考虑看看这个标签相关的日志:

记载了大对象的分配情况和大对象 size。至于后面被哪个 remset 标记,在哪个 code root,如果不是调试 gc 的话一般不用关注

[2024-01-15T15:23:02.748+0800][789.011s][3381829][3381900][debug][gc,humongous ] GC(1379) Live humongous region 0 object size 22420064 start 0x00000001e0000000 with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2024-01-15T15:23:02.748+0800][789.011s][3381829][3381900][debug][gc,humongous ] GC(1379) Live humongous region 1052 object size 22420064 start 0x00000003ee000000 with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2024-01-15T15:23:02.748+0800][789.011s][3381829][3381900][debug][gc,humongous ] GC(1379) Live humongous region 1057 object size 22420064 start 0x00000003f0800000 with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2024-01-15T15:23:02.748+0800][789.011s][3381829][3381900][debug][gc,humongous ] GC(1379) Live humongous region 1065 object size 22420064 start 0x00000003f4800000 with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2024-01-15T15:23:02.748+0800][789.011s][3381829][3381900][debug][gc,humongous ] GC(1379) Live humongous region 1070 object size 8968208 start 0x00000003f7000000 with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 0

8. 标签gc,metaspace

查看 metaspace 相关的 gc 日志,gc,metaspace的 info 级别会输出每次 gc 涉及的 metaspace 内存变化。

[2024-01-15T15:23:03.645+0800][789.908s][3381829][3381900][info ][gc,metaspace ] GC(1381) Metaspace: 66936K(69760K)->66936K(69760K) NonClass: 59381K(60980K)->59381K(60980K) Class: 7554K(8780K)->7554K(8780K)

1. 标签gc,phases,gc,phases,ref,gc,phases,task,gc,ref,gc,start,gc,ref,start,gc,task 等

这些标签与 gc 步骤相关,详细记录了 GC 每步的耗时、软/弱等各类引用处理等信息。可以查看这些标签的日志,来了解 gc 的步骤以及原理。

一般可以通过该类日志查看 GC 在哪步耗时显著大,从而针对性优化。

[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][info ][gc,phases ] GC(1382) Pre Evacuate Collection Set: 0.1ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Prepare TLABs: 0.0ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Choose Collection Set: 0.0ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Humongous Register: 0.1ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][info ][gc,phases ] GC(1382) Evacuate Collection Set: 144.4ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Ext Root Scanning (ms): Min: 0.3, Avg: 0.3, Max: 0.5, Diff: 0.3, Sum: 4.3, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Update RS (ms): Min: 4.0, Avg: 16.6, Max: 56.5, Diff: 52.5, Sum: 215.4, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Processed Buffers: Min: 3, Avg: 12.4, Max: 24, Diff: 21, Sum: 161, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Scanned Cards: Min: 767, Avg: 2468.7, Max: 4190, Diff: 3423, Sum: 32093, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Skipped Cards: Min: 0, Avg: 0.4, Max: 1, Diff: 1, Sum: 5, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Scan RS (ms): Min: 7.2, Avg: 34.5, Max: 62.1, Diff: 54.9, Sum: 448.7, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Scanned Cards: Min: 1501, Avg: 11120.2, Max: 21225, Diff: 19724, Sum: 144563, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Claimed Cards: Min: 1792, Avg: 13903.3, Max: 30483, Diff: 28691, Sum: 180743, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Skipped Cards: Min: 43974, Avg: 105456.0, Max: 143149, Diff: 99175, Sum: 1370928, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) AOT Root Scanning (ms): skipped
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Object Copy (ms): Min: 71.7, Avg: 92.3, Max: 129.0, Diff: 57.3, Sum: 1199.7, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) GC Worker Other (ms): Min: 0.1, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 4.5, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) GC Worker Total (ms): Min: 143.8, Avg: 144.1, Max: 144.3, Diff: 0.5, Sum: 1873.1, Workers: 13
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][info ][gc,phases ] GC(1382) Post Evacuate Collection Set: 1.4ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Code Roots Fixup: 0.0ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Clear Card Table: 0.3ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases ] GC(1382) Reference Processing: 0.1ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Reconsider SoftReferences: 0.0ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases,ref ] GC(1382) SoftRef (ms): skipped
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Notify Soft/WeakReferences: 0.0ms
[2024-01-15T15:23:04.104+0800][790.366s][3381829][3381900][debug][gc,phases,ref ] GC(1382) SoftRef (ms): skipped
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) WeakRef (ms): skipped
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) FinalRef (ms): skipped
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Total (ms): skipped
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Notify and keep alive finalizable: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) FinalRef (ms): skipped
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Notify PhantomReferences: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) PhantomRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) SoftReference:
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Discovered: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Cleared: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) WeakReference:
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Discovered: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Cleared: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) FinalReference:
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Discovered: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Cleared: 0
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) PhantomReference:
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Discovered: 2
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases,ref ] GC(1382) Cleared: 2
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Weak Processing: 0.1ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Merge Per-Thread State: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Code Roots Purge: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Redirty Cards: 0.1ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) DerivedPointerTable Update: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Free Collection Set: 0.3ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Humongous Reclaim: 0.6ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Start New Collection Set: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Resize TLABs: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][debug][gc,phases ] GC(1382) Expand Heap After Collection: 0.0ms
[2024-01-15T15:23:04.104+0800][790.367s][3381829][3381900][info ][gc,phases ] GC(1382) Other: 0.3ms


[2024-01-15T15:23:08.433+0800][794.696s][3381829][3381900][info ][gc,start ] GC(1389) Pause Young (Normal) (G1 Evacuation Pause)
[2024-01-15T15:23:08.433+0800][794.696s][3381829][3381900][info ][gc,task ] GC(1389) Using 13 workers of 13 for evacuation
[2024-01-15T15:23:08.433+0800][794.696s][3381829][3381900][debug][gc,tlab ] GC(1389) TLAB totals: thrds: 47 refills: 1704 max: 181 slow allocs: 56 max 29 waste: 1.1% gc: 15548672B max: 1563232B slow: 1233720B max: 197560B fast: 0B max: 0B
[2024-01-15T15:23:08.433+0800][794.696s][3381829][3381900][debug][gc,alloc,region ] GC(1389) Mutator Allocation stats, regions: 180, wasted size: 0B ( 0.0%)

9. 标签safepoint

我们知道只有到达 safepoint,我们才可以进行 gc,如果我们对这些 safepoint 感兴趣,可以查看这个标签的 debug 级别的日志。

关于 safepoint 的解析、日志观测、调优,感兴趣的同学可以参考这篇文章:

https://zhuanlan.zhihu.com/p/161710652?spm=a2c6h.12873639.article-detail.15.7a8b1da3Hy4DoP

[2024-03-12T17:57:57.360+0800][1388.942s][558968][559235][info ][safepoint,stats ] G1CollectForAllocation [ 1542 3 ][ 578703 173202 13655482720 13656234625 ] 6
[2024-03-12T17:57:57.360+0800][1388.942s][558968][559235][info ][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 153683087494 ns, Reaching safepoint: 578703 ns, Cleanup: 173202 ns, At safepoint: 13655482720 ns, Total: 13656234625 ns

[2024-03-08T11:10:51.558+0800][1624.879s][121648][121979][warning][safepoint ] # SafepointSynchronize::begin: Timeout detected:
[2024-03-08T11:10:51.558+0800][1624.879s][121648][121979][warning][safepoint ] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[2024-03-08T11:10:51.558+0800][1624.879s][121648][121979][warning][safepoint ] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[2024-03-08T11:10:51.558+0800][1624.879s][121648][121979][warning][safepoint ] # "Pipe-Async-Connector-Client-Pool-selector-299" #299 daemon prio=5 os_prio=0 cpu=24998.13ms elapsed=1435.09s tid=0x00007e63dc2e1d00 nid=0x1deb7 runnable [0x0000000000000000]
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] java.lang.Thread.State: RUNNABLE
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] 
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] # "pool-29-IoTDB-Pipe-Connector-Executor-Pool-69" #1476 prio=5 os_prio=0 cpu=18305.09ms elapsed=1320.80s tid=0x00007e63fc376ee0 nid=0x1e842 runnable [0x0000000000000000]
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] java.lang.Thread.State: RUNNABLE
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] 
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] # "pool-29-IoTDB-Pipe-Connector-Executor-Pool-81" #1488 prio=5 os_prio=0 cpu=17034.13ms elapsed=1320.80s tid=0x00007e63fc385400 nid=0x1e84e runnable [0x0000000000000000]
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] java.lang.Thread.State: RUNNABLE
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] 
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] # "pool-26-IoTDB-ClientRPC-Processor-913" #1564 prio=5 os_prio=0 cpu=104459.15ms elapsed=1300.41s tid=0x00007e63e44113c0 nid=0x1e8cb runnable [0x00007e5254478000]
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] java.lang.Thread.State: RUNNABLE
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] 
[2024-03-08T11:10:51.559+0800][1624.879s][121648][121979][warning][safepoint ] # SafepointSynchronize::begin: (End of list)

GCEasy

非常强大的 GC 日志可视化分析报告,强大之处在于自动整合耗时、内存、cause、年龄等各类日志分析,并给出一些调优思路(实测不是特别靠谱,但可以参考)。

国外原版需收费。下面是国内镜像,实测免费:

https://gceasy.ycrash.cn/gc-index.jsp

Java 大数据系统 JVM 调优建议

笔者还调研了 Spark、Hadoop、Alluxio、Hbase、Ratis 等大数据系统的 JVM 默认参数或调优建议,这里贴出提供了相关信息的项目。

Spark

Spark 的目标是确保只有长寿的 RDD 存储在老年代,这样新生代便足以存放短命对象。这将有助于避免 fgc

Spark 建议:

• 查看 GC 日志,如果一次 task 完成前产生了多次 fgc,说明进程内存不够了
• 如果 ygc 很多,而 fgc 不是很多,建议调高 eden 区的大小。eden 区的大小可以设置为稍大于每个 task 需要的内存。如果 eden 的大小为 E,那么可以设置 -Xmn=4/3*E
• 如果观察 GC 日志,发现老年代接近满载,可以尝试从代码层面减少内存使用(spark.memory.fraction,这里不赘述)。此外,还可以减小新生代大小。如果已经减小过 -Xmn,可以试试 NewRatio
• 如果 GC 成为瓶颈(这里没说是吞吐瓶颈还是延迟瓶颈,根据经验一般 G1 对付延迟瓶颈比较有效),可以尝试 G1。增大 G1 的 region size 可能很有用(http://www.oracle.com/technetwork/articles/java/g1gc-1984535.html)

HBase

为了低延迟而调优:

• 使用 CMS collector: -XX:+UseConcMarkSweepGC
• 尽可能调小年轻代大小. Example:-XX:CMSInitiatingOccupancyFraction=70
• 为低时延而非高吞吐而调优: -Xmn512m
• 使用并行收集 eden 的 gc: -XX:+UseParNewGC
• Avoid collection under pressure: -XX:+UseCMSInitiatingOccupancyOnly
• 代码层面的调优:Limit per request scanner result sizing so everything fits into survivor space but doesn’t tenure. In hbase-site.xml, set hbase.client.scanner.max.result.size to 1/8th of eden space (with -Xmn512m this is ~51MB )
• 代码层面的调优:Set max.result.size x handler.count less than survivor space

OS-Level 调优:

• Turn transparent huge pages (THP) off:

echo never > /sys/kernel/mm/transparent_hugepage/enabled
echo never > /sys/kernel/mm/transparent_hugepage/defrag

• Set vm.swappiness = 0(禁用 swap)
• Set vm.min_free_kbytes to at least 1GB (8GB on larger memory systems)(调整内存水位线)
• Disable NUMA zone reclaim with vm.zone_reclaim_mode = 0

典型案例

贴出 9 个典型场景,并概述他们的场景、解决方案和效果

1. 场景:针对 PS new + CMS 的 YGC 调优(主要是吞吐目标)

解决方案:调整 young 区大小、比例(优化 ygc 频率);调整晋升年龄阈值(优化 ygc 耗时);优化偏向锁(safepoint)(优化 ygc 耗时)

效果:Young GC 的频率减少了大概 1/3。GC 的吞量提高了 3.8%,达到了 96.8%

https://zhuanlan.zhihu.com/p/165382850

2. 类似1,是 PS 针对 young 区大小的调优,找到合适的 young 和 old 区比例

https://blog.csdn.net/hilaryfrank/article/details/109598582

3. 场景:Major GC 和 Minor GC 频繁(针对 CMS)

解决方案:调整 young 区大小,防止大量临时对象进入 old 区,让 ygc 更彻底。

效果:通过扩容新生代为为原来的三倍,单次Minor GC时间增加小于5ms,频率下降了60%,服务响应时间TP90,TP99都下降了10ms+,服务可用性得到提升。

4. 场景:请求高峰期发生GC,导致服务可用性下降(针对 CMS)

解决方案:设法让 CMS 在 Remark 前执行一次 ygc,使得新生代的对象数量减少,进而减少 remark 工作量

效果:通过扩容新生代为为原来的三倍,单次Minor GC时间增加小于5ms,频率下降了60%,服务响应时间TP90,TP99都下降了10ms+,服务可用性得到提升。

5. 场景:发生 Stop-The-World 的 GC(针对 CMS)

解决方案:固定 Perm 区大小,防止 Perm 扩容导致的 fgc

效果:调整参数后,服务不再有 Perm 区扩容导致的 STW GC 发生

https://tech.meituan.com/2017/12/29/jvm-optimize.html

6. 场景:年轻代对象晋升过早,大部分对象在 1 岁时便晋升,导致 old 区增长速度过快

解决方案:通过 -XX:SurvivorRatio 扩容 survivor 区

效果:调整参数后,再也没有切量后长暂停的问题了,Young GC 稳定在 30-100ms,成功解决

https://segmentfault.com/a/1190000044467479

7. 场景:G1 Reference Process 环节中:软引用处理时间过长

解决方案:调整参数 -XX:+ParallelRefProcEnabled、-XX:SoftRefLRUPolicyMSPerMB=0,并优化代码减少 Finialize 对象。

效果:mixed gc 稳定到 85ms,耗时大幅降低

https://zhuanlan.zhihu.com/p/463122674

8. 场景:G1 GC 的日志出现 to-space exhausted 问题

解决方案:增大 GC 的速度,使其超过垃圾增长的速度:让G1更早得启动混合式垃圾收集周期,调小 -XX:InitiatingHeapOccupancyPercent;增加每次混合式垃圾收集收集的Old分区数量,调整-XX:G1MixedGCCountTarget;

https://zhuanlan.zhihu.com/p/79643783

9. 场景:Young GC 耗时一直居高不下,更重要的是 Old 区的最大使用量与日递增

解决方案:调大 heapRegionSize

效果:将 Region 大小调到 16M 或者 32M 时,GC 情况会有明显的好转

https://www.jianshu.com/p/0955113a12db

补充附录

GC VM 参数是否支持热修改?

结论:只有极少部分【managable】的参数才可以被热修改。这部分参数大多不是我们 GC 调优常用的,因此 GC 目前还是依赖冷调优。

1. 根据 oracle 官网,jinfo 命令可以实现部分参数热修改。且只有被标记为【managable】的参数才可以被热修改

• 具体语法如下:

image-20240401164237934

比如 JDK8 下,我们可以通过 jinfo 命令热修改 -XX:PrintGC 参数

jinfo -flag +PrintGC pid

1. 那么哪些参数是 managable 的呢?

所有的 JVM 中 manageable 的参数可以从 openjdk 源码(openjdk ./hotspot/src/share/vm/runtime/globals.hpp)中获取

image-20240401164300666

也可以通过 console 命令java -XX:+PrintFlagsFinal -version | grep "manageable" 获得:

JDK8:

image-20240401164311823

JDK11:

image-20240401164328950

JDK17:

image-20240401164337903

不同发行商 JDK 的参数效果相同吗?

所有发行商的 JDK 都是基于开源的 openjdk 进行修改,因此在 VM options 上都保证了向后兼容,可以放心使用。

👉 使用 oracle、openjdk、correto 三款最常用的 JDK 进行验证,常用的参数均能 work

设置矛盾效果的 GC 参数,JVM 如何表现?

结论:如果 -XX:MaxGCPauseMillis 和 -XX:GCTimeRatio 设置产生的效果发生矛盾,会一定程度影响 GC 的表现

实验数据敏感,在此省略。

-XX:+AlwaysPreTouch 对启动性能的影响

AlwaysPreTouch 对 IoTDB 启动性能影响的实验:

1. 环境:M2 pro 16G JDK 8/11

• ConfigNode:1068ms(加 AlwaysPreTouch)
• DataNode:1369ms(加 AlwaysPreTouch)
• ConfigNode:999ms(不加 AlwaysPreTouch)
• DataNode:1374ms(不加 AlwaysPreTouch)

2. 环境: 32G JDK 8

• ConfigNode:1044ms(加 AlwaysPreTouch)
• DataNode:1349ms(加 AlwaysPreTouch)
• ConfigNode:1031ms(不加 AlwaysPreTouch)
• DataNode:1430ms(不加 AlwaysPreTouch)

3. 环境:Ubuntu 754G JDK11

• DataNode:大约 1-2 s(不加 AlwaysPreTouch)
• DataNode:大约 20+ s(加 AlwaysPreTouch)

结论:

1. AlwaysPreTouch 在常见的小内存场景下对启动的影响不大,但在大内存场景下会显著延长启动时间
2. AlwaysPreTouch 主要能提高启动初期的性能,对启动中后期的性能影响不大。因为应用运行初期内存未完全分配,可能会有一些分配内存的开销;但随着应用的运行,当内存已经被 OS 完全分配时,该参数理论上已无优化效果。
3. 对用户来说,启动时间短比启动期间的性能更重要,且用户可以不感知此参数,因此建议该参数不用默认打开

Ref

https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/index.html

https://www.oracle.com/technical-resources/articles/java/g1gc.html

https://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html

https://docs.oracle.com/en/java/javase/17/

https://docs.oracle.com/en/java/javase/11/

https://docs.oracle.com/javase/8/

https://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html#BABFAFAE

https://docs.oracle.com/en/java/javase/11/gctuning/garbage-first-garbage-collector-tuning.html#GUID-379B3888-FE24-4C3F-9E38-26434EB04F89

https://docs.oracle.com/en/java/javase/11/tools/java.html#GUID-3B1CE181-CD30-4178-9602-230B800D4FAE__BABFAFAE

https://docs.oracle.com/en/java/javase/17/docs/specs/man/java.html#advanced-garbage-collection-options-for-java

https://masteranyfield.com/2021/05/13/gcs-of-jvm-tuning-pspo-vs-cms-vs-g1/

https://www.oracle.com/technical-resources/articles/javame/garbagecollection2.html

https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/parallel.html

https://xie.infoq.cn/article/317ccdfabd7694a093925f7fe

https://sematext.com/blog/java-garbage-collection-tuning/#starting-gc-tuning

https://zhuanlan.zhihu.com/p/161710652?spm=a2c6h.12873639.article-detail.15.7a8b1da3cPF1W0

https://developer.aliyun.com/article/978505

http://www.yishuifengxiao.com/2023/10/12/%E4%BB%8E%E9%9B%B6%E7%90%86%E8%A7%A3java%E4%B9%8B%E5%86%85%E5%AD%98%E5%88%86%E9%85%8D%E4%B8%8E%E5%9B%9E%E6%94%B6/

https://zhuanlan.zhihu.com/p/111886882

https://www.cnblogs.com/senlinyang/p/8717611.html

https://www.cnblogs.com/lindev/articles/15467748.html

https://blog.csdn.net/feiyanaffection/article/details/124019544

https://www.cnblogs.com/hongdada/p/14578950.html

https://zhuanlan.zhihu.com/p/628682897

https://stackoverflow.com/questions/67232199/how-to-reduce-time-taken-on-threads-reaching-safepoint-sync-state

https://juejin.cn/post/7068858769706319879

https://segmentfault.com/a/1190000039411521

https://hesey.wang/2018/11/gc-oriented-java-programming.html#comments

https://juejin.cn/post/7109664057002557470#heading-11

https://zhuanlan.zhihu.com/p/193037071