生產系統 SQL 執行異常原因分析

程式通事發表於2018-10-09

起因

最近一段時間,生產系統持續碰到一些資料庫異常,導致 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 預設30sThe 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 預設60sThe 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的設定

如果覺得好的話,請幫作者點個讚唄~ 謝謝

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

生產系統 SQL 執行異常原因分析

來源:https://juejin.im/post/5bbca6ede51d450e6d0122bb

相關文章