OB 运维派 | 优化器走对，执行计划导致查询快 1000 倍

外向笑小鸭子
外向笑小鸭子 2024-01-02 10:19:34 51607
分类专栏： 资讯

针对 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 <= '2025-03-31' ;

 

关键表结构、记录数信息如下：

 

-- 脱敏处理
show create table renzy\G
*************************** 1. row ***************************
Table: renzy
Create Table: CREATE TABLE `renzy` (
`ID` char(18) COLLATE utf8mb4_bin NOT NULL COMMENT ,
...
`ACCT_NO` char(40) COLLATE utf8mb4_bin NOT NULL COMMENT ,
...
`ACCTG_DT` date DEFAULT NULL COMMENT ,
...
PRIMARY KEY (`ID`),
...
KEY `renzy_I2` (`ACCT_NO`) BLOCK_SIZE 16384 LOCAL,
...
KEY `renzy_I5` (`ACCTG_DT`, `ENQ_INST_CD`, `BLON_INST_CD`, `EMRG_STPY_SRC_CD`)
BLOCK_SIZE 16384 LOCAL,
...
) DEFAULT CHARSET = utf8mb4;
1 row in set (0.01 sec)
MySQL > 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 <= '2025-03-31';
+----------+
| TOT_CNT |
+----------+
| 25432155 |
+----------+
1 row in set (12.42 sec)
MySQL > SELECT COUNT(*) AS TOT_CNT FROM renzy;
+----------+
| TOT_CNT |
+----------+
| 25435024 |
+----------+
1 row in set (10.65 sec)

针对 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 <= '2025-03-31' ;

 

关键表结构、记录数信息如下：

 

-- 脱敏处理
show create table renzy\G
*************************** 1. row ***************************
Table: renzy
Create Table: CREATE TABLE `renzy` (
`ID` char(18) COLLATE utf8mb4_bin NOT NULL COMMENT ,
...
`ACCT_NO` char(40) COLLATE utf8mb4_bin NOT NULL COMMENT ,
...
`ACCTG_DT` date DEFAULT NULL COMMENT ,
...
PRIMARY KEY (`ID`),
...
KEY `renzy_I2` (`ACCT_NO`) BLOCK_SIZE 16384 LOCAL,
...
KEY `renzy_I5` (`ACCTG_DT`, `ENQ_INST_CD`, `BLON_INST_CD`, `EMRG_STPY_SRC_CD`)
BLOCK_SIZE 16384 LOCAL,
...
) DEFAULT CHARSET = utf8mb4;
1 row in set (0.01 sec)
MySQL > 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 <= '2025-03-31';
+----------+
| TOT_CNT |
+----------+
| 25432155 |
+----------+
1 row in set (12.42 sec)
MySQL > 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 <=
'2025-03-31') as orginal limit 2000; select last_trace_id();
+---------+
| TOT_CNT |
+---------+
| 1 |
+---------+
1 row in set (0.02 sec)

 

执行计划如下，可见索引 I2 为最优解，索引等值匹配仅需回表 1 次。

 

*************************** 1. row ***************************
Query Plan: ========================================================
|ID|OPERATOR |NAME |EST. ROWS|COST|
--------------------------------------------------------
|0 |LIMIT | |1 |92 |
|1 | SCALAR GROUP BY| |1 |92 |
|2 | TABLE SCAN |renzy(renzy_I2)|1 |92 |
========================================================
...
Outline Data:
-------------------------------------
/*+
BEGIN_OUTLINE_DATA
INDEX(@"SEL$2" "gabsdb.renzy"@"SEL$2" "renzy_I2")
END_OUTLINE_DATA
*/
...
renzy:table_rows:25419080, physical_range_rows:1, logical_range_rows:1,
index_back_rows:1, output_rows:0, est_method:local_storage,
optimization_method=cost_based, avaiable_index_name[renzy_I2,renzy_I5],
pruned_index_name[renzy_I1,renzy_I3,renzy_I4,renzy_I6], unstable_index_name[renzy],
estimation info[table_id:1105009185965290, (table_type:1, version:0-1699898410195654-
1699898410195654, logical_rc:1, physical_rc:1), (table_type:7,
version:1699898401860480-1699898401860480-1699898433101378, logical_rc:0,
physical_rc:0), (table_type:7, version:1699898433101378-1699904137032515-
1699905915658079, logical_rc:0, physical_rc:0), (table_type:5,
version:1699898433101378-1699904137032515-1699905915658079, logical_rc:0,
physical_rc:0), (table_type:0, version:1699905915658079-1699905915658079-
9223372036854775807, logical_rc:0, physical_rc:0)]
...

 

