Monday, August 23, 2010

Deferred Segment Creation機能の面白い2つのバグ

Oracle 11gR2ではDeferred Segment Creationという機能が追加されました。

簡単に言えば、CREATE TABLE文を実行しても実際にデータが追加されるまでにはセグメントが生成されない機能です。このポストではDeferred Segment CreationとINSERT ... SELECT文に関する面白い2つのバグを紹介します。

  • バグ9078678: セグメントのないテーブルへの並列INSERT ... SELECT文に対しる予想実行計画(Explain Plan)は並列ではなく直列実行計画に表示されます。しかし、実際には並列で行なわれます。
  • バグ9329566: セグメントのないテーブルに対してINSERT ...SELECT文を実行すれば、SELECT文を二回実行するバグです。

2つのバグはすべてセグメントかないという特徴から発生するバグです。簡単なテストケースを見ましょう。まずバグ9078678に当たる現象です。


1. オラクルバージョンは11.2.0.1です。

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

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

2. テーブルT1を作ります。テーブルT1はセグメントが存在しない状態です。テーブルT1に対して並列INSERT文章を行なう場合実行計画がどうなるか見ましょう。

TPACK@ukja1120> create table t1(c1 number);

Table created.

TPACK@ukja1120> alter session enable parallel dml;

Session altered.

TPACK@ukja1120> explain plan for
2 insert /*+ parallel(t1 4) */ into t1
3 select level from dual connect by level <= 10000;

Explained.

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

------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
------------------------------------------------------------------------------
| 0 | INSERT STATEMENT | | 1 | 2 (0)| 00:00:01 |
| 1 | LOAD AS SELECT | T1 | | | |
|* 2 | CONNECT BY WITHOUT FILTERING| | | | |
| 3 | FAST DUAL | | 1 | 2 (0)| 00:00:01 |
------------------------------------------------------------------------------

ヒントを付けて並列実行を指定したが直列実行の実行計画が選択されました。


3. 予想実行計画ではなくて実際にSQL文を実行した後並列で実行するかどうかを見ましょう。


TPACK@ukja1120> insert /*+ parallel(t1 4) */ into t1
2 select level from dual connect by level <= 10000;

10000 rows created.

TPACK@ukja1120>
TPACK@ukja1120> commit;

Commit complete.

-- https://sites.google.com/site/ukja/sql-scripts-1/o-s/pqstat
TPACK@ukja1120> @pq_stat

DFO_NUMBER TQ_ID SERVER_TYP PROCESS NUM_ROWS
---------- ---------- ---------- ---------- ----------
1 0 Consumer P000 2500
1 0 Consumer P001 2500
1 0 Consumer P002 2500
1 0 Consumer P003 2500
1 0 Producer QC 10000
1 1 Consumer QC 4
1 1 Producer P000 1
1 1 Producer P001 1
1 1 Producer P002 1
1 1 Producer P003 1


10 rows selected.

STATISTIC LAST_QUERY SESSION_TOTAL
------------------------------ ---------- -------------
Queries Parallelized 0 0
DML Parallelized 1 1
DDL Parallelized 0 0
DFO Trees 1 1
Server Threads 4 0
Allocation Height 4 0
Allocation Width 1 0
Local Msgs Sent 44 44
Distr Msgs Sent 0 0
Local Msgs Recv'd 44 44
Distr Msgs Recv'd 0 0

11 rows selected.

Explain Planをよる予想実行計画では直列実行という結果がでてきたが、実際の結果からは並列に実行されたのがわかります。もっと面白いのはこの状態で(すなわち、テーブルT1にデータが追加された状態)予想実行計画を見直すと並列実行計画にかえるとくうことです。


TPACK@ukja1120> explain plan for
2 insert /*+ append parallel(t1 4) */ into t1
3 select level from dual connect by level <= 10000;

Explained.

------------------------------------------------------
| Id | Operation | Name |
------------------------------------------------------
| 0 | INSERT STATEMENT | |
| 1 | PX COORDINATOR | |
| 2 | PX SEND QC (RANDOM) | :TQ10001 |
| 3 | LOAD AS SELECT | T1 |
| 4 | PX RECEIVE | |
| 5 | PX SEND ROUND-ROBIN | :TQ10000 |
|* 6 | CONNECT BY WITHOUT FILTERING| |
| 7 | FAST DUAL | |
------------------------------------------------------

