【OceanBase诊断调优】—— 断连接问题根因分析

背景

当前用户请求执行的链路主要如下，请求从客户端发送到ObProxy，ObProxy将请求路由到对应的ObServer节点，ObServer处理请求发送回包给ObProxy，ObProxy回给客户端。目前整条链路上都可能发生断连接的场景，比如请求处理时间较长客户端长时间没有收到回包断开连接、用户登录填写错误的集群租户等导致无法登录、ObProxy以及ObServer的内部错误导致断开连接等等。

当断连接发生的时候，用户最直接得到的信息是ObServer返回的错误包提示，用户可以根据错误包的提示作初步的排查，这里提供的信息往往比较少，用户很难确定问题，而且一部分场景下用户无法得到错误包提示，需要排查整条链路上的问题。ObProxy针对断连接问题，提供断连接的诊断信息记录。

断连接诊断方法说明

诊断流程

诊断日志

当发生断连接之后ObProxy会记录一段断连接日志，记录到obproxy_diagnosis.log中，这里会详细记录断连接相关的信息。

以租户名错误为例：

[2023-08-23 20:11:08.567425] [109316][Y0-00007F285BADB4E0] [CONNECTION](trace_type="LOGIN_TRACE", connection_diagnosis={cs_id:1031798792, ss_id:0, proxy_session_id:0, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:58218", server_addr:"*Not IP address [0]*:0", cluster_name:"undefined", tenant_name:"test", user_name:"root", error_code:-4043, error_msg:"dummy entry is empty, please check if the tenant exists", request_cmd:"COM_SLEEP", sql_cmd:"COM_LOGIN"}{internal_sql:""})

这里的错误码遵循以下的格式：

• LOG_TIME：日志打印时间
• TID：线程ID
• TRACE_ID：trace_id，可以通过trace_id与其他日志进行关联
• CONNECTION：代表这条日志为连接诊断相关的日志
• trace_type：诊断类型，目前诊断日志有以下几种类型，不同的诊断类型也对应不同的断连接问题
• CS_ID：OBProxy内部标识客户端连接的ID
• SS_ID：OBProxy内部标识OBProxy与OBServer之间连接的ID
• PROXY_SS_ID：由OBProxy生成的标识客户端连接的ID，会传递给OBServer，可以用来筛选ObServer日志或者sql_audit表
• SERVER_SS_ID：由OBServer生成的标识OBProxy与OBServer之间连接的ID
• CLIENT_ADDR：客户端的IP地址
• SERVER_ADDR：出错或者断连接时对应的OBServer节点的地址
• CLUSTER_NAME：集群名
• TENANT_NAME：租户名
• USER_NAME：用户名
• ERROR_CODE：错误码
• ERROR_MSG：错误信息，诊断断连接的关键内容
• REQUEST_CMD：obproxy当前正在执行的sql语句的类型，可能为内部请求的sql语句类型
• SQL_CMD：用户sql语句的类型
• FIELD_1：额外诊断信息，TRACE_TYPE决定
• FIELD_1_CONTENT：额外诊断内容，TRACE_TYPE决定
• FIELD_2：额外诊断信息，TRACE_TYPE决定
• FIELD_2_CONTENT：额外诊断内容，TRACE_TYPE决定

常见断连接场景

登录断连接

对应trace_type：LOGIN_TRACE

租户名错误诊断日志示例：

[2023-09-08 10:37:21.028960] [90663][Y0-00007F8EB76544E0] [CONNECTION](trace_type="LOGIN_TRACE", connection_diagnosis={cs_id:1031798785, ss_id:0, proxy_session_id:0, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:xxxx", server_addr:"*Not IP address [0]*:0", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10018, error_msg:"fail to check observer version, empty result", request_cmd:"COM_SLEEP", sql_cmd:"COM_LOGIN"}{internal_sql:"SELECT ob_version() AS cluster_version"})

额外诊断信息

internal_sql：obproxy当前执行的内部请求

用户侧使用问题

部署错误

OB侧错误

超时断连接

对应trace_type：TIMEOUT_TRACE

集群过期发起断连接诊断日志示例：

[2023-08-17 17:10:46.834897] [119826][Y0-00007FBF120324E0] [CONNECTION](trace_type="TIMEOUT_TRACE", connection_diagnosis={cs_id:1031798785, ss_id:7, proxy_session_id:7230691830869983235, server_session_id:3221504994, client_addr:"xxx.xxx.xxx.xxx:42468", server_addr:"xxx.xxx.xxx.xxx:xxxx", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10022, error_msg:"OBProxy inactivity timeout", request_cmd:"COM_SLEEP", sql_cmd:"COM_END"}{timeout:1, timeout_event:"CLIENT_DELETE_CLUSTER_RESOURCE", total_time(us):21736})

额外诊断信息：

timeout_event：超时事件

total_time：请求执行时间

ObServer主动断开连接

应trace_type: SERVER_VC_TRACE

ObProxy与ObServer建连失败诊断日志示例：

[2023-08-10 23:35:00.132805] [32339][Y0-00007F74C9A244E0] [CONNECTION](trace_type="SERVER_VC_TRACE", connection_diagnosis={cs_id:838860809, ss_id:0, proxy_session_id:7230691830869983240, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:45765", server_addr:"", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10013, error_msg:"Fail to build connection to observer", request_cmd:"COM_QUERY", sql_cmd:"COM_HANDSHAKE"}{vc_event:"unknown event", total_time(us):2952626, user_sql:"select 1 from dual"})

外诊断信息：

vc_event：断连接相关的事件，用户不需要太关注

total_time：请求执行时间

user_sql：用户请求

ObServer主动断连接的场景ObProxy没有办法收集更为详细的信息，如果ObProxy配置的ObServer节点状态正常则需要配合ObServer的日志进行诊断。

客户端主动断连接

客户端主动断连接日志记录

对应trace_type: CLIENT_VC_TRACE

ObProxy读请求时断开客户端连接诊断日志示例：

[2023-08-10 23:28:24.699168] [32339][Y0-00007F74C9A244E0] [CONNECTION](trace_type="CLIENT_VC_TRACE", connection_diagnosis={cs_id:838860807, ss_id:26, proxy_session_id:7230691830869983239, server_session_id:3221698209, client_addr:"xxx.xxx.xxx.xxx:44701", server_addr:"xxx.xxx.xxx.xxx:xxxx", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10010, error_msg:"An EOS event received from client while obproxy reading request", request_cmd:"COM_SLEEP", sql_cmd:"COM_END"}{vc_event:"VC_EVENT_EOS", total_time(us):57637, user_sql:""})

额外诊断信息：

vc_event：断连接相关的事件，用户不需要太关注

total_time：请求执行时间

user_sql：用户请求

客户端断连接的场景ObProxy没有办法收集更为详细的信息，只能指出客户端方面主动断开连接的操作，比较常见的断连接问题有驱动超时主动断开连接、Druid/Hikaricp/Nginx等中间件主动断连接、网络抖动等问题

ObProxy/ObServer内部错误

一般内部错误

对应trace_type：PROXY_INTERNAL_TRACE / SERVER_INTERNAL_TRACE

诊断日志示例：

[2023-08-10 23:26:12.558201] [32339][Y0-00007F74C9A244E0] [CONNECTION](trace_type="PROXY_INTERNAL_TRACE", connection_diagnosis={cs_id:838860805, ss_id:0, proxy_session_id:7230691830869983237, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:44379", server_addr:"", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10019, error_msg:"OBProxy reached the maximum number of retrying request", request_cmd:"COM_QUERY", sql_cmd:"COM_QUERY"}{user_sql:"USE `ý<8f>ý<91>ý<92>`"})

额外诊断信息：

user_sql：用户请求sql

其他场景

对应trace_type：PROXY_INTERNAL_TRACE

诊断日志示例：

[2023-08-10 23:27:15.107427] [32339][Y0-00007F74CAAE84E0] [CONNECTION](trace_type="PROXY_INTERNAL_TRACE", connection_diagnosis={cs_id:838860806, ss_id:21, proxy_session_id:7230691830869983238, server_session_id:3221695443, client_addr:"xxx.xxx.xxx.xxx:44536", server_addr:"xxx.xxx.xxx.xxx:xxxx", cluster_name:"undefined", tenant_name:"sys", user_name:"", error_code:-5065, error_msg:"connection was killed by user self, cs_id: 838860806", request_cmd:"COM_QUERY", sql_cmd:"COM_QUERY"}{user_sql:"kill 838860806"})

额外诊断信息：

user_sql：用户请求sql

断连接诊断示例

确定断连接方

客户请求到OB的链路比较常见的有以下两种：

客户端的请求到ObServer之间的链路可能需要经过多个节点，中间任意一个节点出现问题时候都会导致客户端的连接断开。所以当发生断连接且客户端没有收到明确的错误包提示断连接原因时，如果从整条链路上开始排查断连接问题的话首先需要确定断连接方。

如果使用的ObProxy具备连接诊断的能力，可以通过诊断日志obproxy_diagnosis.log快速判断发起断连接的一方。

用户可以根据用户名、租户名、集群名、从驱动拿到的thread_id（对应日志cs_id)等、断连接时间等信息从日志中快速筛选出对应的断连接日志，根据trace_type字段判断断连接方

• CLIENT_VC_TRACE：客户端断连接
• SERVER_VC_TRACE：ObServer主动断开连接
• SERVER_INTERNAL_TRACE / PROXY_INTERNAL_TRACE：ObServer/ObProxy内部错误上的追踪日志
• TIMEOUT_TRACE / LOGIN_TRACE：登录失败/超时这两个特殊场景的追踪日志

排查断连接原因

客户端断连接

socketTimeout场景

JDBC默认的socketTimeout配置为0，即不会产生socketTimeout超时，但是部分客户端比如Druid/MyBatis自身有控制socketTimeout的参数，如果发生请求执行时间过长导致的断连接，可以优先确认socketTimeout的配置。

1. 查看对应的obproxy连接诊断日志，确定断连接的基本信息：

[2023-09-07 15:59:52.308553] [122701][Y0-00007F7071D194E0] [CONNECTION](trace_type="CLIENT_VC_TRACE", connection_diagnosis={cs_id:524328, ss_id:0, proxy_session_id:7230691833961840700, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:38877", server_addr:"xxx.xxx.xxx.xxx:50110", cluster_name:"ob1.changluo.cc.xxx.xxx.xxx.xxx", tenant_name:"mysql", user_name:"root", error_code:-10011, error_msg:"An unexpected connection event received from client while obproxy handling request", request_cmd:"COM_QUERY", sql_cmd:"COM_QUERY"}{vc_event:"VC_EVENT_EOS", total_time(us):5016353, user_sql:"select sleep(20) from dual"})

主要诊断信息：

trace_type: CLIENT_VC_TRACE， 判断出是客户端主动断开的连接

error_msg: An unexpected connection event received from client while obproxy handling request，说明客户端在obproxy处理请求时断开连接

total_time: 5016353，请求总的执行时间为5s左右，可以通过total_time去匹配客户端的超时参数

根据诊断信息能确定是客户端主动断开了连接，需要排查客户端相关的问题。

1. 根据obproxy连接诊断日志，从客户端入手排查

查看JDBC堆栈：

The last packet successfully received from the server was 5,016 milliseconds ago.  The last packet sent successfully to the server was 5,011 milliseconds ago.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
        at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1129)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3720)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3609)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4160)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2617)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2778)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2819)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2768)
        at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:949)
        at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:795)
        at odp.Main.main(Main.java:12)
