你是否遇到过这样的突发状况：系统突然无法登录，数据库租户节点线程使用率直接打满，核心业务 SQL 执行时间从毫秒级飙升至 200 + 秒？

最近，我们就遇到了这样一起典型的 OceanBase 故障，根源竟是看似不起眼的时钟同步问题。今天就为大家完整复盘这次故障的排查过程、根因分析和解决方案。

一、前置信息

1.1 数据库信息

● OB版本：3.2.3 BP3

● 租户类型：Oracle

● CPU架构：arm

1.2 问题现象

行内收到反馈系统无法登录，无法使用。
查看数据库，发现该租户一个节点线程使用率已打满。
查看TOP SQL，发现有一条SQL的CPU占比高达99%，且执行时间200+s，执行报错占比90%以上，并且该SQL执行时间趋势为6:50突然从10ms恶化为200+s。
询问项目组得知该SQL为业务前置SQL，每次登录都需要调用，由以上信息初步判断为SQL恶化导致。

二、问题根因分析

2.1 SQL性能下降分析

● 通过查询ocp故障时段的top SQL记录，在7点30分之后，SQL平均执行时间长达200多秒 Top SQL语句如下：

SELECT
  t.user_id,
  t.user_name,
  t.position_id,
  t.user_type,
  t.account_status,
  t.identification_number,
  t.contact_number,
  t.contact_address,
  p.department_id,
  p.department_type,
  p.department_name,
  p.subdivision_id,
  p.parent_department_id,
  p.session_timeout,
  p.authorization_level
FROM
  user_accounts t,
  department_info p
WHERE
  t.department_id = p.department_id
  AND t.user_id = ?;

通过SQL对应的trace id分析SQL某一次整体执行过程： 1、查看该trace_id第一条日志信息，7:54:58到达数据库


[2025-12-01 07:54:58.349385] WARN  [SQL.SESSION] get_cursor (ob_SQL_session_info.cpp:1259) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=7] [dc=0] get cursor info failed(cursor_id=3, get_sessid()=3221629241)

2、通过该trace_id筛选日志


[2025-12-01 07:54:58.349385] WARN  [SQL.SESSION] get_cursor (ob_SQL_session_info.cpp:1259) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=7] [dc=0] get cursor info failed(cursor_id=3, get_sessid()=3221629241)

[2025-12-01 07:54:58.350465] INFO  [LIB] ob_tsi_factory.h:395 [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=184] [dc=0] new instance succ [N9oceanbase6common18ToCStringBufferObjINS0_8ObStringELl5ELl12288EEE] 0xffefe69c8ed0 size=61440, tsi=0xfffed13eb1d0