これはバグです。セグメントがまだ生成されていないテーブルに対する並列実行文章の予想実行計画はまるで直列に実行されうように見えるが、実際には並列に実行されるバグです。すなわち、セグメントのないテーブルに対する並列実行文章の予想実行計画を正確に見せてくれないバグです。


バグ9329566に該当するテストケースも見ましょう。


1. テーブルT1とテーブルT2を同一に生成します。ただ、テーブルT2には一件の行を追加してセグメントもあらかじめ作っておきます。テーブルT1はセグメントがまだ存在しない状態です。10,000ブロックのサイズのテーブルT3も作っておきます。


TPACK@ukja1120> create table t1(c1 varchar2(2000), c2 varchar2(2000), c3 varchar2(2000), c4 varchar2(1000));

Table created.

TPACK@ukja1120> create table t2(c1 varchar2(2000), c2 varchar2(2000), c3 varchar2(2000), c4 varchar2(1000));

Table created.

TPACK@ukja1120>
TPACK@ukja1120> -- insert 1 row into table t2 to create the segment
TPACK@ukja1120> insert into t2 values('1','1','1','1');

1 row created.

TPACK@ukja1120> -- table size 10000 block
TPACK@ukja1120> create table t3
2 as
3 select rpad('x',2000) as c1, rpad('x',2000) as c2, rpad('x',2000) as c3, rpad('x',1000) as c4
4 from dual
5 connect by level <= 10000;

Table created.

2. テーブルT3から最高値を読み込んでテーブルT1(セグメントない)、テーブルT2(セグメントある)へINSERTするクエリのそれぞれのConsistent Getsを比べてみましょう。手軽なテストのためにティパックのSession Snapshot Reportを利用します。

TPACK@ukja1120> exec tpack.begin_session_snapshot;

PL/SQL procedure successfully completed.

TPACK@ukja1120> insert into t1
2 select max(c1), max(c2), max(c3), max(c4) from t3;

1 row created.

TPACK@ukja1120> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

TPACK@ukja1120> insert into t2
2 select max(c1), max(c2), max(c3), max(c4) from t3;

1 row created.

TPACK@ukja1120>
TPACK@ukja1120> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

次の結果を見たら、テーブルT1(セグメントない)に対するINSERTがテーブルT2(セグメントある)に対するINSERTに比べて2倍程度のConsistentを見せます。


TPACK@ukja1120> col item format a40
TPACK@ukja1120> col deltas format a20
TPACK@ukja1120> select item, deltas from table(tpack.session_snapshot_report)
2 where type = 'STAT';

TPACK@ukja1120> select item, deltas from table(tpack.session_snapshot_report)
2 where type = 'STAT';

ITEM DELTAS
---------------------------------------- --------------------
...
physical read bytes 164339712->82305024
consistent gets 20451->10327
...

これもやはりバグです。

  1. テーブルT3からデータを読んでからそのデータをテーブルT1へINSERTしようとします。
  2. どころが、テーブルT1はまだセグメントがありません。したがってまずセグメントを作ります。
  3. ここでオラクルは1番段階で獲得したデータを再活用できずまたテーブルT3からデータを読み込みます。現在のクエリはテーブルT3から最高値(MAX)を取り出しているから、クエリを実行するたびにテーブルのサイズである10,000ブロックを全部読み込まなければなりません。このために、テーブルT1に対するINSERTの際には20,000ブロック(二回読み込むから)、テーブルT2に対するINSERTは10,000ブロック(1回読み込むから)を読み込むようになるのです。


このバグたちはセグメントのないテーブルに対してのみ発生するから致命的なバグとは言いかねます。むしろ開発者がいくら基本的な罠に陥るのかをわかる良い例だといえます。オラクルで発生する多い性能問題がこのようなロジック穴から発生します。性能問題が起こった時このようなロジック穴を見破るテスト能力備えることが重要だといえます。

Monday, August 16, 2010

Batching NLJ最適化と整列

Batching NLJ最適化って聞いたこたあります?Batching NLJとはOracle 11gで紹介されたNested Loops Joinの最適化技法であります。例えば、次の2つの実行計画を見てください。

