通过wireshark分析tcpdump网络数据包进而快速排查解决某环境OceanBase频现的TCP连接异常断开问题

网络 网络管理
TCP 连接异常断开的原因比较复杂,除了跟客户端 jdbc 驱动版本和服务端obproxy 版本有关,也跟数据库的具体配置,客户端与服务端的操作系统的具体配置,甚至网络情况有关。

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;

7.参考链接

责任编辑:武晓燕 来源: 明哥的IT随笔
相关推荐

2019-04-29 07:53:11

TCP数据包TCP网络编程

2011-11-28 16:03:49

wireshark数据包

2020-09-03 15:32:08

Wireshark数据包分析

2020-11-23 10:25:44

tcpdump数据包Linux

2021-07-15 09:57:39

Wireshark数据包长度

2017-08-22 11:30:15

LinuxWireshark过滤数据包

2022-01-14 10:59:07

数据包tcpdump

2013-05-24 08:56:23

VMware虚拟机数据包

2018-09-26 10:45:01

Linux命令tcpdump

2010-04-22 10:07:04

Windows 7本地连接

2013-05-24 09:05:50

Linux虚拟机网络设置VMware网络设置

2014-07-09 09:43:59

2023-11-01 08:04:08

WiresharkTCP协议

2013-01-28 13:32:52

路由器网络设置数据传输

2021-05-12 00:07:27

TCPIP协议

2024-05-08 16:44:40

TCPRST网络协议

2012-09-04 11:08:57

VMwarevSwitchvSwitch配置

2011-01-18 13:50:20

路由跟踪tcptracerou

2020-12-18 10:13:50

wireshark数据包Capture

2022-06-27 17:58:42

pwrueBPF工具
点赞
收藏

51CTO技术栈公众号