java.sql.SQLRecoverableException: IO Error: Socket read timed out 排查歷程

一:

12c遷移19c工程，針對(duì)大數(shù)據(jù)相關(guān)定時(shí)作業(yè)進(jìn)行性能對(duì)比，發(fā)現(xiàn)部分作業(yè)連接19c 出現(xiàn) Socket read timed out 問(wèn)題，并且可以復(fù)現(xiàn)，該部分作業(yè)連接12c并無(wú)異常

初步排查情況如下：

1)在執(zhí)行到某部分sql時(shí)jdbc拋出Error: java.io.IOException: SQLException in nextKeyValue 錯(cuò)誤，導(dǎo)致的原因是Caused by: java.sql.SQLRecoverableException: IO Error: Socket read timed out 

2）jdbc堆棧信息無(wú)ora錯(cuò)誤，看起來(lái)是一個(gè)客戶端單方面錯(cuò)誤

3）連續(xù)查看幾次報(bào)錯(cuò)日志，發(fā)現(xiàn)每次報(bào)錯(cuò)都是在發(fā)起sql后的第11分鐘才拋出異常，詢問(wèn)客戶是否有進(jìn)行timeout相關(guān)測(cè)試，客戶反饋連接串中未設(shè)置任何參數(shù)

4）對(duì)該場(chǎng)景進(jìn)行重現(xiàn)測(cè)試，發(fā)現(xiàn)客戶端報(bào)出Socket read timed out，數(shù)據(jù)庫(kù)會(huì)話依然在執(zhí)行直到sql執(zhí)行結(jié)束

5）關(guān)于socket read timed out初步了解到是客戶端在向數(shù)據(jù)庫(kù)發(fā)起查詢時(shí)等待數(shù)據(jù)返回時(shí)超過(guò)了某個(gè)時(shí)間限制導(dǎo)致超時(shí)

6）了解到j(luò)dbc driver版本是11.2.0.1.0

二：

1)jdbc driver 版本11.2.0.1是不兼容19c，建議客戶先進(jìn)行升級(jí)測(cè)試

2）需要進(jìn)一步排查網(wǎng)絡(luò)是否有超時(shí)設(shè)置

3）通過(guò)以上步驟來(lái)縮小排查范圍

2.討論進(jìn)展如下：

1）客戶否認(rèn)網(wǎng)絡(luò)存在問(wèn)題，但我認(rèn)為是否可以繼續(xù)進(jìn)行抓包排查

2）客戶表示驅(qū)動(dòng)包問(wèn)題可以進(jìn)行升級(jí)驅(qū)動(dòng)測(cè)試，確認(rèn)是否驅(qū)動(dòng)包問(wèn)題

3）提出每次報(bào)錯(cuò)都是在第11分鐘開(kāi)始報(bào)錯(cuò)，客戶提出可能應(yīng)用平臺(tái)有配置過(guò)10分鐘的超時(shí)設(shè)置，開(kāi)發(fā)排查代碼發(fā)現(xiàn)有10分鐘超時(shí)設(shè)置，后面增加超時(shí)時(shí)間再進(jìn)行測(cè)試，發(fā)現(xiàn)不再報(bào)錯(cuò)

4)客戶存在疑問(wèn)，為何同樣的配置在12c不生效，而在19c能夠生效

5）現(xiàn)場(chǎng)同時(shí)排查了數(shù)據(jù)庫(kù)端sqlnet參數(shù)，12c和19c并無(wú)差別

三：

1）詢問(wèn)中間件同事，表示針對(duì)不同數(shù)據(jù)庫(kù)版本可能會(huì)有不同的超時(shí)時(shí)間設(shè)置，這一點(diǎn)找不到相關(guān)資料，詢問(wèn)sr，gcs表示沒(méi)有不同的設(shè)置說(shuō)法

2）中間件同事和sr同時(shí)也建議排查操作系統(tǒng)層，目前只能看到數(shù)據(jù)庫(kù)端os，目前看到的網(wǎng)絡(luò)相關(guān)參數(shù)不確認(rèn)。

3)客戶在測(cè)試環(huán)境使用11.2.0.4版本jdbc 進(jìn)行測(cè)試，發(fā)現(xiàn)同樣在12c不會(huì)超時(shí)，而在19c會(huì)出現(xiàn)超時(shí)

4）為了排除數(shù)據(jù)版本不同造成socket超時(shí)不生效原因，我使用一段java代碼指定不同版本的jdbc driver 分別連接12c和19c 進(jìn)行查詢操作一段，設(shè)置socket timeout 時(shí)間為10s，發(fā)現(xiàn)11.2.0.1和11.2.0.4 的jdbc driver 連接12c和19c 查詢超過(guò)10s后 都能出現(xiàn)超時(shí)情況，進(jìn)一步可以說(shuō)明超時(shí)是否生效與數(shù)據(jù)庫(kù)版本無(wú)關(guān)，同時(shí)也和jdbc版本無(wú)關(guān)，所以問(wèn)題還是出現(xiàn)在應(yīng)用端配置上，將此情況向客戶反饋。

四：

1)將java測(cè)試代碼 readtimeout 從10秒鐘調(diào)整為10分鐘，看是否能復(fù)現(xiàn)客戶的問(wèn)題。

2）調(diào)整為10分鐘進(jìn)行測(cè)試，結(jié)果是19c 正常10分鐘超時(shí)，12c 10分鐘超時(shí)。

3）與gcs jdbc 工程師討論，懷疑12c超時(shí)不生效是因?yàn)榭蛻舳藄ocket api在監(jiān)測(cè)時(shí)不斷接收到數(shù)據(jù)包，導(dǎo)致超時(shí)時(shí)間被不斷延長(zhǎng)。

4）協(xié)調(diào)系統(tǒng)工程師進(jìn)行連接12c和19c的網(wǎng)絡(luò)抓包測(cè)試，發(fā)現(xiàn)連接12c時(shí)，db端每2分鐘會(huì)發(fā)送一個(gè)10 bytes的tns包到client端，隨后client端會(huì)返回ack包。而連接19c時(shí)，db端每2分鐘發(fā)送一個(gè)keep-alive包到client端。從db端來(lái)看，目前配置了sqlnet.expire_time=2,可能與此有關(guān)。

5）與gcs工程師討論，12c為何timeout不生效就應(yīng)該是定時(shí)tns包影響，而19c timeout生效是因?yàn)閗eep-alive 包是相對(duì)比較底層的數(shù)據(jù)包，client端操作系統(tǒng)直接過(guò)濾掉。

五：

1）查詢文檔 Oracle Net 12c: Changes to the Functionality of Dead Connection Detection (DCD) (Doc ID 1591874.1) 發(fā)現(xiàn) 在12c后 ，開(kāi)啟dcd后db端檢測(cè)死連接的方式是從每n分鐘發(fā)送10 bytes tns包改成了 tcp keep-alive包，這里可以解釋19c網(wǎng)絡(luò)抓包中看到的每2分鐘一個(gè)的keep-alive包。

2）但目前來(lái)看，連接12c是使用了傳統(tǒng)的tns包，而19c是使用了新的keep-alive包， 從文檔1591874.1中看是12.1之后就默認(rèn)使用了新的模式，但如果操作系統(tǒng)不支持或者認(rèn)為設(shè)定，可以改為傳統(tǒng)發(fā)送tns包的模式，目前12c是solaris 11.3操作系統(tǒng)，是支持keep -alive的，理論是應(yīng)該支持新模式的，目前找不到更多資料說(shuō)明，這仍是是個(gè)謎團(tuán)。