-- Oracle 10g
------------------------------------------------
| Id | Operation | Name |
------------------------------------------------
| 0 | SELECT STATEMENT | |
|* 1 | COUNT STOPKEY | |
| 2 | TABLE ACCESS BY INDEX ROWID | T2 | <-- Here
| 3 | NESTED LOOPS | |
| 4 | TABLE ACCESS BY INDEX ROWID| T1 |
|* 5 | INDEX RANGE SCAN | T1_N1 |
|* 6 | INDEX RANGE SCAN | T2_N1 |
------------------------------------------------

-- Oracle 11g
------------------------------------------------
| Id | Operation | Name |
------------------------------------------------
| 0 | SELECT STATEMENT | |
|* 1 | COUNT STOPKEY | |
| 2 | NESTED LOOPS | |
| 3 | NESTED LOOPS | |
| 4 | TABLE ACCESS BY INDEX ROWID| T1 |
|* 5 | INDEX RANGE SCAN | T1_N1 |
|* 6 | INDEX RANGE SCAN | T2_N1 |
| 7 | TABLE ACCESS BY INDEX ROWID | T2 | <-- And here
------------------------------------------------

TABLE ACCESS BY INDEX ROWID (T2)のオペレーションの位置の違いに気付いたんでしょうか。これがOracle 11gのNested Loops Join最適化(Batching NLJ)の現れ方です。Batching NLJによって、論理読み込みが減り、性能が効率的になるはずです。

さて、ほんの数日前、Batching NLJ関連の変な整列問題に出会いました。下記は再現のできるテストケースです。ORDER BYのオーバーヘッドなく整列をするために、索引T1_N1を利用していることに注意してください。

create table t1
as
select 1 as c1, mod(level, 4) as c2, level as c3, level as c4, rpad('x',1000) as dummy
from dual
connect by level <= 1000;

create table t2
as
select 1001-level as c1, level as c2, rpad('x',1000) as dummy
from dual
connect by level <= 100;

create index t1_n1 on t1(c1, c2, c3);
create index t2_n1 on t2(c1);

exec dbms_stats.gather_table_stats(user, 't1');
exec dbms_stats.gather_table_stats(user, 't2');

explain plan for
select /*+ leading(t1 t2) use_nl(t2) index_asc(t1) index_asc(t2) */
rownum as rnum,
t2.c1,
t1.c4,
t2.c2
from t1, t2
where
t1.c3 = t2.c1
and t1.c1 = 1
and t1.c2 = 0
and rownum <= 20
;

select * from table(dbms_xplan.display);

-- Read from the disk
alter system flush buffer_cache;

select * from (
select /*+ leading(t1 t2) use_nl(t2) index_asc(t1) index_asc(t2) */
rownum as rnum,
t2.c1,
t1.c4,
t2.c2
from t1, t2
where
t1.c3 = t2.c1
and t1.c1 = 1
and t1.c2 = 0
and rownum <= 20
) where rnum >= 15
;

-- Read from the buffer cache
select * from (
select /*+ leading(t1 t2) use_nl(t2) index_asc(t1) index_asc(t2) */
rownum as rnum,
t2.c1,
t1.c4,
t2.c2
from t1, t2
where
t1.c3 = t2.c1
and t1.c1 = 1
and t1.c2 = 0
and rownum <= 20
) where rnum >= 15
;

-- Disable exceptions for buffer cache misses
alter session set "_nlj_batching_misses_enabled" = 0;

-- Read from the disk
alter system flush buffer_cache;

select * from (
select /*+ leading(t1 t2) use_nl(t2) index_asc(t1) index_asc(t2) */
rownum as rnum,
t2.c1,
t1.c4,
t2.c2
from t1, t2
where
t1.c3 = t2.c1
and t1.c1 = 1
and t1.c2 = 0
and rownum <= 20
) where rnum >= 15
;

-- Read from the buffer cache
select * from (
select /*+ leading(t1 t2) use_nl(t2) index_asc(t1) index_asc(t2) */
rownum as rnum,
t2.c1,
t1.c4,
t2.c2
from t1, t2
where
t1.c3 = t2.c1
and t1.c1 = 1
and t1.c2 = 0
and rownum <= 20
) where rnum >= 15
;

