• 生产系统 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 其他超时时间,mysql 其他超时时间

    从上图可以注意到 net_read_timeoutnet_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 方法
    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 代码逻辑。
    https://www.ibm.com/developerworks/cn/java/j-lo-ibatis-principle/index.html

    查看时序图可知,在真正执行 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 循环插入数据,并不能提升插入的效率。

    参考

    1. JDBC 驱动程序类型
    2. Understanding JDBC Internals & Timeout Configuration
    3. 深入理解 JDBC 的超时
    4. 深入分析JDBC超时机制
    5. mysql: show processlist 详解
    6. 聊聊jdbc socketTimeout的设置

    如果觉得好的话,请帮作者点个赞呗~ 谢谢

    喜欢本文的读者们,欢迎长按关注订阅号程序通事~让我与你分享程序那些事。

  • 相关阅读:
    设计模式-抽象工厂
    设计模式-工厂方法
    设计模式-简单工厂
    设计模式-单例模式
    设计模式使用指南
    适合Java程序员看的UML学习手册
    第六周 Java8新特性
    deepin15.11系统使用罗技k380键盘
    动态规划系列之六01背包问题
    《比勤奋更重要的是底层思维》
  • 原文地址:https://www.cnblogs.com/goodAndyxublog/p/10104578.html
Copyright © 2020-2023  润新知