待機イベントが含まれている10046診断イベントの実行ーOracle11g

Oracle 11gで待機イベントが含まれている10046診断イベントの実行方法を整えてみました。

1. 伝統的な10046診断イベントの使い方は次のとおりです。レベル８以上なら待機イベントが記録されます。

alter session set events '10046 trace name context forever, level 8';

select /* 10046 */ count(*) from user_objects;

alter session set events '10046 trace name context off';

2. 11gからは次のようにsql_traceという「認識できる」名前の診断イベントが使えます。

-- sql_trace + level 8
alter session set events 'sql_trace level 8';

select /* sql_trace_1 */ count(*) from user_objects;

alter session set events 'sql_trace off';

-- sql_trace + wait=true
alter session set events 'sql_trace wait=true';

select /* sql_trace_2 */ count(*) from user_objects;

alter session set events 'sql_trace off';

-- sql_trace + wait=true, bind=true
alter session set events 'sql_trace wait=true, bind=true';

select /* sql_trace_3 */ count(*) from user_objects;

alter session set events 'sql_trace off';

11gから追加された新しい診断イベント機能は強すぎて、次のように特定のSQLを特定することもできます。あまりに有効な機能であるんでしょう。

-- SQL_IDを得て...
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;

col sql_id new_value sql_id1
select sql_id 
from v$sqlarea 
where sql_text = 'select /* sql_trace_4 */ count(*) from user_objects';

col sql_id new_value sql_id2
select sql_id 
from v$sqlarea 
where sql_text = 'select /* sql_trace_5 */ count(*) from user_objects';

-- 1つのSQLに対して
alter session set events 'sql_trace [sql: &sql_id1] wait=true';
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;
alter session set events 'sql_trace off';

-- 複数のSQLに対して
alter session set events 'sql_trace [sql: &sql_id1 | &sql_id2] wait=true';
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;
alter session set events 'sql_trace off';

3. DBMS_MONITORパッケージこそオラクルの公式的なお勧めの方法です。DBMS_MONITORパッケージもSQLを特定する機能が提供したらいいけど、開発者等がまだそこまでは考えていないようです。

exec dbms_monitor.session_trace_enable(waits=>true);

select /* dbms_monitor */ count(*) from user_objects;

exec dbms_monitor.session_trace_disable;

4. DBMS_SYSTEMパッケージやDBMS_SUPPORTパッケージなどの隠しパッケージも同様な機能を提供しています。でも、DBMS_MONITORパッケージが登場した以上必要がなくなったといえます。

col sid new_value sid
col serial# new_value se
select sid, serial# 
from v$session 
where sid = userenv('sid');

exec sys.dbms_system.set_ev(&sid, &se, 10046, 8, null);

select /* dbms_system */ count(*) from user_objects;

exec sys.dbms_system.set_ev(&sid, &se, 10046, 0, null);

SQL_ID値を利用して特定SQLに対してのみ診断イベントを行なう機能が特に有効に見えます。Oracle 11gの拡張された診断イベント機能は次の文書で詳細に紹介しています。

• ORADEBUG DOC
  

Library Cache Pinに対するSelf Deadlockを作ってみよう。

Library Cache Pinに対するSelf Deadlockをとても易く作ってみます。まず次のように空いたプロシージャであるTEST_PROC1を作ります。

create or replace procedure test_proc1 
is
begin
 null;
end;
/

次のPL/SQLブロックでTEST_PROC1を実行し、まのなくTEST_PROC1をコンパイルします。そうすると、セッションはハング状態に落ちってしまいます。

TPACK@ukja1120> begin
  2     test_proc1;
  3
  4     execute immediate 'alter procedure test_proc1 compile';
  5
  6  end;
  7  /

...
(Hang)

ASH(Active Session History)を通じて該当セッションの状態を分析してみると、WaiterとBlockerが一致していることが分かります。Self Deadlockという状態です。

