1.問(wèn)題現(xiàn)象

某客戶(hù)反饋，在其某個(gè)驗(yàn)收環(huán)境，業(yè)務(wù)同學(xué)在進(jìn)行普通的業(yè)務(wù)測(cè)試時(shí)（非性能壓測(cè)場(chǎng)景），某個(gè)微服務(wù)在進(jìn)行數(shù)據(jù)庫(kù)操作時(shí)頻繁出現(xiàn)異常，微服務(wù)日志提示其底層原因是：

com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure\n\nThe last packet successfully received from the server was 9 milliseconds ago.  The last packet sent successfully to the server was 2 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor143.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.alipay.oceanbase.jdbc.Util.handleNewInstance(Util.java:439)
at com.alipay.oceanbase.jdbc.SQLError.createCommunicationsException(SQLError.java:1236)
at com.alipay.oceanbase.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:4394)
at com.alipay.oceanbase.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:4252)
at com.alipay.oceanbase.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4789)
at com.alipay.oceanbase.jdbc.MysqlIO.sendCommand(MysqlIO.java:2993)
at com.alipay.oceanbase.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1396)
at com.alipay.oceanbase.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:831)
at com.alipay.oceanbase.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2042)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:696)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:638)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:688)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:720)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:730)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:798)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:817)

2.問(wèn)題背景

該環(huán)境數(shù)據(jù)庫(kù)服務(wù)端OceanBase 版本為observer 4.2.1.x，而微服務(wù)使用的OceanBase JDBC驅(qū)動(dòng)版本為1.1.7。從OB官方了解到，1.1.7及之前版本的OceanBase JDBC驅(qū)動(dòng)，是容易有這個(gè)連接異常斷開(kāi)的問(wèn)題，OB 官方給的方案是升級(jí) JDBC 驅(qū)動(dòng)，建議至少使用2.4.x以上的版本。 但客戶(hù)反饋，其它環(huán)境包括生產(chǎn)環(huán)境，有些微服務(wù)使用了相同版本的 OceanBase JDBC 驅(qū)動(dòng)，數(shù)據(jù)庫(kù)服務(wù)端也使用了相同版本的OceanBase，但基本都沒(méi)有出現(xiàn)該問(wèn)題，或出現(xiàn)該問(wèn)題的頻率很低，仍希望我們能排查下是否有其它原因，比如是否跟數(shù)據(jù)庫(kù)或操作系統(tǒng)的具體配置，甚至網(wǎng)絡(luò)狀況有關(guān)，希望能夠在短時(shí)間內(nèi)不升級(jí)驅(qū)動(dòng)的情況下，通過(guò)調(diào)整參數(shù)緩解該問(wèn)題。

3.問(wèn)題初步分析

• 異常com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure 其實(shí)指的就是 TCP 連接異常斷開(kāi)，但從從上述報(bào)錯(cuò)日志來(lái)看，微服務(wù)上次成功收到來(lái)自obproxy的數(shù)據(jù)包是 15 毫秒之前，微服務(wù)上次成功發(fā)送數(shù)據(jù)包到 obproxy是1毫秒之前，時(shí)間都很短，而且我們業(yè)務(wù)流量不大（場(chǎng)景是正常業(yè)務(wù)測(cè)試，非性能壓測(cè)），初步推測(cè)可能不是網(wǎng)絡(luò)丟包問(wèn)題，而是 obproxy 或 服務(wù)器的配置問(wèn)題。
• 為排除網(wǎng)絡(luò)問(wèn)題，我們通過(guò) ping 初步測(cè)試了下該環(huán)境的網(wǎng)絡(luò)狀況，結(jié)果數(shù)據(jù)如下，可以看到，內(nèi)網(wǎng)環(huán)境網(wǎng)絡(luò)狀況良好，延遲很低且沒(méi)有丟包：

