1.问题现象
某客户反馈,在其某个验收环境,业务同学在进行普通的业务测试时(非性能压测场景),某个微服务在进行数据库操作时频繁出现异常,微服务日志提示其底层原因是:
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.问题背景
该环境数据库服务端OceanBase 版本为observer 4.2.1.x,而微服务使用的OceanBase JDBC驱动版本为1.1.7。从OB官方了解到,1.1.7及之前版本的OceanBase JDBC驱动,是容易有这个连接异常断开的问题,OB 官方给的方案是升级 JDBC 驱动,建议至少使用2.4.x以上的版本。 但客户反馈,其它环境包括生产环境,有些微服务使用了相同版本的 OceanBase JDBC 驱动,数据库服务端也使用了相同版本的OceanBase,但基本都没有出现该问题,或出现该问题的频率很低,仍希望我们能排查下是否有其它原因,比如是否跟数据库或操作系统的具体配置,甚至网络状况有关,希望能够在短时间内不升级驱动的情况下,通过调整参数缓解该问题。
3.问题初步分析
- 异常com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure 其实指的就是 TCP 连接异常断开,但从从上述报错日志来看,微服务上次成功收到来自obproxy的数据包是 15 毫秒之前,微服务上次成功发送数据包到 obproxy是1毫秒之前,时间都很短,而且我们业务流量不大(场景是正常业务测试,非性能压测),初步推测可能不是网络丢包问题,而是 obproxy 或 服务器的配置问题。
- 为排除网络问题,我们通过 ping 初步测试了下该环境的网络状况,结果数据如下,可以看到,内网环境网络状况良好,延迟很低且没有丢包:
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 连接异常断开的原因比较复杂,除了跟客户端 jdbc 驱动版本和服务端obproxy 版本有关,也跟数据库的具体配置,客户端与服务端的操作系统的具体配置,甚至网络情况有关。
- 由于相关配置参数太多,为快速排查确认问题,我们准备先从网络数据包上进行分析。
- 经过协调,我们首先在微服务端使用 “tcpdump -i any port 2883 -w 2883.pcap” 抓取了约5分钟的网络包,通过微服务日志可以确认,5分钟内出现了上述问题,即 com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure。
- 通过 wireshark 打开上述命令抓取的 pcap网络包后,查看发现有些TCP连接确实是通过 RST 异常关闭的,如下图所示,注意这里的 2883端口即服务端 obproxy的监听端口:
图片
- 为进一步确认问题,我们又协调在 obproxy 服务端也进行了抓包,通过 wireshark 打开抓取的 pcap网络包后,发现其现象跟客户端一致, 即有些TCP连接确实是通过 RST 异常关闭的, 如下图所示,注意这里的 2883端口即服务端 obproxy的监听端口:
图片
按照客户端抓包结果来梳理下:
- 在TCP连接成功创建并正常使用的过程中,微服务通过ob jdbc驱动发送了SQL请求到服务端 obproxy;
- 在约0.001448秒后,服务端 obproxy (2883端口)主动发送了 [FIN,ACK] 信号来关闭该 tcp 连接,这是第一个不太正常的地方,因为正常情况下,obproxy 不会主动关闭 tcp 连接;
- 在约0.03107秒后,微服务收到了来自 obproxy 的 [FIN,ACK] 的关闭连接信号后,并回复了 [PUSH,ACK] 信号以确认收到了关闭连接的信号;
- 在约 0.000033秒后,微服务[FIN,ACK] 来关闭该 TCP 连接,这是第二个不太正常的地方,因为正常情况下,微服务在等待来自服务端的SQL执行结果时,是不会主动关闭 tcp 连接的;
- 在约0.000172秒和0.000043秒后,服务端 obproxy (2883端口)主动发送了两个 [RST] 信号来重置该 tcp 连接;(结合服务端抓包可知,这两个 [RST] 其实分别是对客户端发送的[PUSH,ACK] 和 [FIN,ACK] 数据包的响应);
至此问题的直接原因确认了,不是网络超时或网络丢包引起的,而是 obproxy 因为某种原因,主动发送了[FIN,ACK]来断开连接!
- 进一步跟踪该TCP流,发现 obproxy 在此之前其实有回复异常信息给客户端:“HY000ORA-01000: maximum open cursors exceeded“,如下图所示:
图片
- 进一步通过命令show parameters like '%cursor%' 查看发现,该环境中 open_cursors 参数被配置为 50,而其它没有此类报错的环境中,该参数被配置为500甚至1500!
- 所以该问题的根本原因是,该环境中该 open_cursors参数配置值过低,当某个会话底层实际打开的游标数大于该参数值时,服务端 observer出于自我保护的原因,就发送 [FIN] 主动关闭了该 TCP 连接!这也解释了为什么客户端,会发现频繁创建新的 JDBC 连接的相关日志。
- open_cursors 参数说明如下:”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.问题解决
在该验收环境中,使用命令“alter system set open_cursors=1500;”,将该参数open_cursors的值从50改到1500,问题成功解决。另经咨询DBA,相关规范如下:
- 参数open_cursors:【租户级别生效】,用于设置单个session打开的游标数量,默认是50,太小容易出现ORA-01000 maxium open cursors exceeded ,可根据情况情况修改,计算公式如下:租户内存(64G)*_temporary_file_io_area_size(5%)/宏块(2m) =1600, 修改命令如下: alter system set open_cursors=1500;
- 参数temporary_file_io_area_size:【租户级别生效】,SQL中间结果(比如hash join)在存储层能使用的总大小,可适当调大(租户级别参数,需要通过sys租户来调整),修改命令如下:alter system set "_temporary_file_io_area_size" = 5;
6.问题跟进
- 微服务的异常日志打印逻辑需要优化下,当前的日志揭示了底层原因是 “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”,这个最底层的原因也需要体现在日志中,以方便问题排查;
- 后续微服务需要升级 OB JDBC 驱动版本,建议升级为官方建议的最低版本,比如 OB JDBC 驱动2.4.3;