在 OceanBase 運維過程中，你是否遇到過這樣的場景：執行存儲過程或查詢含 LOB 列的表時，突然拋出 ORA-00600: internal error code, arguments: -4067, RPC session not found 錯誤？導致 SQL 執行失敗、表級恢復任務卡住？
今天這篇文章，就為大家深度剖析這個報錯背後的“元兇”——流式 RPC 超時問題，以及對應的解決和規避方案，幫你快速掃清障礙！
1.環境信息
• OB版本: Server version: OceanBase 4.2.1.11 (r111020032025051316-76704a9622f7e60a1a0b3f962ee2b36a731c644a) (Built May 13 2025 16:47:21)
• CPU架構: Architecture: aarch64
2.問題現象
執行 SQL 報錯ORA-00600: internal error code, arguments: -4067, RPC session not found，或者執行內部 SQL 報錯，從 OBServer 日誌中看到報錯返回了 -4067 。
具體報錯如下:
obclient [ACTEST]> CALL TEST_DUTY_REPORT();ORA-00600: internal error code, arguments: -4067, RPC session not found[xx.xx.xx.36:2882] [2025-12-0109:50:05.104118] [YB420A4A2124-00063BC89639CB73-0-0]atprocedure ACTEST.TEST_UPDATE_FLTTEAM_TO_ATESTS , line : 29, col : 10at ACTEST.TEST_DUTY_REPORT , line : 55, col : 0obclient [ACTEST]>3.關鍵診斷信息
觸發條件(兩種情況)：
- 3.1、執行 SQL 的觸發了遠程執行，並且本地端處理 SQL 結果的時候存在耗時操作（執行 PL 語句的場景比較容易觸發）。
- 3.2、表級恢復任務，inner sql 查詢的表數據包含 LOB 列。
4.事後診斷
關鍵trace_id報錯信息:
/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.101836] INFO [RPC.OBRPC] get_more (ob_rpc_proxy.ipp:52) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=2] transport_ is NULL, use poc_rpc(has_more_=true)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102074] WDIAG [RPC] get_more (ob_rpc_proxy.ipp:102) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=16][errcode=-4067] rpc decode response fail(resp=0xffd90fc04129, resp_sz=198, ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102097] WDIAG [SQL.EXE] setup_next_scanner (ob_direct_receive_op.cpp:243) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=16][errcode=-4067] fail wait response(ret=-4067, dst_addr=""xx.xx.xx.38:2882"")/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102104] WDIAG [SQL.EXE] inner_get_next_row (ob_direct_receive_op.cpp:95) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] fail to setup next scanner(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102110] WDIAG [SQL.ENG] get_next_row (ob_operator.cpp:1089) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=5][errcode=-4067] inner get next row failed(ret=-4067, type=15, op="PHY_DIRECT_RECEIVE", op_id=0)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102121] WDIAG [SQL.EXE] get_next_row (ob_execute_result.cpp:147) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10][errcode=-4067] get next row from operator failed(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102127] WDIAG [SQL] inner_get_next_row (ob_result_set.cpp:411) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=5][errcode=-4067] get next row from exec result failed(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102175] WDIAG [SQL] get_result (ob_spi.cpp:7155) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=47][errcode=-4067] read result error(ret=-4067, row_count=0, for_cursor=true)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102183] WDIAG [SERVER] after_func (ob_query_retry_ctrl.cpp:955) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] [RETRY] check if need retry(v={force_local_retry:true, stmt_retry_times:0, local_retry_times:0, err_:-4067, err_:"OB_SESSION_NOT_FOUND", retry_type:0, client_ret:-4067}, need_retry=false, THIS_WORKER.can_retry()=true, v.ctx_.multi_stmt_item_={is_part_of_multi_stmt:false, seq_num:0, sql:"", batched_queries:NULL, is_ps_mode:false, ab_cnt:0})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102228] WDIAG [SQL] inner_fetch (ob_spi.cpp:6725) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=44][errcode=-4067] failed to get_result, check if need retry(ret=-4067, cli_ret=-4067, retry_ctrl.need_retry()=0)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102242] WDIAG [SQL] do_cursor_fetch (ob_spi.cpp:4437) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=5][errcode=-4067] failed to spi cursor fetch(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102280] WDIAG [SQL] spi_cursor_fetch (ob_spi.cpp:4503) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=37][errcode=-4067] fail to exec do_cursor_fetch(ctx, cursor, OB_INVALID_ID != cursor->get_id() || (package_id != OB_INVALID_ID && OB_INVALID_ID == routine_id), into_exprs, into_count, column_types, type_count, exprs_not_null_flag, pl_integer_ranges, is_bulk, limit, return_types, return_type_count, is_type_record)(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102298] WDIAG [PL] eh_adjust_call_stack (ob_pl_exception_handling.cpp:176) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4][errcode=0] got exception! (error_code=-4067, error_code="OB_SESSION_NOT_FOUND", exception_msg=/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102754] INFO [RPC.OBRPC] abort (ob_rpc_proxy.ipp:198) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=43] transport_ is NULL, use poc_rpc(has_more_=true)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102969] WDIAG [RPC] abort (ob_rpc_proxy.ipp:250) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=11][errcode=-4067] rpc decode response fail(resp=0xffb085204129, resp_sz=198, ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102983] WDIAG [SQL.EXE] inner_close (ob_direct_receive_op.cpp:136) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=9][errcode=-4067] fail to abort(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102990] WDIAG [SQL.ENG] close (ob_operator.cpp:966) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=7][errcode=-4067] Close this operator failed(ret=-4067, op_type="PHY_DIRECT_RECEIVE")/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.102998] WDIAG [SQL.EXE] close (ob_execute_result.cpp:161) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=5][errcode=-4067] close failed(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103004] WDIAG [SQL] do_close_plan (ob_result_set.cpp:784) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] fail close main query(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103010] INFO [SQL.EXE] end_stmt (ob_sql_trans_control.cpp:1170) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4] end stmt(ret=0, plain_select=true, stmt_type=1, savepoint=0, tx_desc={this:0xfffb119a0960, tx_id:{txid:216654461}, state:3, addr:"xx.xx.xx.36:2882", tenant_id:1004, session_id:3221727554, assoc_session_id:3221727554, xid:NULL, xa_mode:"", xa_start_addr:"0.0.0.0:0", access_mode:0, tx_consistency_type:0, isolation:1, snapshot_version:{val:18446744073709551615, v:3}, snapshot_scn:0, active_scn:1764553774431851, op_sn:40826, alloc_ts:1764553774101738, active_ts:1764553774434706, commit_ts:-1, finish_ts:-1, timeout_us:3600000000, lock_timeout_us:60000000, expire_ts:1764557374434706, coord_id:{id:-1}, parts:[{id:{id:1001}, addr:"xx.xx.xx.36:2882", epoch:2801895202926783, first_scn:1764553774431851, last_scn:1764553805099895, last_touch_ts:1764553774431852}], exec_info_reap_ts:1764553774431851, commit_version:{val:18446744073709551615, v:3}, commit_times:0, commit_cb:null, cluster_id:1754451545, cluster_version:17180000523, flags_.SHADOW:false, flags_.INTERRUPTED:false, flags_.BLOCK:false, flags_.REPLICA:false, can_elr:true, cflict_txs:[], abort_cause:0, commit_expire_ts:-1, commit_task_.is_registered():false, modified_tables:[], ref:2}, trans_result={incomplete:false, parts:[], touched_ls_list:[], cflict_txs:[]}, rollback=true, need_rollback=true, session={this:0xfff26bf50378, id:3221727554, deser:false, tenant:"testprod_t01", tenant_id:1004, effective_tenant:"testprod_t01", effective_tenant_id:1004, database:"ACTEST", user:"JZ_OMS_USER", consistency_level:3, session_state:2, autocommit:false, tx:0xfffb119a0960}, exec_ctx.get_errcode()=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103060] WDIAG [SQL] close (ob_result_set.cpp:872) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=48][errcode=0] fail close main query(ret=0, do_close_plan_ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103066] WDIAG [PL] close (ob_pl_type.cpp:2177) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4][errcode=0] close mysql result set failed(ret=0, close_ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103091] WDIAG [SQL] cursor_close_impl (ob_spi.cpp:4547) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] fail to exec cursor->close(*ctx->exec_ctx_->get_my_session())(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103098] WDIAG [SQL] spi_cursor_close (ob_spi.cpp:4572) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] fail to exec cursor_close_impl(ctx, cursor, cur_var.is_ref_cursor_type(), package_id, routine_id, ignore)(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103102] WDIAG [PL] final (ob_pl.cpp:2863) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4][errcode=-4067] failed to get cursor info(tmp_ret=0, func_.get_package_id()=18446744073709551615, func_.get_routine_id()=576388, i=6)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103261] WDIAG [PL] execute (ob_pl.cpp:2147) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=0] failed to execute it(ret=0, package_id=18446744073709551615, routine_id=576388, subprogram_path=[])/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103669] WDIAG [PL] execute (ob_pl.cpp:3928) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=11][errcode=-4067] Unhandled exception has occurred in PL(*ctx_.status_=-4067, ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103684] WDIAG [PL] execute (ob_pl.cpp:1513) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10][errcode=-4067] fail to exec pl.execute()(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103697] WDIAG [PL] execute (ob_pl.cpp:2145) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=9][errcode=-4067] fail to exec execute(ctx, allocator, *(ctx.get_package_guard()), *routine, ¶ms, ((0 == nocopy_params.count()) ? __null : &nocopy_params), &result, status, stack_ctx.is_top_stack(), inner_call, routine->is_function() || in_function, false, loc, is_called_from_sql)(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103720] WDIAG [STORAGE.TRANS] do_local_abort_tx_ (ob_trans_part_ctx.cpp:7876) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10][errcode=0] do_local_abort_tx_(ret=0, ret="OB_SUCCESS", *this={this:0xffbd0eb95a50, trans_id:{txid:216654461}, tenant_id:1004, is_exiting:false, trans_expired_time:1764557374434706, cluster_version:17180000523, trans_need_wait_wrap:{receive_gts_ts_:[mts=0], need_wait_interval_us:0}, stc:[mts=0], ctx_create_time:1764553774434706}{ls_id:{id:1001}, session_id:3221727554, part_trans_action:2, pending_write:0, exec_info:{state:10, upstream:{id:-1}, participants:[], incremental_participants:[], prev_record_lsn:{lsn:2732004631000}, redo_lsns:[{lsn:2732004639361}, {lsn:2732004697720}, {lsn:2732004756077}], redo_log_no:3, multi_data_source:[], scheduler:"xx.xx.xx.36:2882", prepare_version:{val:18446744073709551615, v:3}, trans_type:0, next_log_entry_no:2053, max_applied_log_ts:{val:1764553805046913692, v:0}, max_applying_log_ts:{val:1764553805046913692, v:0}, max_applying_part_log_no:0, max_submitted_seq_no:1764553805097789, checksum:0, checksum_scn:{val:0, v:0}, max_durable_lsn:{lsn:2732004756077}, data_complete:false, is_dup_tx:false, prepare_log_info_arr:[], xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str_.ptr():"data_size:0, data:", bqual_str_.ptr():"data_size:0, data:", g_hv:0, b_hv:0}, need_checksum:true, is_sub2pc:false}, sub_state:{flag:0}, is_leaf():false, is_root():false, busy_cbs_.get_size():0, final_log_cb_:{ObTxBaseLogCb:{base_ts:{val:18446744073709551615, v:3}, log_ts:{val:18446744073709551615, v:3}, lsn:{lsn:18446744073709551615}, submit_ts:0}, this:0xffbd0eb98e48, is_inited_:true, trans_id:{txid:216654461}, ls_id:{id:1001}, ctx:0xffbd0eb95a50, tx_data_guard:{tx_data:NULL}, is_callbacked_:false, is_dynamic_:false, mds_range_:{range_array_.count():0, range_array_:[]}, cb_arg_array_:[], first_part_scn_:{val:18446744073709551615, v:3}}, ctx_tx_data_:{ctx_mgr_:0xffcc266c6030, tx_data_guard_:{tx_data:{tx_id:{txid:216654461}, ref_cnt:1, state:"RUNNING", commit_version:{val:18446744073709551615, v:3}, start_scn:{val:1764553774419360818, v:0}, end_scn:{val:18446744073709551615, v:3}, undo_status_list:{head:null, undo_node_cnt:0{}}}}, read_only_:false}, role_state_:0, start_replay_ts_:{val:18446744073709551615, v:3}, start_recover_ts_:{val:18446744073709551615, v:3}, is_incomplete_replay_ctx_:false, mt_ctx_:{ObIMvccCtx={alloc_type=0 ctx_descriptor=0 min_table_version=1764120894353976 max_table_version=1764120894353976 trans_version={val:4611686018427387903, v:0} commit_version={val:0, v:0} lock_wait_start_ts=0 replay_compact_version={val:0, v:0}} end_code=0 tx_status=0 is_readonly=false ref=0 trans_id={txid:216654461} ls_id=1001 callback_alloc_count=367148 callback_free_count=362296 checksum=0 tmp_checksum=2090807666 checksum_scn={val:1764553804643822891, v:0} redo_filled_count=367130 redo_sync_succ_count=367130 redo_sync_fail_count=0 main_list_length=4852 unsynced_cnt=19 unsubmitted_cnt_=19 cb_statistics:[main=367149, slave=0, merge=0, tx_end=0, rollback_to=0, fast_commit=362297, remove_memtable=0]}, coord_prepare_info_arr_:[], upstream_state:10, retain_cause:-1, 2pc_role:-1, collected:[], ref:3, rec_log_ts:{val:1764553774419360818, v:0}, prev_rec_log_ts:{val:18446744073709551615, v:3}, lastest_snapshot:{val:18446744073709551615, v:3}, state_info_array:[], last_request_ts:1764553805099760, block_frozen_memtable:null})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103865] INFO [STORAGE.TRANS] compensate_abort_log_ (ob_trans_part_ctx.cpp:1860) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=67] compensate abort log(ret=0, this={this:0xffbd0eb95a50, trans_id:{txid:216654461}, tenant_id:1004, is_exiting:false, trans_expired_time:1764557374434706, cluster_version:17180000523, trans_need_wait_wrap:{receive_gts_ts_:[mts=0], need_wait_interval_us:0}, stc:[mts=0], ctx_create_time:1764553774434706}{ls_id:{id:1001}, session_id:3221727554, part_trans_action:2, pending_write:0, exec_info:{state:10, upstream:{id:-1}, participants:[], incremental_participants:[], prev_record_lsn:{lsn:2732004631000}, redo_lsns:[], redo_log_no:0, multi_data_source:[], scheduler:"xx.xx.xx.36:2882", prepare_version:{val:18446744073709551615, v:3}, trans_type:0, next_log_entry_no:2054, max_applied_log_ts:{val:1764553805046913692, v:0}, max_applying_log_ts:{val:1764553805046913692, v:0}, max_applying_part_log_no:0, max_submitted_seq_no:1764553805097789, checksum:0, checksum_scn:{val:0, v:0}, max_durable_lsn:{lsn:2732004756077}, data_complete:false, is_dup_tx:false, prepare_log_info_arr:[], xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str_.ptr():"data_size:0, data:", bqual_str_.ptr():"data_size:0, data:", g_hv:0, b_hv:0}, need_checksum:true, is_sub2pc:false}, sub_state:{flag:88}, is_leaf():false, is_root():false, busy_cbs_.get_size():1, final_log_cb_:{ObTxBaseLogCb:{base_ts:{val:0, v:0}, log_ts:{val:1764553805046913693, v:0}, lsn:{lsn:2732004814423}, submit_ts:1764553805103861}, this:0xffbd0eb98e48, is_inited_:true, trans_id:{txid:216654461}, ls_id:{id:1001}, ctx:0xffbd0eb95a50, tx_data_guard:{tx_data:NULL}, is_callbacked_:false, is_dynamic_:false, mds_range_:{range_array_.count():0, range_array_:[]}, cb_arg_array_:[{log_type:0x200, arg:null}], first_part_scn_:{val:18446744073709551615, v:3}}, ctx_tx_data_:{ctx_mgr_:0xffcc266c6030, tx_data_guard_:{tx_data:{tx_id:{txid:216654461}, ref_cnt:1, state:"RUNNING", commit_version:{val:18446744073709551615, v:3}, start_scn:{val:1764553774419360818, v:0}, end_scn:{val:18446744073709551615, v:3}, undo_status_list:{head:null, undo_node_cnt:0{}}}}, read_only_:false}, role_state_:0, start_replay_ts_:{val:18446744073709551615, v:3}, start_recover_ts_:{val:18446744073709551615, v:3}, is_incomplete_replay_ctx_:false, mt_ctx_:{ObIMvccCtx={alloc_type=0 ctx_descriptor=0 min_table_version=1764120894353976 max_table_version=1764120894353976 trans_version={val:4611686018427387903, v:0} commit_version={val:0, v:0} lock_wait_start_ts=0 replay_compact_version={val:0, v:0}} end_code=0 tx_status=0 is_readonly=false ref=0 trans_id={txid:216654461} ls_id=1001 callback_alloc_count=367148 callback_free_count=362296 checksum=0 tmp_checksum=2090807666 checksum_scn={val:1764553804643822891, v:0} redo_filled_count=367130 redo_sync_succ_count=367130 redo_sync_fail_count=0 main_list_length=4852 unsynced_cnt=19 unsubmitted_cnt_=19 cb_statistics:[main=367149, slave=0, merge=0, tx_end=0, rollback_to=0, fast_commit=362297, remove_memtable=0]}, coord_prepare_info_arr_:[], upstream_state:10, retain_cause:-1, 2pc_role:-1, collected:[], ref:4, rec_log_ts:{val:1764553774419360818, v:0}, prev_rec_log_ts:{val:18446744073709551615, v:3}, lastest_snapshot:{val:18446744073709551615, v:3}, state_info_array:[], last_request_ts:1764553805099760, block_frozen_memtable:null})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103918] INFO [STORAGE.TRANS] abort_ (ob_trans_part_ctx.cpp:1873) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=52] tx abort(ret=0, reason=-6002, reason_str="OB_TRANS_ROLLBACKED", this={this:0xffbd0eb95a50, trans_id:{txid:216654461}, tenant_id:1004, is_exiting:false, trans_expired_time:1764557374434706, cluster_version:17180000523, trans_need_wait_wrap:{receive_gts_ts_:[mts=0], need_wait_interval_us:0}, stc:[mts=0], ctx_create_time:1764553774434706}{ls_id:{id:1001}, session_id:3221727554, part_trans_action:4, pending_write:0, exec_info:{state:10, upstream:{id:-1}, participants:[], incremental_participants:[], prev_record_lsn:{lsn:2732004631000}, redo_lsns:[], redo_log_no:0, multi_data_source:[], scheduler:"xx.xx.xx.36:2882", prepare_version:{val:18446744073709551615, v:3}, trans_type:0, next_log_entry_no:2054, max_applied_log_ts:{val:1764553805046913692, v:0}, max_applying_log_ts:{val:1764553805046913692, v:0}, max_applying_part_log_no:0, max_submitted_seq_no:1764553805097789, checksum:0, checksum_scn:{val:0, v:0}, max_durable_lsn:{lsn:2732004756077}, data_complete:false, is_dup_tx:false, prepare_log_info_arr:[], xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str_.ptr():"data_size:0, data:", bqual_str_.ptr():"data_size:0, data:", g_hv:0, b_hv:0}, need_checksum:true, is_sub2pc:false}, sub_state:{flag:88}, is_leaf():false, is_root():false, busy_cbs_.get_size():1, final_log_cb_:{ObTxBaseLogCb:{base_ts:{val:0, v:0}, log_ts:{val:1764553805046913693, v:0}, lsn:{lsn:2732004814423}, submit_ts:1764553805103861}, this:0xffbd0eb98e48, is_inited_:true, trans_id:{txid:216654461}, ls_id:{id:1001}, ctx:0xffbd0eb95a50, tx_data_guard:{tx_data:NULL}, is_callbacked_:false, is_dynamic_:false, mds_range_:{range_array_.count():0, range_array_:[]}, cb_arg_array_:[{log_type:0x200, arg:null}], first_part_scn_:{val:18446744073709551615, v:3}}, ctx_tx_data_:{ctx_mgr_:0xffcc266c6030, tx_data_guard_:{tx_data:{tx_id:{txid:216654461}, ref_cnt:1, state:"RUNNING", commit_version:{val:18446744073709551615, v:3}, start_scn:{val:1764553774419360818, v:0}, end_scn:{val:18446744073709551615, v:3}, undo_status_list:{head:null, undo_node_cnt:0{}}}}, read_only_:false}, role_state_:0, start_replay_ts_:{val:18446744073709551615, v:3}, start_recover_ts_:{val:18446744073709551615, v:3}, is_incomplete_replay_ctx_:false, mt_ctx_:{ObIMvccCtx={alloc_type=0 ctx_descriptor=0 min_table_version=1764120894353976 max_table_version=1764120894353976 trans_version={val:4611686018427387903, v:0} commit_version={val:0, v:0} lock_wait_start_ts=0 replay_compact_version={val:0, v:0}} end_code=0 tx_status=0 is_readonly=false ref=0 trans_id={txid:216654461} ls_id=1001 callback_alloc_count=367148 callback_free_count=362296 checksum=0 tmp_checksum=2090807666 checksum_scn={val:1764553804643822891, v:0} redo_filled_count=367130 redo_sync_succ_count=367130 redo_sync_fail_count=0 main_list_length=4852 unsynced_cnt=19 unsubmitted_cnt_=19 cb_statistics:[main=367149, slave=0, merge=0, tx_end=0, rollback_to=0, fast_commit=362297, remove_memtable=0]}, coord_prepare_info_arr_:[], upstream_state:10, retain_cause:-1, 2pc_role:-1, collected:[], ref:4, rec_log_ts:{val:1764553774419360818, v:0}, prev_rec_log_ts:{val:18446744073709551615, v:3}, lastest_snapshot:{val:18446744073709551615, v:3}, state_info_array:[], last_request_ts:1764553805099760, block_frozen_memtable:null})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103966] INFO [STORAGE.TRANS] handle_trans_abort_request (ob_trans_service_v4.cpp:2022) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=47] handle trans abort request(ret=0, abort_req={txMsg:{type:22, cluster_version:17180000523, tenant_id:1004, tx_id:{txid:216654461}, receiver:{id:1001}, sender:{id:9223372036854775807}, sender_addr:"xx.xx.xx.36:2882", epoch:-1, request_id:40827, timestamp:1764553805103714, cluster_id:1754451545}, reason:-6002})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.103981] INFO [STORAGE.TRANS] rollback_tx (ob_tx_api.cpp:345) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=13] rollback tx(ret=0, *this={is_inited_:true, tenant_id_:1004, this:0xffbd1b804030}, tx={this:0xfffb119a0960, tx_id:{txid:216654461}, state:7, addr:"xx.xx.xx.36:2882", tenant_id:1004, session_id:3221727554, assoc_session_id:3221727554, xid:NULL, xa_mode:"", xa_start_addr:"0.0.0.0:0", access_mode:0, tx_consistency_type:0, isolation:1, snapshot_version:{val:18446744073709551615, v:3}, snapshot_scn:0, active_scn:1764553774431851, op_sn:40827, alloc_ts:1764553774101738, active_ts:1764553774434706, commit_ts:-1, finish_ts:1764553805103977, timeout_us:3600000000, lock_timeout_us:60000000, expire_ts:1764557374434706, coord_id:{id:-1}, parts:[{id:{id:1001}, addr:"xx.xx.xx.36:2882", epoch:2801895202926783, first_scn:1764553774431851, last_scn:1764553805099895, last_touch_ts:1764553774431852}], exec_info_reap_ts:1764553774431851, commit_version:{val:18446744073709551615, v:3}, commit_times:0, commit_cb:null, cluster_id:1754451545, cluster_version:17180000523, flags_.SHADOW:false, flags_.INTERRUPTED:false, flags_.BLOCK:false, flags_.REPLICA:false, can_elr:true, cflict_txs:[], abort_cause:-6002, commit_expire_ts:-1, commit_task_.is_registered():false, modified_tables:[], ref:2})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104019] WDIAG [SQL.ENG] execute (ob_routine_executor.cpp:214) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=25][errcode=-4067] failed to execute pl(package_id=18446744073709551615, routine_id=576370, ret=-4067, pkg_id=-1)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104028] WDIAG [SQL] open_cmd (ob_result_set.cpp:99) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=8][errcode=-4067] execute cmd failed(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104036] WDIAG [SQL] open (ob_result_set.cpp:158) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=7][errcode=-4067] execute plan failed(ret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104041] WDIAG [SERVER] response_result (ob_sync_cmd_driver.cpp:145) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4][errcode=-4067] close result set fail(cret=-4067)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104048] WDIAG [SERVER] test (ob_query_retry_ctrl.cpp:267) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=6][errcode=-4067] current pl can not retry, commit may have occurred(v={force_local_retry:false, stmt_retry_times:0, local_retry_times:0, err_:-4067, err_:"OB_SESSION_NOT_FOUND", retry_type:0, client_ret:-4067}, v.result_.get_stmt_type()=144)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104059] WDIAG [SERVER] after_func (ob_query_retry_ctrl.cpp:955) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10][errcode=-4067] [RETRY] check if need retry(v={force_local_retry:false, stmt_retry_times:0, local_retry_times:0, err_:-4067, err_:"OB_SESSION_NOT_FOUND", retry_type:0, client_ret:-4067}, need_retry=false, THIS_WORKER.can_retry()=true, v.ctx_.multi_stmt_item_={is_part_of_multi_stmt:false, seq_num:0, sql:"CALL TEST_DUTY_REPORT()", batched_queries:NULL, is_ps_mode:false, ab_cnt:0})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104070] WDIAG [SERVER] response_result (ob_sync_cmd_driver.cpp:151) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10][errcode=-4067] result set open failed, check if need retry(ret=-4067, cli_ret=-4067, retry_ctrl_.need_retry()=0)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104104] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:319) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=4] sending error packet(ob_error=-4067, client error=600, extra_err_info=NULL, lbt()="0x11f84e10 0x934ba80 0x92fb464 0xba7e45c 0xb8826e0 0xb877c24 0xb86c5d0 0xb85beb0 0x902bc38 0x1221b1c0 0xfffc03a687ac 0xfffc039a60fc")/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104165] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:502) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10] dump txn free route audit_record(value=1048581, session->get_sessid()=3221727554, session->get_proxy_sessid()=12398691253611647492)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104178] WDIAG [SERVER] do_process (obmp_query.cpp:808) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=11][errcode=-4067] execute query fail(ret=-4067, timeout_timestamp=4981225601171756)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104225] WDIAG [SQL.PC] common_free (ob_lib_cache_object_manager.cpp:141) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=9][errcode=0] set logical del time(cache_obj->get_logical_del_time()=16907007859462, cache_obj->added_lc()=false, cache_obj->get_object_id()=1157413, cache_obj->get_tenant_id()=1004, lbt()="0x11f84e10 0x9b310a0 0xb8b0174 0x9aa37b4 0xd1c4d98 0xb88e930 0xb88c4fc 0xb87facc 0xb877c24 0xb86c5d0 0xb85beb0 0x902bc38 0x1221b1c0 0xfffc03a687ac 0xfffc039a60fc")/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104237] INFO [SQL.PC] before_cache_evicted (ob_i_lib_cache_object.cpp:76) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=10] before_cache_evicted(this=0xffd777ab4050, this={can_direct_use_param:true, package_id:18446744073709551615, routine_id:576370, out_idx:[], out_name:[], out_type:[], out_type_name:[], out_type_owner:[], is_udt_routine:false})/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.104285] TRACE [TRACE] after_process (obmp_base.cpp:145) [1667145][T1004_L0_G0][T1004][YB420A4A2124-00063BC89639CB73-0-0] [lt=13] [slow query](TRACE=begin_ts=1764553601171810 2025-12-01 01:46:41.171810|[process_begin] u=0 in_queue_time:53, receive_ts:1764553601171756, enqueue_ts:1764553601171761|[start_sql] u=1 addr:{ip:"xx.xx.xx.38", port:17196}|[query_begin] u=1 trace_id:YB420A4A2124-00063BC89639CB73-0-0|[before_processor_run] u=13 |[session] u=1 sid:3221727554, tenant_id:1004|[parse_begin] u=50 stmt:"CALL TEST_DUTY_REPORT()", stmt_len:21|[transform_with_outline_begin] u=62 |[transform_with_outline_end] u=5 |[resolve_begin] u=17 |[resolve_end] u=127 |[pc_choose_plan] u=402 |[pc_choose_plan] u=504 |[pc_choose_plan] u=2798 |[resolve_begin] u=358 |[resolve_end] u=4324 |[get_location_cache_begin] u=298 |[resolve_begin] u=106 |[resolve_end] u=1324 |[resolve_begin] u=1441 |[resolve_end] u=1860 |[resolve_begin] u=282 |[resolve_end] u=1258 |[resolve_begin] u=1922 |[resolve_end] u=2193 |[resolve_begin] u=776 |[resolve_end] u=992 |[resolve_begin] u=185 |[resolve_end] u=2122 |[resolve_begin] u=318 |[resolve_ins_tbl_begin] u=9 |[resolve_ins_tbl_end] u=1868 |[resolve_end] u=345 |[resolve_begin] u=378 |[resolve_end] u=4 |[parse_begin] u=547083 stmt:"START TRANSACTION WITH CONSISTENT SNAPSHOT", stmt_len:42|[transform_with_outline_begin] u=56 |[transform_with_outline_end] u=3 |[resolve_begin] u=11 |[resolve_end] u=10 |[start_trans] u=59 ret:0, trans_id:216653891, timeout:3216671999426528, start_time:1764553601745228|[affected_rows] u=15 affected_rows:0|[parse_begin] u=28 stmt:"delete FROM __all_tenant_error WHERE obj_id = 576379 AND tenant_id = 0 AND obj_seq = 0 AND obj_type = 12", stmt_len:255|[calc_partition_location_begin] u=27 |[tl_calc_part_id_end] u=1 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=6 |[calc_partition_location_end] u=0 |[pc_choose_plan] u=3 |[check_priv] u=2 |[plan_id] u=0 plan_id:927093|[do_open_plan_begin] u=4 plan_id:927093|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=13 |[exec_plan_begin] u=0 |[exec_plan_end] u=7 |[do_open_plan_end] u=0 |[storage_table_scan_begin] u=15 |[S_table_scan_begin] u=41 |[S_table_scan_end] u=425 |[storage_table_scan_end] u=0 |[close_plan_begin] u=42 |[S_revert_iter_begin] u=1 |[S_revert_iter_end] u=7 |[start_end_stmt] u=4 |[end_stmt] u=3 |[close_plan_end] u=0 |[affected_rows] u=0 affected_rows:0|[auto_end_plan_begin] u=1 |[auto_end_plan_end] u=0 |[parse_begin] u=20 stmt:"COMMIT", stmt_len:6|[transform_with_outline_begin] u=13 |[transform_with_outline_end] u=0 |[resolve_begin] u=4 |[resolve_end] u=3 |[affected_rows] u=34 affected_rows:0|[parse_begin] u=353 stmt:"START TRANSACTION", stmt_len:17|[transform_with_outline_begin] u=19 |[transform_with_outline_end] u=2 |[resolve_begin] u=3 |[resolve_end] u=3 |[start_trans] u=38 ret:0, trans_id:216653892, timeout:3216671999425314, start_time:1764553601746442|[affected_rows] u=9 affected_rows:0|[parse_begin] u=20 stmt:"delete FROM __all_tenant_dependency WHERE dep_obj_id = 576379 AND tenant_id = 0 AND dep_obj_type = 12", stmt_len:202|[calc_partition_location_begin] u=22 |[tl_calc_part_id_end] u=1 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=3 |[calc_partition_location_end] u=1 |[pc_choose_plan] u=4 |[check_priv] u=1 |[plan_id] u=1 plan_id:927091|[do_open_plan_begin] u=4 plan_id:927091|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=47 |[exec_plan_begin] u=0 |[exec_plan_end] u=6 |[do_open_plan_end] u=0 |[storage_table_scan_begin] u=18 |[S_table_scan_begin] u=4 |[S_table_scan_end] u=1086 |[storage_table_scan_end] u=0 |[S_delete_rows_begin] u=367 |[S_delete_rows_end] u=641 |[S_delete_rows_begin] u=29 |[S_delete_rows_end] u=912 |[close_plan_begin] u=20 |[S_revert_iter_begin] u=0 |[S_revert_iter_end] u=16 |[start_end_stmt] u=3 |[end_stmt] u=2 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:9|[auto_end_plan_begin] u=1 |[auto_end_plan_end] u=0 |[parse_begin] u=49 |[pc_choose_plan] u=35 |[check_priv] u=1 |[plan_id] u=2 plan_id:927092|[do_open_plan_begin] u=5 plan_id:927092|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=3 |[exec_plan_begin] u=1 |[exec_plan_end] u=5 |[do_open_plan_end] u=0 |[insert_open] u=3 |[insert_start] u=21 |[insert_end] u=31 |[S_insert_rows_begin] u=20 |[S_insert_rows_end] u=46 |[S_insert_rows_begin] u=10 |[S_insert_rows_end] u=10 |[sync_auto_value] u=6 |[close_plan_begin] u=12 |[insert_close] u=1 |[start_end_stmt] u=1 |[end_stmt] u=2 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:1|[auto_end_plan_begin] u=0 |[auto_end_plan_end] u=1 |[parse_begin] u=28 |[pc_choose_plan] u=25 |[check_priv] u=1 |[plan_id] u=1 plan_id:927092|[do_open_plan_begin] u=3 plan_id:927092|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=3 |[exec_plan_begin] u=0 |[exec_plan_end] u=4 |[do_open_plan_end] u=1 |[insert_open] u=1 |[insert_start] u=8 |[insert_end] u=13 |[S_insert_rows_begin] u=9 |[S_insert_rows_end] u=15 |[S_insert_rows_begin] u=7 |[S_insert_rows_end] u=9 |[sync_auto_value] u=4 |[close_plan_begin] u=8 |[insert_close] u=1 |[start_end_stmt] u=1 |[end_stmt] u=1 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:1|[auto_end_plan_begin] u=0 |[auto_end_plan_end] u=1 |[parse_begin] u=25 |[pc_choose_plan] u=24 |[check_priv] u=1 |[plan_id] u=0 plan_id:927092|[do_open_plan_begin] u=4 plan_id:927092|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=1 |[exec_plan_begin] u=1 |[exec_plan_end] u=3 |[do_open_plan_end] u=0 |[insert_open] u=2 |[insert_start] u=8 |[insert_end] u=11 |[S_insert_rows_begin] u=9 |[S_insert_rows_end] u=15 |[S_insert_rows_begin] u=7 |[S_insert_rows_end] u=8 |[sync_auto_value] u=3 |[close_plan_begin] u=8 |[insert_close] u=1 |[start_end_stmt] u=0 |[end_stmt] u=1 |[process_end] u=203354003 |total_timeu=203932474 DROPPED_EVENTS=6601344)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.114707] TRACE [TRACE] print_trace_log_if_necessary_ (ob_trans_ctx.cpp:147) [1666995][T1004_ApplySrv1][T1004][YB420A4A2124-00063BC8968520AD-0-0] [lt=3] [long trans] (TRACE=begin_ts=1764553774434933 2025-12-01 01:49:34.434933|[init] u=0 addr:0xffbd0eb95a50, id:1001, trans_id:{txid:216654461}, ref:0, opid:12475423|[start_trans] u=3 ret:0, left_time:3600000000, ref:2, opid:12475424|[start_access] u=2 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:2, data_seq:1764553774431851, pending:1, ref:2, tid:1794|[end_access] u=508 opid:2, pending:0, ref:2, tid:1794|[start_access] u=523 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:3, data_seq:1764553774431853, pending:1, ref:4, tid:1794|[end_access] u=693 opid:3, pending:0, ref:4, tid:1794|[start_access] u=323 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:4, data_seq:1764553774431855, pending:1, ref:4, tid:1794|[end_access] u=400 opid:4, pending:0, ref:4, tid:1794|[start_access] u=308 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:5, data_seq:1764553774431857, pending:1, ref:4, tid:1794|[end_access] u=394 opid:5, pending:0, ref:4, tid:1794|[start_access] u=293 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:6, data_seq:1764553774437874, pending:1, ref:4, tid:1794|[end_access] u=344 opid:6, pending:0, ref:4, tid:1794|[start_access] u=300 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:7, data_seq:1764553774437876, pending:1, ref:4, tid:1794|[end_access] u=383 opid:7, pending:0, ref:4, tid:1794|[start_access] u=2747 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:8, data_seq:1764553774441361, pending:1, ref:4, tid:1794|[end_access] u=726 opid:8, pending:0, ref:4, tid:1794|[start_access] u=316 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:9, data_seq:1764553774442090, pending:1, ref:4, tid:1794|[end_access] u=346 opid:9, pending:0, ref:4, tid:1794|[start_access] u=305 |[end_access] u=427 opid:10, pending:0, ref:4, tid:1794|[start_access] u=294 |[end_access] u=412 |[start_access] u=314 |[end_access] u=393 |[start_access] u=300 |[end_access] u=421 |[start_access] u=308 |[end_access] u=426 |[start_access] u=311 |[end_access] u=418 |[start_access] u=307 |[end_access] u=427 |[start_access] u=469 |[end_access] u=377 |[start_access] u=293 |[end_access] u=335 |[start_access] u=296 |[after_submit_log] u=799 |[submit_instant_log] u=3 |[end_access] u=65 |[start_access] u=368 |[log_sync_succ_cb] u=488 |[end_access] u=376 |[start_access] u=305 |[end_access] u=340 |[start_access] u=298 |[end_access] u=384 |[start_access] u=300 |[end_access] u=398 |[start_access] u=309 |[end_access] u=403 |[start_access] u=293 |[end_access] u=340 |[start_access] u=298 |[end_access] u=382 |[start_access] u=270 |[end_access] u=188 |[start_access] u=283 |[end_access] u=335 |[start_access] u=304 |[end_access] u=436 |[start_access] u=480 |[end_access] u=369 |[start_access] u=292 |[end_access] u=414 |[start_access] u=292 |[end_access] u=346 |[start_access] u=302 |[end_access] u=393 |[start_access] u=289 |[end_access] u=373 |[start_access] u=296 |[end_access] u=359 |[start_access] u=457 |[end_access] u=372 |[start_access] u=335 |[end_access] u=692 |[start_access] u=305 |[after_submit_log] u=792 |[submit_instant_log] u=2 |[end_access] u=110 |[start_access] u=313 |[end_access] u=361 |[log_sync_succ_cb] u=272 |[start_access] u=99 |[end_access] u=303 |[start_access] u=303 |[end_access] u=429 |[start_access] u=501 |[end_access] u=419 |[start_access] u=314 |[end_access] u=485 |[start_access] u=317 |[end_access] u=408 |[start_access] u=302 |[end_access] u=361 |[start_access] u=293 |[end_access] u=356 |[start_access] u=292 |[end_access] u=403 |[start_access] u=292 |[end_access] u=338 |[start_access] u=294 |[end_access] u=389 |[start_access] u=291 |[end_access] u=401 |[start_access] u=274 |[end_access] u=306 |[start_access] u=315 |[end_access] u=367 |[start_access] u=308 |[end_access] u=410 |[start_access] u=286 |[end_access] u=223 |[start_access] u=2785 |[end_access] u=454 |[start_access] u=290 |[end_access] u=233 |[start_access] u=298 |[end_access] u=409 |[start_access] u=310 |[end_access] u=460 |[start_access] u=344 |[after_submit_log] u=1029 |[submit_instant_log] u=3 |[end_access] u=222 |[start_access] u=593 |[log_sync_succ_cb] u=224 |[end_access] u=115 |[start_access] u=312 |[end_access] u=379 |[start_access] u=365 |[end_access] u=724 |[start_access] u=335 |[end_access] u=468 |[start_access] u=307 |[end_access] u=382 |[start_access] u=357 |[end_access] u=777 |[start_access] u=311 |[end_access] u=347 |[start_access] u=321 |[end_access] u=328 |[start_access] u=311 |[end_access] u=427 |[start_access] u=270 |[end_access] u=195 |[start_access] u=464 |[end_access] u=412 |[start_access] u=295 |[end_access] u=425 |[start_access] u=268 |[end_access] u=170 |[start_access] u=279 |[end_access] u=333 |[start_access] u=285 |[end_access] u=392 |[start_access] u=279 |[end_access] u=194 |[start_access] u=466 |[end_access] u=451 |[start_access] u=298 |[end_access] u=391 |[start_access] u=296 |[end_access] u=460 |[start_access] u=308 |[after_submit_log] u=752 |[submit_instant_log] u=4 |[end_access] u=103 |[start_access] u=314 |[end_access] u=385 |[log_sync_succ_cb] u=205 |[start_access] u=157 |[end_access] u=405 |[start_access] u=300 |[end_access] u=413 |[start_access] u=289 |[end_access] u=327 |[start_access] u=290 |[end_access] u=438 |[start_access] u=354 |[end_access] u=756 |[start_access] u=321 |[end_access] u=455 |[start_access] u=300 |[end_access] u=438 |[start_access] u=351 |[end_access] u=770 |[after_submit_log] u=30597950 |total_timeu=30668930 DROPPED_EVENTS=83503)/home/admin/oceanbase/log/observer.log.20251201095031841:[2025-12-01 09:50:05.115006] TRACE [TRACE] print_trace_log_if_necessary_ (ob_trans_ctx.cpp:147) [1666995][T1004_ApplySrv1][T1004][YB420A4A2124-00063BC8968520AD-0-0] [lt=171] [long trans] (TRACE=begin_ts=1764553774434933 2025-12-01 01:49:34.434933|[init] u=0 addr:0xffbd0eb95a50, id:1001, trans_id:{txid:216654461}, ref:0, opid:12475423|[start_trans] u=3 ret:0, left_time:3600000000, ref:2, opid:12475424|[start_access] u=2 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:2, data_seq:1764553774431851, pending:1, ref:2, tid:1794|[end_access] u=508 opid:2, pending:0, ref:2, tid:1794|[start_access] u=523 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:3, data_seq:1764553774431853, pending:1, ref:4, tid:1794|[end_access] u=693 opid:3, pending:0, ref:4, tid:1794|[start_access] u=323 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:4, data_seq:1764553774431855, pending:1, ref:4, tid:1794|[end_access] u=400 opid:4, pending:0, ref:4, tid:1794|[start_access] u=308 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:5, data_seq:1764553774431857, pending:1, ref:4, tid:1794|[end_access] u=394 opid:5, pending:0, ref:4, tid:1794|[start_access] u=293 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:6, data_seq:1764553774437874, pending:1, ref:4, tid:1794|[end_access] u=344 opid:6, pending:0, ref:4, tid:1794|[start_access] u=300 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:7, data_seq:1764553774437876, pending:1, ref:4, tid:1794|[end_access] u=383 opid:7, pending:0, ref:4, tid:1794|[start_access] u=2747 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:8, data_seq:1764553774441361, pending:1, ref:4, tid:1794|[end_access] u=726 opid:8, pending:0, ref:4, tid:1794|[start_access] u=316 ret:0, trace_id:"YB420A4A2124-00063BC89639CB73-0-0", opid:9, data_seq:1764553774442090, pending:1, ref:4, tid:1794|[end_access] u=346 opid:9, pending:0, ref:4, tid:1794|[start_access] u=305 |[end_access] u=427 opid:10, pending:0, ref:4, tid:1794|[start_access] u=294 |[end_access] u=412 |[start_access] u=314 |[end_access] u=393 |[start_access] u=300 |[end_access] u=421 |[start_access] u=308 |[end_access] u=426 |[start_access] u=311 |[end_access] u=418 |[start_access] u=307 |[end_access] u=427 |[start_access] u=469 |[end_access] u=377 |[start_access] u=293 |[end_access] u=335 |[start_access] u=296 |[after_submit_log] u=799 |[submit_instant_log] u=3 |[end_access] u=65 |[start_access] u=368 |[log_sync_succ_cb] u=488 |[end_access] u=376 |[start_access] u=305 |[end_access] u=340 |[start_access] u=298 |[end_access] u=384 |[start_access] u=300 |[end_access] u=398 |[start_access] u=309 |[end_access] u=403 |[start_access] u=293 |[end_access] u=340 |[start_access] u=298 |[end_access] u=382 |[start_access] u=270 |[end_access] u=188 |[start_access] u=283 |[end_access] u=335 |[start_access] u=304 |[end_access] u=436 |[start_access] u=480 |[end_access] u=369 |[start_access] u=292 |[end_access] u=414 |[start_access] u=292 |[end_access] u=346 |[start_access] u=302 |[end_access] u=393 |[start_access] u=289 |[end_access] u=373 |[start_access] u=296 |[end_access] u=359 |[start_access] u=457 |[end_access] u=372 |[start_access] u=335 |[end_access] u=692 |[start_access] u=305 |[after_submit_log] u=792 |[submit_instant_log] u=2 |[end_access] u=110 |[start_access] u=313 |[end_access] u=361 |[log_sync_succ_cb] u=272 |[start_access] u=99 |[end_access] u=303 |[start_access] u=303 |[end_access] u=429 |[start_access] u=501 |[end_access] u=419 |[start_access] u=314 |[end_access] u=485 |[start_access] u=317 |[end_access] u=408 |[start_access] u=302 |[end_access] u=361 |[start_access] u=293 |[end_access] u=356 |[start_access] u=292 |[end_access] u=403 |[start_access] u=292 |[end_access] u=338 |[start_access] u=294 |[end_access] u=389 |[start_access] u=291 |[end_access] u=401 |[start_access] u=274 |[end_access] u=306 |[start_access] u=315 |[end_access] u=367 |[start_access] u=308 |[end_access] u=410 |[start_access] u=286 |[end_access] u=223 |[start_access] u=2785 |[end_access] u=454 |[start_access] u=290 |[end_access] u=233 |[start_access] u=298 |[end_access] u=409 |[start_access] u=310 |[end_access] u=460 |[start_access] u=344 |[after_submit_log] u=1029 |[submit_instant_log] u=3 |[end_access] u=222 |[start_access] u=593 |[log_sync_succ_cb] u=224 |[end_access] u=115 |[start_access] u=312 |[end_access] u=379 |[start_access] u=365 |[end_access] u=724 |[start_access] u=335 |[end_access] u=468 |[start_access] u=307 |[end_access] u=382 |[start_access] u=357 |[end_access] u=777 |[start_access] u=311 |[end_access] u=347 |[start_access] u=321 |[end_access] u=328 |[start_access] u=311 |[end_access] u=427 |[start_access] u=270 |[end_access] u=195 |[start_access] u=464 |[end_access] u=412 |[start_access] u=295 |[end_access] u=425 |[start_access] u=268 |[end_access] u=170 |[start_access] u=279 |[end_access] u=333 |[start_access] u=285 |[end_access] u=392 |[start_access] u=279 |[end_access] u=194 |[start_access] u=466 |[end_access] u=451 |[start_access] u=298 |[end_access] u=391 |[start_access] u=296 |[end_access] u=460 |[start_access] u=308 |[after_submit_log] u=752 |[submit_instant_log] u=4 |[end_access] u=103 |[start_access] u=314 |[end_access] u=385 |[log_sync_succ_cb] u=205 |[start_access] u=157 |[end_access] u=405 |[start_access] u=300 |[end_access] u=413 |[start_access] u=289 |[end_access] u=327 |[start_access] u=290 |[end_access] u=438 |[start_access] u=354 |[end_access] u=756 |[start_access] u=321 |[end_access] u=455 |[start_access] u=300 |[end_access] u=438 |[start_access] u=351 |[end_access] u=770 |[destroy] u=30609092 |total_timeu=30680072 DROPPED_EVENTS=83506)5.問題原因
接收端在處理流式 RPC 請求時，在工作線程回包之後，處理不會結束而是會繼續阻塞在 wait_for_next_request 上，等待源端發送下一個請求繼續處理，直到工作線程沒有包要回了或者源端發送了一個 abort 請求。但是如果源端網絡異常或者進程被退出，abort 請求沒有被髮出去，就會導致處理端的工作線程一直 hung 在 wait_for_next_request，導致刪除租户後 unit 長時間不釋放，在 OceanBase 數據庫 V4.2.1 BP2 版本上為了解決這個問題，引入了租户工作線程處理流式 RPC 的時候等待下一個請求的最大超時時間的配置項 _stream_rpc_max_wait_timeout，配置項默認值為 30s 。
但是在某些場景下還是可能出現流式 RPC 兩次發送請求之間的間隔超過 30s ，因為這時接收端的工作線程已經退出，這樣就會導致流式RPC第二次發送請求的時候執行失敗，返回 -4067 RPC session not found 的報錯。流式 RPC 兩次發送請求之間的間隔超過 30s 的典型場景：
- 1、執行 PL 語句，查詢表數據時觸發了遠程執行計劃，遠程執行會發送流式 RPC，然後從流式 RPC 的回包中獲取數據行，然後再對每一行執行用户寫的各種 SQL/PL 語句，如果用户的 SQL 執行時間比較長，就很容易導致流式 RPC 兩次發送請求超過 30s（目前線上出現的問題都是執行 PL 的時候觸發的）。
- 2、執行 SQL 查詢一個含有 LOB 列的數據，觸發了遠程執行或者是 inner sql 的 RPC，因為在查 LOB 列數據的時候，每次還要再發一個 RPC，這種情況就會容易導致處理流式 RPC 結果的耗時過長超過 30s 。
6.問題的風險及影響
某些觸發了遠程執行的 SQL 會執行失敗、表級恢復任務卡住。
7.影響租户
影響 OceanBase 數據庫中的 SYS 租户和 Oracle 租户以及 MySQL 租户。
8.影響版本
該問題影響以下 OceanBase 數據庫版本，使用對應版本的用户需特別留意：
- 企業版 V4.2.1 GA（oceanbase-4.2.1.0-100000182023092722）及之後版本；
- 企業版 V4.2.2 GA（oceanbase-4.2.2.0-100000082024011317）及之後版本；
- 企業版 V4.3.0（oceanbase-4.3.0.0-100000072024020200）及之後版本。
9、解決方法及規避方式
9.1、解決方法
升級至問題已修復版本。目前已修復的版本包括 OceanBase 數據庫 V4.2.4（oceanbase-4.2.4.0-100000252024070621）及之後版本、V4.3.1（oceanbase-4.3.1.0-100000212024051522）及之後版本。
9.2、規避方式
在出現問題的租户中調大 _stream_rpc_max_wait_timeout 配置項。 可以直接將 _stream_rpc_max_wait_timeout 設置的更大一些，如設到 2h。
方法如下:
obclient [SYS]> alter system set _stream_rpc_max_wait_timeout = ‘2h’ tenant ‘租户名’;
調整步驟如下:
9.2.1、登錄sys租户 – 查詢調整前的配置:
obclient [SYS]> select * from gv$OB_PARAMETERS where tenant_id='1004' and name='_stream_rpc_max_wait_timeout';+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+| SVR_IP | SVR_PORT | ZONE | SCOPE | TENANT_ID | NAME | DATA_TYPE | VALUE | INFO | SECTION | EDIT_LEVEL |+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+| xx.xx.xx.37 | 2882 | zone2 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 30s | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE || xx.xx.xx.38 | 2882 | zone3 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 30s | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE || xx.xx.xx.36 | 2882 | zone1 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 30s | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE |+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+3 rows in set (0.034 sec)-- 執行參數調整obclient [SYS]> alter system set _stream_rpc_max_wait_timeout='2h' tenant 'testprod_t01';-- 查詢調整後的參數配置obclient [SYS]> select * from gv$OB_PARAMETERS where tenant_id='1004' and name='_stream_rpc_max_wait_timeout';+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+| SVR_IP | SVR_PORT | ZONE | SCOPE | TENANT_ID | NAME | DATA_TYPE | VALUE | INFO | SECTION | EDIT_LEVEL |+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+| xx.xx.xx.37 | 2882 | zone2 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 2h | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE || xx.xx.xx.38 | 2882 | zone3 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 2h | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE || xx.xx.xx.36 | 2882 | zone1 | TENANT | 1004 | _stream_rpc_max_wait_timeout | NULL | 2h | the maximum timeout for a tenant worker thread to wait for the next request while processing streaming RPC | RPC | DYNAMIC_EFFECTIVE |+-------------+----------+-------+--------+-----------+------------------------------+-----------+-------+------------------------------------------------------------------------------------------------------------+---------+-------------------+3 rows in set (0.034 sec)10.再次執行PL(執行成功)
obclient [ACTEST]> CALL TEST_DUTY_REPORT();Query OK, 0 rows affected (21 min 40.898 sec)obclient [ACTEST]>由此可見，調大配置項後，流式 RPC 兩次請求間隔超過 30s 也不會觸發超時，-4067 報錯問題得到有效解決。
如果你在實際操作中遇到了問題，或者有其他優化的見解，歡迎在評論區留言交流，後續我們還會分享更多 OceanBase 實戰乾貨，下次見~
更多技術分享可掃碼關注查看~
