[2023-09-04 14:51:05.785219] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=6] total rowcount, use statistics(table_meta_info_.table_row_count_=801279, table_meta_info_.average_row_size_=2.110000000000000000e+02, table_meta_info_.micro_block_count_=1079, table_meta_info_.part_size_=1.690698690000000000e+08)
[2023-09-04 14:51:05.790906] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=25] total rowcount, use statistics(table_meta_info_.table_row_count_=637044, table_meta_info_.average_row_size_=3.730000000000000000e+02, table_meta_info_.micro_block_count_=2294, table_meta_info_.part_size_=2.376174120000000000e+08)
[2023-09-04 14:51:05.793249] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=24] total rowcount, use statistics(table_meta_info_.table_row_count_=1441854, table_meta_info_.average_row_size_=2.140000000000000000e+02, table_meta_info_.micro_block_count_=1086, table_meta_info_.part_size_=3.085567560000000000e+08)
[2023-09-04 14:51:05.793563] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=24] total rowcount, use statistics(table_meta_info_.table_row_count_=1498923, table_meta_info_.average_row_size_=4.390000000000000000e+02, table_meta_info_.micro_block_count_=7747, table_meta_info_.part_size_=6.580271970000000000e+08)
[2023-09-04 14:51:05.793764] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=18] total rowcount, use statistics(table_meta_info_.table_row_count_=23599, table_meta_info_.average_row_size_=1.950000000000000000e+02, table_meta_info_.micro_block_count_=43, table_meta_info_.part_size_=4.601805000000000000e+06)
[2023-09-04 14:51:05.793969] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=17] total rowcount, use statistics(table_meta_info_.table_row_count_=637044, table_meta_info_.average_row_size_=3.730000000000000000e+02, table_meta_info_.micro_block_count_=2294, table_meta_info_.part_size_=2.376174120000000000e+08)
[2023-09-04 14:51:05.796355] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=21] total rowcount, use statistics(table_meta_info_.table_row_count_=871, table_meta_info_.average_row_size_=3.580000000000000000e+02, table_meta_info_.micro_block_count_=6, table_meta_info_.part_size_=3.118180000000000000e+05)
[2023-09-04 14:51:05.796534] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=26] total rowcount, use statistics(table_meta_info_.table_row_count_=44, table_meta_info_.average_row_size_=1.560000000000000000e+02, table_meta_info_.micro_block_count_=1, table_meta_info_.part_size_=6.864000000000000000e+03)
[2023-09-04 14:51:05.796690] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:10739) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=16] total rowcount, use statistics(table_meta_info_.table_row_count_=872389, table_meta_info_.average_row_size_=4.200000000000000000e+01, table_meta_info_.micro_block_count_=534, table_meta_info_.part_size_=3.664033800000000000e+07)
[2023-09-04 14:51:06.782434] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=17] trace sort need dump(dumped=false, mem_context_->used()=2232984, get_memory_limit()=2306867, profile_.get_cache_size()=2306867, profile_.get_expect_size()=2306867, sql_mem_processor_.get_data_size()=2162688)
[2023-09-04 14:51:06.783515] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=30] trace sort need dump(dumped=false, mem_context_->used()=2364056, get_memory_limit()=2537553, profile_.get_cache_size()=2537553, profile_.get_expect_size()=2537553, sql_mem_processor_.get_data_size()=2293760)
[2023-09-04 14:51:06.855033] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=17] trace sort need dump(dumped=false, mem_context_->used()=2560664, get_memory_limit()=2791308, profile_.get_cache_size()=2791308, profile_.get_expect_size()=2791308, sql_mem_processor_.get_data_size()=2490368)
[2023-09-04 14:51:06.856508] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=23] trace sort need dump(dumped=false, mem_context_->used()=2822808, get_memory_limit()=3070438, profile_.get_cache_size()=3070438, profile_.get_expect_size()=3070438, sql_mem_processor_.get_data_size()=2752512)
[2023-09-04 14:51:06.905105] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=15] trace sort need dump(dumped=false, mem_context_->used()=3083928, get_memory_limit()=3377481, profile_.get_cache_size()=3377481, profile_.get_expect_size()=3377481, sql_mem_processor_.get_data_size()=2949120)
[2023-09-04 14:51:06.971493] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=25] trace sort need dump(dumped=false, mem_context_->used()=3411608, get_memory_limit()=3715229, profile_.get_cache_size()=3715229, profile_.get_expect_size()=3715229, sql_mem_processor_.get_data_size()=3276800)
[2023-09-04 14:51:07.036338] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=24] trace sort need dump(dumped=false, mem_context_->used()=3739288, get_memory_limit()=4086751, profile_.get_cache_size()=4086751, profile_.get_expect_size()=4086751, sql_mem_processor_.get_data_size()=3604480)
[2023-09-04 14:51:07.104081] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=24] trace sort need dump(dumped=false, mem_context_->used()=4132504, get_memory_limit()=4495426, profile_.get_cache_size()=4495426, profile_.get_expect_size()=4495426, sql_mem_processor_.get_data_size()=3997696)
[2023-09-04 14:51:07.173629] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=22] trace sort need dump(dumped=false, mem_context_->used()=4525720, get_memory_limit()=4944968, profile_.get_cache_size()=4944968, profile_.get_expect_size()=4944968, sql_mem_processor_.get_data_size()=4390912)
[2023-09-04 14:51:07.241261] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=22] trace sort need dump(dumped=false, mem_context_->used()=4984472, get_memory_limit()=5439464, profile_.get_cache_size()=5439464, profile_.get_expect_size()=5439464, sql_mem_processor_.get_data_size()=4849664)
[2023-09-04 14:51:07.363024] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=26] trace sort need dump(dumped=false, mem_context_->used()=5443352, get_memory_limit()=5983410, profile_.get_cache_size()=5983410, profile_.get_expect_size()=5983410, sql_mem_processor_.get_data_size()=5308416)
[2023-09-04 14:51:07.428814] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=30] trace sort need dump(dumped=false, mem_context_->used()=6031128, get_memory_limit()=6581751, profile_.get_cache_size()=6581751, profile_.get_expect_size()=6581751, sql_mem_processor_.get_data_size()=5767168)
[2023-09-04 14:51:07.570631] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=31] trace sort need dump(dumped=false, mem_context_->used()=6620952, get_memory_limit()=7239926, profile_.get_cache_size()=7239926, profile_.get_expect_size()=7239926, sql_mem_processor_.get_data_size()=6356992)
[2023-09-04 14:51:07.700789] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=18] trace sort need dump(dumped=false, mem_context_->used()=7276312, get_memory_limit()=7963918, profile_.get_cache_size()=7963918, profile_.get_expect_size()=7963918, sql_mem_processor_.get_data_size()=7012352)
[2023-09-04 14:51:07.824554] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=33] trace sort need dump(dumped=false, mem_context_->used()=7997208, get_memory_limit()=8760309, profile_.get_cache_size()=8760309, profile_.get_expect_size()=8760309, sql_mem_processor_.get_data_size()=7733248)
[2023-09-04 14:51:07.957236] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=22] trace sort need dump(dumped=false, mem_context_->used()=8783768, get_memory_limit()=9636339, profile_.get_cache_size()=9636339, profile_.get_expect_size()=9636339, sql_mem_processor_.get_data_size()=8519680)
[2023-09-04 14:51:08.151498] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=21] trace sort need dump(dumped=false, mem_context_->used()=9701272, get_memory_limit()=10599972, profile_.get_cache_size()=10599972, profile_.get_expect_size()=10599972, sql_mem_processor_.get_data_size()=9437184)
[2023-09-04 14:51:08.270214] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=10] trace sort need dump(dumped=false, mem_context_->used()=10618776, get_memory_limit()=11659969, profile_.get_cache_size()=11659969, profile_.get_expect_size()=11659969, sql_mem_processor_.get_data_size()=10354688)
[2023-09-04 14:51:08.470236] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=27] trace sort need dump(dumped=false, mem_context_->used()=11728792, get_memory_limit()=12825965, profile_.get_cache_size()=12825965, profile_.get_expect_size()=12825965, sql_mem_processor_.get_data_size()=11206656)
[2023-09-04 14:51:08.655324] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=30] trace sort need dump(dumped=false, mem_context_->used()=12842904, get_memory_limit()=14108561, profile_.get_cache_size()=14108561, profile_.get_expect_size()=14108561, sql_mem_processor_.get_data_size()=12320768)
[2023-09-04 14:51:08.932552] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=16] trace sort need dump(dumped=false, mem_context_->used()=14153624, get_memory_limit()=15519417, profile_.get_cache_size()=15519417, profile_.get_expect_size()=15519417, sql_mem_processor_.get_data_size()=13631488)
[2023-09-04 14:51:09.207205] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=34] trace sort need dump(dumped=false, mem_context_->used()=15530008, get_memory_limit()=17071358, profile_.get_cache_size()=17071358, profile_.get_expect_size()=17071358, sql_mem_processor_.get_data_size()=15007744)
[2023-09-04 14:51:09.487693] INFO  [SQL.ENG] preprocess_dump (ob_sort_op_impl.cpp:962) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=30] trace sort need dump(dumped=false, mem_context_->used()=17102872, get_memory_limit()=18778493, profile_.get_cache_size()=18778493, profile_.get_expect_size()=18778493, sql_mem_processor_.get_data_size()=16580608)
[2023-09-04 14:51:09.670649] INFO  [STORAGE] open (ob_tmp_file.cpp:1235) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=32] succeed to open a tmp file(fd=53761, dir=3526057, common::lbt()="0xdbdb755 0xb2d672f 0xb2d5eb2 0x9491af6 0x9491250 0x949311e 0x9955da8 0x3a6b24c 0x93c8a1b 0x93c72ab 0x3a6b24c 0x3a6584d 0x3a63c51 0x3a62e1b 0x3a5e40b 0x3a59524 0x3a5552a 0x3a5365b 0x3a502c1 0x63541f4 0xde4dde7 0xde47bca 0x7f8f9da28dc5 0x7f8f9d75773d")
[2023-09-04 14:51:09.670681] INFO  [SQL.ENG] write_file (ob_ra_datum_store.cpp:1130) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=33] open file success(fd=53761, dir_id=3526057)
[2023-09-04 14:51:09.689685] WDIAG [SQL.ENG] iterate_both_chidren (ob_merge_join_op.cpp:1348) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=6][errcode=-4016] unexpected negative mem bound(ret=-4016, t_mem_bound=2097152, l_mem_bound=2422942, r_mem_bound=-393216, l_store->get_mem_hold()=2490368)
[2023-09-04 14:51:09.689714] WDIAG [SQL.ENG] batch_join_both (ob_merge_join_op.cpp:1403) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=32][errcode=-4016] iterate both children failed(ret=-4016)
[2023-09-04 14:51:09.689719] WDIAG [SQL.ENG] inner_get_next_batch (ob_merge_join_op.cpp:1845) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=5][errcode=-4016] batch join both failed(ret=-4016)
[2023-09-04 14:51:09.689724] WDIAG [SQL.ENG] get_next_batch (ob_operator.cpp:1118) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3][errcode=-4016] get next batch failed(ret=-4016, eval_ctx={batch_idx:0, batch_size:256, max_batch_size:256, frames_:0x7f8c3ebb5090}, id=1, op_name="PHY_MERGE_JOIN")
[2023-09-04 14:51:09.689736] WDIAG [SQL.ENG] next_batch (ob_hash_groupby_op.cpp:1788) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=10][errcode=-4016] fail to get next batch(ret=-4016)
[2023-09-04 14:51:09.689740] WDIAG [SQL.ENG] load_data_batch (ob_hash_groupby_op.cpp:1626) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=4][errcode=-4016] fail to get next batch(ret=-4016)
[2023-09-04 14:51:09.689746] WDIAG [SQL.ENG] inner_get_next_batch (ob_hash_groupby_op.cpp:1503) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=2][errcode=-4016] load data failed(ret=-4016)
[2023-09-04 14:51:09.689749] WDIAG [SQL.ENG] get_next_batch (ob_operator.cpp:1118) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3][errcode=-4016] get next batch failed(ret=-4016, eval_ctx={batch_idx:0, batch_size:256, max_batch_size:256, frames_:0x7f8c3ebb5090}, id=0, op_name="PHY_HASH_GROUP_BY")
[2023-09-04 14:51:09.689755] WDIAG [SQL.ENG] get_next_row (ob_operator.cpp:1391) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=5][errcode=-4016] get next batch failed(ret=-4016)
[2023-09-04 14:51:09.689759] WDIAG [SQL] inner_get_next_row (ob_result_set.cpp:374) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3][errcode=-4016] get next row from exec result failed(ret=-4016)
[2023-09-04 14:51:09.689765] WDIAG [SERVER] response_query_result (ob_query_driver.cpp:233) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3][errcode=-4016] fail to iterate and response(ret=-4016, row_num=0, can_retry=true)
[2023-09-04 14:51:09.689774] WDIAG [SERVER] response_result (ob_sync_plan_driver.cpp:101) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=7][errcode=-4016] response query result fail(ret=-4016)
[2023-09-04 14:51:09.689780] WDIAG [SERVER] after_func (ob_query_retry_ctrl.cpp:872) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=4][errcode=-4016] [RETRY] check if need retry(v={force_local_retry:false, stmt_retry_times:0, local_retry_times:0, err_:-4016, err_:"OB_ERR_UNEXPECTED", retry_type:0, client_ret:-4016}, need_retry=false)
[2023-09-04 14:51:09.689791] WDIAG [SERVER] response_result (ob_sync_plan_driver.cpp:114) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=11][errcode=-4016] result response failed, check if need retry(ret=-4016, cli_ret=-4016, retry_ctrl_.need_retry()=0)
[2023-09-04 14:51:09.690009] INFO  [SQL.EXE] end_stmt (ob_sql_trans_control.cpp:926) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=6] end stmt(ret=0, plain_select=true, stmt_type=1, savepoint=0, tx_desc={this:0x7f8ecc99ce40, tx_id:{txid:0}, state:1, addr:"192.168.0.62:2882", tenant_id:1004, session_id:3221891857, assoc_session_id:3221891857, 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}, snapshot_scn:0, active_scn:-1, op_sn:1, alloc_ts:1693810266046748, active_ts:-1, commit_ts:-1, finish_ts:-1, timeout_us:-1, lock_timeout_us:-1, expire_ts:9223372036854775807, coord_id:{id:-1}, parts:[], exec_info_reap_ts:0, commit_version:{val:18446744073709551615}, commit_cb:null, cluster_id:-1, cluster_version:0, flags_.SHADOW:false, flags_.INTERRUPTED:false, flags_.BLOCK:false, flags_.REPLICA:false, can_elr:true, cflict_txs:[], abort_cause:0, commit_expire_ts:0, commit_task_.is_registered():false, ref:1}, trans_result={incomplete:false, parts:[], touched_ls_list:[], cflict_txs:[]}, rollback=true, session={this:0x7f8e38e980e8, id:3221891857, tenant:"tt_edu", tenant_id:1004, effective_tenant:"tt_edu", effective_tenant_id:1004, database:"edu_dw", user:"edudiagnose@%", consistency_level:3, session_state:2, autocommit:true, tx:0x7f8ecc99ce40}, exec_ctx.get_errcode()=-4016)
[2023-09-04 14:51:09.690067] WDIAG [SERVER] response_result (ob_sync_plan_driver.cpp:121) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=48][errcode=-4016] close result set fail(cret=-4016)
[2023-09-04 14:51:09.690079] INFO  [SERVER] send_error_packet (obmp_packet_sender.cpp:311) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=4] sending error packet(err=-4016, extra_err_info=NULL, lbt()="0xdbdb755 0x7647c01 0x760b1fa 0x3a634d0 0x3a5e40b 0x3a59524 0x3a5552a 0x3a5365b 0x3a502c1 0x63541f4 0xde4dde7 0xde47bca 0x7f8f9da28dc5 0x7f8f9d75773d")
[2023-09-04 14:51:09.690109] INFO  [SERVER] add_changed_session_info (obmp_utils.cpp:81) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=11] success add system var to ok pack(str_kv={key:"ob_statement_trace_id", value:"YB42C0A8003E-000601C0C10DC25D-0-0"}, change_var={id_:10037, old_val_:{"VARCHAR":"YB42C0A8003D-000601C21B7D7214-0-0", collation:"utf8mb4_general_ci", coercibility:"IMPLICIT"}}, new_val={"VARCHAR":"YB42C0A8003E-000601C0C10DC25D-0-0", collation:"utf8mb4_general_ci", coercibility:"IMPLICIT"}, session.get_sessid()=3221891857, session.get_proxy_sessid()=13882479996272054482, change_var.id_=10037)
[2023-09-04 14:51:09.690149] INFO  [SERVER] send_error_packet (obmp_packet_sender.cpp:472) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=16] dump txn free route audit_record(value=5, session->get_sessid()=3221891857, session->get_proxy_sessid()=13882479996272054482)
[2023-09-04 14:51:09.690161] WDIAG [SERVER] do_process (obmp_query.cpp:846) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=10][errcode=-4016] execute query fail(ret=-4016, timeout_timestamp=1693813865779263)
[2023-09-04 14:51:09.690214] INFO  [STORAGE] remove (ob_tmp_file.cpp:1429) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=6] succeed to remove a tmp file(fd=53761, common::lbt()="0xdbdb755 0xb2d9784 0xb2d90cb 0x948fb2d 0x996a49b 0x3a789cd 0x3d04f45 0x3a5eba8 0x3a59524 0x3a5552a 0x3a5365b 0x3a502c1 0x63541f4 0xde4dde7 0xde47bca 0x7f8f9da28dc5 0x7f8f9d75773d")
[2023-09-04 14:51:09.690280] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=13] finish to free a block(ret=0, block_id=357041, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690306] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=13] finish to free a block(ret=0, block_id=357040, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690325] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=8] finish to free a block(ret=0, block_id=357039, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690338] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3] finish to free a block(ret=0, block_id=357038, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690351] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3] finish to free a block(ret=0, block_id=357037, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690371] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=9] finish to free a block(ret=0, block_id=357036, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690384] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=4] finish to free a block(ret=0, block_id=357035, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690402] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=7] finish to free a block(ret=0, block_id=357034, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690420] INFO  [STORAGE] free_macro_block (ob_tmp_file_store.cpp:1057) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=6] finish to free a block(ret=0, block_id=357033, macro_id=[9223372036854775807](ver=0,mode=0,seq=0), dir_id=3526057, free_page_nums=252)
[2023-09-04 14:51:09.690430] INFO  [SQL.ENG] reset (ob_ra_datum_store.cpp:414) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=7] close file success(ret=0, fd=53761)
[2023-09-04 14:51:09.690752] TRACE [TRACE] after_process (obmp_base.cpp:142) [8500][T1004_L0_G0][T1004][YB42C0A8003E-000601C0C10DC25D-0-0] [lt=3] [slow query](TRACE=begin_ts=1693810265779281 2023-09-04 06:51:05.779281|[process_begin] u=0 in_queue_time:17, receive_ts:1693810265779263, enqueue_ts:1693810265779265|[start_sql] u=0 addr:{ip:"192.168.0.61", port:62548}|[query_begin] u=1 trace_id:YB42C0A8003E-000601C0C10DC25D-0-0|[before_processor_run] u=3 |[session] u=2 sid:3221891857, tenant_id:1004|[transform_with_outline_begin] u=272 |[transform_with_outline_end] u=4 |[resolve_begin] u=5 |[resolve_end] u=1119 |[transform_begin] u=58 |[tl_calc_part_id_end] u=4447 |[get_location_cache_begin] u=1 |[tl_calc_part_id_end] u=211 |[tl_calc_part_id_end] u=14 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=10 |[storage_estimation_begin] u=3 |[storage_estimation_end] u=5184 |[tl_calc_part_id_end] u=265 |[get_location_cache_begin] u=1 |[tl_calc_part_id_end] u=117 |[storage_estimation_begin] u=3 |[storage_estimation_end] u=1950 |[tl_calc_part_id_end] u=272 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=93 |[tl_calc_part_id_end] u=20 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=35 |[tl_calc_part_id_end] u=168 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=83 |[storage_estimation_begin] u=3 |[storage_estimation_end] u=31 |[tl_calc_part_id_end] u=88 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=70 |[storage_estimation_begin] u=3 |[storage_estimation_end] u=18 |[tl_calc_part_id_end] u=115 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=66 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=2144 |[tl_calc_part_id_end] u=168 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=98 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=25 |[tl_calc_part_id_end] u=60 |[get_location_cache_begin] u=1 |[tl_calc_part_id_end] u=40 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=16 |[tl_calc_part_id_end] u=100 |[get_location_cache_begin] u=0 |[tl_calc_part_id_end] u=40 |[storage_estimation_begin] u=3 |[storage_estimation_end] u=2116 |[storage_estimation_begin] u=516 |[storage_estimation_end] u=22 |[tl_calc_part_id_end] u=728 |[tl_calc_part_id_end] u=19 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=8 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=11 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=9304 |[tl_calc_part_id_end] u=740 |[tl_calc_part_id_end] u=16 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=5 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=52 |[tl_calc_part_id_end] u=627 |[tl_calc_part_id_end] u=19 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=8 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=7 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=8463 |[tl_calc_part_id_end] u=697 |[tl_calc_part_id_end] u=6 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=35 |[tl_calc_part_id_end] u=660 |[tl_calc_part_id_end] u=12 |[tl_calc_part_id_end] u=25 |[tl_calc_part_id_end] u=13 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=8 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=7 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=8722 |[tl_calc_part_id_end] u=767 |[tl_calc_part_id_end] u=9 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=32 |[storage_estimation_begin] u=465 |[storage_estimation_end] u=17 |[tl_calc_part_id_end] u=630 |[tl_calc_part_id_end] u=19 |[tl_calc_part_id_end] u=13 |[tl_calc_part_id_end] u=12 |[tl_calc_part_id_end] u=15 |[tl_calc_part_id_end] u=12 |[tl_calc_part_id_end] u=13 |[tl_calc_part_id_end] u=12 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=11133 |[storage_estimation_begin] u=705 |[storage_estimation_end] u=22 |[tl_calc_part_id_end] u=588 |[tl_calc_part_id_end] u=12 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=8 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=7 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=9814 |[storage_estimation_begin] u=771 |[storage_estimation_end] u=38 |[storage_estimation_begin] u=396 |[storage_estimation_end] u=18 |[storage_estimation_begin] u=175 |[storage_estimation_end] u=17 |[tl_calc_part_id_end] u=406 |[tl_calc_part_id_end] u=7 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=33 |[tl_calc_part_id_end] u=275 |[tl_calc_part_id_end] u=9 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=6 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=41 |[tl_calc_part_id_end] u=386 |[tl_calc_part_id_end] u=6 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=25 |[tl_calc_part_id_end] u=230 |[tl_calc_part_id_end] u=7 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=4 |[storage_estimation_begin] u=1 |[storage_estimation_end] u=24 |[storage_estimation_begin] u=380 |[storage_estimation_end] u=21 |[tl_calc_part_id_end] u=195 |[tl_calc_part_id_end] u=7 |[storage_estimation_begin] u=2 |[storage_estimation_end] u=26 |[tl_calc_part_id_end] u=187922 |[tl_calc_part_id_end] u=33 |[tl_calc_part_id_end] u=12 |[tl_calc_part_id_end] u=4 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=3 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=3 |[tl_calc_part_id_end] u=5 |[tl_calc_part_id_end] u=1 |[cg_end] u=866 |[plan_id] u=907 plan_id:121984|[tl_calc_part_id_end] u=6 |[tl_calc_part_id_end] u=10 |[tl_calc_part_id_end] u=3 |[tl_calc_part_id_end] u=2 |[tl_calc_part_id_end] u=3 |[tl_calc_part_id_end] u=1 |[do_open_plan_begin] u=6 plan_id:121984|[sql_start_stmt_begin] u=1 |[post_packet] u=31 ret:0, pcode:1808, addr:{ip:"192.168.0.61", port:2882}|[sql_start_stmt_end] u=581 |[exec_plan_begin] u=0 |[exec_plan_end] u=65 |[do_open_plan_end] u=0 |[post_packet] u=412 ret:0, pcode:1311, addr:{ip:"192.168.0.61", port:2882}|[sqc_finish] u=17682 dfo_id:0, sqc_id:0|[process_end] u=3624631 |total_timeu=3911468 DROPPED_EVENTS=353)