[2025-12-01 07:54:58.350502] WARN  [STORAGE.TRANS] check_partition_status (ob_trans_service.cpp:626) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=15] [dc=0] check participant status error(ret=-4038, trans_desc={tenant_id:0, trans_id:{
hash:0, inc:0, addr:
"10.1.1.1", t:0}, snapshot_version:-1, trans_snapshot_version:-1, trans_param:[access_mode=-1, 
type=-1, isolation=-1, magic=17361641481138401520, autocommit=0, consistency_type=0(CURRENT_READ), read_snapshot_type=1(STATEMENT_SNAPSHOT), cluster_version=0, is_inner_trans=0], participants:[], stmt_participants:[], SQL_no:0, max_SQL_no:0, cur_stmt_desc:[stmt_tenant_id=0, phy_plan_type=0, stmt_type=0, consistency_level=-1, execution_id=0, SQL_id=, trace_id=Y0-0000000000000000-0-0, is_inner_SQL=0, app_trace_id_str=, cur_stmt_specified_snapshot_version=-1, cur_query_start_time=0, is_sfu=0, is_contain_inner_table=0, trx_lock_timeout=-1, snapshot_use_publish_version=0, skip_trx=0], need_rollback:
false, trans_expired_time:0, cur_stmt_expired_time:0, trans_type:-1, is_all_select_stmt:
true, stmt_participants_pla:{partitions:[], leaders:[], type_array:[]}, participants_pla:{partitions:[], leaders:[], type_array:[]}, is_sp_trans_exiting:
false, SQL_trans_action:-1, snapshot_gene_type:-1, local_consistency_type:-1, snapshot_gene_type_str:
"UNKNOWN", local_consistency_type_str:
"UNKNOWN", session_id:0, proxy_session_id:0, app_trace_id_confirmed:
false, can_elr:
false, is_dup_table_trans:
false, is_local_trans:
true, trans_need_wait_wrap:{receive_gts_ts:{mts:0}, need_wait_interval_us:0}, is_fast_select:
false, trace_info:{app_trace_info:
"", app_trace_id:
""}, standalone_stmt_desc:{this:0xffda883571e8, trans_id:{
hash:11664684590125545061, inc:2838510259, addr:
"10.1.1.1:2882", t:1764546898349286}, tenant_id:1002, stmt_expired_time:1764547115076381, trx_lock_timeout:-1, consistency_type:0, read_snapshot_type:1, snapshot_version:1764546898010793, is_local_single_partition:
false, is_standalone_stmt_end:
false, first_pkey:{tid:18446744073709551615, partition_id:-1,  ...

[2025-12-01 07:54:58.350535] WARN  [SQL.ENG] check_partition_status (ob_table_scan_op.cpp:2146) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=32] [dc=0] failed to check partition status(ret=-4038)

[2025-12-01 07:54:58.350624] WARN  [SQL.ENG] inner_open (ob_table_scan_op.cpp:1013) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=88] [dc=0] failed to check partition status(ret=-4038)

[2025-12-01 07:54:58.350664] WARN  [SQL.ENG] open (ob_operator.cpp:525) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=39] [dc=0] Open this operator failed(ret=-4038, op_type=
"PHY_TABLE_SCAN")

[2025-12-01 07:54:58.350772] WARN  [SQL.ENG] open (ob_operator.cpp:509) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=107] [dc=0] Open child operator failed(ret=-4038, op_type=
"PHY_NESTED_LOOP_JOIN")

[2025-12-01 07:54:58.350851] WARN  [SQL.EXE] open (ob_execute_result.cpp:179) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=78] [dc=0] open operator failed(ret=-4038)

[2025-12-01 07:54:58.350893] WARN  [SQL] open (ob_result_set.cpp:212) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=42] [dc=0] fail open main query(ret=-4038)

[2025-12-01 07:54:58.350960] WARN  [SQL.SESSION] sync_open (ob_result_set.cpp:153) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=67] [dc=0] fail to 
exec open()(ret=-4038)

[2025-12-01 07:54:58.350992] WARN  [SERVER] open (ob_inner_SQL_result.cpp:125) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=12] [dc=0] open result 
set failed(ret=-4038)

[2025-12-01 07:54:58.351031] WARN  [SERVER] do_execute (ob_inner_SQL_connection.cpp:1119) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=37] [dc=0] result 
set open failed(res.result_set().get_statement_id()=25926154, ret=-4038)

[2025-12-01 07:54:58.351038] WARN  [SERVER] execute (ob_inner_SQL_connection.cpp:1222) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=6] [dc=0] execute SQL failed(ret=-4038, SQL=, retry_cnt=0)

[2025-12-01 07:54:58.351048] INFO  [SERVER] ob_inner_SQL_connection.cpp:491 [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=8] [dc=0] SQL execute need retry(ret=-4038, last_ret=-4038, retry_cnt=0, is_direct_local_plan_retry=
false)

[2025-12-01 07:54:58.351062] INFO  [SERVER] ob_inner_SQL_connection.cpp:501 [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=6] [dc=0] SQL execute need retry(ret=0, last_ret=-4038, retry_cnt=0, sleep_time_us=0)

[2025-12-01 07:54:58.351473] WARN  [SERVER] process_retry (ob_inner_SQL_connection.cpp:566) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=31] [dc=0] need retry, 
set ret to OB_SUCCESS(ret=0, last_ret=-4038, retry_cnt=0)