通过 OCP 的 SQL 诊断获取慢 SQL 的 plan_id，检查慢 SQL 实际命中的 plan。

 

MySQL [oceanbase]> 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 <= ?) as orginal limit 2000
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 >= '' AND
ACCTG_DT <= '') as orginal limit 2000
special_params: 2000
param_infos: {1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},
{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},
{1,0,0,-1,17},{1,0,0,-1,17}
sys_vars:
45,45,12582912,2,4,1,0,0,32,3,1,0,1,1,0,10485760,1,1,0,1,BINARY,BINARY,AL32UTF8,AL16UTF
16,BYTE,FALSE,1,100,64,200,0,13,NULL,1,1,1,1
plan_hash: 10428103352368081688
first_load_time: 2023-11-14 10:14:11.578250
schema_version: 1699927892190832
merged_version: 287
last_active_time: 2023-11-14 11:04:58.127020
avg_exe_usec: 35858760
slowest_exe_time: 2023-11-14 11:04:58.127020
slowest_exe_usec: 171575101
slow_count: 2
hit_count: 7
plan_size: 81984
executions: 8
disk_reads: 1136285
direct_writes: 0
buffer_gets: 18067948
application_wait_time: 0
concurrency_wait_time: 0
user_io_wait_time: 0
rows_processed: 8
elapsed_time: 286870087
cpu_time: 229807460
large_querys: 2
delayed_large_querys: 1
delayed_px_querys: 0
outline_version: 0
outline_id: -1
outline_data: /*+ BEGIN_OUTLINE_DATA INDEX(@"SEL$2" "gabsdb.renzy"@"SEL$2"
"renzy_I5") END_OUTLINE_DATA*/
....
1 row in set (0.09 sec)
MySQL [oceanbase]> 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 <= '') as orginal limit 2000\G
*************************** 1. row ***************************
Query Plan: ========================================================
|ID|OPERATOR |NAME |EST. ROWS|COST|
--------------------------------------------------------
|0 |LIMIT | |1 |92 |
|1 | SCALAR GROUP BY| |1 |92 |
|2 | TABLE SCAN |renzy(renzy_I5)|0 |92 |
========================================================
Outline Data:
-------------------------------------
/*+
BEGIN_OUTLINE_DATA
INDEX(@"SEL$2" "gabsdb.renzy"@"SEL$2" "renzy_I5")
END_OUTLINE_DATA
*/
renzy:table_rows:25419080, physical_range_rows:1, logical_range_rows:1,
index_back_rows:0, output_rows:0, est_method:local_storage,
optimization_method=cost_based, avaiable_index_name[renzy_I2,renzy_I5],
pruned_index_name[renzy_I1,renzy_I3,renzy_I4,renzy_I6], unstable_index_name[renzy]
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 >= '' AND ACCTG_DT <= '') as
orginal limit 2000;
+---------+
| TOT_CNT |
+---------+
| 0 |
+---------+
1 row in set, 2 warnings (0.02 sec)

分析下后续 SQL

为何不淘汰该 plan

 

我们知道，SQL 查询并不需要每次生成查询计划，因为这样涉及到硬解析等耗费性能的操作，所以默认每次会先查询 Plan Cache （硬解析操作包含词法/语法/语义解析，优化器统计信息查询等步骤，参考下图）。

本案例中，后续的 SQL 命中该 Plan 就可以理解，因为要走 I5 索引，range 太大基本为全索引扫描，所以耗时太慢。

 

ACCTG_DT >= '1900-01-01' AND ACCTG_DT <= '2025-03-31'

 

什么时候淘汰这个计划呢？

 

