1.起因:
在半夜执行的定时任务偶现The last packet successfully received from the server was 1,373,532 milliseconds ago问题,导致部分sql没有执行。
2.排查:
2.1 查看日志:
DruidDataSource:discard connection com.mysql.cj.jdbc.exceptions.CommunicationsException:
Communications link failure The last packet successfully received from the server was 1,373,532 milliseconds ago.
The last packet sent successfully to the server was 1,373,554 milliseconds ago.
查了下,这个错误是链接失败,即druid当前使用的连接池中的线程时无效连接,mysql服务端已经把这个连接给断了,但是druid这边不知道,继续使用就报错了。
对于这个问题,看到很多帖子都说去设置mysql服务器的wait_timeout(另外说一下wait_timeout表示通过非交互连接,例如jdbc,interactive_timeout表示交互式连接,通过mysql客户端连接数据库是交互式连接,通过jdbc连接数据库是非交互式连接),但是这个参数是设置空闲连接保持连接状态的最大秒数,例如:
这里如果wait_timeout设置为2355,那么这个sleep状态的链接再过一秒,就会被mysql客户端给断掉,所以一般druid设置的检查时间都会比这个时间短:(druid配置minEvictableIdleTimeMillis:连接保持空闲而不被驱逐的最小时间-毫秒)
另外也会有validationQuery: SELECT 'x',testWhileIdle: true这样的设置,用于检测链接是否有效;但是druid检查有效性有两种方法,一种是
this.ping.invoke(conn, true, validationQueryTimeout * 1000);
用ping的方法,这样配置的validationQuery: SELECT 'x'就不会执行,所以可以在客户端启动参数加上-Ddruid.mysql.usePingMethod=false
,就可以用配置的方法去验证有效性。
但是!我配置了以后该偶现的还是偶现,我决定看看mybatis的日志:
logback.xml配置:
// 仅XxxxDao类输出debug日志
<logger name="com.xxxx.xxxx.xxx.dao.XxxxDao" level="debug" additivity="false">
<appender-ref ref="STDOUT" />
</logger>
以下是执行日志:
[DEBUG] 2021-07-01 01:08:53.262 [Thread-3069] queryDispatch:==> Preparing: SELECT xxxxxx like concat(?,'%')
2021-07-01 01:08:58.826
[DEBUG] 2021-07-01 01:08:53.262 [Thread-3069] queryDispatch:==> Parameters: XXXX(String)
这里可以比较清楚的看到准备的sql和参数,并且发送去了mysql,但是半天后返回了上述的报错,这几条日志都是同一个线程,并且这个方法用到所有的sql的连接池应该都是一个,在准备sql的日志前都有这么一句:
SpringManagedTransaction:JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@5c21e27f] will not be managed by Spring
@5c21e27f应该就是持有同一个连接的代理。
有成功时候:sql跑了30多分钟;也有提交了语句,20分钟后直接报错的,这让我觉得应该不是因为服务端设置了语句执行最大时间的设置,去看了下果然没限制时间:
max_execution_time 0
因为我是半夜1:00执行,我看到这个时间有好多定时任务开始执行,就在想会不会是数据库压力的关系,看到一篇文章:
connect_timeout在获取连接阶段(authenticate)起作用,
interactive_timeout和wait_timeout在连接空闲阶段(sleep)起作用,
net_read_timeout和net_write_timeout在连接繁忙阶段(query)起作用。
net_read_timeout / net_write_timeout 这个参数只对TCP/IP链接有效,分别是数据库等待接收客户端发送网络包和发送网络包给客户端的超时时间,这是在Activity状态下的线程才有效的参数
结合来看,此问题应该是在mysql返回给客户端的时候超时,然后导致连接被断。
现在通过更换了定时任务的执行时间,错峰执行解决了这个问题。
参考:
https://blog.csdn.net/jiadajing267/article/details/79516989
https://blog.csdn.net/qq_37637196/article/details/106053558