時間の節約のために、コメントが付いた簡単な結果を見ましょう。

-- Case1 : batching NLJ enabled
-- when the query reads from the disk
RNUM C1 C4 C2
---------- ---------- ---------- ----------
15 960 960 41
16 964 964 37
17 980 980 21 <-- Why 980 here?
18 968 968 33
19 972 972 29
20 976 976 25

-- when the query reads from the buffer cache
RNUM C1 C4 C2
---------- ---------- ---------- ----------
15 960 960 41
16 964 964 37
17 968 968 33
18 972 972 29
19 976 976 25
20 980 980 21

-- Case 2: batching NLJ disabled
-- when the query reads from the disk
RNUM C1 C4 C2
---------- ---------- ---------- ----------
15 960 960 41
16 964 964 37
17 968 968 33
18 972 972 29
19 976 976 25
20 980 980 21

-- when the query reads from the buffer cache
RNUM C1 C4 C2
---------- ---------- ---------- ----------
15 960 960 41
16 964 964 37
17 968 968 33
18 972 972 29
19 976 976 25
20 980 980 21

いかがでしょう。整列の順序に変わったこと

これは次のように解説できます。
「新しいNested Loops Joinの最適化コードは行が整列されたまま返されることを保障しない。特にディスクからデータを読み出している際には」

これはページネーションクエリ(Pagination Query)を索引とNested Loops Joinを利用して作成したい時に制約になる可能性があると思います。では、この制約がバグというのではありません。オラクルで整列順序を保障する雄一な方法はORDER BY句を与えることだけからです。

この制約を抜けていくためには次の方法で1つくらいを進めます。

  • 隠しパラメーター_nlj_batching_misses_enabledを0にセット
  • 隠しパラメーター_nlj_batching_enabledを0にセット
  • NO_NLJ_BATCHING(T2)ヒントの追加

Tuesday, August 10, 2010

「ティパック」知能的な待機イベントの分析 - Part 1

オラクルが提供する待機イベントとは本?に?特です。どんなDBMSでも待機現象をこんなに詳細に報告してくれる製品はありません。


これはオラクルの性能問題を分析かつ解決すべき私たちには大きいプレゼントである同時?みであります。まるで初?の運?者にポルシェを?えるのと同じだと言えないでしょうか。ポルシェのような車を走らせようとしたらまず丈夫な運?わざが必要です。


待機イベント分析も同?です。正確な分析のためにはオラクルのア?キテクチャ?に?する相?な知識が必要です。これが待機イベント分析の技法がより?範?に使用されうことに邪魔となっています。


待機イベント分析で1つ?をつけなければならないのが大?イベントだけでは意味のある情報を引き出し難しいということです。?連のあるほかの情報が必要である場合がたくさんあります。ティパックではこれを知能的な待機イベントの分析と呼びます。例えをあげてみればこのような追加的な情報が必要です。


  1. cache buffers chainsラッチで競合が?生する場合、おもにどんなブロックで?生しているかわかる?
  2.  row cache objectsラッチで競合が?生する場合、おもにどんなディクショナリ?オブジェクトなのかわかる?
  3. db file sequential readのようなI/O待機いの場合、どんなセグメントのどのような種類のブロックで?生するかわかる?
  4. ラッチ、ロック(Enqueue)、library cache lock、library cache pin、row cache lock、Mutexなどの同期化客?で競合が?生する場合、ホルダ?情報および?連の客?の情報が得られる?

これから?回にわたって待機イベントをもっと知能的に分析するためにどんなデ?タを追加的に分析する必要があらのかいくつかの例を見るつもりです。


1. ホルダ?を突き止め! 


オラクルでの競合は次の六つ程度の同期化客?により?生します。


  • ラッチ
  • ロック
  • Library cache lock
  • Library cache pin
  • Row cache lock
  • Mutex

個?の客?が何を意味しているのかすでにわかっている方?も多いはずなので、詳細な?明は足らないと思います。


同期化客?の種類別に提供されるビュ?が違いですから、ホルダ?を突き止めるときも違うビュ?を?索しなければなりません。幸いに最近バ?ジョンのオラクルではV$SESSIONビィ?のBLOCKING_SESSION、BLOCKING_INSTANCE
などの列から大部分の?況でホルダ?情報が提供されます。大?有?な情報だと言えます。しかし、待機イベントによっては?純にホルダ?を知るだけでは不足である場合もあります。正確にどんなオブジェクトで、どんなモ?ドで?生しているのかなどの情報が必要である場合もあります。