ping -c 10 -i 1 172.253.34.74
PING 172.253.34.74 (172.253.34.74) 56(84) bytes of data.
64 bytes from 172.253.34.74: icmp_seq=1 ttl=61 time=0.727 ms
64 bytes from 172.253.34.74: icmp_seq=2 ttl=61 time=0.231 ms
64 bytes from 172.253.34.74: icmp_seq=3 ttl=61 time=0.278 ms
64 bytes from 172.253.34.74: icmp_seq=4 ttl=61 time=0.227 ms
64 bytes from 172.253.34.74: icmp_seq=5 ttl=61 time=0.219 ms
64 bytes from 172.253.34.74: icmp_seq=6 ttl=61 time=0.227 ms
64 bytes from 172.253.34.74: icmp_seq=7 ttl=61 time=0.384 ms
64 bytes from 172.253.34.74: icmp_seq=8 ttl=61 time=0.235 ms
64 bytes from 172.253.34.74: icmp_seq=9 ttl=61 time=0.232 ms
64 bytes from 172.253.34.74: icmp_seq=10 ttl=61 time=0.331 ms
--- 172.253.34.74 ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9000ms
rtt min/avg/max/mdev = 0.219/0.309/0.727/0.148 ms。

4.問(wèn)題原因

• TCP 連接異常斷開(kāi)的原因比較復(fù)雜，除了跟客戶(hù)端 jdbc 驅(qū)動(dòng)版本和服務(wù)端obproxy 版本有關(guān)，也跟數(shù)據(jù)庫(kù)的具體配置，客戶(hù)端與服務(wù)端的操作系統(tǒng)的具體配置，甚至網(wǎng)絡(luò)情況有關(guān)。
• 由于相關(guān)配置參數(shù)太多，為快速排查確認(rèn)問(wèn)題，我們準(zhǔn)備先從網(wǎng)絡(luò)數(shù)據(jù)包上進(jìn)行分析。
• 經(jīng)過(guò)協(xié)調(diào)，我們首先在微服務(wù)端使用 “tcpdump -i any port 2883 -w 2883.pcap” 抓取了約5分鐘的網(wǎng)絡(luò)包，通過(guò)微服務(wù)日志可以確認(rèn)，5分鐘內(nèi)出現(xiàn)了上述問(wèn)題，即 com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure。
• 通過(guò) wireshark 打開(kāi)上述命令抓取的 pcap網(wǎng)絡(luò)包后，查看發(fā)現(xiàn)有些TCP連接確實(shí)是通過(guò) RST 異常關(guān)閉的，如下圖所示，注意這里的 2883端口即服務(wù)端 obproxy的監(jiān)聽(tīng)端口：

圖片

• 為進(jìn)一步確認(rèn)問(wèn)題，我們又協(xié)調(diào)在 obproxy 服務(wù)端也進(jìn)行了抓包，通過(guò) wireshark 打開(kāi)抓取的 pcap網(wǎng)絡(luò)包后，發(fā)現(xiàn)其現(xiàn)象跟客戶(hù)端一致, 即有些TCP連接確實(shí)是通過(guò) RST 異常關(guān)閉的, 如下圖所示，注意這里的 2883端口即服務(wù)端 obproxy的監(jiān)聽(tīng)端口：

圖片

按照客戶(hù)端抓包結(jié)果來(lái)梳理下：

• 在TCP連接成功創(chuàng)建并正常使用的過(guò)程中，微服務(wù)通過(guò)ob jdbc驅(qū)動(dòng)發(fā)送了SQL請(qǐng)求到服務(wù)端 obproxy；
• 在約0.001448秒后，服務(wù)端 obproxy (2883端口）主動(dòng)發(fā)送了 [FIN,ACK] 信號(hào)來(lái)關(guān)閉該 tcp 連接，這是第一個(gè)不太正常的地方，因?yàn)檎Ｇ闆r下，obproxy 不會(huì)主動(dòng)關(guān)閉 tcp 連接；
• 在約0.03107秒后，微服務(wù)收到了來(lái)自 obproxy 的 [FIN,ACK] 的關(guān)閉連接信號(hào)后，并回復(fù)了 [PUSH,ACK] 信號(hào)以確認(rèn)收到了關(guān)閉連接的信號(hào)；
• 在約 0.000033秒后，微服務(wù)[FIN,ACK] 來(lái)關(guān)閉該 TCP 連接，這是第二個(gè)不太正常的地方，因?yàn)檎Ｇ闆r下，微服務(wù)在等待來(lái)自服務(wù)端的SQL執(zhí)行結(jié)果時(shí)，是不會(huì)主動(dòng)關(guān)閉 tcp 連接的；
• 在約0.000172秒和0.000043秒后，服務(wù)端 obproxy (2883端口）主動(dòng)發(fā)送了兩個(gè) [RST] 信號(hào)來(lái)重置該 tcp 連接；(結(jié)合服務(wù)端抓包可知，這兩個(gè) [RST] 其實(shí)分別是對(duì)客戶(hù)端發(fā)送的[PUSH,ACK] 和 [FIN,ACK] 數(shù)據(jù)包的響應(yīng))；

至此問(wèn)題的直接原因確認(rèn)了，不是網(wǎng)絡(luò)超時(shí)或網(wǎng)絡(luò)丟包引起的，而是 obproxy 因?yàn)槟撤N原因，主動(dòng)發(fā)送了[FIN,ACK]來(lái)斷開(kāi)連接！