可以看到第一次的报错信息： check participant status error(ret=-4038并且存在大量的 -4038报错

3、查看该trace_id最后几条日志信息


[2025-12-01 07:58:35.147025] WARN  [SERVER] process_retry (ob_inner_SQL_connection.cpp:406) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=11] [dc=0] timeout, 
do not need retry(ret=-4012, last_ret=-4664, abs_timeout_us=1764547115146381, now=1764547115147022)

[2025-12-01 07:58:35.147147] WARN  [SERVER] test_and_save_retry_state (ob_query_retry_ctrl.cpp:145) [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=19] [dc=0] this worker is timeout, 
do not need retry(client_ret=-4012, err=-4012, retry_type_=0, THIS_WORKER.get_timeout_ts()=1764547115146381, result.get_stmt_type()=1, result.get_exec_context().need_change_timeout_ret()=
false, session-&gt;get_retry_info().get_last_query_retry_err()=-4038)

[2025-12-01 07:58:35.147600] TRACE [TRACE]obmp_base.cpp:147 [42710][0][YB420A023C9A-00063E201C6D9280-0-0] [lt=6] [dc=0] [slow query](TRACE=begin_ts=1764546898349351 2025-11-30 23:54:58.349351|[start_SQL] u=0 addr:{ip:
"10.1.1.1", port:33922}|[process_begin] u=1 addr:{ip:
"10.1.1.1", port:33922}, in_queue_time:83202969, receive_ts:1764546815146381, enqueue_ts:1764546815146381, trace_id:YB420A023C9A-00063E201C6D9280-0-0|[session] u=3 sid:3221629241, tenant_id:1002|[session] u=14 sid:3221629241, tenant_id:1002|[session] u=2 sid:3221629241, tenant_id:1002|[calc_partition_location_begin] u=277 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=7 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=0 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=5 |[post_packet] u=29 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=744 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=6 |[get_location_cache_begin] u=528 |[result_set_close] u=597 |[close_plan_begin] u=0 |[end_participant_begin] u=1 |[start_end_stmt] u=0 |[auto_end_plan_begin] u=1 |[calc_partition_location_begin] u=771 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=8 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=39 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=4 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=23 |[post_packet] u=32 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=568 |[SQL_start_stmt_begin] u=0 |[SQL_start_participant_begin] u=6 |[result_set_close] u=10207 |[close_plan_begin] u=0 |[end_participant_begin] u=2 |[start_end_stmt] u=1 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=57 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=5 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=16 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=24 |[post_packet] u=22 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=555 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=6 |[result_set_close] u=20107 |[close_plan_begin] u=0 |[end_participant_begin] u=2 |[start_end_stmt] u=0 |[auto_end_plan_begin] u=1 |[calc_partition_location_begin] u=54 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=5 |[calc_partition_location_end] u=1 |[calc_partition_location_begin] u=16 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=16 |[post_packet] u=20 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=1108 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=8 |[result_set_close] u=30166 |[close_plan_begin] u=0 |[end_participant_begin] u=2 |[start_end_stmt] u=1 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=59 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=5 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=23 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=21 |[post_packet] u=25 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=1663 |[SQL_start_stmt_begin] u=0 |[SQL_start_participant_begin] u=8 |[result_set_close] u=40172 |[close_plan_begin] u=1 |[end_participant_begin] u=1 |[start_end_stmt] u=1 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=55 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=4 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=17 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=1 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=16 |[post_packet] u=24 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=558 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=5 |[result_set_close] u=50152 |[close_plan_begin] u=0 |[end_participant_begin] u=3 |[start_end_stmt] u=1 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=62 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=4 |[calc_partition_location_end] u=1 |[calc_partition_location_begin] u=15 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=15 |[post_packet] u=24 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=557 |[SQL_start_stmt_begin] u=0 |[SQL_start_participant_begin] u=6 |[result_set_close] u=60147 |[close_plan_begin] u=0 |[end_participant_begin] u=3 |[start_end_stmt] u=0 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=76 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=5 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=17 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=1 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=17 |[post_packet] u=26 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=557 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=6 |[result_set_close] u=70155 |[close_plan_begin] u=1 |[end_participant_begin] u=3 |[start_end_stmt] u=0 |[auto_end_plan_begin] u=1 |[calc_partition_location_begin] u=110 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=6 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=16 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=22 |[post_packet] u=23 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=556 |[SQL_start_stmt_begin] u=0 |[SQL_start_participant_begin] u=6 |[result_set_close] u=80124 |[close_plan_begin] u=1 |[end_participant_begin] u=3 |[start_end_stmt] u=0 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=66 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=7 |[calc_partition_location_end] u=0 |[calc_partition_location_begin] u=18 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=2 |[calc_partition_location_end] u=0 |[get_plan_type_end] u=17 |[post_packet] u=27 ret:0, pcode:1808, addr:{ip:
"10.1.1.3", port:2882}|[do_open_plan_begin] u=550 |[SQL_start_stmt_begin] u=1 |[SQL_start_participant_begin] u=8 |[result_set_close] u=90152 |[close_plan_begin] u=1 |[end_participant_begin] u=2 |[start_end_stmt] u=1 |[auto_end_plan_begin] u=0 |[calc_partition_location_begin] u=60 |[get_location_cache_begin] u=0 |[process_end] u=216335800 |total_timeu=216798190 DROPPED_EVENTS=1600)

