弱读常见问题排查

确认是否与弱读相关

以下情况可能与弱读相关。

1. 在执行弱读请求时报错，极大概率与弱读功能有关。

   执行弱读语句，也就是要么读一致性级别为 WEAK，可以执行命令查看。

   select @@ob_read_consistency;
   

   要么 SQL 命令中设置了弱读 hint。

   select /*+read_consistency(weak)*/...;
   

2. 查看 observer.log 中报错的日志，与 weak、时间戳、副本选择相关。

   通过 trace id 或者错误码在出错时间段的日志中进行搜索，如果报错的日志中提到了 weak 相关的内容，或者存在版本号落后太多、副本选择不符合预期等情况，则有可能是弱读相关问题。

   例如以下日志表明该日志流不可读，但预期这个日志流是可读的，说明副本选择不符合预期。

   [2023-11-22 14:03:31.229165] INFO  [SQL.OPT] assign_with_only_readable_replica (ob_phy_table_location_info.cpp:90) [44245][UserLocAsyncUp1][T1001][xxxxx-xxxxx-xxxxx-xxxxx] [lt=31] the replica location is invalid(bl_key={server:"xxx.xxx.xxx.xxx:xxxxx", tenant_id:1001, ls_id:{id:1}}, replica_loc={server:"xxx.xxx.xxx.xxx:xxxxx", role:2, sql_port:41035, replica_type:0, property:{memstore_percent_:100}, restore_status:{status:0}, proposal_id:0})
   

   例如以下日志显示 is_weak_read = 1，但实际上是强读场景，说明代码中读一致性不符合预期。

   [2023-11-22 11:38:22.537730] INFO  [SQL.DAS] retry_das_task (ob_data_access_service.cpp:268) [28892][T1002_L0_G0][T1002][xxxxx-xxxxx-xxxxx-xxxxx] [lt=0] [DAS RETRY] check if need tablet level retry(task_op.errcode_=-6231, task_op.errcode_="OB_REPLICA_NOT_READABLE", need_retry=true, task_op.task_flag_=196609, continuous_retry_cnt=8, total_retry_cnt=8, loc_meta={table_loc_id:18446744073709551614, ref_table_id:500214, related_table_ids:[cnt:1, 500006], use_dist_das:0, select_leader:0, is_dup_table:0, is_weak_read:1, unuse_related_pruning:0, is_external_table:0}, tablet_loc={tablet_id:{id:1152921504606847334}, ls_id:{id:1003}, server:"xxx.xxx.xxx.xxx:xxxxx", in_retry:0, partition_id:500778, first_level_part_id:18446744073709551615})
   

3. 内部表中指明了是弱读、读版本号的问题。

   或者是非弱读场景出错，但是在内部表或日志中发现弱读时间戳异常，那么也可能与弱读有关。

   例如转储合并有一条失败记录，diagnose_info 显示是弱读时间戳异常导致的。

   obclient> select * from oceanbase.__all_virtual_compaction_diagnose_info where tenant_id=1004 and status ='failed';
   

   输出结果如下：

   +---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+
   | svr_ip        | svr_port | tenant_id | type         | ls_id | tablet_id           | status | create_time                | diagnose_info                                                 |
   +---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+
   | xx.xxx.xxx.xx |     4001 |      1004 | MEDIUM_MERGE |  1004 | 9223372036854775807 | FAILED | 2023-11-28 10:39:38.700144 | weak read ts is not ready, compaction_scn=1701136214973179751 |
   +---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+
   

总而言之，无论是通过日志看到了日志流的异常，或者是其他地方指向了弱读时间戳的问题，大概率是弱读相关问题。当然随着排查的深入，逐渐定位到原因在其他模块也是有可能的。

日志流状态问题排查

日志流状态问题排查思路

日志流异常（时间戳落后，状态异常）排查思路。

1. 检查参数是否符合预期。

2. 查看日志流状态，判断问题类型。

3. 时间戳问题可以搜索日志，结合代码逻辑分析。

4. 状态问题可以查看内部表，若状态异常需要继续排查相关模块问题。

检查相关参数

弱读失败时，先检查一下相关参数是否符合预期（如果是默认值可以不看）。

select @@ob_max_read_stale_time;
show parameters where name = 'max_stale_time_for_weak_consistency';
show parameters where name = 'weak_read_version_refresh_interval';

其中 weak_read_version_refresh_interval 最好小于等于 1s，例如 100ms，ob_max_read_stale_time 和 max_stale_time_for_weak_consistency 最好相等，且要明显大于 weak_read_version_refresh_interval，例如 5s。如果配置项或变量设置不合理，则可以将其修改为适当的值后再继续重试。 在确认参数没有问题后，再考虑日志流是否存在异常，因为读操作本质上是访问日志流上的数据副本，如果日志流存在问题则弱读就可能失败。

