当前位置：首页 > article >正文

【OceanBase 诊断调优】—— packet fly cost too much time 的根因分析

article 2024/12/24 22:24:20

适用版本

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 毫秒，在 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

查看全文

http://www.kler.cn/a/449883.html