划线反馈

日志未回调/同步超时问题排查

更新时间：2024-05-28 09:56

适用版本：V4.1.x、V4.2.x内容类型：TechNote

当遇到提交的 clog 日志超时未回调时，可能是日志同步流程发生了异常，首先，确认发生超时的租户 id 和 ls_id。

以下分析内容以 1012 租户的 1001 日志流为例。

查询视图

如果集群还能登录，可以先查表确认对应日志流的角色分布以及日志位点情况：

obclient > select * from GV$OB_LOG_STAT where tenant_id = 1012 and ls_id=1001 order by 1,2,3,4,5;

其中 max_lsn 表示副本上已经收到的 lsn 最大的日志，可以看到两个 follower 的 max_lsn 比 leader 的要小，隔几秒再查，如果 follower 的 max_lsn 没有推进，那么说明它发生了异常，比如可能是盘满无法继续收日志。

分析 leader 的日志

首先要确认 palf 日志同步过程是否发生了超时，在 leader 上搜索 palf 的日志：

grep 'PALF.*T1012'    observer.log |  grep 'palf_id=1001' | grep ' ERROR ' | head

如果看到了如下 ERROR 日志，说明日志同步超时（滑动窗口中第一条日志 10 秒未达成多数派），start_id=1013683 表示该条 group log 的 log_id：

[2022-07-13 14:28:51.252175] EDIAG [PALF] check_leader_log_sync_state_ (log_state_mgr.cpp:851) [17546][T1012_LogLoop][T1012][Y0-0000000000000000-0-0] [lt=11] log sync timeout on leader(palf_id=1001, self="xxx.xxx.xxx.xxx:xxxx", now_ns=1657693731252172723, last_check_start_id_time_ns_=1657632769636055624, start_id=1013683) BACKTRACE:0x43365ae 0xc1227da 0xc114133 0x443f3d9 0x443f0b1 0x443ef05 0x443eaa7 0x4576652 0x432a594 0x4570262 0x432a4aa 0x4329c55 0x4329537 0x4329472 0x4323903 0x44d2cb0 0x443e763 0xc316426 0xc311079 0x7fbe53637ea4 0x7fbe52ee1b0c

接下来，我们继续分析palf的日志：

grep 'PALF.*T1012'    observer.log |  grep 'check_and_switch_state.*palf_id=1001' | less

返回结果如下：

