生产系统 SQL 执行异常原因分析

起因

最近一段时间，生产系统持续碰到一些数据库异常，导致 sql 执行失败。

应用环境

Java 1.7 + Mysql 5.6 + spring + ibatis

问题排查

将各种失败的异常记录了一下，碰到最多下面几种异常。

1. java.net.SocketTimeoutException: Read timed out
2. java.sql.BatchUpdateException: No operations allowed after statement closed。
3. com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
   • java.io.EOFException: Can not read response from server. Expected to read 8 bytes, read 7 bytes before connection was unexpectedly lost.
   • java.net.SocketException: Software caused connection abort: recv failed

SocketTimeoutException

针对上面第一种情况，很容易从字面意义就得出是读取超时。然而查询资料 JDBC 存在多种 timeout,仔细研究了一下，梳理一下。

JBDC 可以设置超时时间分别是 Transaction Timeout，Statement Timeout，Socket TimeOut，ConnectionTimeout。上述超时时间层次从上至下。

以下我们从上之下分别了解这几种种超时时间。

Transaction Timeout ：事务超时时间，由多个 Statement 组成。事务的超时时间=N*Statement.timeout+其他代码执行时间。所以我们不应该在一个事务中执行一些 RPC 或 HTTP 等这些长耗时的调用。如果时间卡在这些调用上，会导致事务超时发生回滚。

Statement Timeout：一次语句的执行的时间，可以用来限制一个查询语句的执行时间。但是如果出现网络故障，这个超时间将不起作用。最终需要 Socket TimeOut 解决。

Socket TimeOut ：目前 JDBC 类型存在四种，而我们通常使用的是数据库协议驱动（Database-Protocol driver (Pure Java driver) or thin driver）。这种驱动采用 Socket 用来与数据库通信。若没有设置，一但发生网络故障，SCOKET 读取就会直接阻塞。而设置以后，时间超时后将会抛出 java.net.SocketTimeoutException: Read timed out，防止长时间阻塞，系统不可用。

ConnectionTimeout ：这个超时参数也是与 Socket 建立连接有关。若没有设置，一旦如果数据库相关地址参数错误错误，将会长时间阻塞在建立数据库连接上。

使用网上一张图可以清晰的解析前三者关系。

实际上还存在操作系统层面上 Socket 超时。各个操作系统可以设置相应 Socket 超时时间，然后若 JDBC 没有设置，到了操作系统的超时时间也将会断开。但是我们不能依赖该超时间，因为该时间完全不可控，我们应该显式设置。

综上，针对相关 JDBC 参数我们至少需要设置 ConnectionTimeout 以及 Socket TimeOut.针对 sql 语句，可以设置 Statement Timeout。若存在事务，还可以设置相应 Transaction Timeout。

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException

这个 CommunicationsException 异常会因为其他底层异常导致如以下这两种异常。

1. java.io.EOFException: Can not read response from server. Expected to read 8 bytes, read 7 bytes before connection was unexpectedly lost.
2. java.net.SocketException: Software caused connection abort: recv failed

刚开始碰到该异常，根据 CommunicationsException 查询一下了，大致都是说 Mysql server 端会检测空闲连接，超时后主动断开连接，导致客户端的连接失效。

那么什么是 mysql 的空闲连接那？简单来说，mysql 连接进程 Command 为 sleep 状态。我们可以使用 show processlist ; 查看正在运行的进程。空闲的进程示例如图：

jdbc 连接会根据 mysql wait_timeout 检测空闲连接。若在 wait_timeout 时间内，连接还是空闲状态，mysql server 将会断开这个链接。针对这种情况，采用编码模拟。
采用如下代码：

		try {
			Connection connection = dataSource.getConnection();
			TimeUnit.SECONDS.sleep(11L);
			run.query(connection,"select 'X'", h);
			//Thread.sleep(60000);
		} catch (Exception e) {
			log.error("查询异常", e);
		}

然后设置 mysql wait_timeout=10 。
以下模拟代码获取连接后，休眠11s，这个过程中，mysql 主动断开连接,等真正执行时，程序抛出异常。

以下为报错的情况：

但是底层异常却为 java.net.SocketException: Software caused connection abort: recv failed，而不是 java.io.EOFException。

这个报错却是很疑惑。然后仔细查看 EOFException 后面描述 Expected to read 8 bytes, read 7 bytes before connection was unexpectedly lost，可以看出这个连接其实有一段时间其实还是可用，有读取数据，但是在读取数据过程中，未读到符合数量的相应数据，导致报错。而上面代码模拟的却是连接使用时连接已生效的情况。

