适用版本
OceanBase 数据库所有版本。
问题现象
当存在网络故障或者时钟不同步的问题时，可能会出现选举失败导致无主、系统响应慢等问题。在 observer.log 中，通常会出现 packet fly cost too much time 的告警信息。
[2023-02-09 11:01:23.964345] WARN [RPC.OBRPC] decode (ob_rpc_net_handler.cpp:72) [94639][0][Y0-0000000000000000] [lt=11] [dc=0] packet fly cost too much time(pcode=1872, fly_ts=262454880, send_timestamp=1675911421509460, connection="xxx.xxx.xxx.xxx:2882_yyy.yyy.yyy.yyy:25978_3527_0x7f1568d2c260 t=1675899635855685-1675911683964283 s=0 r=1 io=4316436113/44591866 sq=")
日志解读：从 yyy.yyy.yyy.yyy:25978（对端）发送到 xxx.xxx.xxx.xxx:2882（本机） 的 RPC packet 耗时 262454880 us，在 yyy.yyy.yyy.yyy 发包的时间戳是 1675911421509460。
问题原因
接收端收到 RPC packet 后解码时，会判断 RPC packet 的网络传输耗时，即接收到 packet 时的 recv_timestamp 减去 packet 中来自源端的 send_timestamp 的差值。当差值超过 100ms 时，OceanBase 数据库即会打印告警日志。发生该问题的原因可能是：
- 时钟不同步，对端的时钟落后，或者本端的时钟超前。
- 网络延迟，packet 在网络中的传输受到影响。
- 系统负载高导致，网络、CPU、内存使用异常。
- observer 进程被 gdb 或者 pstack 了，导致线程被暂停。
解决方法
检查时钟同步。
$ clockdiff yyy.yyy.yyy.yyy . host=yyy.yyy.yyy.yyy rtt=750(187)ms/0ms delta=1ms/1ms Fri Sep 8 11:27:56 2023 $ ntpstat synchronised to NTP server (6.x.x.xx) at stratum 3 time correct to within 17 ms polling server every 64 s $ ntpq -p|grep -E "\*|\=|remote" remote refid st t when poll reach delay offset jitter ========================================================================== *xxxxxxxxxxx xxxxx 2 u 16 64 377 1.333 0.046 0.033检查网络延迟。可以通过 ping 大包来观察。
$ ping -i 10 -s 10240 yyy.yyy.yyy.yyy PING 11.xxx.xx.xxx (11.xxx.xx.xxx) 10240(10268) bytes of data. 10248 bytes from yyy.yyy.yyy.yyy: icmp_seq=1 ttl=61 time=0.140 ms 10248 bytes from yyy.yyy.yyy.yyy: icmp_seq=2 ttl=61 time=0.124 ms 10248 bytes from yyy.yyy.yyy.yyy: icmp_seq=3 ttl=61 time=0.122 ms --- yyy.yyy.yyy.yyy ping statistics --- 3 packets transmitted, 3 received, 0% packet loss, time 19999ms rtt min/avg/max/mdev = 0.122/0.128/0.140/0.015 ms如果 rtt 较大，或者有 packet loss，证明网络有问题，需要排查网络环境。
系统负载高导致。可以使用 tsar 观察出现问题时系统的各项指标。
Time ---cpu-- ---mem-- ---tcp-- -----traffic---- --sdb--- --sdc--- --sdf--- --sda--- --sdi--- --sdj--- --sdg--- --sde--- --sdh--- --sdl--- --sdk--- --sdd--- --dm-0-- --dm-1-- --dm-2-- ---load- Time util util retran bytin bytout util util util util util util util util util util util util util util util load1 08/09/23-11:25 7.77 92.88 0.02 1.5M 1.7M 0.30 0.30 0.28 0.87 0.27 0.29 0.31 0.29 0.29 0.31 0.30 0.29 0.00 1.54 0.00 1.86 08/09/23-11:30 7.78 92.90 0.02 1.4M 1.6M 0.28 0.30 0.29 0.38 0.26 0.27 0.31 0.29 0.25 0.27 0.27 0.29 0.00 1.40 0.00 2.16 08/09/23-11:35 7.59 92.88 0.02 1.4M 1.7M 0.29 0.31 0.29 0.55 0.28 0.28 0.31 0.30 0.29 0.31 0.29 0.30 0.00 1.49 0.00 2.69主要关注 tcp retrans、load、mem 等指标：
如果 tcp retrans> 0.2，则认为网络状况较差。
如果 mem、load 接近 100% 了，证明系统存在内存、CPU 的瓶颈，影响网络包的收发效率。这时候可以通过 easy 网络线程的监控日志来佐证。
[2023-05-15 18:28:17.681483] INFO [RPC.FRAME] ob_net_easy.cpp:601 [88307][0][Y0-0000000000000000-0-0] [lt=18] [dc=0] [RPC EASY STAT](log_str="conn count=3/4, request done=7404635/5179373, request doing=0/0") [2023-05-15 18:28:17.682056] INFO [RPC.FRAME] ob_net_easy.cpp:601 [88310][0][Y0-0000000000000000-0-0] [lt=8] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7402021/5162953, request doing=0/0") [2023-05-15 18:28:17.682108] INFO [RPC.FRAME] ob_net_easy.cpp:601 [88309][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7405199/5164208, request doing=0/0") [2023-05-15 18:28:17.682108] INFO [RPC.FRAME] ob_net_easy.cpp:601 [88308][0][Y0-0000000000000000-0-0] [lt=9] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7402609/5163322, request doing=0/0")网络 IO 线程每隔 1s 就会打印线程上的连接数、处理完成/正在处理请求的数量信息，其中 request done 和 request doing 的格式为 requests_in/requests_out。
如果 request doing 的 requests_in 和 requests_out 不都为 0，说明该网络线程处于 busy 状态。如果所有的网络线程都处于 busy 状态，说明 RPC 线程紧张。
如果 IO 线程的打印周期超过 1s，说明当前可能由于负载高或其他原因导致IO线程调度，处理定时任务等也产生了一定偏差。
如果
observer.log中有easy cost too much time、poll handler too much time、EASY SLOW等告警，也说明因为系统负载高、资源紧张导致 easy 线程繁忙。[2022-12-14 22:03:35.561441] WARN __tg_cleanup (easy_connection.c:1010) [87946][Y0-0000000000000000] [lt=34] easy cost too much time: 13550 on_readable: 11.xxx.xx.xxx:5551_33.176.xxx.xx:2882_24992_0x7f1404dbfc70 t=0-1671026615547869 s=0 r=1 io=34294164004/2777560 sq=2775400 [2022-12-14 22:03:35.561452] WARN ev_invoke_pending (ev.c:2131) [87946][Y0-0000000000000000] [lt=8] epoll handler too much time :13581 count=1 malloc=1/1 write=0/0 read=13504/1 server_process=0/0 client_cb=0/0