select * 
from (
 select
  h.session_id as sid,
  to_char(h.sample_time,'mi:ss') as sample_time,
  h.sql_id,
  (select sql_text from v$sqlarea a where a.sql_id = h.sql_id) as sql_text,
  event,
  blocking_session as blocker
 from
  v$active_session_history h
 where
  h.session_id = &sid
 order by h.sample_time desc   
) where rownum <= 20 
;     

 SID SAMPL SQL_ID        SQL_TEXT             EVENT         BLOCKER
---- ----- ------------- -------------------- ---------- ----------
 136 49:10                                    library ca        136
                                              che pin

 136 49:09                                    library ca        136
                                              che pin

 136 49:08                                    library ca        136
                                              che pin

 136 49:07                                    library ca        136
                                              che pin

 136 49:06                                    library ca        136
                                              che pin

 136 49:05                                    library ca        136
                                              che pin

 136 49:04                                    library ca        136
                                              che pin

 136 49:03                                    library ca        136
                                              che pin

 136 49:02                                    library ca        136
                                              che pin

 136 49:01                                    library ca        136
                                              che pin

 136 49:00                                    library ca        136
                                              che pin

 136 48:59                                    library ca        136
                                              che pin

 136 48:58                                    library ca        136
                                              che pin

 136 48:57                                    library ca        136
                                              che pin

 136 48:56                                    library ca        136
                                              che pin

 136 48:55                                    library ca        136
                                              che pin

 136 48:54                                    library ca        136
                                              che pin

 136 48:53                                    library ca        136
                                              che pin

 136 48:52                                    library ca        136
                                              che pin

 136 48:51                                    library ca        136
                                              che pin


20 rows selected.

ティパックが提供する待機イベントの詳細情報からもっと詳しい状態が得られます。

TPACK@ukja1120> select * from table(tpack.session_detail(136,'wait_detail'))

NAME                           VALUE
------------------------------ --------------------
SID                            136
Serial#                        2797
SPID                           5148
Program                        sqlplus.exe
Process                        5404:672
Module                         SQL*Plus
SQL ID                         9pbva4bn2m25b
Child No                       0
SQL Text                       alter procedure test
                               _proc1 compile

Status                         ACTIVE
Blocking Instance              1
Blocking Session               136
SQL Exec Start                 2010/09/15 13:45:34
Event                          library cache pin
Seq#                           130
P1(P1raw)                      384372376(0000000016
                               E90E98)

P2(P2raw)                      384372376(0000000016
                               DAB608)

P3(P3raw)                      384372376(00014F8500
                               010003)

Seconds in wait                40
State                          WAITING
Wait Event                     library cache pin
Holder SID                     136
Namespace                      TABLE/PROCEDURE
Object                         TEST_PROC1
Holding Mode                   2(S)

理由は何と考えますか？

Remote SQL

数日前にデータベースリンクを使う分散クエリ(Distributed Query)の動作原理に対する質問を受けました。それに対する答えを簡単なテストでします。

テスト環境はOracle 11.1.0.6です。

TPACK@ukja1106> -- version
TPACK@ukja1106> select * from v$version where rownum = 1;

BANNER
-----------------------------------------------------------------------

Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production

分散クエリのためにループバックデータベースリンクを作ります。ループバックデータベースリンクとは自己自身がリモートデータベースとなるデータベースリンクとことを意味します。

TPACK@ukja1106> -- create loopback database link
TPACK@ukja1106> create public database link loopback
  2  connect to {user}
  3  identified by {password}
  4  using '{service_name}';

Database link created.

テーブルT1、T2を作ります。

TPACK@ukja1106> -- create table
TPACK@ukja1106> create table t1(c1, c2)
  2  as
  3  select level, level
  4  from dual
  5  connect by level <= 1000
  6  ;

Table created.

TPACK@ukja1106> 
TPACK@ukja1106> create table t2(c1, c2)
  2  as
  3  select level, level
  4  from dual
  5  connect by level <= 1000
  6  ;

Table created.

TPACK@ukja1106> 
TPACK@ukja1106> create index t2_n1 on t2(c1);

Index created.

TPACK@ukja1106> 
TPACK@ukja1106> exec dbms_stats.gather_table_stats(user, 't1');

PL/SQL procedure successfully completed.

TPACK@ukja1106> exec dbms_stats.gather_table_stats(user, 't2');

PL/SQL procedure successfully completed.

