选举层面无主问题排查指南

基本概念简介

• paxos 实例：paxos 是在分布式系统中达成共识的经典算法，在 OceanBase 数据库中使用 paxos 算法来在副本间进行日志同步。

• multi-paxos 与 Leader：朴素的 basic-paxos 协议在应用于一系列日志同步的高并发场景下将会导致 活锁 问题，因此需要一个 Leader 协调写入动作，避免无谓的冲突和开销，可以极大提升系统各副本间达成共识的效率。

• PALF：PALF 是 OceanBase 数据库在 V4.0 版本中将日志同步服务进行打包后的一个框架简称，选举功能是该框架提供的子功能之一。

• Leader 的概念可能超出日志同步：Leader 的概念的引入在分布式系统的多副本间提供了一个全局唯一的状态变更点，因此该概念可以被许多其他模块利用来达成额外的设计。

• 日志流：在 OceanBase 数据库 V4.0 版本中，最大的改变是将 V3.x 版本中的多个分区合并为一个日志流，表结构 Tablet 挂在某一个日志流上，由此可以极大的节省内存、CPU、网络带宽等资源的使用，因此要注意在 V4.0 版本中并不是每个分区对应一个 paxos 实例，而是每个日志流对应一个。

• 租户与日志流：因为在 OceanBase 数据库中有租户间隔离的概念，因此日志流是每个租户独立拥有的。在 V3.x 版本中，通常排查无主问题都是分区级的，需要拿到分区的标识 pkey。 在 V4.0 版本后，排查无主问题将会是日志流级的，因此在排查时要确认租户的 ID 以及日志流的 ID。

• 选举模块的设计保证：对于一个日志流而言，选举在设计上保证任意时刻（除去无主选举和切主间隙，理论上是 99.9%）有且仅有一个 Leader 存在，当发现违背此保证时，视为选举模块异常。

• 租约（Lease）：租约是一把时间锁，是一段时间内的排他性保证，是目前已知的在分布式系统中保证唯一 Leader 又不会丧失活性的唯一手段，选举实际上是使用 basic-paxos 在副本间就租约达成共识。

• election proposer：proposer 是 paxos 中的提案发起者，proposer 会提议开始一次选举，并尝试竞选成为 Leader 。

• election acceptor：acceptor 是 paxos 中的提案审议者，acceptor 会根据基本原则判断是否要接受一项提案（在选举中提案就是租约），并确保任意时刻集群中只有一个 Leader 。

在任意机器上查询 Leader

主要思路是查询 Lease 的 owner 是谁，将 T1 和 id:1 换为其他租户和日志流即可，命令如下。

grep 'T1_.*{id:1}' ./election.log | grep 'dump acceptor info' | awk '{match($0, /^([[0-9:-. ]+]).*owner:"([0-9.:]+)"/, a); print a[1]" "a[2]}'

输出结果如下：

[2022-06-28 11:48:15.678069] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:19.177181] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:22.177618] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:25.177815] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:28.178042] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:31.178080] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:34.677409] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:37.677882] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:41.177600] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:44.677666] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:47.678039] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:51.177957] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:54.677219] xxx.xxx.xxx.xxx:xxxx
[2022-06-28 11:48:57.677273] xxx.xxx.xxx.xxx:xxxx

该查询结果不是理论上 100% 精确的，但 99% 的情况下是够用的。若查询某时间段的 Leader 不是有效的，具体根据本文 网络交互统计信息与图示 这一节内容，进一步分析日志流级别的网络联通性。

现象与思路

• -4038 报错：4038 错误码的定义是 not master，而非 no master，因此在发现 4038 错误后，有两种可能：

  • 当前 Leader 存在，但是 Leader 不是本 Server。(需要排查上层模块问题)。

  • 当前 Leader 不存在。（排查网络连通性问题）。

• 若当时的 Leader 不存在，根据排查问题的经验基本上是网络连通状态有问题（不是指 OBServer 的网络连通状态，而是日志流级别的连通状态），例如：

  • 因为租户没有内存接收不到消息，但是还能发送消息，导致单向网络连通。

  • 因为工作队列积压导致无法接收消息。

  • 因为 server 处于 stop 状态无法接收消息。

  • 其他原因导致的网络连通性问题。

