如何排查网络备库同步卡住

本文介绍网络备库同步卡住问题的排查方法。

确认租户角色以及可恢复位点

obclient> select * from __all_virtual_tenant_info where tenant_id = 1002;

主要关注 tenant_role、 switchover_status 以及 recovery_until_scn 字段：

• tenant_role 表示租户角色：主库 PRIMARY、备库 STANDBY 以及恢复租户 RESTORE。
• switchover_status 表示切换状态：简单来说除 NORMAL 状态外，其余状态均表示正在切换中。
• recovery_until_scn 表示可恢复最大位点。

如下图所示，该租户角色为备租户，并且恢复位点为无穷大。

另外，需要重点关注 recovery_until_scn，如果执行 recover standby cancel 命令，该值将停留在最大同步位点，日志恢复也会停止。

查看日志流恢复状态表

obclient> select * from v$ob_ls_log_restore_status where tenant_id = 1002;

重点关注 "sync_status" 列，表示日志流恢复状态，正常为 NORMAL，其他状态表示恢复异常。

需要注意，该视图仅展示日志流 leader 的恢复状态，对于无主日志流无法展示。同时日志恢复由日志流 leader 进行，请结合 gv$ob_log_stat 视图确认日志流都有 leader。

查看日志恢复源

obclient> select * from cdb_ob_log_restore_source where tenant_id = 1002;

OceanBase 数据库 V4.2.x 版本支持 LOCATION 和 SERVICE 两种类型日志恢复源，分别表示日志上游为归档和网络；也表示该备库为基于归档备库和基于网络备库。

其中 user 字段分别为 user_name 和 tenant_name (源租户名)，cluster_id 和 tenant_id 字段分别为源租户所在集群 cluster_id 以及源租户 tenant_id。

日志同步依赖

由于备库设计原理限制，日志拉取最大位点可以认为是租户 replayable_scn + 3s。 举例： 如果 replayable_scn 对应物理时间为 2023-06-16 14:00:00，那么每个日志流可以拉取日志 scn 不大于 2023-06-16 14:00:03 的日志。当然出于性能考虑，只要备库 end_scn 不大于 2023-06-16 14:00:03，那么可以再最大拉取 16MB 日志。 replayable_scn 相当关键，备库卡主可以先查看 __all_virutal_tenant_info 表的 replayable_scn 列。

查找最慢日志流

obclient> select *, scn_to_timestamp(end_scn) from gv$ob_log_stat where tenant_id = 1002 and role = 'leader' order by end_scn;

由于租户 replayable_scn 取决于最慢日志流 end_scn 以及其他逻辑，因此先查找最慢日志流。

在日志流都有 leader 的前提下，找到最慢日志流 M 以及其 end_scn，如果显著小于其他日志流并且持续不增长，那么可以有理由怀疑它就是罪魁祸首；但是并不充分，再拿最慢日志流与租户 replayable_scn 比较，如果两者相等，那么日志流 M 是问题日志流，如果 M 的 end_scn 大于租户 replayable_scn，并且各个数值不变，联系技术支持进一步确认。

找到最慢日志流，查看 OBServer 日志

从以上分析找到引发问题的日志流 leader，确认其所在 OBServer。可以从日志中进一步发现问题：

T1002_LogRes 线程

该线程是 OBServer 上调度日志恢复的入口，它负责：

• 识别当前备库是归档备库还是网络备库，并调用不同驱动执行对应的恢复任务。
• 对于网络备库，负责按需创建、销毁日志传输模块 log_fetcher，以及为其设定最大可恢复位点。
• 管理为 leader 的日志流，将其添加到 log_fetcher，以及从 log_fetcher 中 remove 掉 follower 日志流。
• 设置日志传输压缩算法。
• 设置日志传输优先上游 region。
• 打印日志流恢复进度。

典型日志打印如下：

• "fetcher init succ" 启动log fetcher。

  

• "add ls" 添加日志流任务到log fetcher，其中包含将ls添加到IDLE_POOL。

  

• "print_slow"。

  

• "traffic" 日志拉取速度。

  

traffic 日志各个字段含义

• stream 表示日志流向主库的哪台 Server 拉取的日志。
• traffic 表示 10s 内日志拉取的平均速度。
• size 或 rpc 表示 10s 内每条 rpc 返回的日志数据的平均大小。
• rpc_cnt 表示 10s 内收到 rpc response 的个数。
• single_rpc 表示 LogFetcher 收到该 rpc 后会休眠一段时间再发起新一轮的 rpc。
• upper_limit 表示拉到了当前日志拉取的最大位点的 rpc 数目。
• max_log 表示拉到了 Server 最新日志的 rpc 数目。
• no_log 表示没有拉到任何日志的 rpc 的数目。
• rpc_time 表示从 LogFetcher 发送 rpc 开始到 LogFetcher 执行完 rpc 的回调函数的总耗时，单位为微秒(us)。
• svr_time 表示 cdcservice 处理 rpc 的总耗时。
• queue 表示 rpc 在 cdcservice 等待队列中的时间。
• process 表示 cdc_service 处理 rpc 请求的耗时。
• net_time 表示网络耗时，l2s 是 local to server 的缩写，表示 rpc 从本地(LogFetcher)发送到 Server(CdcService)的网络耗时。
• s2l(server to local)表示 rpc 从 server(CdcService) 发送到本地(LogFetcher)的耗时。
• cb_time 表示 rpc callback 的执行耗时。

