sql audit只能保存很短时间，查询一次要5min，只能尝试弄一下。
要么贴下慢查询日志也行
observer.log.20220524201424:[2022-05-24 20:07:41.901754] INFO [SQL] ob_sql.cpp:1283 [19908][2748][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=10] [dc=0] It's a large query, need delay, do not need disconnect(avg_process_time=373425632, exec_cnt=2, large_query_threshold=5000000, plan->get_plan_id()=4259, ret=-4023)
observer.log.20220524201424:2022-05-24 20:07:41.901815 parallel(16) */ count(*) FROM xx PARTITION(M202204, M202205) WHERE aa = 251287325 AND bb = 30 AND cc IN ( 0 ) AND dd IN ( 40 , 50 , 60 , 70 ) AND ee < 1653029404748", stmt_len:318|[cache_get_plan_begin] u=5 |[calc_partition_location_begin] u=86 |[tl_calc_by_range_end] u=12 |[tl_calc_part_id_end] u=4 |[get_location_cache_begin] u=1 |[get_location_cache_end] u=9 |[calc_partition_location_end] u=0 |[pc_choose_plan] u=10 |[check_priv] u=4 |[cache_get_plan_end] u=0 |[query_end] u=38 |[process_end] u=2 run_ts:1653394061901577|total_timeu=217)
observer.log.20220524201424:[2022-05-24 20:13:55.441006] INFO [SQL.SESSION] ob_sql_session_info.cpp:90 [19908][2748][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=8] [dc=0] revert schema guard success by sql(session_id=62363, tenant_id=1002, schema_version=1653389096614456)
observer.log.20220524201424:[2022-05-24 20:13:55.441066] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [19908][2748][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=12] [dc=0] long time to hold one guard(schema_mgr=0x7f17398c60d0, tenant_id=1, version=1653048873828760, cur_timestamp=1653394435441020, ref_timestamp=1653394061900894, lbt()="0x99bdb8e 0x27f7292 0x25c5e98 0x61c3b74 0x5a02f8f 0x944da68 0x944b1c7 0x9aec8dc 0x923882f 0x92190ab 0x923748f 0x9216f94 0x92174b7 0x2c70e32 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201424:[2022-05-24 20:13:55.441087] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [19908][2748][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=7] [dc=0] long time to hold one guard(schema_mgr=0x7f0ad3ee27d0, tenant_id=1002, version=1653389096614456, cur_timestamp=1653394435441073, ref_timestamp=1653394061900894, lbt()="0x99bdb8e 0x27f7292 0x25c5e98 0x61c3b74 0x5a02f8f 0x944da68 0x944b1c7 0x9aec8dc 0x923882f 0x92190ab 0x923748f 0x9216f94 0x92174b7 0x2c70e32 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201424:2022-05-24 20:13:55.441197 parallel(16) */ count(*) FROM xx PARTITION(M202204, M202205) WHERE aa = 251287325 AND bb = 30 AND cc IN ( 0 ) AND dd IN ( 40 , 50 , 60 , 70 ) AND ee < 1653029404748", stmt_len:318|[cache_get_plan_begin] u=2 |[calc_partition_location_begin] u=28 |[tl_calc_by_range_end] u=3 |[tl_calc_part_id_end] u=2 |[get_location_cache_begin] u=0 |[get_location_cache_end] u=16 |[calc_partition_location_end] u=0 |[pc_choose_plan] u=6 |[check_priv] u=1 |[cache_get_plan_end] u=1 |[plan_id] u=0 plan_id:4259|[exec_begin] u=2 arg1:false, end_trans_cb:false|[post_packet] u=18 ret:0, pcode:1808, addr:{ip:"10.96.90.156", port:2882}|[do_open_plan_begin] u=1665 plan_id:4259|[sql_start_stmt_begin] u=1 |[sql_start_stmt_end] u=0 |[exec_plan_begin] u=0 |[exec_plan_end] u=28 |[sql_start_participant_begin] u=0 |[sql_start_participant_end] u=1 |[do_open_plan_end] u=0 |[dfo_start] u=92 dfo_id:0|[post_packet] u=109 ret:0, pcode:1304, addr:{ip:"10.38.108.172", port:2882}|[post_packet] u=58 ret:0, pcode:1304, addr:{ip:"10.44.122.22", port:2882}|[dfo_start] u=1117 dfo_id:2147483647|[post_packet] u=29 ret:0, pcode:1472, addr:{ip:"10.38.108.172", port:2882}|[post_packet] u=8 ret:0, pcode:1472, addr:{ip:"10.44.122.22", port:2882}|[sqc_finish] u=69708043 dfo_id:0, sqc_id:0|[sqc_finish] u=303827805 dfo_id:0, sqc_id:1|[close_plan_begin] u=31 |[end_participant_begin] u=56 |[end_participant_end] u=0 |[start_end_stmt] u=0 |[end_stmt] u=0 |[close_plan_end] u=1 |[affected_rows] u=0 affected_rows:-1|[store_found_rows] u=0 found_rows:0, return_rows:1|[auto_end_plan_begin] u=1 |[auto_end_plan_end] u=2 |[result_set_close] u=0 ret:0, arg1:0, arg2:0, arg3:-4008, async:false|[exec_end] u=16 |[query_end] u=153 |[process_end] u=7 run_ts:1653394061901834|total_timeu=373539315)
10.38.108.172
observer.log.20220524201648:[2022-05-24 20:08:51.270466] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [108266][3339][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=0] [dc=0] long time to hold one guard(schema_mgr=0x7f6e33ad3d50, tenant_id=1, version=1653048873828760, cur_timestamp=1653394131270412, ref_timestamp=1653394061913061, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201648:[2022-05-24 20:08:51.270497] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [108266][3339][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=15] [dc=0] long time to hold one guard(schema_mgr=0x7f677f3e61d0, tenant_id=1002, version=1653389096614456, cur_timestamp=1653394131270482, ref_timestamp=1653394061913061, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201648:[2022-05-24 20:08:51.621446] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [106324][3338][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=0] [dc=0] long time to hold one guard(schema_mgr=0x7f6e33ad3d50, tenant_id=1, version=1653048873828760, cur_timestamp=1653394131621302, ref_timestamp=1653394061913061, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201648:[2022-05-24 20:08:51.621537] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [106324][3338][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=73] [dc=0] long time to hold one guard(schema_mgr=0x7f677f3e61d0, tenant_id=1002, version=1653389096614456, cur_timestamp=1653394131621519, ref_timestamp=1653394061913061, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
10.44.122.22
observer.log.20220524200917:[2022-05-24 20:07:57.427655] WARN [COMMON] get_max_iops (ob_io_benchmark.cpp:1047) [177638][3282][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=0] [dc=0] The ObIOBenchmark has not been inited, (ret=-4006)
observer.log.20220524200917:[2022-05-24 20:08:57.427755] WARN [COMMON] get_max_iops (ob_io_benchmark.cpp:1047) [177638][3282][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=12] [dc=0] The ObIOBenchmark has not been inited, (ret=-4006)
observer.log.20220524201940:[2022-05-24 20:10:57.429659] WARN [COMMON] get_max_iops (ob_io_benchmark.cpp:1047) [177638][3282][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=16] [dc=0] The ObIOBenchmark has not been inited, (ret=-4006)
observer.log.20220524201940:[2022-05-24 20:13:55.446888] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [177638][3282][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=13] [dc=0] long time to hold one guard(schema_mgr=0x7f9139a238d0, tenant_id=1, version=1653048873828760, cur_timestamp=1653394435446840, ref_timestamp=1653394061912313, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
observer.log.20220524201940:[2022-05-24 20:13:55.446933] WARN [SHARE.SCHEMA] revert (ob_schema_mgr_cache.cpp:89) [177638][3282][YB420A3EBF1D-0005DBD0AFBC12BE] [lt=27] [dc=0] long time to hold one guard(schema_mgr=0x7f9676d66850, tenant_id=1002, version=1653389096614456, cur_timestamp=1653394435446916, ref_timestamp=1653394061912313, lbt()="0x99bdb8e 0x27f7292 0x25c52d4 0x27b9d9d 0x25c5885 0x554294f 0x3ab2a72 0x3b559fa 0x97463e5 0x9745112 0x9741bcf")
0x99bdb8e 0x27f7292 0x25c5e98 0x61c3b74 0x5a02f8f 0x944da68 0x944b1c7 0x9aec8dc 0x923882f 0x92190ab 0x923748f 0x9216f94 0x92174b7 0x2c70e32 0x97463e5 0x9745112 0x9741bcf 这个堆栈用addr2line打印一下
另外，感觉还是没走到索引呀,explain extended 把更详细的信息打一下吧
$ addr2line -pCfe /media/disk1/oceanbase/bin/observer 0x99bdb8e 0x27f7292 0x25c5e98 0x61c3b74 0x5a02f8f 0x944da68 0x944b1c7 0x9aec8dc 0x923882f 0x92190ab 0x923748f 0x9216f94 0x92174b7 0x2c70e32 0x97463e5 0x9745112 0x9741bcf
oceanbase::common::lbt() at ??:?
oceanbase::share::schema::ObSchemaMgrHandle::revert() at ??:?
oceanbase::share::schema::ObSchemaGetterGuard::reset() at ??:?
oceanbase::sql::ObTenantCachedSchemaGuardInfo::try_revert_schema_guard() at ??:?
oceanbase::sql::ObQueryExecCtx::free(oceanbase::sql::ObQueryExecCtx*) at ??:?
oceanbase::observer::ObMPQuery::process_single_stmt(oceanbase::sql::ObMultiStmtItem const&, oceanbase::sql::ObSQLSessionInfo&, bool, bool, bool&, bool&) at ??:?
oceanbase::observer::ObMPQuery::process() at ??:?
oceanbase::rpc::frame::ObReqProcessor::run() at ??:?
oceanbase::omt::ObWorkerProcessor::process_one(oceanbase::rpc::ObRequest&, int&) at ??:?
oceanbase::omt::ObWorkerProcessor::process(oceanbase::rpc::ObRequest&) at ??:?
oceanbase::omt::ObThWorker::process_request(oceanbase::rpc::ObRequest&) at ??:?
oceanbase::omt::ObThWorker::worker(long&, long&, int&) at ??:?
non-virtual thunk to oceanbase::omt::ObThWorker::run(long) at ??:?
oceanbase::lib::CoKThreadTemp<oceanbase::lib::CoUserThreadTemp<oceanbase::lib::CoSetSched> >::start()::{lambda()#1}::operator()() const at ??:?
oceanbase::lib::CoSetSched::Worker::run() at ??:?
oceanbase::lib::CoRoutine::__start(boost::context::detail::transfer_t) at ??:?
finish at safe_snprintf.c:?
explain extended SELECT /*+ query_timeout(100000000000) parallel(16) */ count(*) FROM tt PARTITION(M202204, M202205) WHERE aa = 251287325 AND bb = 30 AND cc IN ( 0 ) AND dd IN ( 40 , 50 , 60 , 70 ) AND ff < 1653029404748\G
*************************** 1. row ***************************
Query Plan: ==================================================================================================
|ID|OPERATOR |NAME |EST. ROWS|COST |
--------------------------------------------------------------------------------------------------
|0 |SCALAR GROUP BY | |1 |1194027298|
|1 | PX COORDINATOR | |1 |1193983079|
|2 | EXCHANGE OUT DISTR |:EX10000 |1 |1193983078|
|3 | MERGE GROUP BY | |1 |1193983078|
|4 | PX BLOCK ITERATOR| |231499 |1193938859|
|5 | TABLE SCAN |tt(integration_test_idx)|231499 |1193938859|
==================================================================================================
Outputs & filters:
-------------------------------------
0 - output([T_FUN_COUNT_SUM(T_FUN_COUNT(*)(0x7f1b75c63460))(0x7f1980763fc0)]), filter(nil),
group(nil), agg_func([T_FUN_COUNT_SUM(T_FUN_COUNT(*)(0x7f1b75c63460))(0x7f1980763fc0)])
1 - output([T_FUN_COUNT(*)(0x7f1b75c63460)]), filter(nil)
2 - output([T_FUN_COUNT(*)(0x7f1b75c63460)]), filter(nil), dop=16
3 - output([T_FUN_COUNT(*)(0x7f1b75c63460)]), filter(nil),
group(nil), agg_func([T_FUN_COUNT(*)(0x7f1b75c63460)])
4 - output([remove_const(1)(0x7f198076a280)]), filter(nil)
5 - output([remove_const(1)(0x7f198076abb0)]), filter([cast(tt.aa(0x7f1a3da3ec10), DECIMAL(-1, -1))(0x7f1b75c63fb0) = ?(0x7f1a3da3e590)], [tt.bb(0x7f1a3da3f9f0) = 30(0x7f1a3da3f370)], [tt.cc(0x7f1b75c60820) = 0(0x7f1a3da3fc80)], [tt.dd(0x7f1b75c623f0) IN (40, 50, 60, 70)(0x7f1b75c613c0)(0x7f1b75c60ab0)], [tt.ff(0x7f1b75c631d0) < 1653029404748(0x7f1b75c62b50)]),
access([tt.aa(0x7f1a3da3ec10)], [tt.bb(0x7f1a3da3f9f0)], [tt.cc(0x7f1b75c60820)], [tt.dd(0x7f1b75c623f0)], [tt.ff(0x7f1b75c631d0)]), partitions(p[0-1]),
is_index_back=false, filter_before_indexback[false,false,false,false,false],
range_key([tt.aa(0x7f1a3da3ec10)], [tt.bb(0x7f1a3da3f9f0)], [tt.cc(0x7f1b75c60820)], [tt.dd(0x7f1b75c623f0)], [tt.ff(0x7f1b75c631d0)], [tt.order_id(0x7f03b903b8e0)], [tt.create_time(0x7f1b75c57b80)]), range(MIN,MIN,MIN,MIN,MIN,MIN,MIN ; MAX,MAX,MAX,MAX,MAX,MAX,MAX)always true
Used Hint:
-------------------------------------
/*+
QUERY_TIMEOUT(100000000000)
PARALLEL(16)
*/
Outline Data:
-------------------------------------
/*+
BEGIN_OUTLINE_DATA
NO_USE_HASH_AGGREGATION(@"SEL$1")
INDEX(@"SEL$1" "db.tt"@"SEL$1" "integration_test_idx")
QUERY_TIMEOUT(100000000000)
PARALLEL(16)
END_OUTLINE_DATA
*/
Plan Type:
-------------------------------------
DISTRIBUTED
range_key([tt.aa(0x7f1a3da3ec10)], [tt.bb(0x7f1a3da3f9f0)], [tt.cc(0x7f1b75c60820)], [tt.dd(0x7f1b75c623f0)], [tt.ff(0x7f1b75c631d0)], [tt.order_id(0x7f03b903b8e0)], [tt.create_time(0x7f1b75c57b80)]), range(MIN,MIN,MIN,MIN,MIN,MIN,MIN ; MAX,MAX,MAX,MAX,MAX,MAX,MAX)always true
这里query range没有抽取出来，最终还是全表扫描
没抽取出来的原因，可能和
5 - output([remove_const(1)(0x7f198076abb0)]), filter([cast(tt.aa(0x7f1a3da3ec10), DECIMAL(-1, -1))(0x7f1b75c63fb0) = ?(0x7f1a3da3e590)], [tt.bb(0x7f1a3da3f9f0) = 30(0x7f1a3da3f370)], [tt.cc(0x7f1b75c60820) = 0(0x7f1a3da3fc80)], [tt.dd(0x7f1b75c623f0) IN (40, 50, 60, 70)(0x7f1b75c613c0)(0x7f1b75c60ab0)], [tt.ff(0x7f1b75c631d0) < 1653029404748(0x7f1b75c62b50)]),
这里aa做了隐式的cast有关
可以把aa的列类型也发一下
1 个赞
是这个问题，aa的类型是varchar
这里如果对列做cast查询的情况是否能有一个warning的提示，之前似乎遇到过这样的坑，查了比较久。
我测试了一下类似的场景，使用show trace 的功能判断是否走了索引：
table t(id int, name varchar(20), age float);
index i_name on t(name);
执行 select /*+ INDEX_HINT(t i_name) */ * from t where name='123';
期望可以正常走索引，实际上也是：
show trace最后一行：
| t(i_name) | PHY_TABLE_SCAN
SQL改成 select /*+ INDEX_HINT(t i_name) */ * from t where name=123;
show trace最后一行：
| t | PHY_TABLE_SCAN
同时也看不到扫描索引的地方