具体请根据本文 网络交互统计信息与图示 这一节内容，分析日志流级别的网络连通性。

按租户日志流过滤日志内容

按租户日志流过滤日志内容，命令如下：

grep 'T1_.*{id:1},' ./election.log

网络交互统计信息与图示

为了方便排查定位网络连通性问题，选举增加了 dump message count 日志，该日志统计了本副本与其他副本间的消息收发记录（并按照 IP 与消息类型分类，记录最后一次交互的时间戳），使用如下命令 grep 相关日志：

grep 'T1_.*{id:1}' ./election.log | grep 'dump message count' | vim -

输出结果如下：

INFO [ELECTION] operator() (election_proposer.cpp:220) [84306][T1_Occam][T1][Y0-0000000000000000-0-0] dump message count(ls_id="{id:1}", self_addr="xxx.xxx.xxx.xxx:xxxx", state=
match:[Prepare Request, Prepare Response, Accept Request, Accept Response, Change Leader]
"xxx.xxx.xxx.xxx:xxxx":send:[1, 1, (484), (484), 0], rec:[1, 1, (484), (484), 0], last_send:2022-06-28 13:55:57.539092, last_rec:2022-06-28 13:55:57.539163
"xxx.xxx.xxx.xxx:xxxx":send:[1, 0, (484), 0, 0], rec:[1, 1, 0, (484), 0], last_send:2022-06-28 13:55:57.538924, last_rec:2022-06-28 13:55:57.539195
"xxx.xxx.xxx.xxx:xxxx":send:[1, 0, (484), 0, 0], rec:[1, 1, 0, (484), 0], last_send:2022-06-28 13:55:57.538925, last_rec:2022-06-28 13:55:57.539294)

在上述的日志信息中，在第 6 行：match:[Prepare Request, Prepare Response, Accept Request, Accept Response, Change Leader]，表示统计的各种数据收发计数值都 match 哪一种消息类型。在第 7-9 行："xxx.xxx.xxx.xxx:xxxx":send:[1, 1, (484), (484), 0], rec:[1, 1, (484), (484), 0], last_send:2024-04-16 13:55:57.539092, last_rec:2024-04-16 13:55:57.539163，首先是记录了交互的 IP，send 数组中的每个数值统计了发送给这个 IP 的消息数量，rev 数组中的每个数值统计了接收到来自这个 IP 的消息数量，last_send 与 last_rec 分别统计了最后一次发/收这个副本消息的时间。

该日志在每个日志流上打印的间隔至少 10s，其中有括号括起来的数字 (484) 表示距离上一次打印统计信息时发生变化的数字项。

正常的有主连任过程，Leader 与 Follower 之间会通过 Accept Request/Response 消息不断的延续 Lease：

因此关键数值高亮后的典型的消息统计日志在 Leader 上形如（表示它一直在向所有 Follower 发送续约消息，并正常收到了来自所有 Follower 的响应）：

关键数值高亮后的典型的消息统计日志在 Follower 上形如（表示它一直在正常接收来自 Leader 的续约消息，并对其发出了响应）：

如果持续发生无主选举，所有副本之间会通过 Prepare 消息互相交换权重，并在充分交换完信息后进行投票，若投票后选不出 Leader，这一无主选举过程将会一直持续下去：

这是将包括 Leader 在内的多数派 kill 掉后，剩下的一个 Follower 的关键统计值高亮的变化（它一直在广播 prepare 消息，并给自己投票，并且一直收不到其他人的消息）：

无主后，根据网络联通统计数据，可以初步断定是哪台 server 有问题，问题出在发端还是收端。

确定 server 后，看一下网络层面是不是出现了异常，导致选举的消息收发出现了问题：

grep 'pcode.*538[4567]' ./observer.log

内部表事件查询与解析

可以通过 __all_server_event_history 表来查看某个日志流选举模块发生的事件。

具体事件描述待补充。

SQL > SELECT gmt_create,svr_ip,svr_port,event,name3,value3 FROM __all_server_event_history WHERE module="ELECTION" AND value1=$tenant_id AND value2=$ls_id ORDER BY gmt_create;