• 進(jìn)一步跟蹤該TCP流，發(fā)現(xiàn) obproxy 在此之前其實(shí)有回復(fù)異常信息給客戶(hù)端：“HY000ORA-01000: maximum open cursors exceeded“，如下圖所示：

圖片

• 進(jìn)一步通過(guò)命令show parameters like '%cursor%' 查看發(fā)現(xiàn)，該環(huán)境中 open_cursors 參數(shù)被配置為 50，而其它沒(méi)有此類(lèi)報(bào)錯(cuò)的環(huán)境中，該參數(shù)被配置為500甚至1500！
• 所以該問(wèn)題的根本原因是，該環(huán)境中該 open_cursors參數(shù)配置值過(guò)低，當(dāng)某個(gè)會(huì)話底層實(shí)際打開(kāi)的游標(biāo)數(shù)大于該參數(shù)值時(shí)，服務(wù)端 observer出于自我保護(hù)的原因，就發(fā)送 [FIN] 主動(dòng)關(guān)閉了該 TCP 連接！這也解釋了為什么客戶(hù)端，會(huì)發(fā)現(xiàn)頻繁創(chuàng)建新的 JDBC 連接的相關(guān)日志。
• open_cursors 參數(shù)說(shuō)明如下：”specifies the maximum number of open cursors a session can have at once. can use this parameter to prevent a session from opening an excessive number of cursors. Range: [0, 65535] in integer.”

圖片

5.問(wèn)題解決

在該驗(yàn)收環(huán)境中，使用命令“alter system set open_cursors=1500;”，將該參數(shù)open_cursors的值從50改到1500，問(wèn)題成功解決。另經(jīng)咨詢(xún)DBA，相關(guān)規(guī)范如下：

• 參數(shù)open_cursors:【租戶(hù)級(jí)別生效】，用于設(shè)置單個(gè)session打開(kāi)的游標(biāo)數(shù)量，默認(rèn)是50，太小容易出現(xiàn)ORA-01000 maxium open cursors exceeded ，可根據(jù)情況情況修改，計(jì)算公式如下：租戶(hù)內(nèi)存(64G)*_temporary_file_io_area_size(5%)/宏塊（2m) =1600, 修改命令如下： alter system set open_cursors=1500;
• 參數(shù)temporary_file_io_area_size：【租戶(hù)級(jí)別生效】，SQL中間結(jié)果（比如hash join）在存儲(chǔ)層能使用的總大小，可適當(dāng)調(diào)大（租戶(hù)級(jí)別參數(shù)，需要通過(guò)sys租戶(hù)來(lái)調(diào)整），修改命令如下：alter system set "_temporary_file_io_area_size" = 5;

6.問(wèn)題跟進(jìn)

• 微服務(wù)的異常日志打印邏輯需要優(yōu)化下，當(dāng)前的日志揭示了底層原因是 “com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure\n\n The last packet successfully received from the server was 9 milliseconds ago. the last packet sent successfully to the server was 2 milliseconds ago.”, 但并沒(méi)有揭示更底層的原因，即 “HY000ORA-01000: maximum open cursors exceeded”，這個(gè)最底層的原因也需要體現(xiàn)在日志中，以方便問(wèn)題排查；
• 后續(xù)微服務(wù)需要升級(jí) OB JDBC 驅(qū)動(dòng)版本，建議升級(jí)為官方建議的最低版本，比如 OB JDBC 驅(qū)動(dòng)2.4.3；

7.參考鏈接

• https://open.oceanbase.com/blog/10900349
• https://www.oceanbase.com/knowledge-base/oceanbase-database-1000000000763298
• https://segmentfault.com/a/1190000042448986/en