6

线上问题处理案例:出乎意料的数据库连接池 - 京东云技术团队

 1 year ago
source link: https://www.cnblogs.com/jingdongkeji/p/17421092.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

本文是线上问题处理案例系列之一,旨在通过真实案例向读者介绍发现问题、定位问题、解决问题的方法。本文讲述了从垃圾回收耗时过长的表象,逐步定位到数据库连接池保活问题的全过程,并对其中用到的一些知识点进行了总结。

一、问题描述

大促期间,某接口超时次数增多,经排查直接原因是GC耗时过长,查看监控FullGC达500ms以上,接口超时时间与FullGC发生时间吻合。

c799e2d8094b4f299b19e584fb08f05d~noop.image?_iz=58558&from=article.pc_detail&x-expires=1685326435&x-signature=FZcwZx8criA8Wg7aV3D7K6FxhzU%3D

图1 FullGC耗时监控

二、应用基本情况

  • 容器:8C12G;
  • JVM配置:-XX:+UseConcMarkSweepGC -Xms6144m -Xmx6144m -Xmn2048m -XX:ParallelGCThreads=8 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+ParallelRefProcEnabled;
  • 数据库类型:MySQL;
  • 数据库连接池:DBCP;

三、排查过程

1、 GC耗时过长,说明内存中垃圾对象很多。

2、 首先怀疑是否有内存泄漏,观察FullGC后堆内存回收情况,尚属正常,暂时排除内存泄漏原因。

71829a147858444eb6852be88923a6dc~noop.image?_iz=58558&from=article.pc_detail&x-expires=1685326435&x-signature=vQJvUKclgTWsD6NMHLIdn0%2BpDT0%3D

图2 发生FullGC后堆内存回收监控

3、 推断FullGC耗时过长是否因为老年代有大量死亡对象,遂导出FullGC前后堆内存dump,通过比对“保留大小”,发现FullGC后大量数据库相关对象被回收。

c5f28a5e2e8d4ef888ddb56d6e724983~noop.image?_iz=58558&from=article.pc_detail&x-expires=1685326435&x-signature=OWXjiPXNRC%2FhGp%2B2Vskco%2FKbvxE%3D

图3 堆内存对象分析

4、 数据库连接正常应该不会频繁创建和断开,进入老年代后,正常不应该被回收,通过堆dump内容OQL分析每个数据库连接数量,发现很多库连接数都大于“maxActive”数量,可以肯定有很多失效连接。

5、 初步判断直接原因是很多失效数据库连接进入老年代,导致FullGC耗时过长。

6、 怀疑连接池验证周期过长,导致数据库因空闲过长关闭连接,将连接池参数“
timeBetweenEvictionRunsMillis”由1分钟调整到10秒,问题依旧。

7、 阅读DBCP源码,发现是通过
org.apache.commons.pool.impl.GenericObjectPool.Evictor定时任务,按照timeBetweenEvictionRunsMillis配置的周期定时驱逐失效连接,驱逐条件:若连接空闲时间大于“minEvictableIdleTimeMillis”,则会驱逐连接,等待垃圾回收。若开启“testWhileIdle”则会执行“validationQuery”。进一步阅读代码,发现执行“validationQuery”后,连接空闲时间并不会重新计算,导致连接在业务低谷时很容易被淘汰,而数据库连接会关联大量对象,创建、回收成本昂贵,并且影响GC。

8、 反向思考,为何只有在大促期间才发生问题?

48918e3a4b8843b6b29d76187212c65e~noop.image?_iz=58558&from=article.pc_detail&x-expires=1685326435&x-signature=XbVbmd9cCTyif0pXWAsqA%2F%2FqNfc%3D

图4 平时和大促时回收频率对比

可以看到平时由于业务量小,GC不频繁,过期连接没有达到进入老年代阈值,在年轻代被回收。而大促时业务量大,GC频繁,连接在进入老年代以后才过期,导致老年代FullGC时间过长。

9、 至此,基本可以肯定问题原因是数据库连接池不具备“保活”能力,导致连接不断淘汰和新建,在业务高峰时段,连接进入老年代然后失效,造成FullGC耗时过长,最终导致接口超时次数增多。

四、解决方案

方案1:改为G1回收器,对老年代回收是分块进行,可以防止长时间停顿。另外默认MaxTenuringThreshold值是15,可以防止失效连接过早进入老年代;

方案2
minEvictableIdleTimeMillis设置为0,使数据库连接不会自动失效,进入老年代以后一直存活,避免在老年代失效回收;

五、问题总结

数据库连接池并不具备通常理解的“保活”能力,数据库连接在业务不活跃的应用中,会不断淘汰和重连,而连接会通过虚引用方式(
com.mysql.jdbc.NonRegisteringDriver$ConnectionPhantomReference)携带大量对象,如果连接存活时间内YGC次数达到寿命阈值,则会进入老年代,老年代是使用“标记-清除”算法,回收成本更高,进而造成FullGC耗时过长。

六、拓展知识点

1、 Druid连接池同样存在不能“保活”问题,较新版本提供“KeepAlive”选项(未验证);

2、 Druid连接池配置的“validationQuery”语句通常并不会被执行,MySqlValidConnectionChecker在检查连接有效性时,会判断驱动是否实现pingInternal方法,如果实现则会通过此方法验证有效性。MySQL的JDBC驱动实现了该方法,因此“validationQuery”配置的语句通常不会执行;

1b3d4bda64b2432491915b5c0bcab83e~noop.image?_iz=58558&from=article.pc_detail&x-expires=1685326435&x-signature=jjbJ%2BX8k5Wv6PrZiwbgFpuqx6hE%3D

图5 连接有效性校验代码

3、 DBCP和Druid连接池默认都是FILO,如果业务不繁忙,会导致只有最前边的连接被使用-归还-使用,后边连接基本都在无谓的驱逐、重建连接;

4、 虚引用对GC的影响:这些引用只有经过两次GC才能被回收掉,如果进入老年代,则必须经过两次FullGC才能释放内存。本例中由于不断有新的虚引用对象在老年代失效,导致FullGC后,内存水位仍然偏高,会加剧GC压力。新版本JVM已对此做了优化,一次GC可以回收掉;

5、 类似的影响还有finalize方法;

6、 CMS回收器默认MaxTenuringThreshold为6,而ParallelGC和G1均默认15;

本文对数据库连接失效引起的GC问题进行了详细分析,希望读者通过本文对数据库连接“保活”机制、GC问题基本分析方法有所收益,后续该系列文章会继续推出其他案例分享。

作者:京东零售 王利辉

内容来源:京东云开发者社区


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK