問題
對某個庫新增了一個訂閱節點,然后需要把一些應用切到新訂閱庫,以分散負載。當應用切換后,有一個應用每次啟動不到30秒,總是報超時的錯誤,而error log中又沒有任何記錄:
Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.The statement has been terminated.
但是切回連接到原來的訂閱庫就不會超時。
分析
1. 自先排查連接超時,找運維看連接配置,連接超時設定為90秒。排除之。
2. 排查語句超時,找到開發,說找不到歷史版本的源碼了,也就沒有辦法查看SqlCommand.CommandTimeout的設定值,無法繼續排查。
3. 1,2無果的情況下,用XE捕獲一下error信息,這個默認的system_health session就有:
Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration.
Time spent during login: total 2407 ms, enqueued 0 ms, network writes 0 ms, network reads 2407 ms, establishing SSL 0 ms, negotiating SSPI 0 ms, validating login 0 ms,
including user-defined login processing 0 ms.
error code 0x2746 就是10054,使用NET HELPMSG 查看,結果為:Connection forcibly closed by remote host.
好了,到此為止,我斷定問題出在應用端。於是找上開發,運維一起討論,看他們能否詳細排查應用端,結論是:沒辦法。
4. 難道真的沒有辦法了?
既然超時信息能返回到應用端,那么我可以抓包,看到底出什么事了。於是使用Network Monitor一抓:
從抓到的信息來看,圖中選中的行,正是timeout的。它前一條記錄TDS:SQLBatch 從應用端發到服務端,過了一會兒,應用端就超時了。
這就很明顯了,應用端發了一個Batch給數據庫執行,等了一下它自己就說:我超時了。問題就出在這里,它發的是什么語句,執行了多久,造成了超時。
5. 用Profiler跟蹤:
此Batch執行大約用時20s,也得到了具體的語句。
6. 但是為什么切換到原來的訂閱庫就不超時,連接新的訂閱庫就會超時呢?
將5.中抓到的語句分別在兩個實例上執行,發現新的訂閱庫返回8W+行的數據,而舊的只返回6行數據且神速。
再進一步分析語句,原來舊的訂閱庫中,有一個非訂閱表,表中有大量用於篩選的數據;但新訂閱庫只有這個表,沒有數據。
於是將此表數據導入到新訂閱庫中的對應表中,兩者查詢的一結果一致了,應用也不超時了。據此推斷應用代碼中SqlCommand.CommandTimeout絕對小於20s.
總結:
1. 10054錯誤一個很出名的錯誤,原因有多種,比較難排查的一個問題。
2. 如果能這在2. 一步就能確認SqlCommand.CommandTimeout的設定值,並做相應調試排查,將會省了很多事。源碼管理的重要性啊!
3. 做事得細心,新增訂閱后,我只對比兩者的對象是否一樣,如果也核對了表中行數是否一樣,也就不會發生這事了。