// 关键代码段如下（410bp1社区版，这⾥的逻辑和323bp8企业版类似，企业版代码不便贴出）
if (sample_count < SLOW_QUERY_SAMPLE_SIZE) {
// do nothing when query execution samples are not enough
} else {
if (stat_.cpu_time_ <= SLOW_QUERY_TIME_FOR_PLAN_EXPIRE * stat_.execute_times_)
{
// do nothing for fast query
} else if (is_plan_unstable(sample_count, sample_exec_row_count,
sample_exec_usec)) {
set_is_expired(true);
}
ATOMIC_STORE(&(stat_.sample_times_), 0);
}
}
bool ObPhysicalPlan::is_plan_unstable(const int64_t sample_count,
const int64_t sample_exec_row_count,
const int64_t sample_exec_usec)
{
bool bret = false;
if (sample_exec_usec <= SLOW_QUERY_TIME_FOR_PLAN_EXPIRE * sample_count) {
// sample query is fast query in the average
} else if (OB_PHY_PLAN_LOCAL == plan_type_) {
int64_t first_query_range_rows = ATOMIC_LOAD(&stat_.first_exec_row_count_);
if (sample_exec_row_count <= SLOW_QUERY_ROW_COUNT_THRESOLD * sample_count) {
// the sample query does not accesses too many rows in the average
} else if (sample_exec_row_count / sample_count > first_query_range_rows * 10) {
// the average sample query range row count increases great
bret = true;
LOG_INFO("local query plan is expired due to unstable performance",
K(bret), K(stat_.execute_times_),
K(first_query_range_rows), K(sample_exec_row_count), K(sample_count));
}
} else if ( OB_PHY_PLAN_DISTRIBUTED == plan_type_) {
int64_t first_exec_usec = ATOMIC_LOAD(&stat_.first_exec_usec_);
if (sample_exec_usec / sample_count > first_exec_usec * 2) {
// the average sample query execute time increases great
bret = true;
LOG_INFO("distribute query plan is expired due to unstable performance",
K(bret), K(stat_.execute_times_), K(first_exec_usec),
K(sample_exec_usec), K(sample_count));
}
} else {
// do nothing
}
return bret;
}

 

这里淘汰⼀个 Plan 需要满足的条件有 2 个：

 

  • sample_count < SLOW_QUERY_SAMPLE_SIZE)

  • sample_exec_row_count / sample_count > first_query_range_rows * 10

 

这里的 SLOW_QUERY_SAMPLE_SIZE 是常量，OceanBase 4.1.0 的定义是 20；sample_count（采样次数）实质为 Plan 的 SQL 执行次数。

 

static const int64_t SLOW_QUERY_SAMPLE_SIZE = 20; // smaller than
ObPlanStat::MAX_SCAN_STAT_SIZE

 

结合上下文代码来看，意思是满足如下情况就会淘汰 Plan：

 

  • 命中该 Plan 的 SQL 执行大于等于 20 次。

  • （执行的 SQL 扫描总行数 / 执行次数） 大于 （第⼀次 SQL 执行扫描的行数 * 10）

复现以验证

 

1. 清空 plan cache，执行业务第⼀次生成 Plan 的 SQL。

 

MySQL > alter system flush plan cache;
Query OK, 0 rows affected (0.13 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 >= '' AND ACCTG_DT <= '') as
orginal limit 2000;
+---------+
| TOT_CNT |
+---------+
| 0 |
+---------+
1 row in set, 2 warnings (0.02 sec)

 

2. 执行业务 SQL，复现慢的情况。

 

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 <=
'2025-03-31') as orginal limit 2000;
+---------+
| TOT_CNT |
+---------+
| 1 |
+---------+
1 row in set (2 min 51.61 sec)
MySQL > 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 <= '2025-03-31') as orginal limit 2000
...
ELAPSED_TIME: 171575101
...
EXECUTE_TIME: 171574843
...
MEMSTORE_READ_ROW_COUNT: 25416176
SSSTORE_READ_ROW_COUNT: 50832349
...

 

 

这里通过 sql_audit 可以观测到重要的信息：

 

  • ELAPSED_TIME ：执行耗时。

  • MEMSTORE_READ_ROW_COUNT / SSSTORE_READ_ROW_COUNT : 这条 SQL 扫描的行数。

 

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 <=
'2025-03-31') as orginal limit 2000;
+---------+
| TOT_CNT |
+---------+
| 1 |
+---------+
1 row in set (2 min 51.61 sec)
MySQL > 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 <= '2025-03-31') as orginal limit 2000
...
ELAPSED_TIME: 171575101
...
EXECUTE_TIME: 171574843
...
MEMSTORE_READ_ROW_COUNT: 25416176
SSSTORE_READ_ROW_COUNT: 50832349
...MySQL [oceanbase]> 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 <= ?) as orginal limit 2000
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 >= '' AND
ACCTG_DT <= '') as orginal limit 2000
...
outline_id: -1
outline_data: /*+ BEGIN_OUTLINE_DATA INDEX(@"SEL$2" "gabsdb.renzy"@"SEL$2"
"renzy_I5") END_OUTLINE_DATA*/
...

 