テーブルT1(ローカル)が先行テーブルとなり、テーブルT2(リモート)が結合対象となる分散くえりの実行計画です。Remote SQL Informationという部分に注意してください。

TPACK@ukja1106> -- explain plan
TPACK@ukja1106> -- nested loops join
TPACK@ukja1106> 
TPACK@ukja1106> -- execute it, but 0 row
TPACK@ukja1106> explain plan for
  2  select /*+ leading(t1) use_nl(d) */
  3   *
  4  from t1, t2@loopback d
  5  where t1.c1 = d.c1
  6   and t1.c1 < 0
  7  ;

TPACK@ukja1106> select * from table(dbms_xplan.display);

---------------------------------------------------
| Id  | Operation          | Name | Inst   |IN-OUT|
---------------------------------------------------
|   0 | SELECT STATEMENT   |      |        |      |
|   1 |  NESTED LOOPS      |      |        |      |
|*  2 |   TABLE ACCESS FULL| T1   |        |      |
|   3 |   REMOTE           | T2   | LOOPB~ | R->S |
---------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("T1"."C1"<0)

Remote SQL Information (identified by operation id):
----------------------------------------------------

   3 - SELECT /*+ USE_NL ("D") */ "C1","C2" FROM "T2" "D" WHERE "C1"<0 AND :1="C1"
       (accessing 'LOOPBACK' )

Remote SQLとは分散くえりを実行する時、リモートデータベースからデータを伝送させられうためにリモートデータベースで実行するSQLのことです。すなわち、ローカルデータベースはRemote SQLをリモートデータベースに発行してほしいデータを受け付けます。

ローカルデータベースはリモートデータベースからリモートテーブルとインデックスの基本統計情報を伝送されます。その情報を利用して実行計画を作ります。この過程でRemote SQLを作ります。Remote SQLは実際にデータを伝送されるために実行するまではリモートデータベースに送りません。

これを証明するために、クエリを実行した後、リモートデータベースでRemote SQLが実行されたかどうか確認してみます。次のクエリを実行したら、先行テーブルから一件の行もでないので（t1.c1 < 0 の条件のため）リモートデータベースへのデータリクエストもないはずです。つぎの結果を見ると、この推測があたることが分かります。

TPACK@ukja1106> select /*+ leading(t1) use_nl(d) */
  2   *
  3  from t1, t2@loopback d
  4  where t1.c1 = d.c1
  5   and t1.c1 < 0
  6  ;

no rows selected

TPACK@ukja1106> 
TPACK@ukja1106> select sql_id, executions
  2  from v$sqlarea
  3  where sql_text = 'SELECT /*+ USE_NL ("D") */ "C1","C2" FROM "T2" "D" WHERE "C1"<0 AND :1="C1"';

no rows selected

今度は同一なテストを1,000回のデータリクエストをリモートデータベースへ送る分散クエリに対して修行してみます。

TPACK@ukja1106> -- execute it, for 1000 rows
TPACK@ukja1106> explain plan for
  2  select /*+ leading(t1) use_nl(d) */
  3   *
  4  from t1, t2@loopback d
  5  where t1.c1 = d.c1
  6  ;

Explained.

TPACK@ukja1106> 
TPACK@ukja1106> select * from table(dbms_xplan.display);

---------------------------------------------------
| Id  | Operation          | Name | Inst   |IN-OUT|
---------------------------------------------------
|   0 | SELECT STATEMENT   |      |        |      |
|   1 |  NESTED LOOPS      |      |        |      |
|   2 |   TABLE ACCESS FULL| T1   |        |      |
|   3 |   REMOTE           | T2   | LOOPB~ | R->S |
---------------------------------------------------

Remote SQL Information (identified by operation id):
----------------------------------------------------

   3 - SELECT /*+ USE_NL ("D") */ "C1","C2" FROM "T2" "D" WHERE :1="C1" (accessing
       'LOOPBACK' )

1,000回のデータリクエストを送った結果、Remote SQLがリモートデータベースで1,000回修行されました。これはまるでSQL*Plusで該当くえりを1,000回修行したのは同一です。

