生產系統 SQL 執行異常原因分析
最近一段時間，生產系統持續碰到一些資料庫異常，導致 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 這兩個引數。
ofollow,noindex">檢視 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 迴圈插入資料，並不能提升插入的效率。