输出结果如下：

核心日志逐字段解析

选举日志阶段标识

除了 dump info 日志外，选举模块的绝大部分日志打印都有具体的阶段标识。

因为大部分人看选举日志并不关心当时选举对象的具体状态，只想知道当时选举发生了什么事情。

那么只需要关心日志信息前面的中括号 [$phase] 里的内容即可 $phase 内容从有限的阶段集合中取其中之一：

• [INIT] ：表明该日志与选举对象的初始化相关。

• [DESTROY]：表明该日志与选举对象的析构相关。

• [ELECT_LEADER]：表明该日志与无主选举相关。

• [RENEW_LEASE]：表明该日志与续约相关。

• [CHANGE_LEADER]：表明该日志与计划内切主相关。

• [EVENT]：表明该日志与事件记录汇报相关。

• [SET_MEMBER]：表明该日志与成员变更相关。

如下图所示，同样的一条广播 prepare 消息的日志，可能发生于无主选举阶段，也可能发生于续约阶段，日志的阶段标识区分了这两种情况。

选举的 dump 日志解析

选举正常运行时，不会打印任何日志，但会周期性的 dump 选举数据结构的信息（3s），典型 Leader 的 dump proposer info 日志如下：

[2022-04-13 11:33:05.411398] INFO  [ELECTION] election_proposer.cpp:202 [93669][][T1004][0][Y0-0000000000000000-0-0] [lt=14] dump proposer info(*this={id:1, addr:"xxx.xxx.xxx.xxx:50043", role:Leader, ballot_number:0, prepare_success_ballot:0, lease_interval:10.00s, memberlist_with_states:{member_list:{addr_list:["xxx.xxx.xxx.xxx:50043", "xxx.xxx.xxx.xxx:50045", "xxx.xxx.xxx.xxx:50047"], membership_version:{proposal_id:1, config_seq:2}, replica_num:3}, prepare_ok:True, accept_ok_promised_ts:11:33:14.911, follower_promise_membership_version:{proposal_id:1, config_seq:2}}, lease_and_epoch:{leader_lease:{span_from_now:9.501s, expired_time_point:11:33:14.911}, epoch:0}, last_do_prepare_ts:2022-04-13 11:32:08.410298, self_priority:{priority:{is_valid:true, fatal_failures:[], serious_failures:[], is_in_blacklist:false, in_blacklist_reason:, is_server_stopped:false, is_zone_stopped:false, is_manual_leader:false, server_score:0}}, p_election:0x7f150cb0a640})

