tomcat-jdbc连接池对于socketTimeout超时断连的处理BUG

type

status

date

slug

summary

背景

设置超时是保障系统稳定性的一个非常简单而有效的手段。对于数据库连接，我们配置了connectTimeout=1000ms，socketTimeout=1500ms。socketTimeout是tcp层面的超时时间，也就是在读取mysql响应的网络超时参数。超过socketTimeout时间还没有读到数据，那么mysql-connector会直接断开连接，保障应用资源（比如线程）不被一直挂起。典型异常堆栈如下：

而在实际应用过程中，却存在着一些问题：当某条SQL执行超过socketTimeout时，虽然mysql-connector层面会关闭连接，但是在tomcat-jdbc连接池这一层默认并没有对关闭的连接做检验，而是直接放回了连接池中。那么可能会导致在下一次需要连接时取到该连接，执行操作就会引发一次报错：

上面的报错已经是简化后的版本，一般来说你看到的报错信息会更长。因为除了连接已关闭的异常信息之外，还会包含导致这条连接被关闭的直接原因，也就是前面看到的com.mysql.cj.exceptions.CJCommunicationsException

原因分析

如果再深入跟踪一下，你会发现，事情可能会更加复杂一点：

如果超时执行的sql不在事务内，那么其实会有2次报错点

如果超时执行的sql在事务内，那么其实总共会有4次报错点

在事务内执行的流程会更加复杂一些，并且包含了非事务内执行超时的报错点，所以我们直接以第二种情况进行分析。

报错点1：语句执行超时，连接关闭

此时的报错信息就是连接超时相关的异常：

不过这里暂时不会打印异常日志

报错点2：MyBatis翻译异常信息，需要获取数据库类型

MyBatis对于SQL执行报错，会尝试翻译报错信息。

这个过程需要获取到数据库元数据信息，而获取元数据信息需要使用connection执行一次查询，但是此时连接已经被关闭，于是报错（连接已关闭）。不过这个连接已关闭的异常会被捕获之后再进行一次尝试，这一次不再会使用此事务里绑定的连接，而是会从连接池里获取一个新连接去获取元数据。

此时如果获取到的连接是正常的，那么此处不会报错。并且查询完成之后，在finally里会释放连接。此处打印的是WARN级别的异常：

报错点3：Spring事务管理器执行回滚

Spring事务管理器会在事务执行报错时，根据异常类型，判断是否要去回滚事务。默认情况下，RuntimeException或Error都需要回滚。但是此时连接已关闭，执行回滚时会报错。

并且这种场景的异常日志打印的时候会有明显标记。意思是事务rollback的报错覆盖了应用的报错：

报错点4：Spring事务管理器setAutoCommit

最后Spring事务管理器会在事务最后，执行一些清理操作：set autocommit = 1。因为我们开启事务的时候用了set autocommit = 0。

不过可以看到，此处的异常打印的是debug，一般线上应用级别为INFO，所以没什么感知，可忽略。

优化

上述流程除了增加了一些错误日志之外，其实本质上没有什么影响。最主要的问题还是连接关闭之后又被放回了连接池，导致后续的SQL执行受影响。所以在连接放回连接池之前我们要做检查。其实tomcat-jdbc原生就有这样的机制，在把连接放回连接池之前可以配置一个validateSQL，那么连接放回之前要先执行这条SQL，执行成功后才能放回连接池。但是为了性能考虑，我们并没有配置这个环节。而是通过tomcat-jdbc自身的异步检查的机制来做的。

而对于这种场景，其实并不需要执行SQL，而是直接判断底层连接是否关闭即可，不会增加新的IO交互。

注：这里的tomcat-jdbc本身就是经过我们团队二次开发优化过的，可能和官方版本有一些出入。