これから公開する情報はたぶん(!)ホルダ?を突き止める方法を今までのどんな文書より一番?範?で完璧にまとめていることであるはずです。


1.1 ラッチのホルダ?


ラッチホルダ?はV$LATCHHOLDERビュ?から突き止められます。


-- ラッチホルダ?
select h.pid, h.sid, h.laddr, h.name, h.gets
from v$latchholder h, v$session_wait s
where s.sid = &sid
and s.p1raw = h.laddr;

ラッチはとても短い時間に獲得されうため、上のような?純なクエリだけでは欲しい結果を得ることができない場合がたくさんあります。(もちろんオラクルのバグなどによって特定のラッチを長い間持っている場合もあります)


この時に使用できるのがプロファイル方法です。ティパックは1)スナップショット、2)プロファイル2つの方法を使用しています。この中で、プロファイルとは短い時間に記?され、消えてしまう値を可能な限りよく取り出して、要約する方法を意味します。V$LATCHHOLDERビュ?も次のようにプロファイリングできます。


-- ラッチホルダ?プロファイリング
TPACK@ukja1021> select /*+ ordered use_nl(x) */
2 x.sid, x.name, count(*)
3 from
4 (select /*+ no_merge */ level from dual connect by level <= 10000) t1,
5 (select /*+ no_merge */ h.pid, h.sid, h.laddr, h.name, h.gets
6 from v$latchholder h, v$session_wait s
7 where s.sid = &sid
8 and s.p1raw = h.laddr) x
9 group by x.sid, x.name
10 ;
old 7: where s.sid = &sid
new 7: where s.sid = 138

SID NAME COUNT(*)
---------- ------------------------------ ----------
134 shared pool 33
134 library cache 308


1.3 ロックのホルダ?


ロックホルダ?はV$LOCKビュ?で十分です。


-- ロックホルダ?
select
h.sid, -- ホルダ?SID
h.type, -- ロックタイプ
h.id1, -- ID1
h.id2, -- ID2
h.lmode,
t.name,
t.id1_tag,
t.id2_tag,
t.description
from v$lock h, v$lock w, v$lock_type t
where w.sid = { waiter_sid }
and h.id1 = w.id1
and h.id2 = w.id2
and h.lmode > 0
and h.block > 0
and h.type = t.type
;


1.3 Library cache lockのホルダ?


Library cache lockとはLCO(Library Cache Object)を保護するシステムロックです。競合が?生すればlibrary cache lock待機イベントを持ちます。Library cache lockのホルダ?はX$KGLLKビュ?を通じて突き止められます。


-- Library cache lock ホルダ?          
select
(select sid from v$session where saddr = k.kgllkuse) as sid, -- ホルダ?SID
k.kglhdnsp, -- 客?の種類
k.kglnaobj, -- 客?名(SQL文章や表、プロシ?ジャ名など)
decode(k.kgllkmod, 3, '3(X)', 2, '2(S)', 1, '1(N)', k.kgllkmod) as lkmode
from x$kgllk k
where k.kgllkhdl = { v$session_wait.p1raw }
and k.kgllkmod > 0
;


1.4 Library cache pinのホルダ?


Library cache pinとはカ?ソルやプロシ?ジャの?行を保護するシステムロックです。競合が?生すればlibrary cache pin待機イベントを待ちます。Library cache pinホルダ?はX$LGLPNビュ?を通じて突き止められます。


-- Library cache pin ホルダ?
select
(select sid from v$session where saddr = n.kglpnuse) as sid,
o.kglnaobj,
o.kglhdnsp,
decode(n.kglpnmod, 3, '3(X)', 2, '2(S)', 1, '1(N)', n.kglpnmod) as lkmode
from x$kglpn n, x$kglob o
where n.kglpnhdl = { v$session_wait.p1raw }
and n.kglpnmod > 0
and o.kglhdadr = n.kglpnhdl
;


1.5 Row cache lockのホルダ?


