起因
最近一段時間，生產系統持續碰到一些數據庫異常，導致 sql 執行失敗。
應用環境
Java 1.7 + Mysql 5.6 + spring + ibatis
問題排查
將各種失敗的異常記錄了一下，碰到最多下面幾種異常。
- java.net.SocketTimeoutException: Read timed out
- java.sql.BatchUpdateException: No operations allowed after statement closed。
- 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 異常會因為其他底層異常導致如以下這兩種異常。
- 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
剛開始碰到該異常，根據 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 這兩個參數。
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 循環插入數據，並不能提升插入的效率。
參考
- JDBC 驅動程序類型
- Understanding JDBC Internals & Timeout Configuration
- 深入理解 JDBC 的超時
- 深入分析JDBC超時機制
- mysql: show processlist 詳解
- 聊聊jdbc socketTimeout的設置
如果覺得好的話，請幫作者點個贊唄~ 謝謝
喜歡本文的讀者們，歡迎長按關注訂閱號程序通事~讓我與你分享程序那些事。
