GC安全点导致停顿时间过长的案例

前言

前段时间在使用G1垃圾收集时，因服务读写压力过大，于是将-XX:MaxGCPauseMillis参数调整为500ms，运行一段时间后发现垃圾收集的停顿时间经常达到3s以上，但实际垃圾收集器进行回收的动作就只占其中的几百毫秒。

MaxGCPauseMillis：最大停顿时间，默认200ms。顾名思义，G1是garbage first。垃圾优先。G1在该最大停顿时间的指定范围内优先收集收益最大（标记垃圾对象最多）的region。

大概的GC日志如下：

[Times：user=1.51 sys=0.67,real=**0.14** secs]
2025-03-07T 21:05:01.376+0800: 3448319：Total time for which application threads were stopped ：2.2645818 seconds

user：进程执行用户态代码所耗费的处理器时间。
sys：进程执行和心态代码所耗费的处理器时间。
real：执行动作从开始到结束耗费的时钟时间。

前面两个是处理器时间，而最后一个是时钟时间，它们的区别是处理器时间代表的是线程占用处理器一个核心的耗时计数，而时钟时间现实世界中的时间计数，故只需要关注real这个真实感受到的时间即可，因为最终用户只关心发出请求到得到响应所花费的时间，也就是响应速度，而不太关心程序到底是用了多少个线程或者处理器来完成任务。
日志显示本次垃圾收集一共花费了0.14s，但用户线程却足足停顿了2.26秒，两者差距已经远远超出了正常的TTSP（Time To Safepoint）耗时的范畴。

安全点的概念

先理清安全点的概念，避免对于案例有模糊的地方；

安全点：在垃圾收集时，需要STW，也就是要用户线程停止，但用户线程执行时并非在代码指令流的任意位置都能够停顿下来开始垃圾收集，而是强制要求必须执行到达安全点后才能够暂停。

那用户线程如何走到最近的最近安全点呢？
有两种方式：
①抢先式中断：不需要用户线程主动去配合，在垃圾收集发生时，系统会中断所有的用户线程，如果用户线程中断的地方不在安全点上，就恢复这条线程的执行，让它在跑一会再重新中断，直到跑到最近的安全点上。现在几乎没有虚拟机实现采用抢先式中断中暂停线程响应GC事件了。
②主动式中断：当垃圾收集需要中断用户线程时，不直接对线程操作，而是设置一个安全点标志位，各个线程执行过程中会不断轮询这个标志位，一旦发现标志为真时就自己在最近的安全点上主动中断挂起。

案例分析

前言中也说明了用户线程停顿了2.26s，垃圾收集却只花费了0.14s，属实本末倒置了，因为用户线程是主动式中断，于是猜想是否发生垃圾收集时，GC线程在等待用户线程进入安全点这段时间花费了2.26s，最后进入安全点后，GC线程垃圾收集只花费了0.14s？

开始验证：
在启动项目时加入参数-XX:+PrintSafepointStatistics和-XX:PrintSafepointStatisticsCount=1去查看安全点日志，如下：

vmop	[threads: total initially_running wait_to_block]
65968.203: ForceAsyncSafepoint	[931		1		2]
[time: spin block sync cleanup vmop] page_trap_count
[2255  0 2255  11	0]	1

日志显示当前虚拟机（VM Operation），也就是上面的vmop是等待所有用户线程进入到安全点，但是有两个线程特别慢，导致发生长时间的自旋等待。日志中的2255毫秒自旋（spin）时间就是指由于部分线程已走到了安全点，但还有一些特别慢的线程并没有到，所以GC线程无法工作，只能空转等待。
所以怎么找出导致GC线程等待那两个线程呢？
在启动时添加-XX:+SafepointTimeout和-XX:SafepointTimeoutDelay=2000两个参数，让虚拟机在等待线程进入安全点的时间超过2000毫秒时就认为超时，这样就会输出导致问题的线程名称，得到的大概日志如下：

#SafepointSynchroinze::begin: Timeout detected;
#SafepointSynchroinze::begin: Timed out while spinning to reach safepoint.
#SafepointSynchroinze::begin: Threads which did not reach the safepoint:
#"RpcServer.listener,port=24600" #32 daemon prio=5 os_prio=0 tid=0x0000f4c14b22840 nid=0xa621 runnable [0x0000000000000000]
java .lang.Thread.State: RUNNABLE
#SafepointSynchroinze::begin: (End of list)

从日志可以看到是线程名称为“RpcServer.listener,port=24600”导致GC线程发生等待。安全点是以“是否具有让程序长时间执行的特性”为原则进行选定的，所以方法调用、循环跳转、异常跳转这些位置都可能会设置有安全点，但是HotSpot为了避免安全点过多带来过重的负担，对循环还有一项优化措施，认为循环次数较少的话，执行时间应该不会太长，所以是使用int类型或范围更小的数据类型作为索引值的循环默认是不会被防止安全点的，这种循环被称为可数循环。而使用long类型或范围更大的数据类型作为索引值的循环就被称为不可数循环，这种就会被放置安全点。
针对HotSpot有这一优化点，于是翻看RpcServer那块代码发现，很多个上游服务调本服务，有很多连接超时，最后又在清理超时连接的方法发现使用for循环清理，而且是使用int变量记录循环次数，伪代码如下：

for(int i=0;i<list.size;i++){...........socket.close();
}

这是一个可数循环，HotSpot不会在循环中插入安全点。当垃圾收集发生时，如果RpcServer的Listener线程刚好执行到这个方法里的可数循环时，就必须等待循环全部跑完才能进入安全点，此时其他线程也必须一起等待，所以看起来就是长时间的停顿。

解决方法

上面也说过，可数循环不可放置安全点，那改为不可数循环即可，也就是将int变量改为long类型即可。

如有需要收藏的看官，顺便也用发财的小手点点赞哈，如有错漏，也欢迎各位在评论区评论！