可以看到以下信息：

最后报错为超时报错
报错前还有-4012与-4664报错码
SQL真正开始时间戳为：1764546898349351
存在大量获取location事件，并且有 1600 个 event 被丢弃，共耗时216798190us

从日志中可以看到，从SQL执行后，开始获取主副本所在时就报无主(-4038)，后续持续报错无主，并多次在获取location信息阶段(-4664)，直至执行超时。

而无主导致一个简单SQL查询卡住，SQL积压加上源源不断的该SQL的请求，导致租户线程使用率用满，业务无法使用。

2.2 根因分析

通过对问题SQL的分享，可以发现，主要问题是无主导致的SQL执行超时

● 查看[2025-12-01 07:54:58.349385]~[2025-12-01 07:58:35.147600]及之前的选举日志


[2025-12-01 07:54:57.662795] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652640951, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546897321056, sender=
"10.1.1.3:2882")

[2025-12-01 07:54:57.870535] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=13] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652640955, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546897810559, sender=
"10.1.1.2:2882")

[2025-12-01 07:54:57.972649] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710655553547, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546897632008, sender=
"10.1.1.3:2882")

[2025-12-01 07:54:59.811534] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=13] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652640954, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546899750271, sender=
"10.1.1.2:2882")

[2025-12-01 07:54:59.982067] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=14] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710655547943, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546899640493, sender=
"10.1.1.3:2882")

[2025-12-01 07:55:00.182881] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=12] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652640951, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764546900121916, sender=
"10.1.1.2:2882")

[2025-12-01 07:58:14.691117] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652640954, partition_id:0, part_cnt:0}, msg=[
type=100, send_ts=1764547094350196, sender=
"10.1.1.3:2882")

[2025-12-01 07:58:15.201658] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652641204, partition_id:525, part_cnt:0}, msg=[
type=100, send_ts=1764547095140609, sender=
"10.1.1.2:2882")

[2025-12-01 07:58:15.481225] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=12] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652641204, partition_id:525, part_cnt:0}, msg=[
type=100, send_ts=1764547095140536, sender=
"10.1.1.3:2882")

可以发现，有大量的 -7006报错


[2025-12-01 07:58:14.431997] WARN  [ELECT] check_decentralized_majority (ob_election_msg_pool.cpp:334) [43592][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] message t1 timestamp not match(partition={tid:1101710655553547, partition_id:0, part_cnt:0}, t1=1764547092000000, record_t1=-1, ret=-7038)

以及有 -7038报错，搜索ERROR级告警，可清楚看到数据库的错误