检查日志流状态

• 查内部表。

  弱读场景中最常见的问题就是副本（日志流）不可读，原因一般是弱读时间戳落后或者日志流状态异常，不妨先查询内部表观察日志流状态。

  查询 __all_virtual_ls_info 内部表，可以看到日志流基础信息、当前状态、弱读时间戳等。

  obclient> select * from oceanbase.__all_virtual_ls_info;
  

  输出结果如下：

  +------------+----------+-----------+-------+--------------+----------+--------------+---------------------+--------------+---------------------+----------------+----------------+-------------+------------------------------+--------------+------------+
  | svr_ip     | svr_port | tenant_id | ls_id | replica_type | ls_state | tablet_count | weak_read_scn       | need_rebuild | checkpoint_scn      | checkpoint_lsn | migrate_status | rebuild_seq | tablet_change_checkpoint_scn | transfer_scn | tx_blocked |
  +------------+----------+-----------+-------+--------------+----------+--------------+---------------------+--------------+---------------------+----------------+----------------+-------------+------------------------------+--------------+------------+
  | 11.xxx.x.x |    23401 |         1 |     1 | FULL         | LEADER   |          883 | 1701759448288138594 | NO           | 1701746333707807782 |    20265639936 |              0 |           0 |          1701744491477219992 |            0 |          0 |
  | 11.xxx.x.x |    23401 |      1001 |     1 | FULL         | LEADER   |          813 | 1701759448517986005 | NO           | 1701712914332492073 |       67104768 |              0 |           0 |          1701688082212114135 |            0 |          0 |
  | 11.xxx.x.x |    23401 |      1002 |     1 | FULL         | LEADER   |          586 | 1701759448814797204 | NO           | 1701712806815054654 |              0 |              0 |           0 |          1701688096813947256 |            0 |          0 |
  

• 分析日志。

  如果距离报错时间过去太久，日志流的状态已经发生了变化，查表可能就不管用了。这时可以在日志中搜索黑名单相关的信息，黑名单记录了所有不可读的日志流，并且会定期打印列表信息，通过命令过滤关键词获取黑名单相关的信息，命令如下。

  grep -ir 'ob_black_list' observer.log.xxx*
  

  更精准的过滤关键词命令

  grep -ir 'blacklist info print' observer.log.xxx*
  

  输出结果如下：

  [2023-11-22 14:01:16.257546] INFO  [STORAGE.TRANS] operator() (ob_black_list.h:399) [45535][BlackListServic][T0][Y0-0000000000000000-0-0] [lt=9] blacklist info print (value={key:{server:"xxx.xxx.xxx.:xxxxx", tenant_id:1002, ls_id:{id:1016}}, ls_info:{ls_state:2, weak_read_scn:1700632876089608547, migrate_status:0, tx_blocked:true}, update_ts:"2023-11-22 14:01:16.256633"})
  

• 判断问题原因。

  • 如果 migrate_status 或者 tx_blocked 非 0，那么日志流就是处于迁移或者锁定状态，这时候不可读是正常的。

  • 如果日志流状态没有问题，那么可能是弱读时间戳的问题。将 weak_read_scn 与当前时间进行对比，就可以知道弱读时间戳落后了多少。再结合 ob_max_read_stale_time 与错误发生的时间（日志打印时间，或相关表记录的创建时间），就可以判断日志流的时间戳是否可读。

    1. 进行弱读时间戳转换。

       obclient> select usec_to_time(1700632876089608547/1000);
       

       输出结果如下：

       +----------------------------------------+
       | usec_to_time(1700632876089608547/1000) |
       +----------------------------------------+
       | 2023-11-22 14:01:16.089609             |
       +----------------------------------------+
       

    2. 查询 session 变量 ob_max_read_stale_time（单位us）。

       obclient> select @@ob_max_read_stale_time;
       

       输出结果如下：

       +--------------------------+
       | @@ob_max_read_stale_time |
       +--------------------------+
       |                  5000000 |
       +--------------------------+
       

       当确定日志流时间戳不可读后，需要进一步结合代码分析日志，此时也可以联系 OceanBase 技术支持人员协助排查。

进一步分析日志流问题

