生產系統 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 循環插入數據，並不能提高插入的效率。

參考

1. JDBC 驅動程序類型
2. Understanding JDBC Internals & Timeout Configuration
3. 深刻理解 JDBC 的超時
4. 深刻分析JDBC超時機制
5. mysql: show processlist 詳解
6. 聊聊jdbc socketTimeout的設置

---

若是以爲好的話，請幫做者點個讚唄~ 謝謝

喜歡本文的讀者們，歡迎長按關注訂閱號程序通事~讓我與你分享程序那些事。