查询表数据时命令被Killed

chenyk88 · 2023 年7 月 7 日 14:33

查询一个5千万的表数据时命令执行了1分多钟后就被Killed了。。。这个应该设置哪个超时参数？永久设置应该怎么设置？

张雨齐 · 2023 年7 月 7 日 14:35

提示具体错误信息，是事务错误还是单sql超时。
根据错误信息，文档中心搜一下就能看到

洪波 · 2023 年7 月 7 日 14:36

kill现象是什么？报什么错误了

chenyk88 · 2023 年7 月 7 日 14:42

就一条select * from ds1.tipt_advice_execute_plan_log 命令而已，没有错误，执行一分钟就被killed。

洪波 · 2023 年7 月 7 日 15:00

根据这条sql，在GV$OB_SQL_AUDIT这个表里找出对应的trace_id，然后根据trace_id过滤下错误日志，看下是什么原因导致的kill

chenyk88 · 2023 年7 月 7 日 16:21

这个是在GV$OB_SQL_AUDIT查询到的，能看出原因吗？

SVR_IP	SVR_PORT	REQUEST_ID	SQL_EXEC_ID	TRACE_ID	SID	CLIENT_IP	CLIENT_PORT	TENANT_ID	TENANT_NAME	EFFECTIVE_TENANT_ID	USER_ID	USER_NAME	USER_GROUP	USER_CLIENT_IP	DB_ID	DB_NAME	SQL_ID	QUERY_SQL	PLAN_ID	AFFECTED_ROWS	RETURN_ROWS	PARTITION_CNT	RET_CODE	QC_ID	DFO_ID	SQC_ID	WORKER_ID	EVENT	P1TEXT	P1	P2TEXT	P2	P3TEXT	P3	LEVEL	WAIT_CLASS_ID	WAIT_CLASS#	WAIT_CLASS	STATE	WAIT_TIME_MICRO	TOTAL_WAIT_TIME_MICRO	TOTAL_WAITS	RPC_COUNT	PLAN_TYPE	IS_INNER_SQL	IS_EXECUTOR_RPC	IS_HIT_PLAN	REQUEST_TIME	ELAPSED_TIME	NET_TIME	NET_WAIT_TIME	QUEUE_TIME	DECODE_TIME	GET_PLAN_TIME	EXECUTE_TIME	APPLICATION_WAIT_TIME	CONCURRENCY_WAIT_TIME	USER_IO_WAIT_TIME	SCHEDULE_TIME	ROW_CACHE_HIT	BLOOM_FILTER_CACHE_HIT	BLOCK_CACHE_HIT	DISK_READS	RETRY_CNT	TABLE_SCAN	CONSISTENCY_LEVEL	MEMSTORE_READ_ROW_COUNT	SSSTORE_READ_ROW_COUNT	DATA_BLOCK_READ_CNT	DATA_BLOCK_CACHE_HIT	INDEX_BLOCK_READ_CNT	INDEX_BLOCK_CACHE_HIT	BLOCKSCAN_BLOCK_CNT	BLOCKSCAN_ROW_CNT	PUSHDOWN_STORAGE_FILTER_ROW_CNT	REQUEST_MEMORY_USED	EXPECTED_WORKER_COUNT	USED_WORKER_COUNT	SCHED_INFO	FUSE_ROW_CACHE_HIT	PS_CLIENT_STMT_ID	PS_INNER_STMT_ID	TX_ID	SNAPSHOT_VERSION	REQUEST_TYPE	IS_BATCHED_MULTI_STMT	OB_TRACE_INFO	PLAN_HASH	LOCK_FOR_READ_TIME	PARAMS_VALUE	RULE_NAME	PARTITION_HIT	TX_INTERNAL_ROUTING	TX_STATE_VERSION
172.18.95.161	2882	1101187	23759546	YB42AC125FA1-0005FFC97118D64C-0-0	3222156995	172.18.95.159	35036	1004	jmzz_tenant	1004	200001	root	0	172.18.95.158	18446744073709551615		CEE1A1129847A1E62D001F13BC5A424E	select * from ds1.tipt_advice_execute_plan_log	5666	0	13764585	1	-4009	0	0	0	0			0		0		0	0	100	0	OTHER	MAX_WAIT TIME ZERO	0	0	0	0	1	0	0	1	1688712024853791	62891405	0	2	18	1	37	62891333	0	0	0	0	0	0	13260	0	0	1	3	0	13764664	13152	13152	109	108	13130	13765436	0	205088	0	0	\N	0	-1	-1	0	1688712024844894924	2	0	\N	12916817122871780169	0			1	0	0

洪波 · 2023 年7 月 7 日 16:24