执行 show variables like '%timeout%'; 查看 mysql 其他超时时间，

从上图可以注意到 net_read_timeout 与 net_write_timeout 这两个参数。

查看 mysql 官方文档

net_read_timeout 默认30s
The number of seconds to wait for more data from a connection before aborting the read. When the server is reading from the client, net_read_timeout is the timeout value controlling when to abort. When the server is writing to the client,
net_write_timeout 默认60s
The number of seconds to wait for a block to be written to a connection before aborting the write

net_write_timeout 控制 mysql 服务端向客户端写数据超时时间。针对这种情况，在 MysqlIO read 处打上短点，

程序启动时，先放开断点，查看 mysql processlist，看到 mysql 进程 state send to client 时，这个时候使断点生效。这个时候，等待60s 以后，成功复现出如下错误。

net_read_timeout 该超时不知道如何模拟:(。

综上，若发生 com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure 异常，为数据库连接失效，但是失效的原因可能会有多种，大致都与 mysql 各种 timeout 参数相关。

BatchUpdateException

这个错误是发生在数据批量导入时。当时数据量大概 20 多W条，然后在批量插入时抛出该异常。以下为批量插入代码。

getSqlMapClientTemplate().execute(new SqlMapClientCallback<Object>() {
			@Override
			public Object doInSqlMapClient(SqlMapExecutor executor) throws SQLException {
				executor.startBatch();
				for (int i = 0; i < 200000; i++) {
					Demo demo = new Demo();
					demo.setName("asd");
					demo.setAge(String.valueOf(i));
					demo.setSubject("adassad");
					// 原项目 这里会发生一次 RPC调用 现用 Sleep 代替
					try {
						TimeUnit.MILLISECONDS.sleep(10L);
					} catch (InterruptedException e) {
						e.printStackTrace();
					}
					executor.insert("insertDemo", demo);
				}
				executor.executeBatch();
				return null;
			}
		});

这段代码就是使用 ibatis batch 功能，批量插入数据。

其实看到这个异常信息，java.sql.BatchUpdateException: No operations allowed after statement closed 可以明确看出是因为 statement 关闭导致，那么为什么 statement 会提前关闭。下面我们跟踪源码。

现在我们先看 SqlMapClientCallback doInSqlMapClient 方法。debug executor.startBatch() 方法最后其调用的是 SqlMapExecutorDelegate.startBatch 方法

查看代码注释可知，其目的就是为了设置一个状态值，这个状态值下面将用到。

此时我们查看 executor.insert ,正常来说该方法应该会执行sql 语句，然后插入数据库。但是查看源码你会发现，他最后调用的是 MappedStatement.sqlExecuteUpdate,进入方法刚开始就判断上文设置的 session batch 属性。当然这个属性，我们刚开始已经设置成 true ， 所以此时并没有执行 sql 插入动作，而是将这次 sql 以及相关参数存储到内存。

  protected int sqlExecuteUpdate(StatementScope statementScope, Connection conn, String sqlString, Object[] parameters) throws SQLException {
    if (statementScope.getSession().isInBatch()) {
      getSqlExecutor().addBatch(statementScope, conn, sqlString, parameters);
      return 0;
    } else {
      return getSqlExecutor().executeUpdate(statementScope, conn, sqlString, parameters);
    }
  }

最后我们查看 executor.executeBatch，该方法最后调用了 Statement.executeBatch,真正开始执行批量插入。

看完 SqlMapClientCallback 里面的逻辑，现在我们来查看 SqlMapClientTemplate.execute 代码逻辑。

查看时序图可知，在真正执行 SqlMapClientCallback 回调方法逻辑时，这个时候会首先从 DataSource 获取 Connection， 然后后面开始执行 SqlMapClientCallback 回调逻辑，最后释放 Connection。这个过程中若 SqlMapClientCallback 方法执行时间过久，如我们的方法中调用 for 循环中每次都会发生一次 Dubbo 调用，然后由于这个循环需要遍历 20 多 W 数据，这就导致该循环结束就需要半个多小时(假设一次 dubbo 调用耗时 10 ms)，而我们 mysql server wait_timeout 为 300s，所以 mysql server 提前主动释放空闲连接，然后等到真正执行批量插入时，就会导致上面的异常。

题外话：mysql jdbc 使用 Batch 插入时，需要设置 rewriteBatchedStatements=true 参数。若没有设置，其最后等效使用一次 for 循环插入数据，并不能提升插入的效率。