Row cache lockとはディクショナリ?オブジェクトを保護するロックです。競合が?生すればrow cache lock待機イベントを待ちます。Row cache lockのホルダ?はV$ROWCACHE_PARENTビュ?から突き止められます。


-- Row cache lock ホルダ?
select
(select sid from v$session where saddr = h.saddr) as sid, -- ホルダ?SID
h.cache_name, -- ディクショナリ?オブジェクトの種類
h.lock_mode,
h.inst_lock_type
from v$rowcache_parent h, v$rowcache_parent w, v$session s
where h.address = w.address
and w.saddr = s.saddr
and s.sid = { waiter_sid }
and h.lock_mode > 0
;


1.6 Mutexのホルダ?


Mutexのホルダ?はV$MUTEX_SLEEP_HISTORYビュ?を通じて突き止められます。


-- Mutexのホルダ?
select * from (
select
blocking_session as sid, -- ホルダ?SID
(select kglnaobj from x$kglob
where kglnahsh = mutex_identifier
and rownum = 1) as obj_name, -- オブジェクト命(11gで追加)
mutex_type, -- Mutexのタイプ
location, -- Mutexを獲得した位置、すなわち何のためにMutexを獲得しようとしているのか?
sleeps,
gets,
to_char(sleep_timestamp,'yyyy/mm/dd hh24:mi:ss') as sleep_timestamp
from v$mutex_sleep_history
where requesting_session = session_id
order by sleep_timestamp desc
) where rownum <= 1 ;

11gからはMUTEX_IDENTIFIERという有?なコラムが追加されMutex競合の分析がもっと易くなりました。


上の情報からわかるようにホルダ?の?索も大事ものの、もっと具?的にどんな情報で、どんあ客?で問題が?生しているのかを把握することも重要です。このような理由から、文書化されていないV$ビュ?やX$ビュ?を?索するしかありません。


ティパックではSession Detail Reportを通じて上の情報を取り出すことができます。ほぼ同じクエリを使用します。


Library cache pin競合の例で?明してみます。


-- とても長いSQL文章を作ります。正確にいえばハ?ドパ?スの時間が長いSQL文章です。
-- http://sites.google.com/site/ukja/sql-scripts-1/j-m/make_long
TPACK@ukja1021> @make_long
select count(*) from TPACK_REPORT_PARAMS, TPACK_REPORT_CONDITIONS,
TPACK_REPORT_JOB_HIST, TPACK_REPORT_SESSION_TEMP, TPACK_FUNCTION_NAMES,
...