[2022-07-13 14:28:51.837516] INFO  [PALF] check_and_switch_state (palf_handle_impl.cpp:1960) [17546][T1012_LogLoop][T1012][Y0-0000000000000000-0-0] [lt=19] [PALF_DUMP](palf_id=1001, self="xxx.xxx.xxx.xxx:xxxx", [SlidingWindow]={palf_id:1001, self:"xxx.xxx.xxx.xxx:xxxx", lsn_allocator:{max_log_id:1013867, max_lsn:7902913446, max_log_ts:1657632777688274465}, last_submit_lsn:{val1:7902913288}, last_submit_end_lsn:{val1:7902913446}, last_submit_log_id:1013867, last_submit_log_pid:1, max_flushed_lsn:{val1:7902913288}, max_flushed_end_lsn:{val1:7902913446}, max_flushed_log_pid:1, committed_end_lsn:{val1:7901185359}, last_slide_log_id:1013682, last_slide_log_ts:1657632769630792493, last_slide_lsn:{val1:7901174914}, last_slide_end_lsn:{val1:7901185359}, last_slide_log_pid:1, last_slide_log_accum_checksum:581212328, last_fetch_end_lsn:{val1:18446744073709551615}, last_fetch_max_log_id:-1, last_fetch_committed_end_lsn:{val1:18446744073709551615}, last_truncate_lsn:{val1:18446744073709551615}, this:0x7fbb3150c410}, [StateMgr]={this:0x7fbb3150dfd0, self:"xxx.xxx.xxx.xxx:xxxx", palf_id:1001, role:"LEADER", state:"ACTIVE", prepare_meta:{version:1, voted_for:0, log_proposal_id:1}, leader:"xxx.xxx.xxx.xxx:xxxx", leader_epoch:0, is_sync_enabled:true, pending_end_lsn:{val1:18446744073709551615}, scan_disk_log_finished:true, last_check_start_id:1013683, reconfirm_start_time_ns:1657612654326086483, palf_role_change_cb:0x7fbb31511a68}, [ConfigMgr]={palf_id:1001, self:"xxx.xxx.xxx.xxx:xxxx", log_ms_meta:{version:1, proposal_id:1, prev:{config_version:{proposal_id:0, config_seq:1}, log_sync_memberlist:3{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}, log_sync_replica_num:3, arbitration_member:{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:-1, flag:0}, learnerlist:{learner_num:0, learner_array:[]}, degraded_learnerlist:{learner_num:0, learner_array:[]}, access_mode:1, ref_ts_ns:0}, curr:{config_version:{proposal_id:1, config_seq:2}, log_sync_memberlist:3{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}, log_sync_replica_num:3, arbitration_member:{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:-1, flag:0}, learnerlist:{learner_num:0, learner_array:[]}, degraded_learnerlist:{learner_num:0, learner_array:[]}, access_mode:1, ref_ts_ns:0}}, region:"default_region", paxos_member_region_map:{}, ms_state:0, persistent_config_version:{proposal_id:1, config_seq:2}, ms_ack_list:0, resend_config_version:{proposal_id:1, config_seq:2}, resend_log_list:{learner_num:0, learner_array:[]}, register_ts_ns:-1, parent:"xxx.xxx.xxx.xxx:xxxx", parent_keepalive_ts_ns:-1, last_submit_register_req_ts_ns:-1, children:{learner_num:0, learner_array:[]}, last_submit_keepalive_ts_ns:-1, this:0x7fbb3150d0d0}, [LogEngine]={palf_id:1001, is_inited:true, min_block_ts_ns:1657618699840721107, min_block_id:21, base_lsn_for_block_gc:{val1:7649943552}, log_meta:{version:1, log_prepare_meta:{version:1, voted_for:0, log_proposal_id:1}, log_config_meta:{version:1, proposal_id:1, prev:{config_version:{proposal_id:0, config_seq:1}, log_sync_memberlist:3{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}, log_sync_replica_num:3, arbitration_member:{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:-1, flag:0}, learnerlist:{learner_num:0, learner_array:[]}, degraded_learnerlist:{learner_num:0, learner_array:[]}, access_mode:1, ref_ts_ns:0}, curr:{config_version:{proposal_id:1, config_seq:2}, log_sync_memberlist:3{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}, log_sync_replica_num:3, arbitration_member:{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:-1, flag:0}, learnerlist:{learner_num:0, learner_array:[]}, degraded_learnerlist:{learner_num:0, learner_array:[]}, access_mode:1, ref_ts_ns:0}}, log_snapshot_meta:{version:1, base_lsn:{val1:7649943552}, prev_log_info:{log_id:-1, lsn:{val1:18446744073709551615}, log_ts:-1, log_proposal_id:9223372036854775807, accum_checksum:-1}}, log_manifest_meta:{version:1, next_block_id:118}, log_replica_property_meta:{allow_vote:true, replica_type:"NORMAL_REPLICA"}}, log_meta_storage:{log_tail:{val1:733184}, log_block_header:{magic:18754, version:1, min_lsn:{val1:18446744073709551615}, min_timestamp:-1, curr_block_id:274894685184, palf_id:-1}, block_mgr:{log_dir:"/data/log1/hudson//ob1.z3.obs1/store/clog/tenant_1012/1001/meta", dir_fd:420, min_block_id:0, max_block_id:1, curr_writable_block_id:0}, logical_block_size_:67104768, curr_block_writable_size_:66371584}, log_storage:{log_tail:{val1:7902913446}, log_block_header:{magic:18754, version:1, min_lsn:{val1:18446744073709551615}, min_timestamp:-1, curr_block_id:274894685184, palf_id:-1}, block_mgr:{log_dir:"/data/log1/hudson//ob1.z3.obs1/store/clog/tenant_1012/1001/log", dir_fd:424, min_block_id:21, max_block_id:118, curr_writable_block_id:117}, logical_block_size_:67104768, curr_block_writable_size_:15449178}, palf_epoch:2, this:0x7fbb3150e3d0}, [Reconfirm]={palf_id:1001, self:"xxx.xxx.xxx.xxx:xxxx", state:"FINISHED", new_proposal_id:1, prepare_log_ack_list:2"xxx.xxx.xxx.xxx:xxxx";"xxx.xxx.xxx.xxx:xxxx";, curr_paxos_follower_list:2{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}{server:"xxx.xxx.xxx.xxx:xxxx", timestamp:1, flag:0}, majority_cnt:2, start_memberhsip_version:{proposal_id:1, config_seq:2}, majority_max_log_server:"xxx.xxx.xxx.xxx:xxxx", majority_max_accept_pid:0, majority_max_lsn:{val1:0}, saved_end_lsn:{val1:0}, last_submit_prepare_req_ts_ns:1657612654326201636, last_fetch_log_ts_ns:-1, last_record_sw_start_id:-1, this:0x7fbb3150e0d0})

