Monday, September 27, 2010

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

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


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


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の拡張された診断イベント機能は次の文書で詳細に紹介しています。

Wednesday, September 15, 2010

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)

理由は何と考えますか?

Thursday, September 9, 2010

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)は”1”となっています。


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をリモートデータベースの送る。

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