1.問題現(xiàn)象

某客戶反饋，在其某個驗收環(huán)境，業(yè)務(wù)同學(xué)在進(jìn)行普通的業(yè)務(wù)測試時（非性能壓測場景），某個微服務(wù)在進(jìn)行數(shù)據(jù)庫操作時頻繁出現(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.問題背景

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

3.問題初步分析

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

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.問題原因

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

圖片

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

圖片

按照客戶端抓包結(jié)果來梳理下：

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

至此問題的直接原因確認(rèn)了，不是網(wǎng)絡(luò)超時或網(wǎng)絡(luò)丟包引起的，而是 obproxy 因為某種原因，主動發(fā)送了[FIN,ACK]來斷開連接！

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

圖片

• 進(jìn)一步通過命令show parameters like '%cursor%' 查看發(fā)現(xiàn)，該環(huán)境中 open_cursors 參數(shù)被配置為 50，而其它沒有此類報錯的環(huán)境中，該參數(shù)被配置為500甚至1500！
• 所以該問題的根本原因是，該環(huán)境中該 open_cursors參數(shù)配置值過低，當(dāng)某個會話底層實際打開的游標(biāo)數(shù)大于該參數(shù)值時，服務(wù)端 observer出于自我保護的原因，就發(fā)送 [FIN] 主動關(guān)閉了該 TCP 連接！這也解釋了為什么客戶端，會發(fā)現(xiàn)頻繁創(chuàng)建新的 JDBC 連接的相關(guān)日志。
• open_cursors 參數(shù)說明如下：”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.問題解決

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

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

6.問題跟進(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.”, 但并沒有揭示更底層的原因，即 “HY000ORA-01000: maximum open cursors exceeded”，這個最底層的原因也需要體現(xiàn)在日志中，以方便問題排查；
• 后續(xù)微服務(wù)需要升級 OB JDBC 驅(qū)動版本，建議升級為官方建議的最低版本，比如 OB JDBC 驅(qū)動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