• 典型 Follower 的 dump proposer info 打印的信息是 Leader 上打印的信息的子集。

  字段名	二级字段名	三级字段名	含义
  id:1			日志流 ID 。
  addr:"xxx.xxx.xxx.xxx:50043"			本机 IP 地址。
  role:Leader			proposer 当前所扮演的角色（取 Leader 与 Follower 其中之一）。
  ballot_number:0			proposer 当前所处的选举轮次
  prepare_success_ballot:0			proposer prepare 成功的选举轮次（该轮次将用于续约）。
  lease_interval:10.00s			proposer 用于续约的时间长度。
  memberlist_with_states	member_list	addr_list:["xxx.xxx.xxx.xxx:50043", "xxx.xxx.xxx.xxx:50045", "xxx.xxx.xxx.xxx:50047"]	成员列表的IP地址列表。
  		membership_version:{proposal_id:1, config_seq:2}	成员列表的版本号。
  		replica_num:3	成员的副本数量（在成员变更场景中是可能比 IP 地址列表的个数多的）。
  prepare_ok:True		回应本副本 Prepare OK 的状态列表，若全部为 True 或者全部为 False，则只显示 True 或者 False，否则将以列表形式显示各副本的回应状态，例如：[true, false, true]，状态顺序与 addr_list 相对应。
  	accept_ok_promised_ts:20:05:40.760		各副本 acceptor 的 Lease 到期时间点（以本机时钟衡量），当所有副本同步时，只显示一个值，否则将以列表形式显示各副本的 Lease 截止时间点，例如：[20:05:40.760, 20:05:41.760, 20:05:42.760]，状态顺序与 addr_list 相对应。
  	follower_promise_membership_version:{proposal_id:1, config_seq:2}		各副本上一次续约成功的成员版本号，当所有副本同步时，只显示一个值，否则将以列表形式显示各副本的 Lease 截止时间点，状态顺序与 addr_list 相对应。
  lease_and_epoch	leader_lease	span_from_now:9.501s	Leader Lease 还有多久到期。
  		expired_time_point:11:33:14.911	Leader Lease 到期的具体时间点。
  	epoch:0		当前 Lease 所对应的 epoch（对外暴露的 epoch 值，可能小于 ballot_number 和 prepare_success_ballot）。
  last_do_prepare_ts:2022-04-12 19:48:36.757413			该 proposer 上一次试图触发无主选举的时间点
  self_priority	priority	is_valid:true	该优先级是否为有效状态，优先级中的所有字段将用于优先级比较，影响无主选举和有主改选。
  		fatal_failures:[]	该日志流副本上存在的致命错误。
  		serious_failures:[]	该日志流副本上存在的可导致切主的严重错误。
  		is_removed:false	该副本是否在选举黑名单中。
  		removed_reson:	该副本进入选举黑名单的原因。
  		is_server_stopped:false	该副本是否被 stop。
  		is_zone_stopped:false	该副本所在的 Zone 是否被 stop 。
  		is_manual_leader:false	该副本是否是被用户指定的 Leader 。
  		server_score:0	该副本的优先级得分，分数根据副本所在的 Zone 的优先级进行计算，分数越低优先级越高，分数为 0 表示 primary zone，分数为 INT64_MAX 时，表示该副本所在的 Zone 的优先级未被标识。
  p_election:0x7f28d7f8b9d0			选举对象的内存地址。

• 典型的 dump acceptor info 日志如下：

  
  [2022-04-13 12:10:43.153282] INFO [ELECTION] election_acceptor.cpp:120 [15620][][T1004][0][Y0-0000000000000000-0-0] [lt=18] dump acceptor info(*this={id:1, addr:"xxx.xxx.xxx.xxx:50045", ballot_number:0, ballot_of_time_window:0, lease:{owner:"xxx.xxx.xxx.xxx:50043", lease_end_ts:{span_from_now:10.999s, expired_time_point:12:10:54.152}, ballot_number:0}, is_time_window_opened:False, vote_reason:SERVER SCORE, last_time_window_open_ts:2022-04-13 12:09:51.652023, highest_priority_prepare_req_sender:"xxx.xxx.xxx.xxx:50043", highest_priority_prepare_req_ballot:0, prepare_req_with_null_priority:False, p_election:0x7fbae6b720f0})
  

  字段名	二级字段名	三级字段名	含义
  id:1			日志流 ID 。
  addr:"xxx.xxx.xxx.xxx:50045"			本机 IP 地址。
  ballot_number:0			acceptor 所处的选举轮次。
  ballot_of_time_window:0			acceptor 当前或者上一次开启的时间窗口对应的选举轮次。
  lease	owner:"xxx.xxx.xxx.xxx:50043		acceptor 维护的租约信息的持有者。
  	lease_end_ts	span_from_now:10.999s	租约距离当前还有多久到期。
  		expired_time_point:11:43:34.911	到期的具体时间点。
  	ballot_number:0		租约对应的选举轮次。
  is_time_window_opened:False			当前时间窗口的开启状态。
  vote_reason:SERVER SCORE			上一次进行 prepare 投票的原因。
  last_time_window_open_ts:2022-04-13 11:32:08.410474			上一次开启时间窗口的时间点。
  highest_priority_prepare_req_sender:"xxx.xxx.xxx.xxx:50043"
  无主选举阶段缓存的最高优先级的 proposer 的 IP 地址。
  highest_priority_prepare_req_ballot:0
  无主选举阶段缓存的最高优先级的 proposer 的选举轮次。
  prepare_req_with_null_priority:False
  无主选举阶段缓存的最高优先级的 proposer 的的优先级字段是否为空。
  p_election:0x7fbae6b720f0
  选举对象的内存地址。

适用版本

OceanBase 数据库所有版本。