• 弱读时间戳落后。

  如果是日志流 weak_read_scn 落后太多的原因，可以按 weak_read_scn + 1 的数字搜索相关日志，这样能够快速定位到弱读时间戳的来源。因为弱读时间戳计算公式为：

  weak_read_scn = min(replay_service_ts, apply_service_ts, trans_service_ts) - 1
  

  比如 weak_read_scn = 1700633020906964866，那么用 weak_read_scn + 1 = 1700633020906964867 进行搜索，可以找到以下日志。在搜索日志的过程中，可以使用 ls_id、tenant_id 等条件进行筛选。

  [2023-11-22 14:03:31.258323] INFO  [CLOG] get_min_unreplayed_log_info (ob_replay_status.cpp:966) [45400][T1002_TenantWea][T1002][Y0-0000000000000000-0-0] [lt=11] get_min_unreplayed_log_info in skip state(lsn={lsn:0}, scn={val:1700633020906964867, v:0}, this={ls_id_:{id:1018}, is_enabled_:true, is_submit_blocked_:false, role_:2, err_info_:{lsn_:{lsn:18446744073709551615},......
  

  此时可以知道是日志回放位点落后导致弱读时间戳落后，接下来继续分析日志回放阻塞的问题，一般来说可能是 clog 磁盘写满了。

  一般来说找到相关日志后，需要继续分析对应模块的问题，参考如下。

  日志方面参见：排查 OceanBase 数据库 V4.x 版本中日志问题。

  事务方面参见：OceanBase 数据库事务问题排查指南、长事务和悬挂事务的巡检与应急方法。

• 处于迁移状态。

  如果 migrate_status 不为 0，说明日志流处于迁移状态中，等待迁移完成后日志流就会恢复可读。如果长时间卡在迁移状态，就需要进行迁移问题的排查。

  迁移复制问题排查。

• 处于锁定状态。

  如果 tx_blocked 为 true，说明日志流被某个事务锁定了，一般等待该事务完成即可。如果事务长时间卡住，就需要进行事务问题的排查。

  事务方面参见：OceanBase 数据库事务问题排查指南、长事务和悬挂事务的巡检与应急方法。

案例：弱读位点不推进导致 medium merge 卡住

问题描述

场景： 迁移 + transfer + bmsql + sqlgen 。

问题： 弱读位点不推进导致 medium merge 卡住。

## 通过查询内部表 __all_virtual_compaction_diagnose_info 获取任务状态为 failed 的指定租户中未完成指定类型的 Compaction 任务的 Partition 的诊断信息。
obclient> select * from oceanbase.__all_virtual_compaction_diagnose_info where tenant_id=1004 and status ='failed';

输出结果如下：

+---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+
| svr_ip        | svr_port | tenant_id | type         | ls_id | tablet_id           | status | create_time                | diagnose_info                                                 |
+---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+
| xx.xxx.xxx.xx |     4001 |      1004 | MEDIUM_MERGE |  1004 | 9223372036854775807 | FAILED | 2023-11-28 10:39:38.700144 | weak read ts is not ready, compaction_scn=1701136214973179751 |
+---------------+----------+-----------+--------------+-------+---------------------+--------+----------------------------+---------------------------------------------------------------+

通过分析上述信息，问题是合并卡住，原因是 weak read ts is not ready, compaction_scn=1701136214973179751 。将 compaction_scn 的值 1701136214973179751 转换一下是 2023-11-28 09:50:14.973180，明显早于合并任务的创建时间 2023-11-28 10:39:38.700144。问题的核心就在于弱读时间戳过于落后，搜索 generate_weak_read_timestamp_ 找到生成弱读时间戳的日志，可以看到时间戳是来源于 log_service_ts。

在代码中跟踪其来源，log_service_ts 的值来自于 max_applied_scn 和 max_replayed_scn 的最大值，而日志显示 max_applied_scn 是不可用的（v=3，而且数字明显很大），因此 max_replayed_scn 就是弱读时间戳的最终来源，如下所示。

} else {
    scn = std::max(max_replayed_scn, max_applied_scn) > SCN::min_scn() ?
             std::max(max_replayed_scn, max_applied_scn) : SCN::min_scn();
    CLOG_LOG(TRACE, "get_max_decided_scn", K(ret), K(id), K(max_replayed_scn), K(max_applied_scn), K(scn));
  }

然后查看日志分析 max_replayed_scn 落后的原因，发现该日志流处于迁移状态长时间未结束，没有同步和回放任何日志，因此 max_replayed_scn 是落后的，查询语句如下。

select usec_to_time(weak_read_scn/1000), * from __all_virtual_ls_info where tenant_id = 1004 and svr_port = 4001;

最后经过分析，判断是 clog 盘写满触发日志回收，日志流无法正常回放 clog 日志，最终导致弱读时间戳落后。

## 创建 18.9 万 tablet 耗时较多 42 分钟，导致 clog 被回收，触发 rebuild 。
[xxxxx@xxxxxx /data/1/ob1.z1.obs1/log]
$grep "create all tablets finish" observer.log.20231128095225561 |grep T1004
[2023-11-28 09:52:09.224481] INFO  [STORAGE] create_all_tablets (ob_storage_ha_tablet_builder.cpp:270) [43576][T1004_START_MIG][T1004][xxxxx-xxxxx-xxxxx-xxxxx] [lt=7] create all tablets finish(ret=0, sys_tablet_count=3, data_tablet_count=189466)

[xxxxx@xxxxxx /data/1/ob1.z1.obs1/log]
$grep tablets_builder_create_all_tablets observer.log.20231128095225561 |grep T1004
[2023-11-28 09:52:09.224488] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [43576][T1004_START_MIG][T1004][xxxxx-xxxxx-xxxxx-xxxxx] [lt=5][errcode=-4389] destruct(*this=time guard 'tablets_builder_create_all_tablets' cost too much time, used=2550927688)

综上信息分析可知不是 BUG。问题原因是 clog 盘满导致日志回放滞后，进而导致弱读时间戳落后。

弱读类型问题排查

弱读类型问题排查思路

弱读类型问题最好结合代码分析日志，需要稍微了解弱读的实现方案。

1. 先确定预期的读一致性类型，查看变量 ob_read_consistency 值以及是否有 hint。

2. 再看 SQL 层日志判断的读类型是否符合预期，cl=1(FROZEN),2(WEAK),3(STRONG)。

3. 根据当前不符合预期的标记，结合代码分析标记来源，根据来源继续查找日志。

4. 如果有日志则继续排查相关模块的问题，然后修复问题。

5. 如果没有日志可以加日志复现，若无法复现则加防御代码和日志，下次出现了再看。

确定预期的读一致性类型

基于 trace id 在日志中搜索 stmt_setup_snapshot_，可以看到执行的语句以及一致性级别，其中的 cl=2 表示一致性级别为 2(WEAK)，说明这是一个弱读请求，通过命令过滤关键词获取日志内容，命令如下。

$grep -ir 00060C87C2239AB4 observer.log* | grep 'stmt_setup_snapshot_'

输出结果如下：

observer.log.20231215160725692:[2023-12-15 16:05:46.544120] INFO  [STORAGE.TRANS] stmt_setup_snapshot_ (ob_sql_trans_control.cpp:666) [51827][T1004_L0_G0][T1004][xxxxx-xxxxx-xxxxx-xxxxx] [lt=18] [debug] stmt_setup_snapshot_ start (ret=0, cl=2, plan_ctx=0x7fb60a604760)

分析读类型不符合预期的原因

当存在读一致性类型不符合预期的情况时，一般可在日志中看到类似 is_weak_read:0 的内容，或者通过日志判断代码走到了属于弱读的流程中。无论是通过查看日志还是分析代码，应该是能够知道出问题的代码位置的。如果要继续分析，需要对弱读类型的判断机制有一定了解。 基于代码中这个类似 is_weak_read = true 的标记，追踪它是在哪里设置为 true 的，然后继续分析相关代码的逻辑。这时候如果出现了很多分支无法确定代码路径，可能需要增加日志复现或者联系 OceanBase 技术支持人员提供相应的协助。

案例：备库SQL执行过程中语句 consistency_level 不一致

问题描述

强读场景（当前只关注弱读类型的问题），日志中出现 is_weak_read:1 信息，读类型不符合预期。

通过分析上述信息，这个错误的弱读类型是从 loc_meta 打印出来的。在常规路径下，判断读类型都会调用 get_is_weak_read 函数，而通过 trace id 搜索到的日志没有发现对 get_is_weak_read 的调用，说明其中的 flag_ 是在其他地方设置的。增加日志复现分析，首先可以确定从 SQL 层开始这是一个强读请求（cl=3）。

通过打印调用栈可以发现，更新 loc_meta.flag_ 的地方位于 build_table_loc_meta 函数中，而其中的 src 结构早在一个小时前就创建了。

这是根据地址 0x7fc61f20c118 搜索这个 loc_meta 结构最初的来源，在时间点 12:54:52 就已经存在了，而报错日志的时间是 14:13:27。

用过时 loc_meta 的 flag 去覆盖当前请求的 loc_meta。

副本选择问题排查

副本选择问题排查思路

副本选择不符合预期，一般是选择机制存在问题，大概率是黑名单的问题，其他根据实际情况具体分析。

1. 首先分析日志，被排除的副本是真的不可用还是误判了（参考 检查日志流状态 这一小节内容）。

2. 如果是真的不可读，继续分析是弱读时间戳落后还是日志流状态不可读，时间戳落后则按前面的思路分析。

3. 如果是误判，分析是否使用了黑名单，黑名单可以搜索 black_list 日志进行分析，会定期打印黑名单列表。

4. 如果是其他机制误判，则具体情况具体分析。

案例：3F primary_zone=z1, kill -15 场景 RTO 回退严重

问题描述

RTO 回退严重，超过 15s 甚至 20s。杀掉一个节点后，TPS 存在十多秒的跌零的问题。

查询超时，如下语句。

select QUERY_SQL, TRACE_ID, EXECUTE_TIME, usec_to_time(REQUEST_TIME) from GV$OB_SQL_AUDIT where usec_to_time(REQUEST_TIME) like '%15:26:3%' and DB_NAME like '%sysbench%' order by EXECUTE_TIME desc limit 30;

通过分析上述信息，首先查看 leader 状态，可以看到时间点 2023-11-14 15:26:26，leader 已经在 z2 上任，但之后依然有十几秒 TPS 跌零（见问题描述），可见选举没有问题。

查看日志搜索 WDIAG，发现很多 -4722 错误码，源头来自 all_select_leader 函数中的报错 fail to get leader，意思是没有获取到 leader 副本。进一步分析发现，assign_with_only_readable_replica 函数打印的日志，日志流类型为 leader（role=2），但是却被判断为不可用，这显然是不合逻辑的。

分析代码发现，该日志流在黑名单中，因而判断它不可读。但是当前时刻该日志流已经成为了 leader，由此推测黑名单是不准确的。

int ObOptTabletLoc::assign_with_only_readable_replica(const ObObjectID &partition_id,
                                                      const ObObjectID &first_level_part_id,
                                                      const common::ObTabletID &tablet_id,
                                                      const ObLSLocation &ls_location)
{
    ......
      bool in_black_list = false;
      if (OB_FAIL(bl_key.init(replica_loc.get_server(), ls_location.get_tenant_id(), ls_location.get_ls_id()))) {
        LOG_WARN("init black list key failed", K(ret));
      } else if (OB_FAIL(ObBLService::get_instance().check_in_black_list(bl_key, in_black_list))) {
        LOG_WARN("check in black list failed", K(ret));
      } else if (!in_black_list) {
        if (OB_FAIL(replica_locations_.push_back(replica_loc))) {
          LOG_WARN("Failed to push back replica locations",
                   K(ret), K(i), K(replica_loc), K(replica_locations_));
        }
      } else {
        LOG_INFO("the replica location is invalid", K(bl_key), K(replica_loc));
      }

搜索黑名单日志，可以看到日志流的状态是 follower，因为主库的 leader 是不可能被加入黑名单的。那说明该日志流之前是 follower，成为 leader 之后黑名单没能及时刷新，从而导致了误判。

日志流黑名单默认是 3s 刷新一次，刷新的方式是查询内部表。通过日志可以看到，查内部表的 SQL 超时（10s），导致更新失败，而查询失败 3 次才会清空黑名单，因而导致黑名单出现十多秒的延迟。这条内部 SQL 中的 hint 实际上不会生效，需要调用专门的接口设置超时时间才行，这里就是导致黑名单长时间未更新的关键原因。

observer.log.20231122112615034:[2023-11-22 11:24:48.311055] WDIAG [STORAGE.TRANS] do_thread_task_ (ob_black_list.cpp:204) [16268][BlackListServic][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4012] fail to execute sql(ret=-4012, ret="OB_TIMEOUT", sql=select /*+query_timeout(2000000)*/ a.svr_ip, a.svr_port, a.tenant_id, a.ls_id, a.role,   nvl(b.weak_read_scn, 1) as weak_read_scn, nvl(b.migrate_status, 0) as migrate_status, nvl(b.tx_blocked, 0) as tx_blocked   from oceanbase.__all_virtual_ls_meta_table a left join oceanbase.__all_virtual_ls_info b   on a.svr_ip = b.svr_ip and a.svr_port = b.svr_port and a.tenant_id = b.tenant_id and a.ls_id = b.ls_id;)

然而就算解决了 SQL 超时的问题，黑名单仍然存在 3s 的延迟，所以需要兜底机制。

综上信息分析可知切主过程中，黑名单访问内部表超时，没有及时更新，导致 leader 副本无法被访问，进而导致 TPS 长时间跌零的问题。

解决方法

黑名单查内部表手动设置超时时间（2s），避免线程长时间卡住。

适用版本

OceanBase 数据库所有版本。