Vilden 's blog
0%

2023-08-23-GC引发的服务端调用超时问题

Posted on Edited on

背景

交接过来的的服务，在上游服务调用服务的过程会偶发调用超时，通过观察监控，可以看到超时的时候和服务端gc的时间点一致，基本定位是gc导致的问题

通用的解决办法

  • 服务端低峰期主动gc，比如这个问题每7天出现一次，那么可以每天在服务的低峰期进行主动gc，这样内存问题就不会积攒下来导致最后的问题
  • 上游服务端增加backup_request策略，所谓backup_request与一般的超时重试策略的不同点是，不等到一个请求完全超时，提早发起第二个请求，哪个请求返回的快则以哪个请求响应。这种场景适用于幂等的场景，一般情况下读场景都可以用。提早于第一个请求超时，可能存在的一些缺点就是大面积异常情况下可能会造成连锁反应，比如引起服务端压力过大的问题，一般根据长尾耗时设定，比如95、99配置

以上的方法是通用解决办法，其中backup_request更是适用于各种读请求长尾耗时问题场景

根因解决法

为什么gc会慢呢，看日志分析下呗;)

哪里慢

1
2
2023-03-02T08:45:04.735+0800: 1881614.842: [GC remark 1881614.842: [Finalize Marking, 0.0005386 secs] 1881614.842: [GC ref-proc, 0.4752358 secs] 1881615.318: [Unloading, 0.0380676 secs], 0.5152717 secs]
 [Times: user=0.44 sys=0.29, real=0.51 secs]

remark耗时0.51s，预定的超时时间是400，那确实会导致客户端会超时。

Remark阶段是Stop-The-World（以下简称为STW）的，即在执行垃圾回收时，Java应用程序中除了垃圾回收器线程之外其他所有线程都被挂起，意味着在此期间，用户正常工作的线程全部被暂停下来，这是低延时服务不能接受的。

remark为什么慢

增加-XX:+PrintReferenceGC参数，定位remark阶段的回收引用类别,可以看到具体耗时

1
2
2023-03-12T15:52:46.435+0800: 257165.945: [GC remark 257165.945: [Finalize Marking, 0.0003873 secs] 257165.945: [GC ref-proc257165.945: [SoftReference, 6472 refs, 0.0020659 secs]257165.947: [WeakReference, 414 refs, 0.0001294 secs]257165.947: [FinalReference, 3317 refs, 0.0099064 secs]257165.957: [PhantomReference, 5784 refs, 107 refs, 0.4313675 secs]257166.389: [JNI Weak Reference, 0.0001421 secs], 0.4470736 secs] 257166.392: [Unloading, 0.0436440 secs], 0.4937819 secs]
 [Times: user=0.59 sys=0.14, real=0.50 secs]

可以看到0.50秒的gc耗时中,[PhantomReference, 5784 refs, 107 refs, 0.4313675 secs]

PhantomReference问题定位

PhantomReference是什么?
虚引用也称为“幽灵引用”，它是最弱的一种引用关系。如果一个对象仅持有虚引用，那么它就和没有任何引用一样，在任何时候都可能被垃圾回收器回收。为一个对象设置虚引用关联的唯一目的只是为了能在这个对象被收集器回收时收到一个系统通知。当垃圾回收器准备回收一个对象时，如果发现它还有虚引用，就会在垃圾回收后，将这个虚引用加入引用队列，在其关联的虚引用出队前，不会彻底销毁该对象。所以可以通过检查引用队列中是否有相应的虚引用来判断对象是否已经被回收了。

通过dump内存分析后，可以看到有NonRegisteringDriver的大对象

再往下看可以发现是Mysql Driver中的虚拟引用使用了PhantomRefence，Mysql driver在创建Connection时，会调用NonRegisteringDriver#trackConnection，生成虚引用，并存入connectionPhantomRefs中。在本例中显然connectionPhantomRefs中存放的虚引用数目过多，导致了gc时间过长

看看github的druid 的issue: https://github.com/alibaba/druid/issues/2782
有其他用户在使用druid时也反馈了这个问题，druid项目成员在issue中回复ConnectionPhantomReference 是 MySQL JDBC 驱动创建的，和 druid 没有关系。 PhantomReference 造成的 GC remark 问题可以加 JVM 参数 -XX:+ParallelRefProcEnabled 解决。

-XX:+ParallelRefProcEnabled的作用：加快remarkref proc 的速度

结果

增加参数后，0.11S 完成GC remark，PhantomReference耗时降低到0.05s，问题解决~