[2025-12-01 06:11:31.611894] INFO  [ELECT] leader_revoke_ (ob_election.cpp:2026) [43592][0][Y0-0000000000000000-0-0] [lt=5] [dc=0] leader revoke(election={partition:{tid:1101710652640955, partition_id:0, part_cnt:0}, is_running:
true, is_changing_leader:
true, self:
"10.1.1.1:2882", proposal_leader:
"10.1.1.3:2882", cur_leader:
"10.1.1.1:2882", curr_candidates:3{server:
"10.1.1.1:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.2:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.3:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}, curr_membership_version:1764540556349318, leader_lease:[1764540595010000, 1764540691600000], election_time_offset:4610000, active_timestamp:1757009773716420, T1_timestamp:1764540687000000, leader_epoch:1764540584800000, state:0, role:1, stage:1, 
type:-1, replica_num:3, unconfirmed_leader:
"10.1.1.3:2882", unconfirmed_leader_lease:[1764540690210000, 1764540701010000], takeover_t1_timestamp:1764540675800000, is_need_query:
true, valid_candidates:2{server:
"10.1.1.1:2882", timestamp:-1, flag:0, need_encrypt:
false}{server:
"10.1.1.2:2882", timestamp:-1, flag:0, need_encrypt:
false}, change_leader_timestamp:1764540689800000, ignore_log:
false, leader_revoke_timestamp:1764540691611861, vote_period:4, lease_time:9800000, move_out_timestamp:1764540683368861, eg_part_array_idx:-1, eg_id_hash:0})

[2025-12-01 06:11:31.611940] ERROR [ELECT] run_gt1_task (ob_election.cpp:2548) [43592][0][Y0-0000000000000000-0-0] [lt=10] [dc=0] leader_revoke, please attention!(revoke reason=
"leader lease expired", election={partition:{tid:1101710652640955, partition_id:0, part_cnt:0}, is_running:
true, is_changing_leader:
false, self:
"10.1.1.1:2882", proposal_leader:
"10.1.1.3", cur_leader:
"10.1.1.1", curr_candidates:3{server:
"10.1.1.1:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.2:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.3:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}, curr_membership_version:1764540556349318, leader_lease:[0, 0], election_time_offset:4610000, active_timestamp:1757009773716420, T1_timestamp:1764540687000000, leader_epoch:1764540584800000, state:0, role:0, stage:1, 
type:-1, replica_num:3, unconfirmed_leader:
"10.1.1.3:2882", unconfirmed_leader_lease:[1764540690210000, 1764540701010000], takeover_t1_timestamp:1764540675800000, is_need_query:
true, valid_candidates:0, change_leader_timestamp:0, ignore_log:
false, leader_revoke_timestamp:1764540691611861, vote_period:4, lease_time:9800000, move_out_timestamp:1764540683368861, eg_part_array_idx:-1, eg_id_hash:0}) BACKTRACE:0xeed8e98 0xabcb168 0x494bf18 0x494bafc 0x494b9d0 0x92a2440 0x9218ca4 0x92171e8 0x928b8d4 0xab809cc 0x4a54d00 0xedb4058 0xedb3e9c 0xf05169c

[2025-12-01 06:11:31.621992] WARN  [ELECT] check_decentralized_majority (ob_election_msg_pool.cpp:334) [43593][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] message t1 timestamp not match(partition={tid:1101710652640953, partition_id:0, part_cnt:0}, t1=1764540687000000, record_t1=-1, ret=-7038)

[2025-12-01 06:11:31.878345] WARN  [ELECT] handle_election_msg_unlock_ (ob_election_mgr.cpp:601) [42107][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] handle query leader error(ret=-7006, partition={tid:1101710652641204, partition_id:525, part_cnt:0}, msg=[
type=100, send_ts=1764540691540714, sender=
"10.1.1.3:2882")

[2025-12-01 06:11:32.010664] WARN  [ELECT] run_gt2_task (ob_election.cpp:2991) [43592][0][Y0-0000000000000000-0-0] [lt=33] [dc=0] not send devote vote(ret=0, election={partition:{tid:1101710652640955, partition_id:0, part_cnt:0}, is_running:
true, is_changing_leader:
false, self:
"10.1.1.1:2882", proposal_leader:
"10.1.1.3", cur_leader:
"10.1.1.1", curr_candidates:3{server:
"10.1.1.1:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.2:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}{server:
"10.1.1.3:2882", timestamp:1757009773708619, flag:0, need_encrypt:
false}, curr_membership_version:1764540556349318, leader_lease:[0, 0], election_time_offset:4610000, active_timestamp:1757009773716420, T1_timestamp:1764540687000000, leader_epoch:1764540584800000, state:4, role:0, stage:1, 
type:-1, replica_num:3, unconfirmed_leader:
"10.1.1.3:2882", unconfirmed_leader_lease:[1764540690210000, 1764540701010000], takeover_t1_timestamp:1764540675800000, is_need_query:
true, valid_candidates:0, change_leader_timestamp:0, ignore_log:
false, leader_revoke_timestamp:1764540691611861, vote_period:4, lease_time:9800000, move_out_timestamp:1764540683368861, eg_part_array_idx:-1, eg_id_hash:0}, is_send_vote=
true, server=
"10.1.1.1:2882", cur_ts=1764540692010617)

leader_revoke, please attention!(revoke reason="leader lease expired6:11该表租约已到期，需要切主，而后续却是无法得到投票信息，导致持续的缺主

2.3 问题定位

> 3.x版本的OceanBase 数据库的选举模型是依赖时钟同步的选举方案，同个分区的多个全能副本在一个选举周期内进行预投票、投票、计票广播以及结束投票，最终敲定唯一的主副本。当选举成功后，每个副本会签订认定 Leader 的租约（Lease）。

在租约过期前，Leader 会不断发起连任，正常情况下能够一直连任成功。如果 Leader 没有连任成功，在租约到期后会周期性的发起无主选举，保证数据有主副本对外提供数据服务。

而理想情况下成为Leader的的基础条件为：

多个副本节点之间时钟完全一致。
所有选举的投票消息都有效快速地达到了目标地。

Paxos 选举协议会检查每个消息在发送端和接收端的时间差（即消息的延迟时间），并且设置了最大允许的延迟，其中同时考虑了 2 个机器间的 时钟延迟上限（最大为 100 ms）和 rpc 延迟上限（最大为 200 ms）。

当消息延迟超过上限后，就认为是过期消息，就会被 RootService 的选举模块忽略，此时选举不能正常进行，会导致 OceanBase 数据库集群没有主副本或者发生脑裂。

根据上述的官方文档内容，以及已知情况：

该报错时间点租户、涉及表、分区，均未被删除
所有节点运行正常，无宕机情况
网络正常
租户资源使用情况正常
集群节点主机状态正常，无相关告警
为选举阶段问题，并非Clog 模块在再确认阶段失败

那么，只剩从以下两方面查看：

1、查看时钟延迟

最直观的查看方法为登录集群节点进行查看时钟延迟时间


使用 chronyc sources -v 或 ntpq -p方式验证时钟时效

而OB日志中，需要时钟延迟大于500ms才会在日志中进行打印

并未搜索到相关日志内容

而在主机上查看时发现 主机与时钟服务器间延迟已达400ms

2、查看rpc 延迟

RPC异常时会记录至日志中


grep 
'message not in time' election.log -----判断选举的消息是否存在延迟

grep 
'packet fly cost too much'  observer.log -----检查是否存在 RPC 相关的异常

grep 
"packet fly" observer.log|grep 
"fly_ts=" --color  ----查看RPC延迟时间(RPC异常时会记录)


[2025-12-01 06:25:07.123556] WARN  [ELECT] process_vote_prepare_ (ob_election_group.cpp:789) [38224][0][Y0-0000000000000000-0-0] [lt=7] [dc=0] message not 
in time(ret=-7011, self={is_running:
true, eg_part_cnt:100, eg_id:{eg_id_hash:7124759360868384791, server:
"10.1.1.2:2882", create_time:1757009781922097}, eg_version:10238, pre_destroy_state:
false, is_all_part_merged_in:
true, self:
"10.1.1.3:2882", cur_leader:
"10.1.1.2:2882", sorted_member_list:0, tenant_id:1002, lease_start:0, lease_end:1764541516800000, active_timestamp:1757009784602026, T1_timestamp:1764541506000000, state:1, role:0, replica_num:0, unconfirmed_leader:
"10.1.1.2:2882", takeover_t1_timestamp:1764541506000000, vote_period:1, lease_time:9800000}, msg=[
type=6, send_ts=1764541507400167, sender=
"10.1.1.2:2882", T1=1764541507400000, cur_leader=
"10.1.1.2:2882", new_leader=
"10.1.1.2:2882", lease_time=9800000], cur_ts=1764541507123548, msg fly cost=-276619, delta over msg_t1=-276452)


[2025-12-01 06:11:23.368921] WARN  [RPC.OBRPC] decode (ob_rpc_net_handler.cpp:207) [43532][0][Y0-0000000000000000-0-0] [lt=12] [dc=0] packet fly cost too much time(pcode=2311, fly_ts=337132, send_timestamp=1764540683031780, connection=
"10.1.1.1:2882_10.1.1.3:47732_204_0xfffb37172140 tp=0 t=1757009601124124-1764540683368908 s=0 r=0 io=344372983027/63661404996 sq=63661401571")

通过查看RPC延迟可以明显看到，节点间的延迟已经达到了300+ms，已经严重影响了集群的正常使用。

可以看到问题根因，为时钟同步异常

具体问题发生情况分析如下：

主机时钟同步异常→主机间rpc延迟异常→Leader租约到期→无法得到有效投票信息→表无主→业务SQL查询该表→超时+业务SQL持续进入→SQL积压导致租户线程打满，导致系统不可用

三、解决方案及建议

● 优化 NTP 时钟同步架构，选用低延迟、高可用的 NTP 服务节点（建议优先部署本地内网 NTP 集群），通过精细化高可用配置确保 OceanBase 集群所有 observer 节点间的时钟偏差严格控制在 50ms 以内，至多不超过100ms，以恢复集群时钟一致性，保障数据库服务在正常态运行。

● 配置ocp告警推送，及时发现问题并处理

四、Q&A

Q：1、时钟延时日志中是否有显示

A：OB日志中，需要时钟延迟大于500ms才会在日志中进行打印

Q：2、为什么最后一条日志的时间会显示"2025-11-30 23:54:58.349351"

A：OB日志记录显示时间为+0时区时间，换算到+8时区后为"2025-12-01 07:54:58.349351"

Q：3、租约到期是为什么？

A：选出Leader之后，Leader会在自己的租约过期之前不断发起连任，正常情况下能够一直连任成功。与无主选举不同，连任过程是事件驱动的，主要步骤如下:

1.Leader检查租约剩余时长，若达到连任条件，则给所有参与者发送连任请求;

2.参与者收到连任请求后，确认Leader与本地信息一致，则给其发送投票消息;

3.Leader收到投票消息后，暂存于本地，并检查当前票数是否超过半数，若未超过则继续等待，若超过则连任成功，给所有参与者发送新的租约。

当前租约时长为9.8s，Leader在租约经过5,6s时开始尝试连任，若连任失败则每隔1.4s尝试一次，直至租约过期

五、参考文档

https://www.oceanbase.com/knowledge-base/oceanbase-database-20000000075?back=kb

https://www.oceanbase.com/knowledge-base/oceanbase-database-20000000165

很多时候，数据库故障的根源并非复杂的内核问题，而是时钟同步、网络延迟这类基础配置项。如果你也遇到过类似的 OceanBase 故障，欢迎在评论区留言交流！下次见~

更多技术分享可扫码关注查看~

ITPub博客

系统突然无法登录？ OceanBase 线程打满，元凶竟是时钟同步