1、背景
线上一个服务偶尔会产生【Unknown thread id: XXX】异常
1.1、异常堆栈
org.springframework.jdbc.UncategorizedSQLException:
### Error updating database. Cause: java.sql.SQLException: Unknown thread id: 64278282
### The error may involve com.xxx.xxx_xxxxx.xxx.dao.XxxDao.insert-Inline
### The error occurred while setting parameters
### SQL: INSERT INTO `t_xxx_xxx_xxx` (XXX,XXX,XXX) VALUES (?, ?, ? )
### Cause: java.sql.SQLException: Unknown thread id: 64278282
; uncategorized SQLException for SQL []; SQL state [HY000]; error code [1094]; Unknown thread id: 64278282; nested exception is java.sql.SQLException: Unknown thread id: 64278282
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:84)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:371)
at com.sun.proxy.$Proxy26.insert(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.insert(SqlSessionTemplate.java:240)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:52)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
at com.sun.proxy.$Proxy28.insert(Unknown Source)
// 省略了部分信息
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1521)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1478)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.sql.SQLException: Unknown thread id: 64278282
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:959)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3870)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3806)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2470)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2617)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2546)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2504)
at com.mysql.jdbc.StatementImpl.executeInternal(StatementImpl.java:840)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:740)
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:119)
1.2、初步总结定位
异常都集中在一个数据库,产生异常的语句并不同,操作的表也不同,insert、update、select都发现过这种异常。
可确认的是部分异常时间点数据库确实存在高负载。只是不明白为何sql失败会得到这样的一种异常信息呢?
2、问题
- 是什么:这个异常是什么类型的异常
- 如何产生:这个异常是怎么产生的
- 如何解决:如何解决这个异常
3、调研
围绕这以上三个问题,我们逐个解析。
3.1、是什么
首先我们通过两个维度来解析一下这个异常,分别是数据库维度和应用维度。
3.1.1、数据库层面异常解析
由于我们用的是mysql数据库,那么mysql到底是如果定义和描述异常的。可参考:mysql官网的描述
我们文中所谓的mysql异常在mysql层面叫做error(下文称:mysql错误),我们从官网摘取了如下信息:
mysql错误分类
按照错误产生来源可以分为两种
- 服务端错误:启动或者关闭进程(需要dba干预的),执行sql发生问题(dba可干预,也很大可能需要反馈给客户端的)。错误码范围:[1000,1999],目前有6、7百个
- 客户端错误:通常都是与服务端的通信问题产生的异常(例:主机连接不通)。错误码范围:[2000,+],目前比较少,只有几十个。
mysql错误结构
mysql错误信息由错误码、SQLSTATE值以及错误描述三部分组成。
对照一下我们上文异常堆栈中的信息:
SQL state [HY000]; error code [1094]; Unknown thread id: 64278282
- 错误码(符号标识)
纯数字组成(例:1094)、每个错误码都有一个对应的符号标识(例如:ER_NO_SUCH_THREAD),这些错误码是mysql自己定义的,不适用于其他数据库。 - SQLSTATE值
一共由5个字符组成,值取自ansi sql和odbc,比数字错误代码更标准化,值的前两个字符表示错误类型- 00标识成功
- 01标识警告
- 02标识未找到
- 03[+]标识异常
- 对于服务端发生的错误,并不是所有的mysql错误码都能对应上一个SQLSTATE值,这个时候就用【HY000】,表示常规错误。
- 对于客户端发生的错误,都用【HY000】表示。
- 错误描述
异常简要描述(例:Unknown thread id: %lu)。
小结
经过这个小科普我们可以得出结论,我们得到的这个异常是个服务端异常。这个异常没有对应的SQLSTATE值,这是一个mysql特有的自定义异常。能得到的有效描述信息仅仅就是字面的意思(未知的或者说是不能识别的线程id)。
3.1.2、应用框架层面异常解析
通过异常堆栈我们可以发现:
栈顶异常是:org.springframework.jdbc.UncategorizedSQLException
栈底异常是:java.sql.SQLException
UncategorizedSQLException异常解析
spring有几个主要模块,IOC、AOP、数据访问和集成、WEB以及远程操作、测试框架等。数据访问和集成是spring框架中比较核心的一部分,spring在数据访问和继承方面的一个体现就是spring框架统一了数据访问异常体系,对于常见的数据访问操作异常进行了包装(可以参见org.springframework.dao和org.springframework.transaction两个包下的异常类)。
那么UncategorizedSQLException指代的是什么类型的异常呢?
- 通过类所处位置确定异常范围
UncategorizedSQLException类位于org.springframework.jdbc包下,并没有位于dao或者transaction包下,这也就说明他是spring框架对于jdbc实现的一个特定异常。 - 通过类名也可见一斑
UncategorizedSQLException以SQLException结尾,说明应该和java.sql.SQLException有关。 - 分析该类源码(为了节省篇幅,去掉了部分注释和代码)
/**
* Exception thrown when we can't classify a SQLException into
* one of our generic data access exceptions.
*/
public class UncategorizedSQLException extends UncategorizedDataAccessException {
/** SQL that led to the problem */
private final String sql;
public UncategorizedSQLException(String task, String sql, SQLException ex) {
super(task + "; uncategorized SQLException for SQL [" + sql + "]; SQL state [" +
ex.getSQLState() + "]; error code [" + ex.getErrorCode() + "]; " + ex.getMessage(), ex);
this.sql = sql;
}
/**
* Return the underlying SQLException.
*/
public SQLException getSQLException() {
return (SQLException) getCause();
}
/**
* Return the SQL that led to the problem.
*/
public String getSql() {
return this.sql;
}
}
- 通过该类的注释可以得到如下信息:
当我们无法将SQLException分类为一个通用数据访问异常时,就会抛出这个异常。
- 还可以通过UncategorizedSQLException的父类UncategorizedDataAccessException的注释我们得到如下信息:
当我们仅仅知道是底层(译者注:这里所谓的底层指的底层api,JDBC等)出了问题,没有更细化的信息的时候就可以使用这个异常。举了个例子:jdbc抛出的SQLException。
- 这个异常类定义了一个字符串类型的sql属性
- 这个异常类还定义了一个getSQLException方法,返回一个SQLException对象
SQLException
1、该类位于java.sql包下,属于jdk的类。
2、java.sql包是干什么的?
这个包我们日常开发可能很少关注和留意,但是另外一个概念大家肯定都不陌生,那就是JDBC。JDBC是java定义的一套进行数据库操作的规范,是一套api,这套api里面既有接口也有普通的类。jdbc的所有接口和类都在java.sql包下。java.sql包就是jdbc所在。java.sql包下大部分是接口,需要各个数据库厂商进行实现。
- jdbc的接口:Driver、Connection、Statement等。
- jdbc的普通类:SQLException就是其中之一。还有 DriverManager、Date、JDBCType(枚举)等。
小结
到这一步,从应用框架层面确定了这个底层异常是jdbc的一个SQLException。没有被mybatis包装(因为我们也用到了mybatis框架,但是异常堆栈中并没有发现有mybatis框架定义的异常),被spring包装成了一个UncategorizedSQLException抛出。
经过以上两种角度的分析,同时以点带面的科普了相关知识点,还都是理论和现象之间的互相印证而已,主要解答了这个异常是什么,接下要分析这个异常是如何产生的
3.2、如何产生
通过场景分析总结的时候,我们提到应该是由于当时(发生异常的时间点)数据库压力较大,导致了sql执行失败,可是为什么是这样一种异常,而不是更具象化的异常呢,为什么不是超时异常和获取不到连接异常呢?
从度娘和谷歌搜这个异常(unknown thread id)几乎得不到什么有价值的参考信息,是否这个异常是个特殊场景或者具有公司特色的异常。
于是我们可能还是需要从源码层面找一找答案。
再来观察异常堆栈:
Caused by: java.sql.SQLException: Unknown thread id: 71436599
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:959)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3870)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3806)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2470)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2617)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2546)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2504)
at com.mysql.jdbc.StatementImpl.executeInternal(StatementImpl.java:840)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:740)
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:119)
3.2.1、StatementImpl$CancelTask部分源码解析
异常堆栈的栈底很清楚的说明了调用com.mysql.jdbc.StatementImpl类的内部类CancelTask的run方法的时候产生了这个异常。代码行号是119。我们通过行号路由的相关代码片段:
public class StatementImpl implements Statement {
//此处省略了很多代码
protected boolean wasCancelled = false; // 标识是否被取消
protected boolean wasCancelledByTimeout = false; // 标识是否因超时被取消
class CancelTask extends TimerTask {
//此处省略了很多代码
SQLException caughtWhileCancelling = null;// 接收并存储取消过程中发生的SQLException类型异常
StatementImpl toCancel;// 指向要取消的StatementImpl实例
CancelTask(StatementImpl cancellee) throws SQLException {
//此处省略了很多代码
}
@Override
public void run() {
Thread cancelThread = new Thread() {
@Override
public void run() {
Connection cancelConn = null;
java.sql.Statement cancelStmt = null;
try {
if (StatementImpl.this.connection.getQueryTimeoutKillsConnection()) {
//此处省略了很多代码
} else {
synchronized (StatementImpl.this.cancelTimeoutMutex) {
if (CancelTask.this.origConnURL.equals(StatementImpl.this.connection.getURL())) {
//All's fine
cancelConn = StatementImpl.this.connection.duplicate();
cancelStmt = cancelConn.createStatement();
119 cancelStmt.execute("KILL QUERY " + CancelTask.this.connectionId);
} else {
//此处省略了很多代码
}
/*
* 执行到这里说明外部类实例的Statement任务因为超时被成功取消,所以以下的两个标识都设置为true
*/ CancelTask.this.toCancel.wasCancelled = true;
CancelTask.this.toCancel.wasCancelledByTimeout = true;
}
}
} catch (SQLException sqlEx) {
/*
* 如果捕捉到的是SQLException
* 那么赋给自己的实例变量caughtWhileCancelling(并没有向上抛出)。
*/
CancelTask.this.caughtWhileCancelling = sqlEx;
} catch (NullPointerException npe) {
} finally {
//此处省略了很多代码
}
}
};
cancelThread.start();
}
}
//此处省略了很多代码
}
代码段中119行号对应的就是产生异常的代码行。
到这里有几个点值得讲一讲。
- StatementImpl类是干什么的?
他是jdbc的Statement接口的实现,通过jdbc来进行绝大部分数据操作,都是通过Statement的executeXXX方法进行的。 - CancelTask是干什么的?
他是StatementImpl的内部类,如果设置了Statement超时机制,那么该类的作用就是在Statement执行超时的时候取消掉这个Statement任务。 - KILL QUERY 是干什么的?
这个命令在我们的业务代码里几乎用不到,但是对于DBA来讲,应该再熟悉不过。
当某个sql进行了全表扫描;某个ddl激发了元数据锁,导致后续所有请求阻塞;这些时候都需要DBA进行及时干预,杀掉这些危险进程,这个时候用到的就是kill命令。
KILL 命令有两种使用方法,可参考:mysql官网的描述- KILL xxid: 杀掉xxid对应的sql线程,同时杀掉其关联的连接。
- KILL QUERY xxid: 仅仅杀掉xxid对应的sql线程,不会杀掉对应的连接。
根据以上分析就说明我们的业务层面配置了statement超时,而且也确实执行超时了,也触发了取消任务去kill这个超时的任务。但是取消的过程中产生了异常,抛出到了我们业务层面上。
这时又产生了几个疑问。
- 取消任务是一个独立的线程,和业务主线程是隔离的,怎么取消失败的异常会抛到业务主线程里(代码层面并没有向外抛出)?
- 这个超时的sql到底取消了没有?
这就需要继续观察源码,这次我们要从业务sql执行的角度来观察。我们常规的业务sql语句最终都会交给Statement接口的execute方法们(该方法有几个重载方法)来执行。这些方法在StatementImpl类和PrepareStatement类中的实现都是调用各自类中的私有方法executeInternal来执行,而executeInternal方法在两者中的实现主体流程大体相同,我们就以StatementImpl中的源码为例进行分析。
3.2.2、StatementImpl的executeInternal方法中的超时逻辑解析
private boolean executeInternal(String sql, boolean returnGeneratedKeys) throws SQLException {
MySQLConnection locallyScopedConn = checkClosed();
synchronized (locallyScopedConn.getConnectionMutex()) {
// 此处省略了部分代码
try {
// 此处省略了部分代码
if (useServerFetch()) {
//连接参数里如果设置了useServerFetch=true则会执行这部分逻辑,最终还是会路由到PrepareStatement的executeInternal的方法中
rs = createResultSetUsingServerFetch(sql);
} else {
CancelTask timeoutTask = null; // 声明一个取消任务变量
String oldCatalog = null;
try {
/* 如果enableQueryTimeouts配置为true(默认为true)
* 超时时间不等于0(此处的判断等同于大于0),这毫秒值是必须为大于等于0的数值,这个地方之所以没有用>0,是因为setTimeoutInMillis方法中做了校验,若设置一个小于0的数值会抛出异常。
* 校验数据库版本必须为5.0.0以上
*/
if (locallyScopedConn.getEnableQueryTimeouts() && this.timeoutInMillis != 0 && locallyScopedConn.versionMeetsMinimum(5, 0, 0)) {
timeoutTask = new CancelTask(this); // 创建一个取消任务
/*
* 把这个任务交给一个Timer调度器进行调度,timeoutInMillis毫秒后开始执行该取消任务(如果业务在timeoutInMillis的时间里没有执行完,就会被调度触发的取消任务取消掉)。
* 结合Timer和CancelTask的源码,我们可以发现,当Timer调度执行其队列任务时,会调用任务的run方法,那么当调用CancelTask的run方法的时候,会触发其内部取消线程的执行(cancelThread.start();)
*/
locallyScopedConn.getCancelTimer().schedule(timeoutTask, this.timeoutInMillis);
}
if (!locallyScopedConn.getCatalog().equals(this.currentCatalog)) {
oldCatalog = locallyScopedConn.getCatalog();
locallyScopedConn.setCatalog(this.currentCatalog);
}
// 此处省略部分代码
// 这一步才真正的执行sql语句,返回结果
rs = locallyScopedConn.execSQL(this, sql, this.maxRows, null, this.resultSetType, this.resultSetConcurrency,
createStreamingResultSet(), this.currentCatalog, cachedFields);
// 判断是否存在超时取消任务,配置了超时机制,那么就存在
if (timeoutTask != null) {
// 如果取消任务的caughtWhileCancelling变量不为空(在CancelTask源码分析过该变量的类型是SQLException)
if (timeoutTask.caughtWhileCancelling != null) {
942(就是这儿) throw timeoutTask.caughtWhileCancelling; //抛出该SQLException异常
}
// 走到这一步说明,取消任务没有发生异常。有可能未执行;有可能取消成功;
// 无论是那种情况,都可任务已经sql已经返回结果了,取消任务没有必要存在了,所以取消掉这个调度任务
timeoutTask.cancel();
// 置为空,为了能被尽快回收。如果不置为空,就意味着外部类的StatementImpl实例一直引用这个取消任务,只要StatementImpl实例不销毁,那么这个timeoutTask就不被销毁。
timeoutTask = null;
}
synchronized (this.cancelTimeoutMutex) {
if (this.wasCancelled) { // 如果自己的statement被成功取消
SQLException cause = null; // 定义个jdbc异常,用来指向具体子类
if (this.wasCancelledByTimeout) { // 如果是因为超时被取消
cause = new MySQLTimeoutException(); // 生成一个mysql超时异常
} else {
cause = new MySQLStatementCancelledException(); // 生成一个mysql取消异常
}
resetCancelledState(); // 重置wasCancelled和wasCancelledByTimeout为false
throw cause; // 抛出异常
}
}
} finally {
// 在finally中做进一步的资源清理
// 这个地方重点留意,这是个try-finally结构,没有catch。
// 意思就是,如果产生异常,会直接抛出给调用方
// 例如:发生socket timeout时,中断执行,把异常抛出给上层方法处理
if (timeoutTask != null) {
timeoutTask.cancel(); // 取消掉任务
locallyScopedConn.getCancelTimer().purge(); // 从任务队列中移除掉被取消的任务
}
if (oldCatalog != null) {
locallyScopedConn.setCatalog(oldCatalog);
}
}
}
if (rs != null) {
// 此处省略了部分代码
}
return ((rs != null) && rs.reallyResult());
} finally {
locallyScopedConn.setReadInfoMsgEnabled(readInfoMsgState);
this.statementExecuting.set(false);
}
}
}
通过上面的源码解读我们可以回答前文提到的两个问题。
-
取消任务是一个独立的线程,和业务主线程是隔离的,怎么取消失败的异常会抛到业务主线程里(代码层面并没有向外抛出)?
- 首先CancelTask中捕捉到SQLException没有抛出,只是赋给了自己的一个实例变量caughtWhileCancelling。
- 其次在executeInternal方法中,会检查CancelTask实例(timeoutTask)的实例变量caughtWhileCancelling是否为空,不为空,则抛出该异常。
正因为这两点,取消任务的发生的异常才通过业务线程抛出了。
-
这个超时的sql到底取消了没有?
因为取消过程中发生了异常,所以超时的sql并没有被取消,sql还是继续执行了,而是在sql执行成功之后,通过后置的校验,抛出了这个取消异常。- 抛出异常的时候,后续流程肯定会中断。
- 无论业务sql是否处于事务当中,读操作都肯定执行成功了。
- 如果业务sql处于事务当中的话,那么写操作可以被回滚。
- 如果业务sql没有处在事务当中的话,那么写操作不会被回滚。
经过以上两部分的源码解析,我们可以确定异常产生的背景是我们配置了statement超时机制,当主线程的statement执行超时,异步线程取消任务去kill超时的主线程的statement时发生了这个异常。但是这个取消异常只是暂存了起来,等到主线程statement执行完成后,才由后置的校验机制检测到,抛出。这里还需要待进一步探讨几个问题。
- 超时是如何设置的?
- 为什么取消会失败?
3.2.3、超时设置
本文所讨论的超时设置是基于spring + mybatis + jdbc 的架构来讲。鉴于关于这方面的知识在网络上已经找到介绍的非常详尽的文章,所以这里我们不详细展开,附上两个参考地址:
深入理解JDBC超时机制(原文翻译)
深入理解JDBC超时机制(英文原文)
基于本文所论述内容的需求,从以上文章中摘取了部分图文。
应用与数据库间的timeout层级
transaction timeout设置
事务的超时时间只存在于高层框架层面,jdbc里没有这个概念。如果使用spring框架,那么可以通过xml或者注解的方式进行配置。
1、针对部分方法生效(3秒超时)
<tx:method name=“…” timeout=“3″/>
2、针对某个类或者类的某个方法生效 (3秒超时)
@Transactional(timeout=3)
事务超时针对的是整个事务的执行时间,这里面就不单单包括数据库的操作时间,其他的业务处理也算在内。事务时间=statement时间*n + 杂七杂八的时间。
jdbc的statement timeout设置
statement timeout用来限制statement的执行时长,timeout的值通过调用JDBC的java.sql.Statement.setQueryTimeout(int timeout) API进行设置。因我们使用mybatis框架,所以一般可以通过两种方式配置该超时时间。
1、全局配置
可以通过设置全局的defaultStatementTimeout进行配置,以下配置片段中设置了3秒超时。
<configuration>
<settings>
<!-- 省略了其他配置 -->
<setting name="defaultStatementTimeout" value="3" />
</settings>
<mappers>
<!-- 省略了其他配置 -->
</mappers>
</configuration>
2、单独配置
可以在具体的mapper文件的指定语句上配置timeout。以下配置片段中为单个sql设置了1秒超时。
<select id="getListFromGroupBy" resultType="java.util.Map" timeout="1">
select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100
</select>
MySQL JDBC Statement的QueryTimeout处理过程(5.0.8)
jdbc的socket timeout设置
我们目前所使用的jdbc的实现(mysql-connector-java-XXX.jar)底层是通过socket与数据库进行通信,不同的数据库厂商针对自己的不同数据库提供不同的jdbc实现。基于socket通信如果不设置超时时间,很有可能在出现网络问题时产生无限等待,最终耗尽系统资源。socket timeout 可以解释为传输(读写)超时,和其形影不离的还有一个 connect timeout,可以解释为建立连接超时。鉴于我们使用DBCP来配置数据库连接池,一般把参数配置写到prop文件中,再通过xml配置文件引用。
1、properties配置
设置了连接超时为1秒,读写超时为5秒
jdbc.connectionProperties=connectTimeout=1000;socketTimeout=5000;useUnicode=true;characterEncoding=utf8[;**key=**val]
2、xml配置
<bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource" abstract="true">
<!-- 省略了其他配置 -->
<property name="connectionProperties" value="${jdbc.connectionProperties}"/>
</bean>
在mysql的jdbc实现中,这两个设置最终都通过ConnectionImpl(继承了ConnectionPropertiesImpl)传递给MysqlIO,MysqlIO封装了底层的socket操作。那么如果socket超时了会产生什么样的异常呢?
socket timeout 异常堆栈
org.springframework.dao.RecoverableDataAccessException:
### Error querying database. Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 120,104 milliseconds ago. The last packet sent successfully to the server was 120,099 milliseconds ago.
### The error may exist in mapper/filter/XxxMapper.xml
### The error may involve com.xxxx.xxxx_xxxx.filter.dao.XxxDao.findByXxxId-Inline
### The error occurred while setting parameters
### SQL: //此处略去
### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:408)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:983)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3457)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3357)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3797)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2470)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2617)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2550)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1192)
at sun.reflect.GeneratedMethodAccessor146.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
at com.sun.proxy.$Proxy74.execute(Unknown Source)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:62)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:78)
at sun.reflect.GeneratedMethodAccessor145.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
at com.sun.proxy.$Proxy70.query(Unknown Source)
at org.apache.ibatis.executor.ReuseExecutor.doQuery(ReuseExecutor.java:59)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:96)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82)
at sun.reflect.GeneratedMethodAccessor156.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy69.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113)
at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358)
... 104 more
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2946)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3367)
... 143 more
- 栈顶异常信息翻译一下
The last packet successfully received from the server was 120,104 milliseconds ago. The last packet sent successfully to the server was 120,099 milliseconds ago.
最后一次从服务端成功接收的数据包是120104毫秒(120秒多一点)之前,最后一次成功发送到服务端的数据包是120099毫秒(120秒多一点)之前。
- 栈底的Caused by: java.net.SocketTimeoutException: Read timed out已经很清楚的说明了引起异常的原因是读超时。
超时设置总结
给出一个生产系统的真实配置来说明一下各种超时参数该如何配置
- connect/socket timeout
connectTimeout=1000;socketTimeout=120000
- statement timeout
<setting name="defaultStatementTimeout" value="3" />
- transaction timeout
未设置
该系统就是上文提到的一个核心业务系统,需要对外提供高性能的接口,同时也承担了定时数据刷新任务。(此处先不讨论拆分成两个系统的事情)。该系统所依赖的数据库集群每天凌晨都会有大量的etl数据写操作,届时数据库io压力相当大。
- 对外提供高性能接口,大部分操作可命中缓存,少部分请求会穿透到库,鉴于接口性能要求以及外部代理层的3秒超时设置,也就是说如果sql执行超过3秒就相当于请求失败。所以把statement timeout 设置为3秒。
- 数据刷新任务的自身逻辑就包含着从库中删除老数据,并从外部的nosql数据源抽取新数据写入到库中。读写操作自身就比较繁忙,若再和etl数据写入赶到一起的话很容易产生请求阻塞或连接断开的情况。socket timeout一定要配置的,但是鉴于是处于凌晨的定时任务,超时时间可以设置稍微长一些,可以减少失败批次的概率。所以设置了120秒(2分钟),这个值也是根据自身系统情况调整过几次之后定的值。
- 鉴于自身业务提供的高性能接口是只读服务、所以无需开启事务。定时刷新任务存在循环的大批量的写操作,且还存在高延迟的可能,单批写操作是针对单表,所以也必要开启小事务,更不可能采取一个大事务的方式来保证所有批次一起提交,系统层面采用小批次失败重试机制来保证成功率。
上文 《socket timeout 异常堆栈》中的异常就是真实环境下的异常堆栈。到这里你是否有个疑问,statement设置了3秒超时,socket设置了2分钟超时,按理说应该是statement执行sql先超时,应该永远得到的是statement的超时异常,为什么会得到socket read timeout异常呢?
这个可以这样理解,当socket已经存在阻塞的时候,我们的异步的statement取消任务同样也要经由socket把kill命令传输给数据库层面,这样的请求同样也存在被阻塞的可能,也就是说取消请求同样也可能得不到响应。即使取消请求很快得到了回应,因为主线程socket还在阻塞,得不到mysql线程被kill的消息,也无法继续往下执行,最终还是会因为超时异常而绕过后续的和取消任务有关的后置校验。当然如果主线程阻塞时间超过3秒,但不到2分钟,且statement取消线程获取到资源快速得到响应。这样的场景下我们得到的就是statement超时异常(MySQLTimeoutException)或者取消失败异常(SQLException)了。而在我们上文提到的两个场景中,我们得到都是取消失败异常(SQLException)。
3.2.4、为什么取消会失败
我们设置了statement超时,那么当statement执行时间超过设定值的时候,我们希望他能被kill掉,进而通过业务层面能够得到一个期待中的异常(MySQLTimeoutException),但是我们却得到了一个取消失败异常(SQLException),而且我们上文中也提到,这种情况下statement的sql是没有被取消掉的,还是正常执行的(执行用时肯定超过了设定的超时时间)。这也就是等于说我们的statement超时设置没有起到应有的作用。所以取消失败这个情况很有必要仔细追查一下。
再探Unknown thread id
上文源码分析中已经提到,这个异常是在执行kill query xxid的时候抛出的,字面意思就是“未知的线程id”,根据字面意思我们可以猜测应该是mysql服务器无法识别该线程id,无法识别很有可能是因为这个线程id不存在,如果是这个线程id不存在那么又可能是因为什么原因不存在呢?
- 从来就没有存在过(应用层提供的id就是错误的)
- 线程存在过,因为某些原因可能已经被销毁了。
要想得到上面问题的准确答案,我们可以在线下环境尝试复现一下这个异常场景,进行观察定位。于是我们需要做以下事情。
1)监控mysql的线程
我们要想监控到mysql服务的线程信息,可以通过information_schema.processlist表查看到当前运行的线程信息
select * from information_schema.processlist
2)准备一个慢sql
需要一个慢sql,起码要保证大部分情况下执行时间都超过1s,那么我们就可以把statement timeout设置为1s,这样执行该sql的时候就可以触发超时。
我找了一个测试环境的数据表,表里有40多万的数据,然后写了个稍微复杂点的分组查询,最后经测试几乎每次执行耗时都要超过3s。该sql如下:
select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100
大家不必太关注这个sql的业务逻辑【没有业务意义的】,仅仅就是为了造一个慢sql而已。
3)代码以及配置准备
1、在mapper语句层面配置超时
<select id="getListFromGroupBy" resultType="java.util.Map"
useCache="false" timeout="1">
select
c_name,c_code,d_name,d_code,count(*) from
t_xxx_xxx group by
c_name,c_code,d_name,d_code order by rand() limit
100
</select>
以上针对那个平均执行耗时超过3s的sql配置查询超时(statement 超时)为1s,这样能够9成以上概率是可以触发超时异常的。
2、junit单元测试代码
@Test
public void testStatementTimeout() {
List<Map<String, Object>> list = xxxBusiness.getListFromGroupBy(); // 最终会执行那个慢sql
Assert.assertTrue(list.size() == 100);
}
4)启动测试
1、启动单元测试
2、从mysql线程信息中找到我们的sql
由于我所使用的mysql用户权限较大,为了能够直观明了了关注到重点信息,修改了一下查看进行信息的sql
select `ID`,`HOST`,`COMMAND`,`INFO` from information_schema.processlist where db='db_xxx' and length(info)>0 order by id desc;
这样我们就仅仅关注了db_xxx库的所有sql语句线程了。
鉴于我们的业务sql需要3s左右才能执行完成,所以我们可以手动不间断的刷新这条查询线程的sql,就能够发现这个业务sql对应的记录信息。一旦发现就可以停止刷新了,因为再刷新可能记录就不存在了(因为业务sql执行完成之后线程就销毁了)。
- 在单元测试刚启动,业务sql还没有执行的时候,我们得到的结果列表如下:
ID | HOST | COMMAND | INFO |
---|---|---|---|
553063 | 192.168.35.194:59007 | Query | select ID ,HOST ,COMMAND ,INFO from information_schema.processlist where db=‘db_xxx’ and length(info)>0 order by id desc LIMIT 0, 1000 |
- 刷新几次后,业务sql开始执行单未执行完成时,我们得到的结果列表如下:
ID | HOST | COMMAND | INFO |
---|---|---|---|
553696 | 192.168.2.10:40730 | Query | select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100 |
553063 | 192.168.35.194:59007 | Query | select ID ,HOST ,COMMAND ,INFO from information_schema.processlist where db=‘db_xxx’ and length(info)>0 order by id desc LIMIT 0, 1000 |
备注:表格里的ID列对应的就是线程id,HOST列对应的是发起请求的客户端地址(192.168.35.194是我本机ip)
3、从异常信息中获取线程id
junit的异常堆栈信息如下
org.springframework.jdbc.UncategorizedSQLException:
### Error querying database. Cause: java.sql.SQLException: Unknown thread id: 3805330
### The error may exist in mapper/xxx/XxxMapper.xml
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100
### Cause: java.sql.SQLException: Unknown thread id: 3805330
; uncategorized SQLException for SQL []; SQL state [HY000]; error code [1094]; Unknown thread id: 3805330; nested exception is java.sql.SQLException: Unknown thread id: 3805330
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:84)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
// 省略了部分信息
Caused by: java.sql.SQLException: Unknown thread id: 3805330
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:959)
// 省略了部分信息
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:119)
从异常信息中我们可以得到要取消的线程id为:3805330
5)分析测试结果
通过以上实验,我们成功复现了Unknown thread id异常。
通过对mysql线程信息的观察,我们确定了业务sql对应的线程id是【553696】,但是取消线程要取消的线程id确是【3805330】,二者直观上看数值就相差悬殊,很显然我们要取消的是一个不正确的id。通过这样的现象可以回答我们之前的问题。
线程id不存在是因为:从来就没有存在过(应用层提供的id就是错误的)。
接下来我们分析为何应用层提供的id是错误的?
还是继续分析我们测试过程中观察到的数据。之前说过mysql线程信息中HOST列表示的是通信的客户端地址,我通过本机的mysql GUI工具连接上远程数据库,并发起查询processlist的请求,所以结果集的第二行中的HOST对应我本机的ip:192.168.35.194。可是我同样是在本机进行的单元测试,为什么业务sql对应的ip是:192.168.2.10而不是192.168.35.194呢?
这是因为我们用了ProxySQL,ProxySQL是一个高性能的MySQL中间件,提供强大的规则引擎,他的其中一个特性是可帮助我们的应用程序透明的实现读写分离。
浅析ProxySQL
正是因为我们的应用连接的是ProxySQL,而不是真正的mysql,所以我们应用和数据库之间的请求响应都是由ProxySQL来代理转发的,所以才会出现,连接数据库的客户端是ProxySQL的所属主机而不是我本机。
既然我们应用和mysql之间有一层中间件,那么应用层所得到的错误的id,会不会和ProxySQL有关,会不会是ProxySQL中的什么id呢?
于是在ProxySQL的官网查阅了一番,最后得到了如下有效信息,可以通过以下sql查看ProxySQL的进程(线程)信息
select * from stats_mysql_processlist
鉴于数据库中间件由DBA维护,研发没有直接权限,所以求助DBA查询了一下,通过DBA给出的结果集发现,原来我们得到的【3805330】对应的是ProxySQL的SessionID。
ProxySQL是一定要遵守mysql通信协议的,不然就谈不上对请求和接收两端透明;ProxySQL作为一个代理层中间件,为了实现自身的价值,使得他可能需要对通信内容进行部分更改(仅限于部分协议中规定的属性)以适应自身的功能需要。
在应用层和mysql建立TCP连接后,mysql server端主动发起的握手请求报文中会包含有一个4字节的connection id值,这个值就对应着mysql的线程id,ProxySQL把这个id替换成自己的SessionID返回给应用层。
应用层发起kill命令,附带的id就是SessionID,但是因为kill命令属于请求正文,ProxySQL不能分析和更改请求正文的,所以把kill query SessionID的命令发送到mysql时,mysql里根本找不到对应的ProxySQL的SessionID,所以抛出Unknown thread id异常。这里还有一个更危险的场景,如果恰好有一个mysql的线程id和SessionID相同,那就会是各种奇异现象了。
所以我们得出的结论是:
ProxySQL作为一个mysql中间件,对于mysql服务端发送给应用客户端的握手报文的connection id值进行了替换,导致了应用客户端在kill场景中,kill了错误的id,从而会引发此种Unknown thread id异常。注意:我们的结论是我们的场景下
3.3、如何解决
3.3.1、不使用ProxySQL
接上文提到的测试用例,修改数据库连接配置,改为直连数据库。其他配置和代码一律维持原样。最终我们得到了如下异常:
org.springframework.dao.QueryTimeoutException:
### Error querying database. Cause: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
### The error may exist in mapper/xxx/XxxMapper.xml
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100
### Cause: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
; SQL []; Statement cancelled due to timeout or client request; nested exception is com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:118)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:371)
at com.sun.proxy.$Proxy31.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:198)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:122)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:64)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
at com.sun.proxy.$Proxy39.getListFromGroupBy(Unknown Source)
// 省略了部分信息
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:75)
at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:254)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:89)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:193)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:86)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:678)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)
Caused by: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2765)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2550)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1192)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.mysql.jdbc.MultiHostConnectionProxy$JdbcInterfaceProxy.invoke(MultiHostConnectionProxy.java:91)
at com.sun.proxy.$Proxy165.execute(Unknown Source)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:62)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:78)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
at com.sun.proxy.$Proxy161.query(Unknown Source)
at org.apache.ibatis.executor.ReuseExecutor.doQuery(ReuseExecutor.java:59)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Invocation.proceed(Invocation.java:49)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy160.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358)
... 42 more
- spring框架的包装异常为:org.springframework.dao.QueryTimeoutException
- 被spring包装的cause为:com.mysql.jdbc.exceptions.MySQLTimeoutException
这也间接证明了我们之前的结论,statement超时场景下是因为ProxySQL的问题引发了Unknown thread id异常。
不使用ProxySQL可以解决这个问题,但是也达不到我们用ProxySQL的目的了(对应用透明的读写分离)
3.3.2、从ProxySql官网寻求答案
经过一番求索,最终在ProxySql的issue板块中找到了答案。
renecannao commented on 25 Nov 2018
Feature implemented in 1.4.13 and 2.0.0
ProxySql的作者针对类似问题的回复是在1.4.13版本和2.0.0版本这个问题得到了修复。
于是和DBA确认了下线上环境和测试环境当前用的版本
- 线上环境是1.3的版本
- 测试环境是1.4.8的版本
3.3.3、升级ProxySql
为了验证官网的说法,DBA协助升级了测试环境的ProxySql版本到1.4.15。
接上文提到的测试用例,修改数据库连接配置,再改为连接ProxySql。其他配置和代码一律维持原样。最终我们得到了如下异常:
org.springframework.dao.QueryTimeoutException:
### Error querying database. Cause: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
### The error may exist in mapper/xxx/XxxMapper.xml
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select c_name,c_code,d_name,d_code,count(*) from t_xxx_xxx group by c_name,c_code,d_name,d_code order by rand() limit 100
### Cause: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
; SQL []; Statement cancelled due to timeout or client request; nested exception is com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request
at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:118)
//省略了部分信息
可见我们通过升级ProxySql到1.4.13以上版本的时候,unknown thread id的问题得到解决。