通过 plan_cache_plan_stat 可看到这条 SQL 命中了第⼀次 SQL 执行时生成的 Plan（不符合预期）。

 

3. 继续通过脚本执行多次。

 

#!/bin/bash
for i in `seq 1 30`
do
echo ">>> do $i"
mysql -h12.240.68.36 -P3306 -uroot@tgabsua2g00#obcdcbsuat01 -pOceanBase_123# -Dgabsdb -
A -c -NBe "select now();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 <= '2025-03-31') as orginal limit 2000; select
last_trace_id();select now();"
done
# ./1.sh
...
>>> 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 <= '2025-03-31') as orginal limit 2000
...
ELAPSED_TIME: 207
PLAN_ID: 7334178
...
MEMSTORE_READ_ROW_COUNT: 1
SSSTORE_READ_ROW_COUNT: 2
MySQL [oceanbase]> 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 <= ?) as orginal limit 2000
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 <= '2025-03-31') as orginal limit 2000
...
first_load_time: 2023-11-14 16:12:51.547434
...
slowest_exe_time: 2023-11-14 16:12:51.547618
slowest_exe_usec: 4139
...
elapsed_time: 8279
...
outline_id: -1
outline_data: /*+ BEGIN_OUTLINE_DATA INDEX(@"SEL$2" "gabsdb.renzy"@"SEL$2"
"renzy_I2") END_OUTLINE_DATA*/
...

 

5. OBS 日志关键信息

 

