通过10046 event来获取真实的执行计划

原文发表在http://l4j.cc/2019/04/09/10046-event-and-sql-plan/

获取SQL执行计划的方式有很多，但是某些时候获取的SQL执行计划并不是准确的，只有在SQL真实执行之后获取到的SQL PLAN才是真实准确的，其他方式(如，explain plan)获取到的执行计划都有可能因为绑定绑定变量和当时SQL执行环境的影响而导致获取到的执行计划可能不准确。对于AUTOTRACE开关，当执行SET AUTOT ON和SET AUTOT TRACE命令此时的SQL是实际执行过的，所以此时获取到的执行计划是准确的。而SET AUTOT TRACE EXP命令时稍有不同，当执行的是SELECT语句时SQL语句并不会实际执行，此时获取到的执行计划和直接使用explain plan命令获取的结果是一致的，但是对于DML命令则会实际执行该SQL。 下面看一个例子，说明SET AUTOT TRACE EXP并不会真实的执行SELECT语句，以此为例来介绍如何确定SQL是否真实执行。 首先，我们直接执行SQL，可以在V$SQLAREA里看到EXECUTIONS的值为1。

SQL> SELECT PCT_USED,PCT_FREE FROM TEST_ENV.TB_TABLE_LIST WHERE TABLE_NAME='DBMS_SQLPATCH_STATE'; PCT_USED PCT_FREE ---------- ---------- 40 10 SQL> SELECT EXECUTIONS FROM V$SQLAREA WHERE SQL_TEXT LIKE 'SELECT PCT_USED,PCT_FREE FROM TEST_%'; EXECUTIONS ---------- 1 SQL> ALTER SYSTEM FLUSH SHARED_POOL;--该操作为了方便后面查询，生产环境勿执行 系统已更改。 

打开SET AUTOT TRACE EXP，后重复上述SQL，可以看到EXECUTIONS的值为0，表明SQL并没有真实执行。

SQL> SET AUTOT TRACE EXP SQL> SELECT PCT_USED,PCT_FREE FROM TEST_ENV.TB_TABLE_LIST WHERE TABLE_NAME='DBMS_SQLPATCH_STATE'; 执行计划 ---------------------------------------------------------- Plan hash value: 3473397811 ---------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ---------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 23 | 2 (0)| 00:00:01 | | 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TB_TABLE_LIST | 1 | 23 | 2 (0)| 00:00:01 | |* 2 | INDEX RANGE SCAN | IDX_TB_TABLE_LIST_TBNAME | 1 | | 1 (0)| 00:00:01 | ---------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 2 - access("TABLE_NAME"='DBMS_SQLPATCH_STATE') SQL> SET AUTOTRACE OFF SQL> SELECT EXECUTIONS FROM V$SQLAREA WHERE SQL_TEXT LIKE 'SELECT PCT_USED,PCT_FREE FROM TEST_%'; EXECUTIONS ---------- 0 

另一种获取SQL真实执行计划的方式是通过10046事件，通过这种方式我们可以看到更细粒度的结果展示，如每一个步骤所执行的逻辑读、物理读和花费的时间等，这对于某些复杂SQL诊断时会比较有用。

什么是10046事件？

10046 event是ORACLE提供的一个性能分析工具，可以用来跟踪某一个session所执行的SQL语句或者或者PL/SQL语句各个阶段中遇到的等待事件、消耗的逻辑读、物理读、消耗的时间、执行计划等。 10046 event有以下9个有效跟踪级别：

1. level 1 启用标准SQL_TRACE的功能，包含时间消耗、处理的行数，物理读和写的数、执行计划等
2. level 4 在level 1 的基础上多了变量绑定
3. level 8 在level 1 的基础上多了等待事件
4. level 12 即level 4+level 8
5. level 16 level 1的基础上为每一次执行生成执行计划信息(11.1之后的版本才有)
6. level 28 level 4+level 8+level 16
7. level 32 比level 1少了执行计划信息(11.1之后的版本才有)
8. level 64 在level 1的基础上，如果某游标比上次执行的时间多消耗了1min以上则还会生成执行计划信息(11.2之后的版本才有)
9. level 68 即leve4 + level 64

如何使用？

通过以下三个步骤我们可以通过10046 event来获取执行计划：

1. 在当前session激活10046 event，有以下两种方式：

alter session set events '10046 trace name context forever,level 12' oradebug setmypid oradebug event 10046 trace name context forever,level 12

