【SQL文本一样，执行计划一样，执行效率有快有慢？】

原创张sir 2023-05-30

609

一、前言

上周碰到一个问题还是挺奇怪的，开发同事说有个sql从oracle的主库执行挺快，从备库执行就很慢，刚听到这个问题的时候，我第一反应可能是带入的执行计划不一样或者数据有倾斜；后面经过沟通得知SQL文本一毛一样，带入的变量也没毛病。按理说备库是主库的一个物理拷贝，统计信息啥的应该也都是一样的，执行计划应该也是一样的，后面经过分析发现里面大有门道。

二、分析

1、执行计划分析

SQL文本如下：

select b.hstrade_accname,
       a.tot_net_val,
       AA.BB('DR201800079',
                                   to_date('2023-05-17', 'yyyy-MM-dd') - 365,
                                   to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.BB('DR201800079',
                                   to_date('2023-05-17', 'yyyy-MM-dd') -
                                   365 * 3,
                                   to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.BB('DR201800079',
                                   b.PRODUCT_START_DATE - 1,
                                   to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.BB('DR201800079',
                                   to_date('2023-01-01', 'yyyy-MM-dd'),
                                   to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.CC('DR201800079',
                               to_date('2023-05-17', 'yyyy-MM-dd') - 365,
                               to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.CC('DR201800079',
                               to_date('2023-05-17', 'yyyy-MM-dd') - 365 * 3,
                               to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.CC('DR201800079',
                               b.PRODUCT_START_DATE - 1,
                               to_date('2023-05-17', 'yyyy-MM-dd')) ,
       AA.CC('DR201800079',
                               to_date('2023-01-01', 'yyyy-MM-dd'),
                               to_date('2023-05-17', 'yyyy-MM-dd')) 
       
  from test
...... 


执行计划如下：

```SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2775751092

-----------------------------------------------------------------------------------------------------------
| Id  | Operation			    | Name		  | Rows  | Bytes | Cost (%CPU)| Time	  |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT		    |			  |	1 |   210 |   180   (0)| 00:00:03 |
|   1 |  NESTED LOOPS OUTER		    |			  |	1 |   210 |   180   (0)| 00:00:03 |
|   2 |   NESTED LOOPS OUTER		    |			  |	1 |   189 |    10   (0)| 00:00:01 |
|   3 |    NESTED LOOPS OUTER		    |			  |	1 |   168 |	9   (0)| 00:00:01 |
|   4 |     NESTED LOOPS OUTER		    |			  |	1 |   134 |	8   (0)| 00:00:01 |
|   5 |      NESTED LOOPS OUTER 	    |			  |	1 |   113 |	7   (0)| 00:00:01 |
|   6 |       NESTED LOOPS OUTER	    |			  |	1 |    92 |	6   (0)| 00:00:01 |
|   7 |        NESTED LOOPS OUTER	    |			  |	1 |    71 |	5   (0)| 00:00:01 |
|   8 | 	NESTED LOOPS OUTER	    |			  |	1 |    50 |	4   (0)| 00:00:01 |
|   9 | 	 TABLE ACCESS BY INDEX ROWID| TEST1	          |	1 |    29 |	3   (0)| 00:00:01 |
|* 10 | 	  INDEX UNIQUE SCAN	    | PK_ACCT_DAILY	  |	1 |	  |	2   (0)| 00:00:01 |
|* 11 | 	 INDEX UNIQUE SCAN	    | PK_ACCT_METRIC	  |	1 |    21 |	1   (0)| 00:00:01 |
|* 12 | 	INDEX UNIQUE SCAN	    | PK_ACCT_DAILY	  |	1 |    21 |	1   (0)| 00:00:01 |
|* 13 |        INDEX UNIQUE SCAN	    | PK_ACCT_DAILY	  |	1 |    21 |	1   (0)| 00:00:01 |
|* 14 |       INDEX UNIQUE SCAN 	    | PK_ACCT_DAILY	  |	1 |    21 |	1   (0)| 00:00:01 |
|* 15 |      INDEX UNIQUE SCAN		    | PK_ACCT_DAILY	  |	1 |    21 |	1   (0)| 00:00:01 |
|  16 |     TABLE ACCESS BY INDEX ROWID     | AM_ACCTINFO	  |	1 |    34 |	1   (0)| 00:00:01 |
|* 17 |      INDEX UNIQUE SCAN		    | PK_ACCTINFO	  |	1 |	  |	0   (0)| 00:00:01 |
|* 18 |    INDEX UNIQUE SCAN		    | PK_ACCT_DAILY	  |	1 |    21 |	1   (0)| 00:00:01 |
|* 19 |   TABLE ACCESS FULL		    | TEST4               |	1 |    21 |   170   (0)| 00:00:03 |
-----------------------------------------------------------------------------------------------------------

查看执行计划，从执行计划看，并没有什么特殊，

2、SQL Monitor分析

从主备节点跑的sql monitor看，主库执行的快，逻辑读很低，备库执行的慢，逻辑读很高。
主库：

备库：

4、SQL文本分析

仔细看SQL文本发现这个SQL其实调用了几个自定义的函数，仔细分析了下包的内容，发现内部存在一些比较复杂的调用关系，这里有一个怀疑，虽然多次执行原SQL的where条件都一样，但是在包内部的执行的函数由于访问了其他的表，很多变量结果集可能就不一样了。经过测试发现实际上经过测试当AA.BB函数的时候，整个SQL就会慢下来。函数BB的内容如下：

其中有调用了DD函数，这个DD函数又是一个封装在一个包体里。由于该SQL涉及多个函数的调用，很难分析出具体慢在哪个SQL，除了一个个分析调用关系，还有别的更好的方法么？
有，那就是10046，通过10046可以看到详细的执行计划的情况，已经函数调用关系。

5、10046发现问题

alter session set events '10046 trace name context forever, level 12';
执行SQL
alter session set events '10046 trace name context off';

用tkprof格式化生成的trc文件后发现一个SQL执行效率不高：

SQL ID: cakspq89zm1pv Plan Hash: 575777130

SELECT MAX(TO_NUMBER(TO_CHAR(DT,'YYYYMMDD'))) 
FROM
 TEST I1 WHERE I1.WIND_CODE = :B2 AND I1.DT <= :B1 


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse      167      0.00       0.00          0          0          0           0
Execute    167      0.00       0.00          0          0          0           0
Fetch      166    266.84     267.63          0  332223673          0         166
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      500    266.85     267.64          0  332223673          0         166

查看SQL日常执行情况：

有两个执行计划，其中575777130看起来逻辑读很高，2555789231逻辑读很低。
比较两个执行计划：

执行计划575777130走的索引是metric3，2555789231走的索引是metric2。
比较索引的情况：

metric2的选择性更好，metric3的选择性比较差。