T1002_LogRouteS 线程

该线程负责为每个 log_fetcher 中的日志流找到可以拉取日志的上游 OBServer，如下为正常打印：

"update server list succ" 发现日志上游 Server。

"其他错误报错" 连不上主库了。

LogFetcher 相关问题排查

找到最慢日志流后需要确定日志流进度落后的原因，现象可能会有两种。

• 日志流进度在推进，也就是说日志流的 end_scn 在变化，但是推进得很慢。
• 日志流进度卡住。

日志流进度推进慢

执行 grep FETCH_STREAM observer.log | grep traffic |grep ls_id:{id:xxx 命令来查看对应时间段内 LogFetcher 中日志流拉取链路各个阶段耗时统计，日志打印如下。

[2023-06-20 10:19:00.594842] INFO  [TLOG.FETCHER] do_stat (ob_log_ls_fetch_stream.cpp:322) [73218][T1004_LogRessvr][T1004][Y5F6C0B7C05CD-0005FE85EF138CC0-0-0] [lt=9] [STAT] [FETCH_STREAM] stream="11.124.5.100:24425"(0x7f49040101e0:HOT)({tenant_id:1004, ls_id:{id:1001}})(FETCHED_LOG:1.81GB) traffic=15.29MB/sec log_size=178411183 size/rpc=14.18MB log_cnt/rpc=596 rpc_cnt=12(1/sec) single_rpc=0(0/sec)(upper_limit=0(0/sec),max_log=0(0/sec),no_log=0(0/sec),max_result=0(0/sec)) rpc_time=539068 svr_time=(queue=101,process=36707) net_time=(l2s=12558,s2l=449508) cb_time=40193 rpc_time=977742 flush_time=0 read_log_time=977662(log_entry=56757,trans=0) trans_count=0 trans_size=0.00B 

该日志每 10s 打印一次，统计了 10s 内 rpc 的总体情况，因此统计项均为 10s 内 rpc 相关活动的统计项。

1. 首先可以看 upper_limit 字段是否为 0，如果出现 upper_limit 频繁不为 0 的情况则需要回过头去看 replayable_scn 推进慢的问题。

2. 看 rpc_time，这里所有的时间的单位都是微秒(us)，如果 rpc_time 耗时较大，那么需要看看是 svr_time/net_time/cb_time 中哪一部分耗时较大，svr_time 耗时较大可能是 Server 负载高或 group_id=13 的队列积压等，如果是 net_time 耗时较高，则需要看主备库之间的延时和带宽是否符合预期，如果 cb_time 耗时高，可能是备库压力大，可以联系技术支持排查。

3. 看 rpc_time，如果 rpc_time 较大，那么需要看看备库是否存在 cpu 负载高，日志盘负载高或者日志写入限速的问题。

4. 看 single_rpc，single_rpc=upper_limit+max_log+no_log+max_result。

   1. upper_limit 大，看备库 sync_scn 推进速度是否有卡住现象。
   2. max_log 大，这个不为 0 意味着拉到了主库的最新日志，一般不用关心。
   3. no_log 大，说明没拉到主库日志，一般是拉到主库这个日志流的所有日志了，如果这时候这个日志流还一直不同步，可以联系技术支持排查。
   4. max_result 大，说明备库处理不过来拉到的日志，看看是不是备库 cpu 或者日志盘负载高。

日志流进度卡住

1. 查询视图 v$log_ls_restore_status 视图，或者 grep "fetch log fail" 查看是否有 rpc 失败的问题。
2. 如果没有 rpc 失败的问题，查看日志流的 end_scn 是不是超过了 sync_scn + 3s (OceanBase 数据库 V4.2.1 BP3 和 V4.2.3 之后版本是 6s），可以通过日志 grep 'print_fetcher_stat.*T${tenant_id}' 来看 global_upper_limit，然后 grep 'slow fetch progress' 来看看 log_progress 最小的日志流的 log_progress 是否超过了global_upper_limit，如果超过了，就看 sync_scn 无法推进的问题。
3. 如果不是 sync_scn 不推进的问题，grep "update_server_list.*TXXXX"|grep id:{$ls_id}，看看是不是 Server 列表查不到了，如果 Server 列表查不到，同步也会卡住。
4. fgrep '[STAT] [BLACK_LIST] [ADD]' 看看是不是有 Server 被加入黑名单了，不过在网络备库的场景下，一般会伴随着 rpc 失败。

主库同步日志信息

网络备库由日志流 leader 找主库任意一台 Server（有一定策略如优先拉 follower、优先拉指定 region），主库 Server 发送日志到备库。其中关键日志为: "fetch_log done"，该日志不代表拉取日志成功，仅代表主库收到拉取日志 rpc 请求，需要看具体内容。

• 执行 grep "fetch_log done" 命令，如果 debug_err 和 err 不为0，那么主库读取日志过程中失败，一般会反映到备库上。
• 执行 grep "fetch_log done" 命令，如果 debug_err 和 err 为0，但是 fetch_total_time 较大，那么可能是读日志耗时太长，可能会导致 rpc 超时。