經過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可讓咱們獲取到更多詳細信息來定位相關性能問題。

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。