The last packet successfully received from the server was XXX milliseconds ago 問題排查

1.起因:

在半夜執(zhí)行的定時任務偶現(xiàn)The last packet successfully received from the server was 1,373,532 milliseconds ago問題,導致部分sql沒有執(zhí)行。

2.排查:

2.1 查看日志:

DruidDataSource:discard connection com.mysql.cj.jdbc.exceptions.CommunicationsException: 
Communications link failure The last packet successfully received from the server was 1,373,532 milliseconds ago. 
The last packet sent successfully to the server was 1,373,554 milliseconds ago.

查了下,這個錯誤是鏈接失敗,即druid當前使用的連接池中的線程時無效連接,mysql服務端已經(jīng)把這個連接給斷了,但是druid這邊不知道,繼續(xù)使用就報錯了。

對于這個問題,看到很多帖子都說去設置mysql服務器的wait_timeout(另外說一下wait_timeout表示通過非交互連接,例如jdbc,interactive_timeout表示交互式連接,通過mysql客戶端連接數(shù)據(jù)庫是交互式連接,通過jdbc連接數(shù)據(jù)庫是非交互式連接),但是這個參數(shù)是設置空閑連接保持連接狀態(tài)的最大秒數(shù),例如:

mysql監(jiān)控

這里如果wait_timeout設置為2355,那么這個sleep狀態(tài)的鏈接再過一秒,就會被mysql客戶端給斷掉,所以一般druid設置的檢查時間都會比這個時間短:(druid配置minEvictableIdleTimeMillis:連接保持空閑而不被驅逐的最小時間-毫秒)
另外也會有validationQuery: SELECT 'x',testWhileIdle: true這樣的設置,用于檢測鏈接是否有效;但是druid檢查有效性有兩種方法,一種是this.ping.invoke(conn, true, validationQueryTimeout * 1000);用ping的方法,這樣配置的validationQuery: SELECT 'x'就不會執(zhí)行,所以可以在客戶端啟動參數(shù)加上
-Ddruid.mysql.usePingMethod=false,就可以用配置的方法去驗證有效性。

但是!我配置了以后該偶現(xiàn)的還是偶現(xiàn),我決定看看mybatis的日志:
logback.xml配置:

// 僅XxxxDao類輸出debug日志
    <logger name="com.xxxx.xxxx.xxx.dao.XxxxDao" level="debug" additivity="false">
        <appender-ref ref="STDOUT" />
    </logger>

以下是執(zhí)行日志:

[DEBUG] 2021-07-01 01:08:53.262 [Thread-3069] queryDispatch:==> Preparing: SELECT  xxxxxx like concat(?,'%')
2021-07-01 01:08:58.826
[DEBUG] 2021-07-01 01:08:53.262 [Thread-3069] queryDispatch:==> Parameters: XXXX(String)

這里可以比較清楚的看到準備的sql和參數(shù),并且發(fā)送去了mysql,但是半天后返回了上述的報錯,這幾條日志都是同一個線程,并且這個方法用到所有的sql的連接池應該都是一個,在準備sql的日志前都有這么一句:
SpringManagedTransaction:JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@5c21e27f] will not be managed by Spring
@5c21e27f應該就是持有同一個連接的代理。

有成功時候:sql跑了30多分鐘;也有提交了語句,20分鐘后直接報錯的,這讓我覺得應該不是因為服務端設置了語句執(zhí)行最大時間的設置,去看了下果然沒限制時間:
max_execution_time 0

因為我是半夜1:00執(zhí)行,我看到這個時間有好多定時任務開始執(zhí)行,就在想會不會是數(shù)據(jù)庫壓力的關系,看到一篇文章:

connect_timeout在獲取連接階段(authenticate)起作用,

interactive_timeout和wait_timeout在連接空閑階段(sleep)起作用,

net_read_timeout和net_write_timeout在連接繁忙階段(query)起作用。

net_read_timeout / net_write_timeout 這個參數(shù)只對TCP/IP鏈接有效,分別是數(shù)據(jù)庫等待接收客戶端發(fā)送網(wǎng)絡包和發(fā)送網(wǎng)絡包給客戶端的超時時間,這是在Activity狀態(tài)下的線程才有效的參數(shù)
結合來看,此問題應該是在mysql返回給客戶端的時候超時,然后導致連接被斷。

現(xiàn)在通過更換了定時任務的執(zhí)行時間,錯峰執(zhí)行解決了這個問題。

參考:
https://blog.csdn.net/jiadajing267/article/details/79516989
https://blog.csdn.net/qq_37637196/article/details/106053558

最后編輯于
?著作權歸作者所有,轉載或內容合作請聯(lián)系作者
【社區(qū)內容提示】社區(qū)部分內容疑似由AI輔助生成,瀏覽時請結合常識與多方信息審慎甄別。
平臺聲明:文章內容(如有圖片或視頻亦包括在內)由作者上傳并發(fā)布,文章內容僅代表作者本人觀點,簡書系信息發(fā)布平臺,僅提供信息存儲服務。

相關閱讀更多精彩內容

友情鏈接更多精彩內容