查看日志中的如下字段：

最后一条生成并开始处理的 group_log，其 end_lsn、log_id 如下：last_submit_end_lsn:{val1:7902913446}, last_submit_log_id:1013867。
当前本地写盘成功的位点：max_flushed_end_lsn:{val1:7902913446}。
当前已经达成多数派的位点：committed_end_lsn:{val1:7901185359}。

如果 max_flushed_end_lsn < last_submit_end_lsn，说明本地写盘位点没有推到最新，可能写盘流程慢或者卡了；如果 max_flushed_end_lsn == last_submit_end_lsn，说明本地写盘都已完成。再看 committed_end_lsn，如果其小于 last_submit_end_lsn 和 max_flushed_end_lsn，那说明最后这条日志本地写盘已经完成，但未达成多数派，那么大概率是 follower 上发生了异常。

分析 follower 的日志

在其中一个 follower 上（如果有多个 follower，依次查看），同样搜索该租户日志流的 palf 日志：

grep 'T1012.*PALF_DUMP.*palf_id=1001'  observer.log | less

可能遇到的异常如下。

盘满

目前遇到比较常见的异常就是 follower 上日志盘满，导致无法接收新的日志，盘满对应的 ERROR 日志如下：

[2022-07-13 16:07:52.682656] EDIAG [PALF] try_recycle_blocks (palf_env_impl.cpp:615) [17525][T1012_PalfGC][T1012][Y0-0000000000000000-0-0] [lt=10] clog disk space is amlost full(this={self:"xxx.xxx.xxx.xxx:xxxx", log_dir:"/data/log1/hudson//ob1.z2.obs1/store/clog/tenant_1012", disk_options:{log_disk_size(MB):8192, log_disk_utilization_threshold(%):80, log_disk_utilization_limit_threshold(%):95}}, disk_options={log_disk_size(MB):8192, log_disk_utilization_threshold(%):80, log_disk_utilization_limit_threshold(%):95}, capacity(MB):=8192, can_used_disk_size(MB):=6553, used(MB):=7782) BACKTRACE:0x43365ae 0xc1227da 0xc114133 0x443f3d9 0x443f0b1 0x443ef05 0x443eaa7 0x45952c5 0x4594860 0x435007a 0x434ea3d 0x51fc139 0xc316426 0xc311079 0x7f0edd22eea4 0x7f0edcad8b0c

盘满后，就无法继续收日志了，会伴随着 receive_log 相关的报错，盘满的错误码是 -4264：

[2022-07-13 16:20:50.834441] WARN  [PALF] receive_log (palf_handle_impl.cpp:2257) [100883][T1012_TNT_L0][T1012][Y965645869EB-0005E396FB4A2751-0-0] [lt=8] log outof disk space(ret=-4264, this={palf_id:1001, self:"xxx.xxx.xxx.xxx:xxxx", has_set_deleted:false}, server="xxx.xxx.xxx.xxx:xxxx", push_log_type=1, lsn={val1:524032340})