2. 执行目标SQL
3. 在当前session关闭10046 event：

alter session set events '10046 trace name context off' oradebug event 10046 trace name context off

推荐使用oradebug的方式，这样可以通过oradebug tracefile_name来获取tracefile的绝对路径。对于直接获取到的tracefile不直观，看起来非常吃力，可以通过ORACLE提供的tkprof来对得到的trace文件进行翻译

案例操作

SQL> oradebug setmypid 已处理的语句 SQL> oradebug event 10046 trace name context forever,level 12 已处理的语句 SQL> select a.table_name,a.pct_used,b.column_name from test_env.tb_table_list a,test_env.tb_column_list b where a.owner=b.owner and a.table_name=b.table_name and b.table_name='DBMS_SQLPATCH_STATE'; . . . . DBMS_SQLPATCH_STATE 40 S_CACHED_LSINVENTORY 已选择 27 行。 SQL> oradebug tracefile_name C:\APP\ADMINISTRATOR\diag\rdbms\orcl\orcl\trace\orcl_ora_3016.trc SQL> oradebug event 10046 trace name context off 已处理的语句 SQL> C:\Users\Administrator>tkprof C:\APP\ADMINISTRATOR\diag\rdbms\orcl\orcl\trace\orcl_ora_2548.trc C:\explain_orcl_ora_2548.txt TKPROF: Release 18.0.0.0.0 - Development on 星期五 4月 5 16:05:18 2019 Copyright (c) 1982, 2018, Oracle and/or its affiliates. All rights reserved. 

翻译后的结果如下：

******************************************************************************** select a.table_name,a.pct_used,b.column_name from test_env.tb_table_list a,test_env.tb_column_list b where a.owner=b.owner and a.table_name=b.table_name and b.table_name='DBMS_SQLPATCH_STATE' call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.01 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 3 0.01 0.07 856 863 0 27 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 0.03 0.08 856 863 0 27 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 27 27 27 HASH JOIN (cr=863 pr=856 pw=0 time=78538 us starts=1 cost=246 size=63 card=1) 1 1 1 TABLE ACCESS FULL TB_TABLE_LIST (cr=101 pr=99 pw=0 time=23646 us starts=1 cost=31 size=26 card=1) 27 27 27 TABLE ACCESS FULL TB_COLUMN_LIST (cr=762 pr=757 pw=0 time=42700 us starts=1 cost=214 size=444 card=12) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ Disk file operations I/O 2 0.00 0.00 SQL*Net message to client 3 0.00 0.00 db file sequential read 2 0.01 0.01 db file scattered read 36 0.01 0.04 SQL*Net message from client 3 6.98 7.06 PGA memory operation 1 0.00 0.00 ******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.01 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 3 0.01 0.07 856 863 0 27 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 0.03 0.08 856 863 0 27 Misses in library cache during parse: 1 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 6 0.00 0.00 SQL*Net message from client 6 80.00 104.95 db file sequential read 2 0.01 0.01 PGA memory operation 1 0.00 0.00 Disk file operations I/O 5 0.00 0.00 db file scattered read 36 0.01 0.04 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.01 0.00 0 0 0 0 Execute 124 0.01 0.04 0 0 0 0 Fetch 233 0.01 0.04 10 399 0 422 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 359 0.04 0.08 10 399 0 422 Misses in library cache during parse: 2 Misses in library cache during execute: 15 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 10 0.00 0.04 PGA memory operation 7 0.00 0.00 Disk file operations I/O 1 0.00 0.00 1 user SQL statements in session. 19 internal SQL statements in session. 20 SQL statements in session. ******************************************************************************** Trace file: C:\APP\ADMINISTRATOR\diag\rdbms\orcl\orcl\trace\orcl_ora_2548.trc Trace file compatibility: 12.2.0.0 Sort options: default 1 session in tracefile. 1 user SQL statements in trace file. 19 internal SQL statements in trace file. 20 SQL statements in trace file. 20 unique SQL statements in trace file. 2176 lines in trace file. 0 elapsed seconds in trace file. 

从结果中可以看到SQL的执行计划、每个阶段(Parse、Execute、Fetch)cpu时间返回的行数、所涉及等待事件、row source操作的具体情况等详细的信息。当我们通过AUTOTRACE以及DBMS_XPLAN方式无法确定SQL具体性能问题时，10046可以让我们获取到更多详细信息来定位相关性能问题。