#grep YB420CF01A46-0006009B012FF1D0-0-0 observer.log.20231114161*|less
observer.log.20231114161017:[2023-11-14 16:10:15.813150] INFO [SQL] ob_sql.cpp:1769
[86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=17] [dc=0] It is a large query, need
delay, do not need disconnect(avg_process_time=123860984, exec_cnt=20,
large_query_threshold=5000000, plan->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 <= '2025-03-31') as orginal limit 2000",
stmt_len:287|[process_end] u=85 run_ts:1699949415813082|total_timeu=98)
observer.log.20231114161302:[2023-11-14 16:12:51.412696] INFO [SQL.ENG]
ob_physical_plan.cpp:736 [86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=15] [dc=0]
local query plan is expired due to unstable performance(bret=true,
stat_.execute_times_=21, first_query_range_rows=0, sample_exec_row_count=1525906500,
sample_count=20)
observer.log.20231114161302:[2023-11-14 16:12:51.412725] WARN [SHARE.SCHEMA] revert
(ob_schema_mgr_cache.cpp:131) [86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=11]
[dc=0] long time to hold one guard(schema_mgr=0x7ee87934c610, tenant_id=1,
version=1697523399752200, cur_timestamp=1699949571412714,
ref_timestamp=1699949415812628, lbt()="0xf51231f 0x6158f04 0x4f5992c 0x50c61cc
0x4ed2f6f 0x4ecf518 0x4ecc8ef 0x4ecaa6e 0xb8c71f1 0x4ec9c90 0xb8c4d31 0x4ec58f6
0xb8c52a7 0xf3f17f3 0xf3f164f 0xf6901df")
observer.log.20231114161302:[2023-11-14 16:12:51.412738] WARN [SHARE.SCHEMA] revert
(ob_schema_mgr_cache.cpp:131) [86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=8]
[dc=0] long time to hold one guard(schema_mgr=0x7edddba39170, tenant_id=1005,
version=1699931135472584, cur_timestamp=1699949571412734,
ref_timestamp=1699949415812628, lbt()="0xf51231f 0x6158f04 0x4f5992c 0x50c61cc
0x4ed2f6f 0x4ecf518 0x4ecc8ef 0x4ecaa6e 0xb8c71f1 0x4ec9c90 0xb8c4d31 0x4ec58f6
0xb8c52a7 0xf3f17f3 0xf3f164f 0xf6901df")
observer.log.20231114161302:[2023-11-14 16:12:51.412798] TRACE [TRACE]obmp_base.cpp:147
[86881][0][YB420CF01A46-0006009B012FF1D0-0-0] [lt=5] [dc=0] [slow query]
(TRACE=begin_ts=1699949415813229 2023-11-14 08:10:15.813229|[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:162, receive_ts:1699949415813066,
enqueue_ts:1699949415813225, trace_id:YB420CF01A46-0006009B012FF1D0-0-0|[session] u=2
sid:3221784053, tenant_id:1005|[parse_begin] u=6 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 <= '2025-03-31') as orginal limit 2000",
stmt_len:287|[exec_begin] u=29 arg1:false, end_trans_cb:false, plan_id:7328133|
[do_open_plan_begin] u=8 |[sql_start_stmt_begin] u=1 |[sql_start_participant_begin] u=5
|[storage_table_scan_begin] u=56 |[storage_table_scan_end] u=116 |[get_row] u=155437570
|[result_set_close] u=161554 |[close_plan_begin] u=0 |[revert_scan_iter] u=96 |
[end_participant_begin] u=3 |[start_end_stmt] u=1 |[affected_rows] u=0
affected_rows:-1|[store_found_rows] u=1 found_rows:0, return_rows:1|
[auto_end_plan_begin] u=0 |[process_end] u=86
run_ts:1699949415813230|total_timeu=155599534)

 

第 21 次执行的 SQL 的关键日志信息：

 

[2023-11-14 16:12:51.412696] INFO [SQL.ENG] ob_physical_plan.cpp:736 [86881][0]
[YB420CF01A46-0006009B012FF1D0-0-0] [lt=15] [dc=0] local query plan is expired due to
unstable performance(bret=true, stat_.execute_times_=21, first_query_range_rows=0,
sample_exec_row_count=1525906500, sample_count=20)

 

由该日志，关键信息如下：

 

  • sample_exec_row_count=1525906500

  • sample_count=20

  • 3first_query_range_rows=0

 

结合代码可知该结果满足 Plan 淘汰条件，从而 plan expire。

sample_exec_row_count / sample_count > first_query_range_rows * 10
1525906500 / 20 > 0 * 10
// 这⾥ 1525906500 的结果，不难得知，是单次SQL扫描⾏数 * 20.
// 即（25416176 + 50832349） * 20 = 1524970500 约等于 1525906500
MEMSTORE_READ_ROW_COUNT: 25416176
SSSTORE_READ_ROW_COUNT: 50832349

网站声明：如果转载，请联系本站管理员。否则一切后果自行承担。

本文链接：https://www.xckfsq.com/news/show.html?id=34079
赞同 0
评论 0 条

相关文章

外向笑小鸭子
外向笑小鸭子L0
粉丝 0 发表 622 + 关注 私信
上周热门
如何使用 StarRocks 管理和优化数据湖中的数据？  2966
【软件正版化】软件正版化工作要点  2885
统信UOS试玩黑神话：悟空  2855
信刻光盘安全隔离与信息交换系统  2743
镜舟科技与中启乘数科技达成战略合作，共筑数据服务新生态  1277
grub引导程序无法找到指定设备和分区  1244
华为全联接大会2024丨软通动力分论坛精彩议程抢先看！  169
2024海洋能源产业融合发展论坛暨博览会同期活动-海洋能源与数字化智能化论坛成功举办  168
点击报名 | 京东2025校招进校行程预告  164
华为纯血鸿蒙正式版9月底见！但Mate 70的内情还得接着挖...  161
本周热议
我的信创开放社区兼职赚钱历程 40
今天你签到了吗？ 27
信创开放社区邀请他人注册的具体步骤如下 15
如何玩转信创开放社区—从小白进阶到专家 15
方德桌面操作系统 14
我有15积分有什么用? 13
用抖音玩法闯信创开放社区——用平台宣传企业产品服务 13
如何让你先人一步获得悬赏问题信息？（创作者必看） 12
2024中国信创产业发展大会暨中国信息科技创新与应用博览会 9
中央国家机关政府采购中心：应当将CPU、操作系统符合安全可靠测评要求纳入采购需求 8
热门标签更多

加入交流群

请使用微信扫一扫!