确认盘满问题之后，可以通过盘满问题排查手册继续分析原因。

RPC 队列积压

还有一种可能是 leader 和 follower 之间的 RPC 通信发生异常，比如 follower 上 RPC 请求队列发生积压（大概率是有死锁），可以在落后的 follower 上搜索如下日志确认是否有积压：

grep 'dump tenant info.*id:1012'   observer.log

如果是请求积压的场景，类似的日志如下：

[2022-07-06 22:37:19.082819] INFO  [SERVER.OMT] run1 (ob_multi_tenant.cpp:2015) [79546][MultiTenant][T0][Y0-0000000000000000-0-0] dump tenant info(tenant={id:1012, tenant_meta:{unit:{tenant_id:1004, unit_id:1008, has_memstore:true, unit_status:"NORMAL", config:{unit_config_id:1002, name:"mysql_box", min_cpu:4, max_cpu:4, min_memory:"18.6264515GB", max_memory:"18.6264515GB", log_disk_size:"18.6264515GB", min_iops:1000000, max_iops:10000000, max_session_num:64, iops_weight:0}, mode:0, create_timestamp:1657116616115944, is_removed:false}, super_block:{tenant_id:1004, replay_start_point:ObLogCursor{file_id=1, log_id=473, offset=354117}, ls_meta_entry:[270](ver=0,mode=0,seq=269), tablet_meta_entry:[271](ver=0,mode=0,seq=270), gts_limited_id:1657116685926171850, gti_limited_id:1000001, das_limited_id:1}, create_status:1}, unit_min_cpu:"4.000000000000000000e+00", unit_max_cpu:"4.000000000000000000e+00", slice:"0.000000000000000000e+00", slice_remain:"0.000000000000000000e+00", token_cnt:16, sug_token_cnt:16, ass_token_cnt:16, lq_tokens:4, used_lq_tokens:4, stopped:false, idle_us:9966404, recv_hp_rpc_cnt:33, recv_np_rpc_cnt:834, recv_lp_rpc_cnt:0, recv_mysql_cnt:301, recv_task_cnt:0, recv_large_req_cnt:19, tt_large_quries:437, pop_normal_cnt:183679, actives:16, workers:16, nesting workers:7, lq waiting workers:0, req_queue:total_size=649 queue[0]=0 queue[1]=0 queue[2]=634 queue[3]=0 queue[4]=15 queue[5]=0 , large queued:3, multi_level_queue:total_size=0 queue[0]=0 queue[1]=0 queue[2]=0 queue[3]=0 queue[4]=0 queue[5]=0 queue[6]=0 queue[7]=0 , recv_level_rpc_cnt:cnt[0]=0 cnt[1]=0 cnt[2]=0 cnt[3]=0 cnt[4]=0 cnt[5]=242 cnt[6]=0 cnt[7]=0 , group_map:group_id = 1,queue_size = 12800,recv_req_cnt = 258978,pop_req_cnt = 258978,token_cnt = 4,min_token_cnt = 4,max_token_cnt = 4,ass_token_cnt = 4 , rpc_stat_info: pcode=0x1516:cnt=10837 pcode=0x1501:cnt=8949 pcode=0x1502:cnt=6852 pcode=0x150a:cnt=3500 pcode=0x150b:cnt=1543})

其中 group_map:group_id = 1,queue_size = 12800 显示 group_id=1 的线程池（palf+election专用）请求积压了 12800。接下来可以用 sudo obstack $pid 的方式查看堆栈，确认是否存在死锁。

RPC 分配内存失败

RPC 处理请求时如果分配内存失败会导致请求进不来，搜索方式如下：

grep '\-4013'   observer.log  | grep rpc

如果能搜到日志，说明有此类问题，可以继续关注下里面的 pcode。

适用版本

OceanBase 数据库 V4.x 版本。

Clog 盘满如何排查

如何查看 clog 超限的日志

OceanBase 数据库