-- セッション#1で上のクエリを行います。(私のテスト環境で2分50秒くらいかかります)
TPACK@ukja1021> exec dbms_application_info.set_client_info('session1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.39
TPACK@ukja1021> @long_parse
....

-- セッション#1と同時にセッション#2で同じクエリを行います。
TPACK@ukja1021> exec dbms_application_info.set_client_info('session2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.04
TPACK@ukja1021> @long_parse
...

セッション#2はセッション#1がハ?ドパ?スを行なう間、待機?態になります。セッション#2に?してSession Detail Reportを?集して待機イベントを詳細に分析します。

-- セッション#2のSID
TPACK@ukja1021> col sid new_value sid
TPACK@ukja1021> select sid from v$session where client_info = 'session2';

SID
----------
138

1 row selected.

Elapsed: 00:00:00.14

-- セッション#2のSession Detail Report
TPACK@ukja1021> col name format a30
TPACK@ukja1021> col value format a45
TPACK@ukja1021> set pages 200
TPACK@ukja1021> set long 10000000
TPACK@ukja1021> select * from table(tpack.session_detail(&sid, 'wait_detail'));
old 1: select * from table(tpack.session_detail(&sid, 'wait_detail'))
new 1: select * from table(tpack.session_detail( 138, 'wait_detail'))

NAME VALUE
------------------------------ ---------------------------------------------
SID 138
Serial# 711
SPID 3724
Program sqlplus.exe
Process 5364:5208
Module SQL*Plus
SQL ID
Child No
SQL Text
Status ACTIVE
Blocking Instance 1
Blocking Session 134
Event library cache pin
Seq# 4137
P1(P1raw) 970230240(39D489E0)
P2(P2raw) 970230240(36A9AB34)
P3(P3raw) 970230240(000000C8)
Seconds in wait 10
State WAITING
Wait Event library cache pin
Holder SID 134
Namespace CURSOR
Object select count(*) from TPACK_SGA_STAT, TPACK_SG
A_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK
_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TP
ACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT,
TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_ST
AT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA
_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_
SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_S

GA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPAC
K_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, T
PACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_D
UMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_
HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP,
TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_
DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK
_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPA

CK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUM
P, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HE
AP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TP
ACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DU
MP, TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM,
TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM, TP
AC

Holding Mode 3(X)

NamespaceとObject情報からlibrary cache pin待機に?するより正確な分析が可能です。Oracle 11gではlibrary cache pinではなくてMutexに?する競合が?生します。

TPACK@ukja1106> select * from table(tpack.session_detail(&sid, 'wait_detail'));
old 1: select * from table(tpack.session_detail(&sid, 'wait_detail'))
new 1: select * from table(tpack.session_detail( 127, 'wait_detail'))

NAME VALUE
------------------------------ ---------------------------------------------
SID 127
Serial# 1642
SPID 2656
Program sqlplus.exe
Process 5364:5208
Module SQL*Plus
SQL ID
Child No
SQL Text
Status ACTIVE
Blocking Instance 1
Blocking Session 139
SQL Exec Start
Event cursor: pin S wait on X
Seq# 631
P1(P1raw) 3859422310(00000000E60A1C66)
P2(P2raw) 3859422310(00000000008B0000)
P3(P3raw) 3859422310(0000000000050256)
Seconds in wait 0
State WAITING
Wait Event cursor: pin S wait on X
Holder SID 139
Mutex Type Cursor Pin
Location
Target Object select count(*) from TPACK_SGA_STAT, TPACK_SG
A_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK
_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TP
ACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT,
TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_ST
AT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA
_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_
SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_S

GA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPAC
K_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, T
PACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_D
UMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_
HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP,
TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_
DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK
_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPA

CK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUM
P, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HE
AP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TP
ACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DU
MP, TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM,
TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM, TP
AC

Last Sleep Time 2010/06/29 16:03:51
Gets 1
Sleeps 611

重要なのは待機現象が?生するとき適切なビュ?から適切なデ?タを?索することができるかということです。ティパックはその中核心的なデ?タを自動に?集してくれるだけです。


以前のポスト


  1. 「ティパック」性能問題をトラブルシュ?ティングする2つのフレ?ム
  2. 「ティパック」oradebug

Thursday, August 5, 2010

「ティパック」oradebug

このポストの目的はoradebugの使用法全?を?明することではなくてティパックで使われているoradebugコマンドを簡?に紹介することです。


1. 特定のプロセスにバインディング


ティパックがoradebugコマンドを使用する理由は特定のプロセスに自由にバインディングできるからです。


-- SYSDBA ユ?ザ?でログイン
sqlplus "/as sysdba"

-- 現在のプロセスにバインディング
SQL> oradebug setmypid

-- 特定のセッションのOS Process IDでバインディング
SQL> select sid, serial#,
(select spid from v$process where addr = paddr) as ospid
from v$session
where sid = (select sid from v$mystat where rownum = 1);

SID SERIAL# OSPID
---------- ---------- ------------
144 2446 4872

SQL> oradebug setospid 4872
Oracle pid: 16, Windows thread id: 4872, image: ORACLE.EXE (SHAD)

特定のプロセスにバインディングするには次の4つの方法があります。

SQL> oradebug help
SETMYPID Debug current process
SETOSPID {ospid} Set OS pid of process to debug
SETORAPID {orapid} ['force'] Set Oracle pid of process to debug
SETORAPNAME {orapname} Set Oracle process name to debug -- 11g에서 추가
...

SETOSPIDコマンドを主に使用する理由はUnix/Linux環境ではProcess ID(PID)を得るのが易いからです。でも、ティパックでは特定のセッションを指定するためにSession ID(SID)をパラメ?タ?で使用します。オラクルではSIDが一番認識しやすい値からです。


2. トレ?スファイルの名前の獲得


ティパックでは特定のプロセスに?してイベントやダンプを行い、その中身を?み?む作業がいくつかあります。したがって、トレ?スファイルの名前を正確にえるのが大事です。oradebug tracefile_name名前がそれに?たります。


SQL> oradebug tracefile_name
c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc

上の作業をティパックでは次のように行なえます。

-- 143番セッションのトレ?スファイルの名前
SQL> select tpack.get_tracefile_name(143) from dual;
c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc

-- レ?スファイルの中身
SQL> select * from table(tpack.get_tracefile_contents('c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc'))

あるいは次のようなクエリを通じても得られます。しかし、ファイル名の正確なフォ?マットはバ?ジョンやOSにより?わられます。もう1つの短所は該?プロセスがサ?バ?プロセスなのか、バックグラウンドプロセスなのかを事前に知ることが必要で、プロセスの種類によりどんなディレクトリ?にファイルが書き?まれるのかも判?したければならないということです。このような複?性のためにティパックではoradebug tracefile_nameコマンドを利用します。

select
d.value||'\'||p.value||'_ora_'||s.spid||'.trc' as trace_file_name
from
(
select value
from v$parameter
where name = 'instance_name'
) p,
(
select value
from v$parameter
where name = 'user_dump_dest'
) d,
(
select spid
from v$process
where addr = (
select paddr
from v$session
where sid = {sid here}
)
) s

3. 診?イベントの修行


特定のプロセスにバインディングした後は該?プロセスに?して診?イベントが行なわれます。


-- 診?イベントの活性化
SQL> oradebug event 10046 trace name context forever, level 12

-- 診?イベントの非活性化
SQL> oradebug event 10046 context off

-- トレ?スファイルの確認
SQL> oradebug tracefile_name
SQL> ed {tracefile_name}

上の作業をティパックでは次のように行われます。

-- 診?イベントの活性化
SQL> exec tpack.begin_diag_trace(143, 10046, 12);

-- 診?イベントの非活性化
SQL> exec tpack.end_diag_trace(143, 10046);

-- トレ?スファイルの確認
SQL> select * from table(tpack.get_diag_trace(143));

ティパックを利用すればoradebugを利用するためにテルネットで接?する必要かないし、クライアントでSQL*Plusですべての作業ができます。ティパックのもう1つの長所は診?イベントを活性した後に生成された中身だけを?み?むということです。すなわち、診?イベントを活性する前に、もうほかの作業により書き?まれた多くのデ?タわスキップされ、今度の作業により書き?まれた中身だけを?み?みます。


4. ダンプの修行


特定のプロセスにバインディングした後、該?プロセスに?して多?なダンプファイルを生成できます。次に簡?な例があります。


-- レベル1でCallstackダンプの修行
SQL> oradebug dump callstack 1

-- PGA Heap Dump。Level 0x20000001とは最上位ヒ?プだけではなくてサイズが大きい五つのサブヒ?プに?して再?的にダンプを修行しろという意味です。非常に有?な機能だと言えます。
SQL> oradebug dump heapdump 0x20000001

ティパックではヒ?プダンプファイルから?み?んだデ?タを加工して分析レポ?トを提供します。

-- 143番セッションに?してCallstackダンプを1秒?たり10回行い、その結果を要約してレポ?ト
SQL> select * from table(tpack.callstack_prof_report(143));

-- 143番セッションに?してPGA Heap Dumpをレベル0x20000001で行い、この結果をレポ?ト
SQL> select * from table(tpack.pga_heap_report(143, 2));

ティパックは性能トラブルシュ?ティングに必要な基本的なデ?タの一部を診?イベントやダンプを通じて得ています。PGA Heap DumpやCallstack Dumpが代表的な例です。このようなデ?タを得るための一番易い(もしかしたら唯一
な)方法としてoradebugを使用しています。


1つの技術的な難しさはSQLコマンドからどうすればoradebugを自由に呼び出すのかということです。ティパックではJava Stored Procedureを利用しています。これに?する詳細なお話は次のポストで進める予定です。


性能トラブルシュ?ティングの段階が深まるほどoradebugの魅力におぼれるはずです。特にOracle 11gでは完全に新しく設計されたOracle Debugging Frameworkが提供され、それに連れてoradebugの機能ももっと?くなりました。詳細な?容は次の文書を?考してください。





以前のポスト


  1. 「ティパック」性能問題をトラブルシュ?ティングする2つのフレ?ム