一次数据库查询超时优化问题的实战记录

问题发现

在七月份时，经常发现有几个定时任务报错，查看了下异常原因，大概定位是数据库执行异常

### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Unsupported command
### The error may exist in class path resource [mapper/XXXXXXXXX-Mapper.xml]
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select t3.cino, t2.sn as orderSn,             t2.provider_id as providerId,             t4.logistics_no as logisticsSn,             t2.`name`,      
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Unsupported command
; Unsupported command; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Unsupported command
org.springframework.dao.DataAccessResourceFailureException: 
### Error querying database.  Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Unsupported command
### The error may exist in class path resource [mapper/XXXXXXXXXOMapper.xml]
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select t3.cino, t2.sn as orderSn,             t2.provider_id as providerId,             t4.logistics_no as logisticsSn,         
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Unsupported command

查找原因

1 和 DBA 排查 mycat（公司使用 mycat ）和 mysql 的错误日志。发现是应用服务这边会给 MyCat 发送一个 KILL QUERY 命令，而 myCat 不支持该 KILL QUERY 命令。才给应用服务返回了 Unsupported command 异常错误

2021-07-02 10:46:33.567  WARN [$_NIOREACTOR-37-RW] (io.mycat.server.ServerQueryHandler.query(ServerQueryHandler.java:96)) - Unsupported command:KILL QUERY 2956587

2 上网搜索了下 KILLQUERY 发生的场景，在一篇文章深入分析JDBC超时机制找到问题所在，sql 执行超时，jdbc 会向 mysql 服务发送一个kill 命令，从而让 mysql 停止 sql 执行。不过传给了 mycat 服务，mycat 没有处理该命令，而是直接报错返回

3 查看了下应用服务的配置，在 jdbc:url 统一配置的 mysql socket 执行超时时间是 15s。而在 mybatis 单独的 sql 执行语句配置的设置更长，是 20s（注意这里的配置是 xml 加注解的方式）

3.1 mybatis xml里的 sql 语句我单独在客户端执行，测试的 sql 执行时间大概在 6，7 秒左右，是不会超过 15s 这个限制的，但是从定时任务调度日志看，每次任务总体上就执行了 8 秒左右，说明 mycat 确实是在15秒内收到超时 KILL 命令，从而导致sql 执行失败

4 想着是不是在其他地方配置超时。细看了下 mybatis 的配置，还真有一个统一 sql 超时配置，default-statement-timeout = 5

从mybatis 源码文档上看，单独设置的 mybatis @Options timeout属性是会覆盖掉在 yml 配置的 default-statement-timeout属性的。难道是 @Options 没生效？

5 因此决定本地调试一波。发现 @Options 还真的没生效，jdbc的 queryTimeout 取值的是 mybatis在yml的全局配置

解决问题

上面提到, sql 的 statment 混合使用了 mybatis 的注解和xml混合使用。猜测应该是 mybatis 的注解和xml 使用方式是不兼容的。因此试着在 xml 的 statment 修改了 timeout配置。设置 timeout = 60。发现配置生效了，如下图

后面也试着将 sql 放置到 mybatis 的 @Select 注解,去掉 xml 的 statement。@Options 的配置也是可以生效的。mybatis 的@Options 和 xml 是无法同时生效的，可能 mybatis 其他的注解一样和 xml 配置不能同时生效，希望读者以后能避开这个坑

额外话：Transaction Timeout、Statement Timeout、Socket timeout 的区别

上面 mybatis 配置的 timeout 其实就是Statement Timeout。还有就是在jdbc:url 配置的socketTimeout；其实还有是spring定义的一个事务超时： Transaction Timeout

它们三者的关系是在怎样的呢

Statement Timeout

statement timeout 是用来限制一条语句 statement 的执行时长，可通过调用JDBC的java.sql.Statement.setQueryTimeout(int timeout) 进行设置，不过一般是通过ORM框架来进行设置
在 myBatis中，statement timeout 的默认值是通过 defaultStatementTimeout 属性进行设置。同时还可以在 xml 中 select，insert，update标签设置timeout属性，从而对不同 sql 语句配置超时时间

Transaction Timeout

Spring 提供的 transaction timeout 配置也非常简单，它会记录每个事务的开始时间和消耗时间，当超出timeout值时将抛出异常。
假设某个事务中包含 3 个statement，每个statement的执行时间是 100ms，其他业务逻辑的执行时间是 50ms，那么transaction timeout至少应该设置为350ms(100 * 3 + 50)

Socket timeout

JDBC的 socket timeout 在数据库被突然停掉或是发生网络错误时十分重要。由于TCP/IP的结构原因，socket没有办法探测到网络错误，因此应用也无法主动发现数据库连接断开。如果没设置 socket timeout 的话，应用在数据库返回结果前会无期限地等下去，这种连接被称为 dead connection

优先级顺序

Socket timeout 级别优于 Transaction Timeout，而Transaction Timeout 级别优于 Statement Timeout。也就是说如果 Statement Timeout 大于 Transaction Timeout 或者 Socket timeout，则无法生效
不推荐使用socket timeout来限制statement的执行时长，因此socket timeout的值必须要高于statement timeout，否则，socket timeout将会先生效，这样statement timeout就变得毫无意义

频道导航