Druid连接偶发性失效问题排查

Cause: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 1,838,049 milliseconds ago. The last packet sent successfully to the server was 1,838,050 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.

2.1、分析报错信息

根据上述报错信息，我们可以看出是因为A应用实例设置的Druid连接空闲时间时长超过了MySQL的连接空闲时间（wait_timeout），导致虽然MySQL服务端主动断开了连接，但是客户端A应用未能感知到连接已失效，仍然在使用，最终报错。

Druid的报错信息也同时给出了如下修复建议：

1. 添加testWhileIdle=true配置，应用实例在使用连接前进行连接有效性的检查。
2. 添加autoReconnect=true配置，连接到数据源的连接发生中断，Druid会尝试自动重新连接。
3. 加长MySQL的wait_timeout空闲连接超时时间，使其大于客户端应用实例的连接超时时间。

2.2、结合应用A情况，逐个分析上述建议：

1. A应用已配置testWhileIdle=true，申请连接时会进行检测，因此建议1对于此问题修复无效。
2. 查看druid源码得知autoReconnect已废弃，应用A使用了替代配置autoReconnectForPools默认值为true，未作修改。因此建议2对于此问题修复无效。
3. 加长MySQL的wait_timeout空闲连接超时时间，使其大于客户端的空闲连接超时时间。根据建议3，我们怀疑本次问题可能是由于客户端应用A与MySQL间的空闲连接超时时间设置不合理，导致MySQL空闲连接超时时间小于客户端应用的A连接空闲超时时间。

2.3、结合建议3对MySQL、应用A进行分析：

1. MySQL的wait_timeout公司统一配置为30分钟，MySQL官方默认配置为8小时。
2. 应用A的Druid核心连接空闲时间maxEvictableIdleTimeMillis配置为7小时，非核心连接空闲时间minEvictableIdleTimeMillis配置为5分钟。
3. 应用A的Druid的timeBetweenEvictionRunsMillis配置为1分钟。

为保证客户端应用的连接空闲超时时间比MySQL服务端的短，我们需确保应用中druid的timeBetweenEvictionRunsMillis、minEvictableIdleTimeMillis和MySQL的wait_timeout这三个配置满足以下公式：

timeBetweenEvictionRunsMillis + minEvictableIdleTimeMillis < wait_timeout
timeBetweenEvictionRunsMillis + maxEvictableIdleTimeMillis < wait_timeout

2.4、总结

timeBetweenEvictionRunsMillis 1分钟 + maxEvictableIdleTimeMillis 7小时 > wait_timeout 30分钟

很显然，A应用的相关配置并不满足我们上面总结的两个公式，这样就导致了当应用A的Druid与MySQL之间的连接超过30分钟无请求时，MySQL端废弃了连接，但Druid连接池并没有废弃此连接，仍然在使用，最终导致了上述的偶发报错。

2.5、解决方案如下

1. 根据官方建议将Druid升级最新的稳定版本。
2. Druid的maxEvictableIdleTimeMillis配置应小于MySQL的wait_timeout（30分钟）配置。
3. Druid新版中提供了KeepAlive参数，设为true，核心连接空闲时间超过2分钟（默认）时，会执行连接检测并初始化客户端、服务端连接空闲时间。

   
   

2.6、修复结果

修复完成后，经过运行测试，我们发现每天还是会零星出现了1到2次类似报错（下述称作问题2）。难道上面解决方案没生效？我们接着分析、排查。

三、问题2现象

1. 从报错信息中我们看到idleMills（连接空闲时间）、lastvalidleMillis（上次连接使用时间）时间分别为47毫秒、243毫秒、1917毫秒，并没有超过MySQL的空闲连接超时时间30分钟，所以此问题不同于上述问题。

2. 应用在使用连接时，MySQL已废弃此连接（空闲时间超过30分钟）。

3. MySQL连接空闲时间显示此连接超过1小时未接受数据。

3.1、问题2分析

1. 报错频率降低，从每天20多次降至1到2次。说明上面修复方案虽然有效，但并没有完全解决问题。
2. 日志系统中显示Druid检测到了部分失效连接并进行了重连。说明Druid的Keepalive和maxEvictableIdleTimeMillis等配置虽然有效，但是出现了偶发性失效的现象。
3. Druid与MySQL的连接使用时间不一致，进而导致Keepalive、maxEvictableIdleTimeMillis等配置偶发性的失效。
4. 存在数据库Druid连接被激活，但是MySQL连接并没有被激活的现象。

3.2、问题2排查

通过对比数据库连接空闲时间与Druid连接空闲时间的情况，确实发现Druid执行了检测SQL，但是MySQL数据库连接并没有被激活的情况。到底是哪里出现问题了呢？此时我们仔细观察Druid检测SQL执行情况图可以看到，Druid是上午5点-6点半左右一直没有执行检查SQL，此时正好存在问题2报错，为什么时间这个巧合？上午5点整，难道是有什么定时任务导致此问题？

Druid检测SQL执行情况

MySQL数据库连接空闲时间

带着这些疑问，我们看下A应用上午5点钟确实有个定时任务在执行某个接口，既然找到了怀疑对象，那我们分析、测试下这个接口，看它有是否会导致数据库Druid连接被激活，MySQL连接未被激活的问题。

接口执行情况如下图所示：

3.3、分析接口

此接口使用到了sharding-jdbc进行了分库分表查询，仅查询了sharding0、sharding1、sharding2、sharding3数据库中的某表。

3.4、测试接口

接下来我们尝试请求此接口，然后持续观察应用的Druid与MySQL的连接空闲时间，看下有什么发现。

3.5、测试结果

通过测试，我们确实发现在持续请求此接口时，确实存在Druid连接被激活，MySQL数据库的连接未被激活的场景。

3.6、Debug接口代码

既然找到了罪魁祸首，那我们在逐步debug这个接口查询过程的代码有何特殊之处，会导致出现如此特殊的情况.

1. MyBatis查询业务数据库结果后尝试获取多结果集。

2. MyBatis尝试获取多结果集（多条不同SQL结果），并判断是否含有多结果集数据，若没有则不执行SQL。

3. MyBatis获取shardingJDBC多数据源中的第一个数据源（不分库分表的数据库ds）中尝试获取查询结果。

4. Druid将不分库分表的数据库ds的连接放回连接池前，并重置连接激活时间。

   
   
5. 连接的lastActiveTimeMillis被重置，导致keepalive和maxEvictableIdleTimeMillis失效。

3.7、问题2总结

结合上面的debug，发现个奇怪的现象，此接口仅查询了sharding0、sharding1、sharding2、sharding3数据库中的某表，并没有查询ds数据库，为什么会查询这个库？原来是shardingJDBC将不分库分表的库与分库分表的库合并为一个统一的逻辑数据源，导致在MyBatis中获取多结果集时激活了错误数据库（不分库分表的数据库ds）的连接，进而导致Druid连接维护相关配置的失效。

既然问题找到了，我们看下对于部分数据库分库分表的场景，xxl-job官方是如何建议的，官方给出了两个方法如下图。既然我们使用了方法1出现了上述问题2，于是我们按照方法2将不参与分库分表的数据源独立于ShardingSphere之外，在应用中使用多个数据源分别处理分片和不分片的情况，问题得到彻底解决。

上述组件版本

Druid重要参数介绍

作者介绍

Mossad-K，基础框架研发专家，主要负责信也科技容器云相关工作。

参考文档

druid源码: 

https://github.com/alibaba/druid

xxl-job官方文档: 

https://www.xuxueli.com/xxl-job

招聘信息