Caused by: java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:170)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3163)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3620)
     9 more

The last packet successfully received from the server was 5,013 milliseconds ago. The last packet sent successfully to the server was 5,012 milliseconds ago.Caused by: java.net.SocketTimeoutException: Read timed out 可以从堆栈以及收发包时间中大致判断这里是socketTimeout触发的问题。

ObProxy断连接

net_write_timeout超时场景（非常见场景）

obproxy会读取observer设置的net_write_timeout配置，控制收包和发包时传包的超时时间，该配置默认时间为60s，当网络环境比较极端或者observer回包处理较慢时可能会出现obproxy net_write_timeout超时断连接的问题

1. 根据obproxy断连接诊断日志判断断连接方

[2023-09-08 01:22:17.229436] [81506][Y0-00007F455197E4E0] [CONNECTION](trace_type="TIMEOUT_TRACE", connection_diagnosis={cs_id:1031798827, ss_id:342, proxy_session_id:7230691830869983244, server_session_id:3221753829, client_addr:"xxx.xxx.xxx.xxx:34901", server_addr:"xxx.xxx.xxx.xxx:21102", cluster_name:"undefined", tenant_name:"mysql", user_name:"root", error_code:-10022, error_msg:"OBProxy inactivity timeout", request_cmd:"COM_QUERY", sql_cmd:"COM_QUERY"}{timeout(us):6000000, timeout_event:"CLIENT_NET_WRITE_TIMEOUT", total_time(us):31165295})

