OceanBase 数据库集群出现因 -4138 异常引发 -4654 不断重试进而导致简单 SQL 执行变慢

执行节点日志
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102945] WARN  setup_next_scanner (ob_direct_receive.cpp:296) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=4] [dc=0] 
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102955] WARN  [SQL.EXE] setup_next_scanner (ob_direct_receive.cpp:299) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=6] [dc=0] while fetching first scanner, the remote rcode is not OB_SUCCESS(ret=-4138, err_msg="", dst_addr=""192.168.96.56:2882"")
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102965] INFO  [SQL.RESV] ob_sql_context.cpp:189 [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=6] [dc=0] add a server to invalid server list(ret=0, invalid_server="192.168.96.56:2882", invalid_servers_=["192.168.96.56:2882"])
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102974] WARN  [SQL.EXE] inner_open (ob_direct_receive.cpp:128) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=8] [dc=0] failed to setup first scanner(ret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102985] WARN  [SQL.ENG] open (ob_phy_operator.cpp:154) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=9] [dc=0] Open this operator failed(ret=-4138, op_type="PHY_DIRECT_RECEIVE")
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102990] WARN  [SQL.ENG] open (ob_phy_operator.cpp:175) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=4] [dc=0] fail to process error(ret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102993] WARN  [SQL.EXE] open (ob_execute_result.cpp:52) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] root op fail to open(ret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.102997] WARN  [SQL] open (ob_result_set.cpp:198) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] fail open main query(ret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103000] WARN  [SQL] sync_open (ob_result_set.cpp:139) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] fail to exec open()(ret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103007] INFO  [SERVER] ob_query_retry_ctrl.cpp:567 [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=2] [dc=0] check if need retry(client_ret=-4138, err=-4138, retry_type_=2, retry_times=2, multi_stmt_item={is_part_of_multi_stmt:true, seq_num:0, sql:"select count(*) as cnt from oc_user_shop_cart_item where cart_id = 200011025007"})
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103012] WARN  [SERVER] response_result (ob_sync_plan_driver.cpp:73) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=4] [dc=0] result set open failed, check if need retry(ret=-4138, cli_ret=-4138, retry_ctrl_.need_retry()=1)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103021] WARN  [SERVER] response_result (ob_sync_plan_driver.cpp:80) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] close result set fail(cret=-4138)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103025] WARN  [SERVER] do_process (obmp_query.cpp:776) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] execute query fail(ret=-4138, timeout_timestamp=1737537595168095)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103032] WARN  [SERVER] do_process (obmp_query.cpp:821) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] [dc=0] try to execute again(ret=-4138, type=1, retry_type=2, timeout_remain=32065065)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.103055] WARN  [SERVER] process (obmp_query.cpp:321) [92235][2262][xxxxx-xxxxx-xxxxx-xxxxx] [lt=4] [dc=0] fail execute sql(sql_id="", sql=select count(*) as cnt from oc_user_shop_cart_item where cart_id = 200011025007, sessid=3222840202, ret=-4138, ret="OB_SNAPSHOT_DISCARDED", need_disconnect=false)
observer7.log/observer.log.20250122171923:[2025-01-22 17:19:23.210426] WARN  [SQL.OPT] all_select_leader (ob_phy_table_location_info.cpp:495) [92251][2294][xxxxx-xxxxx-xxxxx-xxxxx] [lt=9] [dc=0] fail to get leader(ret=-4654, phy_part_loc_info.get_partition_location()={table_id:{value:1103909674340740, first:1004, second:53636}, partition_id:0, partition_cnt:0, pg_key:{tid:1103909674340740, partition_id:0, part_cnt:0}, replica_locations:[{server_:"192.168.211.125:2882", role_:2, sql_port_:2881, replica_type_:0, attr_:{pos_type_:4, merge_status_:2, zone_type_:3, zone_status_:3, start_service_time_:0, server_stop_time_:0, server_status_:4}, is_filter_:false, replica_idx_:-1}, {server_:"192.168.46.143:2882", role_:2, sql_port_:2881, replica_type_:0, attr_:{pos_type_:4, merge_status_:2, zone_type_:3, zone_status_:3, start_service_time_:0, server_stop_time_:0, server_status_:4}, is_filter_:false, replica_idx_:-1}, {server_:"192.168.46.147:2882", role_:2, sql_port_:2881, replica_type_:0, attr_:{pos_type_:4, merge_status_:2, zone_type_:3, zone_status_:3, start_service_time_:0, server_stop_time_:0, server_status_:4}, is_filter_:false, replica_idx_:-1}, {server_:"192.168.96.58:2882", role_:2, sql_port_:2881, replica_type_:0, attr_:{pos_type_:4, merge_status_:2, zone_type_:3, zone_status_:3, start_service_time_:0, server_stop_time_:0, server_status_:4}, is_filter_:false, replica_idx_:-1}], renew_time:1737537563113187, is_mark_fail:false})
远端节点日志：
observera.log/observer.log.20250122171837:[2025-01-22 17:17:29.942543] WARN  [STORAGE] get_inc_read_tables (ob_table_store.cpp:360) [105125][3174][xxxxx-xxxxx-xxxxx-xxxxx] [lt=16] [dc=2] no table found for specified version(ret=-4138, handle={table_count:4, [{i:0, table_key:{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, ref:2}{i:1, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, ref:2}{i:2, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, ref:2}{i:3, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}, ref:2}]}, snapshot_version=1737537449941836)
observera.log/observer.log.20250122171837:[2025-01-22 17:17:29.942595] WARN  [STORAGE] get_read_tables (ob_table_store.cpp:218) [105125][3174][xxxxx-xxxxx-xxxxx-xxxxx] [lt=13] [dc=0] failed to get_inc_read_tables(ret=-4138, snapshot_version=1737537449941836, PRETTY_TS(*this)={ObTableStore_Pretty:this:0x7f1a5d732940, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, uptime:1737097340129414, table_count:5, start_pos:1, inc_pos:2, is_ready_for_read:true, replay_tables:[{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1736964010800905, base_version:0, snapshot_version:1736964010800905}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1049-0-0"}, {table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}], multi_version_start:1737093731330254, pg_memtable_mgr:{[]}, complement_minor_sstable:NULL, table_array:{
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]  pos      table_type version  base_version     multi_ver_start  snapshot_version max_merge_ver    upper_trans_ver     start_log_ts     end_log_ts       max_log_ts       ref  flag cpat 
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MAJOR      1049     0                1736964010800905 1736964010800905 1736964010800905 1736964010800905    0                0                0                1    0    1    
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]  start    MAJOR      1050     0                1737050410316949 1737050410316949 1737050410316949 1737050410316949    0                0                0                2    0    1    
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]  inc      MINI       0        1737050407841228 1737050407841228 1737050511291240 1737050511291240 1737050511291240    1737050407841228 1737050511291240 1737050511291240 2    0    1    
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MINI       0        1737050511291240 1737087008660507 1737090570730047 1737090570730047 1737090570730047    1737050511291240 1737090570730047 1737090570730047 2    0    1    
observera.log/observer.log.20250122171837:[105125] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MINI       0        1737090570730047 1737093731330254 1737097333912335 1737097333912335 1737097333912335    1737090570730047 1737097333912335 1737097333912335 2    0    1    }})
observera.log/observer.log.20250122171837:[2025-01-22 17:17:31.051530] WARN  [STORAGE] get_inc_read_tables (ob_table_store.cpp:360) [104739][2402][xxxxx-xxxxx-xxxxx-xxxxx] [lt=8] [dc=1] no table found for specified version(ret=-4138, handle={table_count:4, [{i:0, table_key:{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, ref:2}{i:1, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, ref:2}{i:2, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, ref:2}{i:3, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}, ref:3}]}, snapshot_version=1737537451050751)
observera.log/observer.log.20250122171837:[2025-01-22 17:17:31.051747] WARN  [SQL.ENG] open (ob_phy_operator.cpp:154) [104739][2402][xxxxx-xxxxx-xxxxx-xxxxx] [lt=15] [dc=0] Open this operator failed(ret=-4138, op_type="PHY_TABLE_SCAN")
observera.log/observer.log.20250122171837:[2025-01-22 17:17:31.275166] WARN  [STORAGE] get_inc_read_tables (ob_table_store.cpp:360) [104808][2540][xxxxx-xxxxx-xxxxx-xxxxx] [lt=10] [dc=0] no table found for specified version(ret=-4138, handle={table_count:4, [{i:0, table_key:{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, ref:2}{i:1, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, ref:2}{i:2, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, ref:2}{i:3, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}, ref:2}]}, snapshot_version=1737537451274373)
observera.log/observer.log.20250122171837:[2025-01-22 17:17:31.275215] WARN  [STORAGE] get_read_tables (ob_table_store.cpp:218) [104808][2540][xxxxx-xxxxx-xxxxx-xxxxx] [lt=11] [dc=0] failed to get_inc_read_tables(ret=-4138, snapshot_version=1737537451274373, PRETTY_TS(*this)={ObTableStore_Pretty:this:0x7f1a5d732940, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, uptime:1737097340129414, table_count:5, start_pos:1, inc_pos:2, is_ready_for_read:true, replay_tables:[{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1736964010800905, base_version:0, snapshot_version:1736964010800905}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1049-0-0"}, {table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, {table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}], multi_version_start:1737093731330254, pg_memtable_mgr:{[]}, complement_minor_sstable:NULL, table_array:{
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]  pos      table_type version  base_version     multi_ver_start  snapshot_version max_merge_ver    upper_trans_ver     start_log_ts     end_log_ts       max_log_ts       ref  flag cpat 
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MAJOR      1049     0                1736964010800905 1736964010800905 1736964010800905 1736964010800905    0                0                0                1    0    1    
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]  start    MAJOR      1050     0                1737050410316949 1737050410316949 1737050410316949 1737050410316949    0                0                0                2    0    1    
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]  inc      MINI       0        1737050407841228 1737050407841228 1737050511291240 1737050511291240 1737050511291240    1737050407841228 1737050511291240 1737050511291240 2    0    1    
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MINI       0        1737050511291240 1737087008660507 1737090570730047 1737090570730047 1737090570730047    1737050511291240 1737090570730047 1737090570730047 2    0    1    
observera.log/observer.log.20250122171837:[104808] [ xxxxx-xxxxx-xxxxx-xxxxx ]           MINI       0        1737090570730047 1737093731330254 1737097333912335 1737097333912335 1737097333912335    1737090570730047 1737097333912335 1737097333912335 2    0    1    }})
observera.log/observer.log.20250122171837:[2025-01-22 17:17:31.722991] WARN  [STORAGE] get_inc_read_tables (ob_table_store.cpp:360) [104743][2410][xxxxx-xxxxx-xxxxx-xxxxx] [lt=11] [dc=1] no table found for specified version(ret=-4138, handle={table_count:4, [{i:0, table_key:{table_type:1, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050410316949, base_version:0, snapshot_version:1737050410316949}, log_ts_range:{start_log_ts:0, end_log_ts:0, max_log_ts:0}, version:"1050-0-0"}, ref:2}{i:1, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737050407841228, base_version:1737050407841228, snapshot_version:1737050511291240}, log_ts_range:{start_log_ts:1737050407841228, end_log_ts:1737050511291240, max_log_ts:1737050511291240}, version:"0-0-0"}, ref:2}{i:2, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737087008660507, base_version:1737050511291240, snapshot_version:1737090570730047}, log_ts_range:{start_log_ts:1737050511291240, end_log_ts:1737090570730047, max_log_ts:1737090570730047}, version:"0-0-0"}, ref:2}{i:3, table_key:{table_type:7, pkey:{tid:1103909674340740, partition_id:0, part_cnt:0}, table_id:1103909674340743, trans_version_range:{multi_version_start:1737093731330254, base_version:1737090570730047, snapshot_version:1737097333912335}, log_ts_range:{start_log_ts:1737090570730047, end_log_ts:1737097333912335, max_log_ts:1737097333912335}, version:"0-0-0"}, ref:2}]}, snapshot_version=1737537451721986)

## 问题原因

该问题为产品缺陷导致，该缺陷导致 SQL 读取副本时获取到了错误的版本号。

## 关键信息

关键日志：

## 问题的风险及影响

SQL 执行变慢，业务耗时增加。

## 影响租户

影响 OceanBase 数据库中的 SYS 租户和 Oracle 租户以及 MySQL 租户。

## 适用版本

OceanBase 数据库 V2.x、V3.x 版本。

## 解决方法

* 升级至问题已修复版本。目前已修复的版本包括 OceanBase 数据库 V3.2.3 BP11（oceanbase-3.2.3.3-111000032024070822）。

* 应急方法：

  * 重启异常节点。

  * 将 Leader 切换到其他节点。