需要根据这个trace_id，到observer的日志目录下，过滤日志内容，看下sql为什么被kill
grep “trace_id” observer.log*

近墨者 · 2023 年7 月 7 日 16:31

RET_CODE=-4009 官方提示是相关IO错误。

你把timeout相关的变量提供出来，看一看：show variables like ‘%timeout%’;

chenyk88 · 2023 年7 月 7 日 16:37

这个是跟踪到的日志

chenyk88 · 2023 年7 月 7 日 17:13

[2023-07-07 16:58:28.836733] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=4] write cond wakeup
[2023-07-07 16:58:28.838552] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=10] write cond wakeup
[2023-07-07 16:58:28.902155] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=6] write cond wakeup
[2023-07-07 16:58:28.917828] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=12] write cond wakeup
[2023-07-07 16:58:29.097540] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=9] write cond wakeup
[2023-07-07 16:58:31.467888] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=8] write cond wakeup
[2023-07-07 16:58:32.544932] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=7] write cond wakeup
[2023-07-07 16:58:51.521751] INFO [RPC.OBMYSQL] print_session_info (ob_sql_nio.cpp:980) [40573][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=10] [sql nio session](*s={this:0x7f36509c5290, fd:258, err:0, last_decode_time_:1688720308801658, last_write_time_:1688720331521735, read_buffer_.get_consume_sz():808, get_pending_flag():1, get_trace_id():YB42AC125FA1-0005FFC97118D66B-0-0})
[2023-07-07 16:59:07.241289] INFO [RPC.OBMYSQL] print_session_info (ob_sql_nio.cpp:980) [40573][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=10] [sql nio session](*s={this:0x7f36509c5290, fd:258, err:0, last_decode_time_:1688720308801658, last_write_time_:1688720347241236, read_buffer_.get_consume_sz():808, get_pending_flag():1, get_trace_id():YB42AC125FA1-0005FFC97118D66B-0-0})
[2023-07-07 16:59:22.993065] INFO [RPC.OBMYSQL] print_session_info (ob_sql_nio.cpp:980) [40573][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=7] [sql nio session](*s={this:0x7f36509c5290, fd:258, err:0, last_decode_time_:1688720308801658, last_write_time_:1688720362992954, read_buffer_.get_consume_sz():808, get_pending_flag():1, get_trace_id():YB42AC125FA1-0005FFC97118D66B-0-0})
[2023-07-07 16:59:26.980788] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=9] write cond wakeup
[2023-07-07 16:59:28.063419] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=10] write cond wakeup
[2023-07-07 16:59:29.063495] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=12] write cond wakeup
[2023-07-07 16:59:29.811814] WDIAG [RPC.OBMYSQL] handle_sock_event (ob_sql_nio.cpp:818) [40573][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=11][errcode=-4015] sock error detect by epoll(mask=8221, *s={this:0x7f36509c5290, fd:258, err:5, last_decode_time_:1688720308801658, last_write_time_:1688720367063267, read_buffer_.get_consume_sz():808, get_pending_flag():1, get_trace_id():YB42AC125FA1-0005FFC97118D66B-0-0})
[2023-07-07 16:59:30.063551] INFO [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:393) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=8] write cond wakeup
[2023-07-07 16:59:30.063563] WDIAG [RPC.OBMYSQL] write_data (ob_sql_nio.cpp:398) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=10][errcode=-4009] write data error(errno=104)
[2023-07-07 16:59:30.063568] WDIAG [RPC.OBMYSQL] push_close_req (ob_sql_nio.cpp:707) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=5][errcode=-4015] user req close, and epoll thread already set error(*s={this:0x7f36509c5290, fd:258, err:5, last_decode_time_:1688720308801658, last_write_time_:1688720370063567, read_buffer_.get_consume_sz():808, get_pending_flag():2, get_trace_id():YB42AC125FA1-0005FFC97118D66B-0-0})
[2023-07-07 16:59:30.063578] WDIAG [SERVER] flush_buffer (obmp_packet_sender.cpp:936) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=9][errcode=-4009] write response fail(ret=-4009)
[2023-07-07 16:59:30.063582] WDIAG [SERVER] try_encode_with (obmp_packet_sender.cpp:846) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=3][errcode=-4009] failed to flush_buffer(ret=-4009, last_ret=-4019)
[2023-07-07 16:59:30.063586] WDIAG [SERVER] response_packet (obmp_packet_sender.cpp:284) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=3][errcode=-4009] failed to encode packet(ret=-4009)
[2023-07-07 16:59:30.063589] WDIAG [SERVER] response_query_result (ob_query_driver.cpp:209) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=3][errcode=-4009] response packet fail(ret=-4009, row=0x7f35518cef58, row_num=13792907, can_retry=false)
[2023-07-07 16:59:30.063594] WDIAG [SERVER] response_query_result (ob_query_driver.cpp:230) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=4][errcode=-4009] fail to iterate and response(ret=-4009, row_num=13792907, can_retry=false)
[2023-07-07 16:59:30.063599] WDIAG [SERVER] response_result (ob_sync_plan_driver.cpp:101) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=4][errcode=-4009] response query result fail(ret=-4009)
[2023-07-07 16:59:30.063637] WDIAG [STORAGE] reset (ob_access_service.cpp:1143) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=2][errcode=-4389] guard used too much time(guard_used_us=61261128, ls_id={id:1002}, lbt()=“0xf0bba8c 0xbdea58c 0x4033e57 0x4032889 0x401ba5e 0x401af94 0x99592a1 0x401812b 0x3fb66b3 0x3fb33ec 0x3fb0562 0x3fabed9 0x3fa9d9a 0x3fa6768 0x6a0ad14 0xf3666c7 0xf35faca 0x7f36f7b723fb 0x7f36f7727c23”)
[2023-07-07 16:59:30.063656] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:311) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=6] sending error packet(err=-4009, extra_err_info=NULL, lbt()=“0xf0bba8c 0x7f702dc 0x7f2d8b8 0x3fb6646 0x3fb33ec 0x3fb0562 0x3fabed9 0x3fa9d9a 0x3fa6768 0x6a0ad14 0xf3666c7 0xf35faca 0x7f36f7b723fb 0x7f36f7727c23”)
[2023-07-07 16:59:30.063671] INFO [SERVER] add_changed_session_info (obmp_utils.cpp:81) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=5] success add system var to ok pack(str_kv={key:“ob_statement_trace_id”, value:“YB42AC125FA1-0005FFC97118D66B-0-0”}, change_var={id_:10037, old_val_:{“VARCHAR”:“Y0-0”, collation:“utf8mb4_general_ci”, coercibility:“SYSCONST”}}, new_val={“VARCHAR”:“YB42AC125FA1-0005FFC97118D66B-0-0”, collation:“utf8mb4_general_ci”, coercibility:“IMPLICIT”}, session.get_sessid()=3222217918, session.get_proxy_sessid()=12399077860797779456, change_var.id_=10037)
[2023-07-07 16:59:30.063695] INFO [SERVER] send_error_packet (obmp_packet_sender.cpp:472) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=12] dump txn free route audit_record(value=5, session->get_sessid()=3222217918, session->get_proxy_sessid()=12399077860797779456)
[2023-07-07 16:59:30.063702] WDIAG [SERVER] do_process (obmp_query.cpp:848) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=5][errcode=-4009] execute query fail(ret=-4009, timeout_timestamp=1688720808801658)
[2023-07-07 16:59:30.063718] WDIAG [SQL.SESSION] set_session_state_ (ob_basic_session_info.cpp:5458) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=3][errcode=-5066] session is killed(ret=-5066, sessid_=3222217918, proxy_sessid_=12399077860797779456, state=1)
[2023-07-07 16:59:30.063730] WDIAG [RPC.OBMYSQL] async_write_data (ob_sql_sock_session.cpp:152) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=6][errcode=-4009] sock has error(ret=-4009)
[2023-07-07 16:59:30.063735] WDIAG [SERVER] flush_buffer (obmp_packet_sender.cpp:932) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=4][errcode=-4009] write response fail(ret=-4009)
[2023-07-07 16:59:30.063738] WDIAG [SERVER] process (obmp_query.cpp:436) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=3][errcode=-4009] failed to flush_buffer(tmp_ret=-4009)
[2023-07-07 16:59:30.063743] TRACE [TRACE] after_process (obmp_base.cpp:142) [799531][T1004_L0_G0][T1004][YB42AC125FA1-0005FFC97118D66B-0-0] [lt=4] [slow query](TRACE=begin_ts=1688720308801665 2023-07-07 08:58:28.801665|[process_begin] u=0 in_queue_time:7, receive_ts:1688720308801658, enqueue_ts:1688720308801658|[start_sql] u=0 addr:{ip:“172.18.95.159”, port:65040}|[query_begin] u=1 trace_id:YB42AC125FA1-0005FFC97118D66B-0-0|[before_processor_run] u=1 |[session] u=0 sid:3222217918, tenant_id:1004|[calc_partition_location_begin] u=22 |[tl_calc_part_id_end] u=1 |[get_location_cache_begin] u=0 |[calc_partition_location_end] u=3 |[get_plan_type_end] u=2 |[pc_choose_plan] u=1 |[check_priv] u=2 |[plan_id] u=0 plan_id:5666|[do_open_plan_begin] u=2 plan_id:5666|[sql_start_stmt_begin] u=0 |[sql_start_stmt_end] u=9 |[exec_plan_begin] u=0 |[exec_plan_end] u=20 |[do_open_plan_end] u=0 |[storage_table_scan_begin] u=49 |[S_table_scan_begin] u=3 |[S_table_scan_end] u=50 |[storage_table_scan_end] u=0 |[close_plan_begin] u=61261770 |[S_revert_iter_begin] u=4 |[S_revert_iter_end] u=39 |[start_end_stmt] u=4 |[end_stmt] u=1 |[close_plan_end] u=0 |[affected_rows] u=0 affected_rows:-1|[store_found_rows] u=0 found_rows:0, return_rows:13792908|[auto_end_plan_begin] u=1 |[auto_end_plan_end] u=3 |[session] u=11 sid:3222217918, tenant_id:1004|[query_end] u=62 |[process_end] u=16 run_ts:1688720308801667|total_timeu=61262077)
[2023-07-07 16:59:30.812732] INFO [RPC.OBMYSQL] destroy (obsm_conn_callback.cpp:223) [40573][sql_nio0][T0][Y0-0000000000000000-0-0] [lt=7] connection close(sessid=3222217918, proxy_sessid=12399077860797779456, tenant_id=1004, server_id=3, from_proxy=true, from_java_client=false, c/s protocol=“OB_2_0_CS_TYPE”, is_need_clear_sessid_=true, ret=0, trace_id=YB42AC125FA1-0005FFC97118D66B-0-0, conn.pkt_rec_wrapper_=[start_pkt_pos_:7, cur_pkt_pos_:9, pkt_rec[0]:{send:obp_mysql_header_{len_:5760, seq_:3}, pkt_name:“PKT_OKP”, obp_mysql_header_.is_send_:1}, pkt_rec[1]:{send:obp20_header_:{payload_len:470, pkt_seq:0, req_id:5020112, flag_.flags:43, ext_flags:0}, obp_mysql_header_{len_:413, seq_:2}, pkt_name:“PKT_OKP”, obp_mysql_header_.is_send_:1}, pkt_rec[2]:{receive:obp20_header_:{payload_len:132, pkt_seq:0, req_id:5020113, flag_.flags:43, ext_flags:0}, obp_mysql_header_{len_:47, rec_:51, seq_:0}, obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[3]:{send:obp_compess_header_{com_len:13255, com_seq:1}, obp20_header_:{payload_len:13227, pkt_seq:1, req_id:5020113, flag_.flags:9, ext_flags:0}, obp_mysql_header_{len_:49, seq_:2}, pkt_name:“PKT_RESHEAD”, obp_mysql_header_.is_send_:1}, pkt_rec[4]:{send:obp_compess_header_{com_len:13255, com_seq:1}, obp20_header_:{payload_len:13227, pkt_seq:1, req_id:5020113, flag_.flags:9, ext_flags:0}, obp_mysql_header_{pkt_num_:85, seq_:87}, pkt_name:“PKT_FIELD”, obp_mysql_header_.is_send_:1}, pkt_rec[5]:{send:obp_compess_header_{com_len:13255, com_seq:1}, obp20_header_:{payload_len:13227, pkt_seq:1, req_id:5020113, flag_.flags:9, ext_flags:0}, obp_mysql_header_{len_:9, seq_:88}, pkt_name:“PKT_EOF”, obp_mysql_header_.is_send_:1}, pkt_rec[6]:{send:obp_compess_header_{com_len:13255, com_seq:1}, obp20_header_:{payload_len:13227, pkt_seq:1, req_id:5020113, flag_.flags:9, ext_flags:0}, obp_mysql_header_{pkt_num_:13792907, seq_:227}, pkt_name:“PKT_ROW”, obp_mysql_header_.is_send_:1}, pkt_rec[7]:{send:obp_compess_header_{com_len:124, com_seq:33}, obp20_header_:{payload_len:96, pkt_seq:33, req_id:5020113, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:21, seq_:228}, pkt_name:“PKT_ERR”, obp_mysql_header_.is_send_:1}, pkt_rec[8]:{send:obp_compess_header_{com_len:124, com_seq:33}, obp20_header_:{payload_len:96, pkt_seq:33, req_id:5020113, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:75, seq_:229}, pkt_name:“PKT_OKP”, obp_mysql_header_.is_send_:1}], disconnect_state=4)

洪波 · 2023 年7 月 7 日 18:08

你自己客户端有设置什么吧，1分钟断开连接了，会话请求被关闭了