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

时间 2019-11-12

原文原文链接

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

获取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。bash

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并无真实执行。session

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诊断时会比较有用。ide

什么是10046事件？

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

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

如何使用？

经过如下三个步骤咱们能够经过10046 event来获取执行计划：性能

在当前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翻译

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

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

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

案例操做

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.

翻译后的结果以下：orm

********************************************************************************

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可让咱们获取到更多详细信息来定位相关性能问题。