OceanBase 数据库中启用 pkt-nio 功能时 RPC 的 fly_ts 耗时长的原因

• OceanBase 数据库从 V4.2.1 BP3、V4.2.3、V4.3 开始的版本这条日志，在 send_timestamp 之后，增加打印了 peer="xxx.xxx.xxx.xxx:xxxx", sz=xxx 的信息：

  WDIAG [RPC] create (ob_poc_rpc_server.cpp:141) [16163][pnio1][T0][xxxxx-xxxxx-xxxxx-xxxxx] [lt=28][errcode=0] PNIO packet wait too much time between proxy and server_cb(pcode=5402, fly_ts=1000162, send_timestamp=1713240251458326, peer="xxx.xxx.xxx.xxx:xxxx", sz=xxx)
  

• OceanBase 数据库 V4.1 和之前的版本使用 easy 框架处理 RPC，可参见 packet fly cost too much time 进行排查。

1. 两台机器之间时钟不同步，使用 clockdiff IP 命令来确认。

2. 网络延迟大，通过 ping 大包来确认。

3. 系统负载高导致，网络、CPU、内存使用异常。

4. OBServer 进程被 gdb 或者 pstack 了，导致线程被暂停。

具体可参考 packet fly cost too much time 。

上述，第 1、2 种情况，两台机器之间的 fly_ts 通常为一个恒定范围的值，而且 fly_ts 的日志会持续打印。

• 查看 fly_ts 日志中关于 fly_ts 耗时长的 RPC 的发送端地址有哪些。

• 问题可能出现在打印了 fly_ts 的 OBServer（RPC 接收端）上，也可能出现在发送端的 OBServer 上。

  • 如果对端地址属于不同的 OBServer，大概率是接收端的问题，优先在出现了 fly_ts 的 OBServer 上进行排查。

  • 如果发送端地址只有一个，大概率是这个发送端的问题，优先到这个地址的 OBServer上，按照后续步骤查看相关日志和监控进行排查。

    • 例如，在测试环境中，一个 IP 上可能会起多个 OBServer，这时候就不好确定地址是否属于不同的 OBServer，需要执行 lsof -i:port，来确认这个 port 是属于哪个 OBServer 进程的。

• 如果 fly_ts > 500ms，如果是网络框架层的原因导致的延迟，发送端或者接收端 pkt-nio 层通常会打印 delay_warn 的相关日志。

• 如果打印的带有 delay_warn 的日志里，只有 [delay_warn] pktc_flush_cb delay high: xxx start_us=xxx 或者 [delay_warn] pkts_flush_cb delay high: xxx start_us=xxx 这样的，基本都是 socket 上数据读写慢导致的。

  • 可能的原因罗列如下。

  1. 主备库之间设置了网络限速，打印 fly_ts 日志的线程名都是 pnio2，pcode 为 0x853（OB_LS_FETCH_LOG2），搜索 set ratelimit as 日志可以看到 server 限制的带宽。

  2. tc 设置了延迟，因为 RPC 的流量压力比较大导致了延迟放大。

  3. tc/iptables 限制了带宽或者网络本身的带宽不够，而上层发 RPC 的压力比较大，导致了延迟。

  4. socket 的对端没有及时 read 数据，可能是对端网络 IO 线程 hung 住或者执行慢，需要根据对端的日志中进行排查。 在 delay_warn 里打印对端的地址。

  2 和 3 在表现上是相同的，都和上层发送 RPC 的压力相关，对于 pkt-nio 来说没办法区分是哪一种情况，因为都是 socket 发送缓冲区上的数据消耗得慢，最终导致 RPC 请求积压在发送队列上。

• 如果还有 [delay_warn] eloop handle events delay high 和 [delay_warn] cost too much time: xxx, procedure: xxx 的日志，说明是网络 IO 线程中有一些调用占据了过长的时间，导致 IO 线程没有来得及去处理其它 RPC 请求。这两条日志会打印是什么过程导致了耗时（包括执行 RPC 回调、deliver 接收到的 RPC 请求、内存申请、read 系统调用、write 系统调用）。

  过程	[delay_warn] eloop handle events delay high 的日志	[delay_warn] cost too much time: xxx, procedure: xxx 的日志
  执行RPC回调	client_cb= '一个比较长的时间'	procedure: pn_pktc_resp_cb
  deliver 接收到的 RPC 请求	server_process=	procedure: pn_pkts_handle_func
  内存申请	malloc=	procedure: mod_alloc
  read 系统调用	read=	procedure: sk_read
  write 系统调用	write=	procedure: sk_writev

  • deliver 接收到的 RPC 请求是指网络 IO 线程从 socket 里读到数据后，解析成 ObRequest 并 deliver 到租户队列的过程，这时候可以继续搜索 rpc_serve_cb、rpc_request_create 的日志，结合代码进行排查。

  • 对于 read 系统调用或者 write 系统调用耗时长的问题，通常是系统可用内存不足、触发了内存直接回收导致的慢（ xxx），这时在网络探活中也有相关日志的打印。

    grep -rn "net_keepalive" observer.log |grep "cost too much time"
    

适用版本

OceanBase 数据库 V4.1.x,V4.2.x 版本。