主要诊断信息：

trace_type: TIMEOUT_TRACE， 判断出ObProxy因为超时主动断开连接

timeout_event: CLIENT_NET_WRITE_TIMEOUT，判断出obproxy因为net_write_timeout超时断连接

根据诊断信息就能确定这里触发了net_write_timeout，客户端连接等待数据超过6s（非默认值），导致连接断开，通过修改系统变量延长超时限制可以暂时规避。

登录失败

rootservice_list指定的observer不可用

1. 排查诊断日志

[2023-09-08 10:37:21.028960] [90663][Y0-00007F8EB76544E0] [CONNECTION](trace_type="LOGIN_TRACE", connection_diagnosis={cs_id:1031798785, ss_id:0, proxy_session_id:0, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:44018", server_addr:"*Not IP address [0]*:0", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-10018, error_msg:"fail to check observer version, empty result", request_cmd:"COM_SLEEP", sql_cmd:"COM_LOGIN"}{internal_sql:"SELECT ob_version() AS cluster_version"})

主要诊断信息：

trace_type:LOGIN_TRACE，确定这里登录失败的问题

internal_sql:SELECT ob_version() AS cluster_version，确定登录过程中obproxy执行该内部请求失败

error_msg:fail to check observer version, empty result，确定这里内部请求失败的原因为结果集为空

这里看到proxy执行内部请求 "SELECT ob_version() AS cluster_version" 失败，结果集为空，这条sql是obproxy查询集群版本的请求，用户首次登录时obproxy会执行这条请求校验集群信息，当obproxy启动时配置的rootservice_list错误或者observer宕机时，obproxy查询失败，即导致登录失败。

客户端连接数达obproxy上限

1. 排查诊断日志

[2023-09-08 11:19:26.617385] [110562][Y0-00007FE1F06AC4E0] [CONNECTION](trace_type="LOGIN_TRACE", connection_diagnosis={cs_id:1031798805, ss_id:0, proxy_session_id:0, server_session_id:0, client_addr:"xxx.xxx.xxx.xxx:40004", server_addr:"*Not IP address [0]*:0", cluster_name:"undefined", tenant_name:"sys", user_name:"root", error_code:-5059, error_msg:"Too many sessions", request_cmd:"COM_SLEEP", sql_cmd:"COM_LOGIN"}{internal_sql:""})

主要诊断信息：

trace_type:LOGIN_TRACE，确定这里登录失败的问题

error_msg:Too many session，确定这里因为连接数达到上限导致登录失败

1. 直接根据错误包判断

$ obclient -hxxx.xxx.xxx.xxx -P2899 -uroot@sys -Dtest -A -c 
ERROR 1203 (42000): Too many sessions

如何借助obdiag来快速分析断连问题

使用示例

目前obdiag支持了断连问题的场景，目前支持obproxy 4.2.2.0及之后的版本。

obdiag rca run --scene=disconnection --input_parameters='{"since":"1d"}'

input_patameters是一个用于输入不同根因分析场景下需要引入的变量赋值，输入对象的应该为一个json格式的字符串用于解析。

since代表需要往回追溯的时间，默认为30分钟

record示例：

如图为一次断联的排查，确认了事件类型为CLIENT_VC_TRACE，判断出是客户端主动断开的连接，需要客户端配合去进行诊断。

后续场景升级

目前基于obproxy已有日志进行排查，后续将逐步进行深入的根因分析

有兴趣的DBA和开发者可以加入obdiag SIG进行共建开发。

技术支持

排查思路及流程感谢 怀有（潘锐鸿） 提供。

附录

•obdiag 下载地址： https://www.oceanbase.com/softwarecenter

•obdiag 官方文档： https://www.oceanbase.com/docs/obdiag-cn

•obdiag github地址： GitHub - oceanbase/obdiag: obdiag (OceanBase Diagnostic Tool) is designed to help OceanBase users quickly gather necessary information and analyze the root cause of the problem.

•obdiag SIG 营地： [obdiag SIG] 诊断工具组 · OceanBase 技术交流