10046 eventで実際の実行計画を取得


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 EXPSELECT文が実際に実行されていないことを説明します.これを例に、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が提供する性能分析ツールであり、あるセッションで実行されたSQL文またはPL/SQL文の各段階で遭遇した待機イベント、消費された論理読み、物理読み、消費された時間、実行計画などを追跡するために使用することができる. 10046 eventには、次の9つの有効な追跡レベルがあります.
  • level 1標準SQL_を有効にするTRACEの機能は、時間消費、処理の行数、物理的読み書きの数、実行計画などを含む
  • level 4はlevel 1に加えて変数バインドが多くなった
  • レベル8はレベル1に加えて待機イベントが多くなった
  • レベル12すなわちレベル4+レベル8
  • level 16 level 1に基づき、実行ごとに実行計画情報を生成する(11.1以降のバージョンのみ)
  • level 28 level 4+level 8+level 16
  • レベル32はレベル1より実行計画情報が少ない(11.1以降のバージョンのみ)
  • level 64 level 1に基づき、あるカーソルが前回よりも1 min以上経過していれば実行計画情報も生成される(11.2以降のバージョンのみ)
  • level 68すなわちleve 4+level 64
  • 使用方法


    実行計画は、次の3つのステップで10046 eventで取得できます.
  • 現在セッションで10046 eventをアクティブ化するには、次の2つの方法があります.
  • alter session set events ‘10046 trace name context forever,level 12’ oradebug setmypid oradebug event 10046 trace name context forever,level 12
  • 実行先SQL
  • 現在セッションで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では、より詳細な情報を取得してパフォーマンスの問題を特定できます.