TPACK@ukja1106> select /*+ leading(t1) use_nl(d) */
  2   *
  3  from t1, t2@loopback d
  4  where t1.c1 = d.c1
  5  ;

        C1         C2         C1         C2
---------- ---------- ---------- ----------
         1          1          1          1
         2          2          2          2
         3          3          3          3
...
       999        999        999        999
      1000       1000       1000       1000

1000 rows selected.

TPACK@ukja1106> 
TPACK@ukja1106> col sql_id new_value sql_id
TPACK@ukja1106> select sql_id, executions
  2  from v$sqlarea
  3  where sql_text = 'SELECT /*+ USE_NL ("D") */ "C1","C2" FROM "T2" "D" WHERE :1="C1"';

SQL_ID        EXECUTIONS
------------- ----------
6skxmvb24s6v4       1000

DBMS_XPLAN.DISPLAY_CURSOR関数を利用したら、リモートデータベースでのRemote SQLの実行計画も分かります。次のようにIndex Range Scanが選択されました。

TPACK@ukja1106> select * from table(dbms_xplan.display_cursor('&sql_id', null));

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2    |     1 |     7 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T2_N1 |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("C1"=:1)

今度はNested Loops JoinではなくてHash Joinに対して同一なテストを修行してみます。Remote SQLは次のようです。

TPACK@ukja1106> explain plan for
  2  select /*+ leading(t1) use_hash(d) */
  3   *
  4  from t1, t2@loopback d
  5  where t1.c1 = d.c1
  6  ;

Explained.

TPACK@ukja1106> 
TPACK@ukja1106> select * from table(dbms_xplan.display);

---------------------------------------------------
| Id  | Operation          | Name | Inst   |IN-OUT|
---------------------------------------------------
|   0 | SELECT STATEMENT   |      |        |      |
|*  1 |  HASH JOIN         |      |        |      |
|   2 |   TABLE ACCESS FULL| T1   |        |      |
|   3 |   REMOTE           | T2   | LOOPB~ | R->S |
---------------------------------------------------


Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."C1"="D"."C1")

Remote SQL Information (identified by operation id):
----------------------------------------------------

   3 - SELECT /*+ USE_HASH ("D") */ "C1","C2" FROM "T2" "D" (accessing 'LOOPBACK' )

たとえ1,000件をフェッチするのは同様ですが、Hash Joinの特性上リモートデータベースへRemote SQLを1,000回送ることではなく、ただ一回の実行でほしいデータを受け付けることができます。したがって実行回数(EXECUTIONS)は”１”となっています。

TPACK@ukja1106> select /*+ leading(t1) use_hash(d) */
  2   *
  3  from t1, t2@loopback d
  4  where t1.c1 = d.c1
  5  ;

        C1         C2         C1         C2
---------- ---------- ---------- ----------
         1          1          1          1
         2          2          2          2
         3          3          3          3
...
       999        999        999        999
      1000       1000       1000       1000

1000 rows selected.

TPACK@ukja1106> col sql_id new_value sql_id
TPACK@ukja1106> select sql_id, executions
  2  from v$sqlarea
  3  where sql_text = 'SELECT /*+ USE_HASH ("D") */ "C1","C2" FROM "T2" "D"';

SQL_ID        EXECUTIONS
------------- ----------
0uksumbhuswyx          1

1 row selected.

そしてRemote SQLはTable Full Scanの実行計画を持ちます。

TPACK@ukja1106> select * from table(dbms_xplan.display_cursor('&sql_id', null));

SQL_ID  0uksumbhuswyx, child number 0
-------------------------------------
SELECT /*+ USE_HASH ("D") */ "C1","C2" FROM "T2" "D"

Plan hash value: 1513984157

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     3 (100)|          |
|   1 |  TABLE ACCESS FULL| T2   |  1000 |  7000 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------

上の一連のテスト結果を見ると次のような結論が下せます。

• 分散くえりの動作方式はローカルクエリの動作方式とほとんど同一。
  
• リモートデータベースからデータを伝送されるためRemote SQLをリモートデータベースの送る。
  

これから、分散クエリをテストする時、上のような方法の分析が役に立つことをお願いします。