现象描述:
前天下午,同事告诉我他有个查询的sql特别奇怪,第一遍查询1秒左右能出来,不改任何地方,再次查询却需要100秒左右,随便修改一点条件,哪怕换个注释,再查又是1秒能查出来,再次执行还是100秒左右才出来。
听到这个现象后,我验证了确实存在这个现象,查看数据库的一切状态,指标都正常,此时对查询的表也没有什么操作。还是来看看执行计划情况吧。
问题分析:
通过set autotrace on来查看执行计划情况:
第一遍执行时的执行计划:
-------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 58 | 3707 (1)| 00:00:45 | | |
| 1 | SORT AGGREGATE | | 1 | 58 | | | | |
| 2 | NESTED LOOPS SEMI | | 1 | 58 | 3707 (1)| 00:00:45 | | |
| 3 | PARTITION RANGE ITERATOR | | 8 | 272 | 141 (0)| 00:00:02 | 1 | 30 |
|* 4 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_MAIL_CLCT | 8 | 272 | 141 (0)| 00:00:02 | 1 | 30 |
|* 5 | INDEX RANGE SCAN | INDEX_SENDER_POST_CODE | 276 | | 62 (0)| 00:00:01 | 1 | 30 |
| 6 | PARTITION RANGE AND | | 577K| 13M| 3707 (1)| 00:00:45 |KEY(AP)|KEY(AP)|
|* 7 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_DLV | 577K| 13M| 3707 (1)| 00:00:45 |KEY(AP)|KEY(AP)|
| 8 | BITMAP CONVERSION TO ROWIDS | | | | | | | |
|* 9 | BITMAP INDEX RANGE SCAN | P_TB_EVT_DLV | | | | |KEY(AP)|KEY(AP)|
-------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
Statistics
----------------------------------------------------------
208 recursive calls
0 db block gets
455962 consistent gets
2 physical reads
0 redo size
537 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
7 sorts (memory)
0 sorts (disk)
1 rows processed
第二遍执行的执行计划:
-------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 58 | 3707 (1)| 00:00:45 | | |
| 1 | SORT AGGREGATE | | 1 | 58 | | | | |
| 2 | NESTED LOOPS SEMI | | 1 | 58 | 3707 (1)| 00:00:45 | | |
| 3 | PARTITION RANGE ITERATOR | | 8 | 272 | 141 (0)| 00:00:02 | 1 | 30 |
|* 4 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_MAIL_CLCT | 8 | 272 | 141 (0)| 00:00:02 | 1 | 30 |
|* 5 | INDEX RANGE SCAN | INDEX_SENDER_POST_CODE | 276 | | 62 (0)| 00:00:01 | 1 | 30 |
| 6 | PARTITION RANGE AND | | 577K| 13M| 3707 (1)| 00:00:45 |KEY(AP)|KEY(AP)|
|* 7 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_DLV | 577K| 13M| 3707 (1)| 00:00:45 |KEY(AP)|KEY(AP)|
| 8 | BITMAP CONVERSION TO ROWIDS | | | | | | | |
|* 9 | BITMAP INDEX RANGE SCAN | P_TB_EVT_DLV | | | | |KEY(AP)|KEY(AP)|
-------------------------------------------------------------------------------------------------------------------------------
Statistics
----------------------------------------------------------
9 recursive calls
1 db block gets
3307979 consistent gets
3266357 physical reads
176 redo size
537 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> SQL> SQL>
执行计划一样,但是发现第二遍的逻辑读和物理读比第一次大了非常多,但是为什么会导致逻辑读和物理读多那么多呢?是不是这样查的执行计划不准。用dbms_xplan.display_cursor看看。
第一次执行的执行计划,也就是快的那次:SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('8940hwpvjskxc',0));
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8940hwpvjskxc, child number 0
-------------------------------------
Plan hash value: 1825533607
-------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2231 (100)| | | |
| 1 | SORT AGGREGATE | | 1 | 58 | | | | |
| 2 | NESTED LOOPS SEMI | | 1 | 58 | 2231 (1)| 00:00:27 | | |
| 3 | PARTITION RANGE ITERATOR | | 5 | 170 | 115 (0)| 00:00:02 | 15 | 31 |
|* 4 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_MAIL_CLCT | 5 | 170 | 115 (0)| 00:00:02 | 15 | 31 |
|* 5 | INDEX RANGE SCAN | INDEX_SENDER_POST_CODE | 276 | | 36 (0)| 00:00:01 | 15 | 31 |
| 6 | PARTITION RANGE AND | | 440K| 10M| 2231 (1)| 00:00:27 |KEY(AP)|KEY(AP)|
|* 7 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_DLV | 440K| 10M| 2231 (1)| 00:00:27 |KEY(AP)|KEY(AP)|
| 8 | BITMAP CONVERSION TO ROWIDS | | | | | | | |
|* 9 | BITMAP INDEX RANGE SCAN | P_TB_EVT_DLV | | | | |KEY(AP)|KEY(AP)|
-------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
39 rows selected.
DongCS 23:45:13
第二次执行,慢的那次:
SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('8940hwpvjskxc',1));
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 8940hwpvjskxc, child number 1
-------------------------------------
Plan hash value: 2676587892
-------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 698K(100)| | | |
| 1 | SORT AGGREGATE | | 1 | 58 | | | | |
|* 2 | HASH JOIN SEMI | | 223 | 12934 | 698K (1)| 02:19:46 | | |
| 3 | PARTITION RANGE ITERATOR | | 23962 | 795K| 5183 (1)| 00:01:03 | 15 | 31 |
|* 4 | TABLE ACCESS BY LOCAL INDEX ROWID| TB_EVT_MAIL_CLCT | 23962 | 795K| 5183 (1)| 00:01:03 | 15 | 31 |
|* 5 | INDEX RANGE SCAN | INDEX_SENDER_POST_CODE | 17841 | | 127 (0)| 00:00:02 | 15 | 31 |
| 6 | PARTITION RANGE ITERATOR | | 47M| 1085M| 693K (1)| 02:18:41 | 107 | 306 |
|* 7 | TABLE ACCESS FULL | TB_EVT_DLV | 47M| 1085M| 693K (1)| 02:18:41 | 107 | 306 |
-------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
Note
-----
- cardinality feedback used for this statement
39 rows selected.
这次查处的执行计划果然不一样,TB_EVT_DLV是全表扫描,最后还多了一个cardinality feedback的注释!
在metalink上查找cardinality feedback相关信息,发现cardinality feedback是oracle11g的一个新特性:
Cardinality feedback monitoring may be enabled in the following cases:
Tables with no statistics, multiple conjunctive or disjunctive filter predicates on a table, and predicates containing complex operators that the optimizer cannot accurately compute selectivity estimates for.
In some cases, there are other techniques available to improve estimation; for instance, dynamic sampling or multi-column statistics allow the optimizer to more accurately estimate selectivity of conjunctive predicates. In cases where these techniques apply, cardinality feedback is not enabled.
However, if multi-column statistics are not present for the relevant combination of columns, the optimizer can fall back on cardinality feedback.
对应的有个隐含参数:_optimizer_use_feedback,按照metalink上相关文档提供的信息,尝试将这个参数设置为false。
alter system set "_optimizer_use_feedback"=false scope=both;
再来查看上面的那个sql,发现现在无论查询多少次都是在1秒左右能查出。看来这个是oracle11g cardinality feedback的bug。将这个新特性关掉就ok了。
参考文档:
Cardinality Feedback - Frequently Asked Questions [ID 1344937.1]
Bug 8521689 - SubOptimal execution plan on second execution of GROUP BY query [ID 8521689.8]
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/12129601/viewspace-719736/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/12129601/viewspace-719736/