转载

RCA：JDBC驱动自身问题引发的FullGC

公众号HelloJava刊出一篇《 MySQL Statement cancellation timer 故障排查分享》，作者的某服务的线上机器报 502（502是 nginx 做后端健康检查时不能连接到 server 时抛出的提示），他用 jstack -l 打印线程堆栈，发现了大量可疑的“ MySQL Statementcancellation timer ”，进一步探究原因，原来是业务应用将数据库更新操作和云存储传图操作放在同一个事务。当云存储发生异常时，由于缺少云存储操作的快速失败，并且缺少对整体事务的超时控制，导致整个应用被夯住，进而 502。

作者文中还谈及他排查过程中注意到 MySQL-Connector-Java 的一个 bug，在 5.1.27 版本以前 MySQL Statement cancellation timer 会导致 Perm 区 Leak，内存泄漏后进而业务应用异常。

我们恰巧遇到过这个坑。鉴于这个坑的排查过程和测试验证还挺有趣，我贴一下去年我们的 RCA 报告：

RCA：JDBC驱动自身问题引发的FullGC

郑昀基于田志全和端木洪涛的分析报告 2015/6/30

关键词： Java，JDBC，升级，MySQL驱动，频繁数据查询，mysql-5.1.34，mysql-5.0.7

问题现象：

2015年4月22日（周日）晚间，线上 TaskMall 工程（一个 Java 工程）频繁报警。分析 jvm 情况，taskmall 在内存使用上确实存在问题，可能有大量对象不正常堆积：

RCA：JDBC驱动自身问题引发的FullGC

图2 155 jmap

问题原因：

频繁的大数据查询场景下，mysql-5.1.34 驱动的性能远优于 mysql-5.0.7 驱动。一定要及时升级驱动啊。

RCA类型：

维护问题。

其实我们在RCA(Root Cause Analysis)第四季就曾经遇到此类问题：

第四季案例5 官方驱动也会设计不当，及时升级

—— 实例：

2013年1月，由于 PHP 一直使用 MongoDB PHP Driver 1.2.x 驱动，导致 PHP-FPM 模式下，每一个 PHP Worker 进程都有自己独立的 mongodb 连接池，从而导致连接数极易超标，占用内存数也随之倍增，MongoDB 负载很重。

如当时编辑后台192 --> mongodb-165 之间的连接数基本维持在：750～751个左右。

升级到 mongodb-php driver 1.3.2 驱动之后，日常连接数大为下降。

——教训：

引入了重要存储介质的驱动之后，如spymemcahced、mongodb php/java driver、jedis等，保持跟踪它们的动态，第一时间更新驱动。

问题分析：

志全分析堆栈信息发现，系统中有大量的 CancelTask 定时任务需要执行。

RCA：JDBC驱动自身问题引发的FullGC

图3 大量的CancelTask

为什么会有这么多的任务呢？

这是 mysql 的一个定时任务，主要用于查询超时处理。即，系统在执行一个 sql 查询时，jdbc 会给你一个超时时间。为了保证超时时间后，能够关闭 statement，会打开一个保护关闭的定时任务。如果超时情况下，sql 还没响应执行，cancel task 就会执行关闭任务。注，ibatis 的默认超时时间为3秒（<setting name="defaultStatementTimeout" value="3000" />）。

RCA：JDBC驱动自身问题引发的FullGC