任仲禹
爱可生数据库高级工程师，擅长故障分析和性能优化。
针对 OceanBase 3.2.3 BP8 版本，项目组反馈某 SELECT 语句在⼀段时间内查询耗时极慢，相比正常时耗时差 1000 倍以上。具体如下：
慢 SELECT
SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO = '6222620117273900882') AND
LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT LIKE '05%' AND
EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-01-01' AND ACCTG_DT SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO = '6222620117273900882');
+---------+
| TOT_CNT |
+---------+
| 1 |
+---------+
1 row in set (0.02 sec)
MySQL > SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE ACCTG_DT >= '1900-01-01' AND
ACCTG_DT SELECT COUNT(*) AS TOT_CNT FROM renzy;
+----------+
| TOT_CNT |
+----------+
| 25435024 |
+----------+
1 row in set (10.65 sec)
排查过程
正常执行不慢
MySQL > select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO =
'6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT
LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-01-01' AND ACCTG_DT select * from gv$plan_cache_plan_stat where plan_id=7288229 G
*************************** 1. row ***************************
...
plan_id: 7288229
...
statement: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = ?) AND LAWENF_NTIST_TP_CD NOT LIKE ? AND LAWENF_NTIST_TP_CD NOT LIKE ? AND
EMRG_STPY_SRC_CD != ? AND ACCTG_DT >= ? AND ACCTG_DT = '' AND
ACCTG_DT select * from oceanbase.gv$plan_cache_plan_explain where
tenant_id=1005 and port=2882 and plan_id=7288229 and ip='12.240.26.70'G
....
PLAN_LINE_ID: 2
OPERATOR: PHY_TABLE_SCAN
NAME: renzy(renzy_I5)
ROWS: 0
COST: 91
PROPERTY: table_rows:25419080, physical_range_rows:1, logical_range_rows:1,
index_back_rows:0, output_rows:0, est_method:local_storage,
avaiable_index_name[renzy_I2,renzy_I5]
...
上述结果的关键信息如下：
-
query_sql ：为该 plan 第⼀次执行时的 SQL 语句。
-
first_load_time ：缓存该 plan 并 hit 的时间。
-
slowest_exe_usec ：该计划的最慢耗时。
-
outline_id ： 是否命中了绑定的 outline，-1 即未命中。
-
statement ：参数化后的 SQL 语句。
-
name : 该 plan 走的索引。
分析下第⼀次的 SQL
为啥要走 I5 索引
通过下面的执行计划和执行耗时可知，第⼀次执行的语句因为字段 ACCTG_DT 检索不到数据，所以走 I5 效率最高。
MySQL > explain extended select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = '6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND
LAWENF_NTIST_TP_CD NOT LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '' AND
ACCTG_DT select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO =
'6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT
LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '' AND ACCTG_DT = '1900-01-01' AND ACCTG_DT select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO =
'6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT
LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '' AND ACCTG_DT select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO =
'6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT
LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-01-01' AND ACCTG_DT select last_trace_id();
+-----------------------------------+
| last_trace_id() |
+-----------------------------------+
| YB420CF01A46-0006009AD91C51ED-0-0 |
+-----------------------------------+
1 row in set (0.04 sec)
MySQL > select * from oceanbase.gv$sql_audit where trace_id='YB420CF01A46-
0006009AD91C51ED-0-0'G
...
TRACE_ID: YB420CF01A46-0006009AD91C51ED-0-0
...
SQL_ID: 2B53F4C1C330C2C089C7518CD71D667A
QUERY_SQL: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = '6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND
LAWENF_NTIST_TP_CD NOT LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-
01-01' AND ACCTG_DT select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE (ACCT_NO =
'6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT
LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-01-01' AND ACCTG_DT select last_trace_id();
+-----------------------------------+
| last_trace_id() |
+-----------------------------------+
| YB420CF01A46-0006009AD91C51ED-0-0 |
+-----------------------------------+
1 row in set (0.04 sec)
MySQL > select * from oceanbase.gv$sql_audit where trace_id='YB420CF01A46-
0006009AD91C51ED-0-0'G
...
TRACE_ID: YB420CF01A46-0006009AD91C51ED-0-0
...
SQL_ID: 2B53F4C1C330C2C089C7518CD71D667A
QUERY_SQL: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = '6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND
LAWENF_NTIST_TP_CD NOT LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-
01-01' AND ACCTG_DT select * from gv$plan_cache_plan_stat where plan_id=7289113 G
*************************** 1. row ***************************
...
sql_id: 2B53F4C1C330C2C089C7518CD71D667A
...
statement: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = ?) AND LAWENF_NTIST_TP_CD NOT LIKE ? AND LAWENF_NTIST_TP_CD NOT LIKE ? AND
EMRG_STPY_SRC_CD != ? AND ACCTG_DT >= ? AND ACCTG_DT = '' AND
ACCTG_DT >> do 17 # 耗时 2分钟27s 命中
2023-11-14 16:05:36
1
YB420CF01A46-0006009B016C66EE-0-0
2023-11-14 16:08:03
>>> do 18 # 耗时 2min12s 命中
2023-11-14 16:08:03
1
YB420CF01A46-0006009AFF8FF46D-0-0
2023-11-14 16:10:15
>>> do 19 # 耗时 2min36s 命中
2023-11-14 16:10:15
1
YB420CF01A46-0006009B012FF1D0-0-0
2023-11-14 16:12:51
>>> do 20 # 耗时 1s内 未命中，恢复正常
2023-11-14 16:12:51
1
YB420CF01A46-0006009AFEBDA7C6-0-0
2023-11-14 16:12:51
>>> do 21
2023-11-14 16:12:51
1
YB420CF01A46-0006009B016F1561-0-0
2023-11-14 16:12:52
...
可以观察到，命中该 Plan 的 SQL 执行次数大于 20 次（含手工执行）后，该"不符合预期的" Plan 被淘汰。
4. 再次执行的 SQL 的 sql_audit 和 plan_cache_plan_stat，可看到重新生成了 Plan。
MySQL > select * from oceanbase.gv$sql_audit where trace_id='YB420CF01A46-
0006009AFEBDA7C6-0-0'G
SQL_ID: 2B53F4C1C330C2C089C7518CD71D667A
QUERY_SQL: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = '6222620117273900882') AND LAWENF_NTIST_TP_CD NOT LIKE '12%' AND
LAWENF_NTIST_TP_CD NOT LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND ACCTG_DT >= '1900-
01-01' AND ACCTG_DT select * from gv$plan_cache_plan_stat where plan_id=7334178 G
*************************** 1. row ***************************
...
plan_id: 7334178
sql_id: 2B53F4C1C330C2C089C7518CD71D667A
...
statement: select * from (SELECT COUNT(*) AS TOT_CNT FROM renzy WHERE
(ACCT_NO = ?) AND LAWENF_NTIST_TP_CD NOT LIKE ? AND LAWENF_NTIST_TP_CD NOT LIKE ? AND
EMRG_STPY_SRC_CD != ? AND ACCTG_DT >= ? AND ACCTG_DT = '1900-
01-01' AND ACCTG_DT get_plan_id()=7328133, ret=-4023)
observer.log.20231114161017:[2023-11-14 16:10:15.813208] TRACE [TRACE]obmp_base.cpp:156
[86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=18] [dc=0] [packet retry query]
(TRACE=begin_ts=1699949415813080 2023-11-14 08:10:15.813080|[start_sql] u=0 addr:
{ip:"12.241.29.28", port:16606}|[process_begin] u=0 addr:{ip:"12.241.29.28",
port:16606}, in_queue_time:13, receive_ts:1699949415813066,
enqueue_ts:1699949415813067, trace_id:YB420CF01A46-0006009B012FF1D0-0-0|[session] u=3
sid:3221784053, tenant_id:1005|[parse_begin] u=10 stmt:"select * from (SELECT COUNT(*)
AS TOT_CNT FROM renzy WHERE (ACCT_NO = '6222620117273900882') AND LAWENF_NTIST_TP_CD
NOT LIKE '12%' AND LAWENF_NTIST_TP_CD NOT LIKE '05%' AND EMRG_STPY_SRC_CD != 'JZ05' AND
ACCTG_DT >= '1900-01-01' AND ACCTG_DT = '1900-01-01' AND ACCTG_DT
