Sunday, June 28, 2009

Oracle性能Troubleshootingに必須なプログラミング知識ーSQL*Plusでのパラメータ使用

Oracleに性能異常現状が発生した時、分析のためにさまざまな作業を行うようになります。このような作業を効果的にするために知らなければならない基本的なプログラミング知識があります。このぐらいの知識がなければ、分析の速度と正確度が落ちてしまうといえます。

その中でも一番基本的なものがSQL*Plusでパラメータを取り交わす方法です。この方法を身につけたら一見複雑に見える作業も易しく処理できる場合がたくさんあります。

簡単な例で説明します。まず、test.sqlスクリプトを二つのパラメータで実行します。
UKJA@ukja116> @test "logical reads" "name,class,value"

次のようにさまざまの方式でこのパラメータを利用できます。
select name, value from v$sysstat
where name like '%&1%';

NAME VALUE
------------------------------ --------------------
session logical reads 4,462,033


define __STATNAME = &1

select name, value from v$sysstat
where name like '%&__STATNAME%';

NAME VALUE
------------------------------ --------------------
session logical reads 4,462,033

define __COLUMNS = "&2"

select &__COLUMNS from v$sysstat
where name like '%&__STATNAME%';

NAME CLASS VALUE
------------------------------ ---------- --------------------
session logical reads 1 4,462,033

COLUMN命令のNEW_VALUEオプションを使えば、SQLの結果の特定の値をSQL*Plusの変数に変換できます。とても有効な方法です。
col name new_value matching_name

select &__COLUMNS from v$sysstat
where name like '%&__STATNAME%';
NAME CLASS VALUE
------------------------------ ---------- --------------------
session logical reads 1 4,462,033

prompt matching_name

select &__COLUMNS from v$sysstat
where name = '&matching_name';

NAME CLASS VALUE
------------------------------ ---------- --------------------
session logical reads 1 4,462,033

ホスト変数を使ってPL/SQLと連動してパラメータをお互いに取り交わすこともできます。複雑なロジックを具現したい場合に有効です。
var matching_name varchar2(100)

begin
select name into :matching_name
from v$sysstat
where name like '%&__STATNAME%';
end;
/

print :matching_name

MATCHING_NAME
--------------------------------------------------------------------------------
session logical reads

この方法の最高峰は次のようにカーソルオブジェクトを取り交わすことです。
var v_cursor refcursor;

declare
v_sql varchar2(4000);
begin

v_sql := 'select &__COLUMNS from v$sysstat
where name = ''&matching_name''';

open :v_cursor for v_sql;

end;
/

print :v_cursor;

NAME CLASS VALUE
------------------------------ ---------- --------------------
session logical reads 1 4,462,033

上で紹介した方法の中で特にSQL*PLusを呼び出す時パラメータを得る方式とCOLUMN...NEW_VALUE命令を使って動的にパラメータを受ける方式だけは必ず身につける必要があります。

このような方法をよく活用すればなにより自分の生活が美しくて便利になるからです。

Wednesday, June 24, 2009

Index Tree Dumpをもっと便利に使用しよう。

索引の性能問題を分析する時はいつもリーフブロックをダンプすべき必要性を感じます。例えば、索引の3番目のリーフブロックをダンプして、この内容を分析しようと思うと仮定してみましょう。
UKJA@ukja116> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
PL/SQL Release 11.1.0.6.0 - Production
CORE 11.1.0.6.0 Production
TNS for 32-bit Windows: Version 11.1.0.6.0 - Production
NLSRTL Version 11.1.0.6.0 - Production

Elapsed: 00:00:00.03
UKJA@ukja116>
UKJA@ukja116> create table t1(c1 int, c2 char(100));

Table created.

Elapsed: 00:00:00.01
UKJA@ukja116>
UKJA@ukja116> insert into t1
2 select level, 'dummy' from dual
3 connect by level <= 1000
4 ;

1000 rows created.

Elapsed: 00:00:00.01
UKJA@ukja116>
UKJA@ukja116> create index t1_n1 on t1(c1, c2);

Index created.

Elapsed: 00:00:00.01
UKJA@ukja116> -- do index tree dump
UKJA@ukja116> exec tree_dump('t1_n1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01

Index Tree Dumpの結果は次のようです。
----- begin tree dump
branch: 0x1c00af4 29362932 (0: nrow: 17, level: 1)
leaf: 0x1c00af5 29362933 (-1: nrow: 62 rrow: 62)
leaf: 0x1c00af6 29362934 (0: nrow: 62 rrow: 62)
leaf: 0x1c00af7 29362935 (1: nrow: 61 rrow: 61)
leaf: 0x1c00af8 29362936 (2: nrow: 61 rrow: 61)
leaf: 0x2802ad9 41954009 (3: nrow: 61 rrow: 61)
leaf: 0x2802ada 41954010 (4: nrow: 61 rrow: 61)
leaf: 0x2802adb 41954011 (5: nrow: 61 rrow: 61)
leaf: 0x2802adc 41954012 (6: nrow: 61 rrow: 61)
leaf: 0x2802add 41954013 (7: nrow: 61 rrow: 61)
leaf: 0x2802ade 41954014 (8: nrow: 61 rrow: 61)
leaf: 0x2802adf 41954015 (9: nrow: 61 rrow: 61)
leaf: 0x2802ae0 41954016 (10: nrow: 61 rrow: 61)
leaf: 0x2c0268a 46147210 (11: nrow: 61 rrow: 61)
leaf: 0x2c0268b 46147211 (12: nrow: 61 rrow: 61)
leaf: 0x2c0268c 46147212 (13: nrow: 61 rrow: 61)
leaf: 0x2c0268d 46147213 (14: nrow: 61 rrow: 61)
leaf: 0x2c0268e 46147214 (15: nrow: 22 rrow: 22)
----- end tree dump

この情報をもとに特定のリーフブロックをダンプするためには、1)DBA(Data Block Address)をCopy&Pasteし、2)そのDBAをファイル番号とブロック番号で変化し、3)SQL*Plusで"alter system dump datafile f# block b#"命令文を実行しなければなりません。

このような退屈な作業は私が一番きらいなものです。いい知らせは、下のように自動化したスクリプトを使ってもう少し便利に作業をすることが可能だということです。
UKJA@ukja116>
UKJA@ukja116> select
2 prefix||
3 type ||
4 ' max_rows=' || nrow ||', '||
5 'cur_rows=' || rrow ||', '||
6 'dump=alter system dump datafile ' ||
7 dbms_utility.data_block_address_file(to_dec(dba)) || ' block ' ||
8 dbms_utility.data_block_address_block(to_dec(dba))
9 from (
10 select
11 regexp_substr(column_value, '^[[:space:]]+') as prefix,
12 regexp_substr(column_value, '(branch|leaf)') as type,
13 regexp_replace(regexp_substr(column_value, '(branch:|leaf:) [^ ]+'),
14 '(branch:|leaf:) 0x', '') as dba,
15 substr(regexp_substr(column_value, 'nrow: [[:digit:]]+'), 7) as nrow,
16 substr(regexp_substr(column_value, 'rrow: [[:digit:]]+'), 7) as rrow
17 from table(get_trace_file1)
18 where regexp_like(column_value, '(branch:|leaf:)')
19 )
20 ;

PREFIX||TYPE||'MAX_ROWS='||NROW||','||'CUR_ROWS='||RROW||','||'DUMP=ALTERSYSTEMD
--------------------------------------------------------------------------------
branch max_rows=17, cur_rows=, dump=alter system dump datafile 7 block 2804
leaf max_rows=62, cur_rows=62, dump=alter system dump datafile 7 block 2805
leaf max_rows=62, cur_rows=62, dump=alter system dump datafile 7 block 2806
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 7 block 2807
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 7 block 2808
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10969
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10970
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10971
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10972
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10973
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10974
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10975
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10976
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9866
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9867
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9868
leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9869
leaf max_rows=22, cur_rows=22, dump=alter system dump datafile 11 block 9870

18 rows selected.

Elapsed: 00:00:00.06

上の結果を使えば、ただダンプ命令文(alter system dump datafile 11 block 9870)をSQL*PlusにCopy&Pasteするだけで必要な作業が終わります。

簡単なトリックだけで退屈に見える作業が知能的で面白い作業に変わるいい例です。

Monday, June 22, 2009

実戦!Oracle Regular Expression

Oracle10gからRegular Expressionが提供されていますが、私がよく使用しません。何より、理解しにくいし、速度ものろいからです。バグも少なくないんです。

でも、特定の作業にはRegular Expressionがほんとに有効な時が多いです。もちろん、私はいつも単純な表現だけ使用します。複雑なものなら使う考え自体をしないでしょう。私にはこのぐらいの機能で充分です。

いくつの例を通じて私がRegular Expressionを使用する例と紹介します。

1.1番目の例は10046トレースファイルを自分の意図で分析することです。
drop table t1 purge;

create table t1(c1 int);

ed temp.sql
/*
begin
for idx in 1 .. 300000 loop
insert into t1(c1) values(idx);
end loop;
end;
/
*/

ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp

exec dbms_lock.sleep(1);
@trace_on 10046 8
@temp
@trace_off

INSERT INTO T1(C1)
VALUES
(:B1 )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 300000 7.98 29.66 0 2012 309299 300000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 300001 7.98 29.66 0 2012 309299 300000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
buffer busy waits 2810 1.02 13.09
latch: library cache pin 31 0.03 0.12
latch: cache buffers chains 11 0.04 0.08
latch: library cache 14 0.05 0.12
log file switch completion 7 0.99 2.24
log file switch (checkpoint incomplete) 4 0.75 1.31
enq: HW - contention 18 0.03 0.07
enq: TX - contention 9 0.00 0.00
enq: FB - contention 8 0.01 0.01
latch: redo allocation 2 0.04 0.07
log buffer space 2 0.26 0.26

buffer busy waits待機に問題があるみたいです。追加的な分析のためにソーストレースファイルを開けてみると、このような姿です。
WAIT #6: nam='buffer busy waits' ela= 26148 file#=10 block#=27298 class#=1 obj#=89644 tim=94342641391
EXEC #6:c=0,e=64798,p=0,cr=4,cu=4,mis=0,r=1,dep=1,og=1,tim=94342680018
EXEC #6:c=0,e=55,p=0,cr=6,cu=4,mis=0,r=1,dep=1,og=1,tim=94342680397
EXEC #6:c=0,e=29,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342683501
WAIT #6: nam='buffer busy waits' ela= 18336 file#=10 block#=27310 class#=1 obj#=89644 tim=94342704683
EXEC #6:c=0,e=18644,p=0,cr=8,cu=4,mis=0,r=1,dep=1,og=1,tim=94342704954
EXEC #6:c=0,e=29,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342707772
EXEC #6:c=0,e=23,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342708005
WAIT #6: nam='buffer busy waits' ela= 26111 file#=10 block#=27314 class#=1 obj#=89644 tim=94342738234

いま、私がしようとするのはbuffer busy waits待機現状をクラス別、ファイル別でどのように分布しているのかを分析するのです。Regular Expression! このような簡単な表現で充分です。
UKJA@ukja102> define __VALUE = 'WAIT #6: nam=''buffer busy waits'' ela= 18336 file#=10 block#=27310
class#=1 obj#=89644 tim=94342704683'
UKJA@ukja102> prompt &__VALUE
WAIT #6: nam='buffer busy waits' ela= 18336 file#=10 block#=27310 class#=1 obj#=89644 tim=9434270468
3
UKJA@ukja102>
UKJA@ukja102> select
2 substr(regexp_substr(q''&__VALUE'', 'ela= [[:digit:]]+'), 6) as ela,
3 substr(regexp_substr(q''&__VALUE'', 'file#=[[:digit:]]+'), 7) as f#,
4 substr(regexp_substr(q''&__VALUE'', 'block#=[[:digit:]]+'), 8) as b#,
5 substr(regexp_substr(q''&__VALUE'', 'class#=[[:digit:]]+'), 8) as c#
6 --from table(get_trace_file2('temp.trc'))
7 from dual
8 where
9 regexp_like(q''&__VALUE'', 'buffer busy waits')
10 ;

ELA F# B# C
----- -- ----- -
18336 10 27310 1

実際にRegular Expressionを通じてクラス別、ファイル別buffer busy waits待機を分析した結果は次のようです。
UKJA@ukja102> select
2 c#, count(*), sum(ela)
3 from t_temp1
4 group by c#
5 ;

C# COUNT(*) SUM(ELA)
---------- ---------- ----------
1 2808 13098056
8 2 10

Elapsed: 00:00:00.04
UKJA@ukja102>
UKJA@ukja102> select
2 f#, c#, count(*), sum(ela)
3 from t_temp1
4 group by f#, c#
5 ;

F# C# COUNT(*) SUM(ELA)
---------- ---------- ---------- ----------
11 1 1323 5553501
11 8 2 10
12 1 1002 4062191
10 1 483 3482364

Elapsed: 00:00:00.03


本当に有効な分析結果ではありませんか。

2. 2番目の例はPusedoカーソルに対してどんなオブジェクトと関連があるのかを判断するのです。
V$SQLビューには現れないカーソルオブジェクトが使用されることが時々あります。下の文書によく説明されています。

http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/

ここで、table_4_9_15d7b_0_0_のようなPseudoオブジェクトの名前が見られますが、ここで四つめの文字列(15d7b)がベースオブジェクトのIDです。Regular Expressionを使ったら次のように手軽に変換できます。
UKJA@ukja116> select to_dec(regexp_substr('table_4_9_15d7b_0_0_', '[^_]+', 1, 4))
2 as object_id
3 from dual
4 ;

OBJECT_ID
----------
89467


3. Heapダンプの分析
PGAやSGAのダンプを実行すれば次のように個別のChunkに対する大きさおよび種類など詳細な情報を得ることができます。
EXTENT 10 addr=083BC23C
Chunk 83bc244 sz= 3696 perm "perm " alo=3696
Chunk 83bd0b4 sz= 2316 perm "perm " alo=2316
Chunk 83bd9c0 sz= 212 freeable "PLS cca hp desc"
Chunk 83bda94 sz= 2068 freeable "kjztprq struct "
EXTENT 11 addr=08522048
Chunk 8522050 sz= 18448 perm "perm " alo=18448
EXTENT 12 addr=083BA1B8
Chunk 83ba1c0 sz= 4272 perm "perm " alo=4272
Chunk 83bb270 sz= 3928 recreate "KSFQ heap " latch=00000000
ds 83bc1d4 sz= 3928 ct= 1
Chunk 83bc1c8 sz= 92 freeable "KSFQ heap descr"


この情報たちをRegular Expressionを通じて分析するには次のような簡単な水準で充分です。
UKJA@ukja116> define __VALUE = '  Chunk 4f1436cc sz=   248116    freeable  "session heap   "  ds=085
A760'
UKJA@ukja116> prompt &__VALUE
Chunk 4f1436cc sz= 248116 freeable "session heap " ds=085A760
UKJA@ukja116>
UKJA@ukja116> select
2 substr(regexp_substr('&__VALUE', 'sz=[ ]*[[:digit:]]+'),4) as chunk_size,
3 regexp_substr('&__VALUE', '(freeable|free|perm|recreate)') as chunk_type,
4 regexp_substr('&__VALUE', '"[[:print:]]+"') as obj_type,
5 substr(regexp_substr('&__VALUE', 'ds=[[:xdigit:]]+'),4) as subheap
6 from dual
7 where
8 regexp_like('&__VALUE', 'Chunk')
9 ;

CHUNK_SIZ CHUN OBJ_TYPE SUBHEAP
--------- ---- ----------------- -------
248116 free "session heap " 085A760


下に実際の分析事例があります。
UKJA@ukja102> select
2 chunk_type,
3 decode(chunk_type, 'free',
4 count(*)/2, count(*)) as count#,
5 decode(chunk_type, 'free',
6 sum(chunk_size/2), sum(chunk_size)) as size#
7 from t_temp2
8 group by chunk_type
9 ;

CHUNK_TYPE COUNT# SIZE#
-------------------- ---------- ----------
perm 32 181928
recreate 8 87180
freeable 3584 498650144
free 3552 99660580

Elapsed: 00:00:00.12
UKJA@ukja102>
UKJA@ukja102> select
2 obj_type,
3 decode(obj_type, '" "',
4 count(*)/2, count(*)) as count#,
5 decode(obj_type, '" "',
6 sum(chunk_size/2), sum(chunk_size)) as size#
7 from t_temp2
8 group by obj_type
9 ;

OBJ_TYPE COUNT# SIZE#
-------------------- ---------- ----------
"KFIO PGA struct" 1 72
"KSFQ heap " 1 3928
"KJZT context " 1 60
"kpuinit env han" 1 1584
"perm " 32 181928
" " 3552 99660580
"kzsna:login nam" 1 24
"kews sqlstat st" 1 1292
"PLS cca hp desc" 1 212
"callheap " 2 2144
"kopolal dvoid " 5 2524
"session heap " 3547 498632732
"PLS non-lib hp " 3 18560
"koh-kghu call h" 2 1328
"KFK PGA " 1 260
"KSFQ heap descr" 1 92
"Fixed Uga " 1 20572
"ldm context " 13 12712
"external name " 1 24
"kjztprq struct " 1 2068
"Alloc environm " 1 4144
"kgh stack " 1 17012
"qmtmInit " 4 13980
"joxp heap " 2 2000

24 rows selected.

Elapsed: 00:00:00.17
UKJA@ukja102>
UKJA@ukja102>
UKJA@ukja102> select
2 subheap, count(*), sum(chunk_size)
3 from t_temp2
4 where subheap is not null
5 group by subheap
6 ;

SUBHEAP COUNT(*) SUM(CHUNK_SIZE)
-------------------- ---------- ---------------
083BD9CC 2 10320
08563470 3 12436
085A7600 3546 498567256

Elapsed: 00:00:00.09


本当に有効な情報を簡単に得ることができると思いませんか。もちろんRegular Expressionではないといっても可能かもしれませんが、Regular Expressionのほうがもっと柔軟な方法です。でも、Regular Expressionを使いすぎると性能の劣化があるかもしれないから注意が必要です。

Thursday, June 18, 2009

LOBのデータタイプとSQL*Trace

LOBに対するSQL*Traceで次のような非正常な現状を見たことがありますか。

二つの表T1とT2がありますし、この二つの表はサイズは同じですが、データ型だけの違いがあります。一つはLOBであり、一つはVARCHAR2です。
create table t1(c1 int, c2 clob);

declare
v_clob clob := rpad('x', 4000, 'x');
begin
for idx in 1 .. 1000 loop
insert into t1 values(idx, v_clob);
end loop;
end;
/

create table t2(c1 int, c2 varchar2(4000));

declare
v_varchar varchar2(4000) := rpad('x', 4000, 'x');
begin
for idx in 1 .. 1000 loop
insert into t2 values(idx, v_varchar);
end loop;
end;
/

T1.LOBの読み込みには2分ぐらいかかります。
UKJA@ukja102> select * from t1;

C1
----------
C2
--------------------------------------------------------------------------------
583
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...

1000 rows selected.

Elapsed: 00:02:05.53
UKJA@ukja102>

反面、T2.VARCHAR2の読み込みには10分がかかります。
UKJA@ukja102> select * from t2;

C1
----------
C2
--------------------------------------------------------------------------------
5
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...
1000 rows selected.

Elapsed: 00:00:10.50

パフォーマンスの違いはここで関心のそとです。非正常的な点はtkprofの結果で見えます。
select * 
from
t1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1001 0.14 0.09 0 1009 0 1000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1003 0.14 0.09 0 1009 0 1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61

Rows Row Source Operation
------- ---------------------------------------------------
1000 TABLE ACCESS FULL T1 (cr=1009 pr=0 pw=0 time=41472 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1002 0.00 0.00
SQL*Net message from client 1002 0.00 0.13
********************************************************************************

T1.LOBを読み込みにかかった時間は2分だったけど、tkprofの結果は0.1秒の時間ばかり報告しています。この2分はどこに行ったことでしょうか。

T2.VARCHAR2に対する結果は期待したとおりです。約10秒の待機時間を報告しています。
select * 
from
t2

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 68 0.01 0.01 0 1005 0 1000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 70 0.01 0.02 0 1005 0 1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61

Rows Row Source Operation
------- ---------------------------------------------------
1000 TABLE ACCESS FULL T2 (cr=1005 pr=0 pw=0 time=8348 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 68 0.00 0.00
SQL*Net more data to client 2 0.00 0.00
SQL*Net message from client 68 0.51 10.46
********************************************************************************

なぜOracleがLOBに対する読み込みの時間を反映しなかったんでしょうか。もっとおかしいものは全体のtkprofの結果にはその時間が含まれているというものです。
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.01 0.00 0 0 0 0
Execute 6 0.00 0.00 0 0 0 0
Fetch 1007 0.14 0.09 0 1009 0 1003
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1018 0.15 0.09 0 1009 0 1003

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 102009 0.00 0.31
SQL*Net message from client 102009 0.03 32.35
direct path read 201000 0.06 58.51

...

本当にへんです! どこかに、値の不一致がいると言うとしかできません。これを確認するためには元のトレースフォイルを見る必要があります。
PARSING IN CURSOR #1 len=16 dep=0 uid=61 oct=3 lid=61 tim=155701141356 hv=2245880055 ad='2e6260a8'
select * from t1
END OF STMT
PARSE #1:c=0,e=925,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=155701141350
EXEC #1:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=155701142972
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143147
WAIT #1: nam='SQL*Net message from client' ela= 358 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143714
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144019
FETCH #1:c=0,e=312,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=155701144249
WAIT #1: nam='SQL*Net message from client' ela= 161 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144584
WAIT #0: nam='direct path read' ela= 24239 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701169489
WAIT #0: nam='direct path read' ela= 440 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701170930
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701171143
WAIT #0: nam='SQL*Net message from client' ela= 1273 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701172643
WAIT #0: nam='direct path read' ela= 26168 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701199245
WAIT #0: nam='direct path read' ela= 787 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701200504
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701200820
WAIT #0: nam='SQL*Net message from client' ela= 450 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701201480
...


CURSOR#1(select * from t1)を実行しながら、いきなりWAIT#1ではない、WAIT#0で番号を変えてしまいます。

このWAIT#0はどこから来たことでしょうか。追加的なテストでこれを打ち明けてみます。セッション1でLOBを読み込むQueryを行いながら、セッション2でモニターリングします。
-- session #1(sid=140)
select * from t1;

UKJA@ukja102> -- session #2
UKJA@ukja102> col sql_id new_value v_sql_id
UKJA@ukja102> col prev_sql_id new_value v_prev_sql_id
UKJA@ukja102> col kglnaobj new_value v_kglnaobj
UKJA@ukja102>
UKJA@ukja102> select sql_id, prev_sql_id from v$session where sid = 140
2 ;

SQL_ID PREV_SQL_ID
------------- -------------
fa45sbd422h0k 27uhu2q2xuu7r

Elapsed: 00:00:00.01
UKJA@ukja102>-- Note that the CURRENT query is not shown in V$SQL
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_sql_id';
old 1: select sql_text from v$sql where sql_id = '&v_sql_id'
new 1: select sql_text from v$sql where sql_id = 'fa45sbd422h0k'

no rows selected

Elapsed: 00:00:00.00
UKJA@ukja102>-- The CURRENT query is reported as the PREVIOUS query
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_prev_sql_id';
old 1: select sql_text from v$sql where sql_id = '&v_prev_sql_id'
new 1: select sql_text from v$sql where sql_id = '27uhu2q2xuu7r'

SQL_TEXT
--------------------------------------------------------------------------------
select * from t1

Elapsed: 00:00:00.01
UKJA@ukja102>-- Although the current query is not existent in the v$sql,
-- it should exist in the X$KGLOB - the mother of all LCOs

UKJA@ukja102> select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id';
old 1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id'
new 1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = 'fa45sbd422h0k'

KGLHDNSP
----------
KGLNAOBJ
--------------------------------------------------------------------------------
0
table_4_9_15d7b_0_0_

0
table_4_9_15d7b_0_0_


Elapsed: 00:00:00.01
UKJA@ukja102>-- What does table_4_9_15d7b_0_0_ mean?
UKJA@ukja102> select object_name from dba_objects
2 where object_id = to_dec(regexp_substr('&v_kglnaobj', '[^_]+', 1, 4));
old 2: where object_id = to_dec(regexp_substr('&v_kglnaobj', '[^_]+', 1, 4))
new 2: where object_id = to_dec(regexp_substr('table_4_9_15d7b_0_0_', '[^_]+', 1, 4))

OBJECT_NAME
--------------------------------------------------------------------------------
T1

上のテスト結果は何を話してありますか。OracleはLOBデータを読み込むために内部的なカーソル(table_4_9_15d7b_0_0_)を作ってこれを通じてデータを取っていたことです。そのために、本来のQueryである”select * from t1”には何らの情報も含まれなかったのです。

Tkprofの結果を解析する時はこのような特徴を考えていればいいでしょう。

関連するブログは次のようです。
http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/
http://dioncho.wordpress.com/2009/04/20/lob-sql_id-and-lco/

Sunday, June 14, 2009

Errorstack dumpを使ってバインド値をわかる

もう実行が終わったQueryのバインド値を獲得するのは技術的に不可能なものです。唯一な方法は10046イベントをレベル4以上で活性化したり、Auditingを活性化することのみです。しかし、10046トレースとAuditingはoverheadがかなり大きくて実際の運営環境では適用しにくいです。

一つの適用可能な方法はerrorstack(レベル>=2)です。Errorstack dumpはcallstackや他の情報の外にもバインド変数の値を出力してくれます。

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
...
Bind bytecodes
Opcode = 2 Bind Twotask Scalar Sql In (may be out) Copy
oacdef = 2bdb5bf0 Offsi = 36, Offsi = 0
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
kxsbbbfp=080aa6e0 bln=22 avl=02 flg=05
value=1

Errorstackの問題点の一つは必ず現在問題が発生している中に実行されなければならないということです。すなわち、残業が必要になることです。これは私たちが願うものではありませんでしょう。

ここで、いくつのアイディアを出すことができます。
1. ORA-00001 イベントトレース
下のようにすればORA-00001(unique key violation)が発生するたびにerrorstackを実行できます。

alter system set events '1 trace name errorstack level 2, forever';
or
alter session events '1 trace name errorstack level 2, forever';

ORA-00001エラーを起こすバインド値を分かることが目的なら、上の方法で簡単にできます。

2. システムをmonitoringしながら自動的にerrorstackを実行
例えば、下のようなScriptを見ましょう。

connect /as sysdba

var sid number;

begin
for idx in 1 .. 1000000 loop
dbms_lock.sleep(1);
select min(sid) into :sid from v$lock
where type = 'TX' and request > 0
               and block = 0 and ctime > 30;

if :sid > 0 then
exit;
end if;
end loop;
end;
/

print :sid

col spid new_value v_spid

select spid from v$process
where addr in (select paddr from v$session where sid = :sid);

oradebug setospid &v_spid

oradebug dump errorstack 2

このScriptはv$lockビューをmonitoringしながら、TX Lockを30秒以上待っているSessionについてerrorstackを実行します。結果は下のような問題のバインド値です。

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
curflg=44 fl2=0 par=00000000 ses=2EB3F224
sqltxt(2E5F0058)=insert into t1 values(:b1, 1)
hash=bbc06f38e42d1542e8fdfe7363d9ab40
parent=2945F7D0 maxchild=02 plk=2C75C638 ppn=n
cursor instantiation=080479E8
child#1(27DB82B0) pcs=295262B8
clk=2B138D44 ci=2AD04520 pn=2C7CEA94 ctx=2B7508A8
kgsccflg=0 llk[080479EC,080479EC] idx=0
xscflg=c0110676 fl2=d100008 fl3=42222008 fl4=0
Bind bytecodes
Opcode = 2 Bind Twotask Scalar Sql In (may be out) Copy
oacdef = 2bdb5bf0 Offsi = 36, Offsi = 0
kkscoacd
Bind#0 <-- これ!
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
kxsbbbfp=080aa6e0 bln=22 avl=02 flg=05
value=1


たとえerrorstackがバインド値を分かる完璧な方法ではないですが、overheadが小さいことを考慮すればとても魅力的な方法だと言えます。

Thursday, June 11, 2009

Callstackを通じるTroubleshootingの簡単な例

下を見てください。想像できる一番簡単な問い合わせです。

UKJA@ukja102> select * from dual;
... <-- Hanged!!!

その簡単さにもかかわらず、Hangされてしまいました。この問題の分析のために、Sessionの情報を見てみましょう。

SYS@ukja10> @session_list

SID SERIAL# PROGRAM EVENT SQL_TEXT
----- ------- ---------- -------------------- ------------------------------
146 6578 sqlplus.ex SQL*Net message from
e client
...

SYS@ukja10> exec print_table('select * from v$session where sid = 146');
SADDR : 2EB2FDFC
SID : 146
SERIAL# : 6578
AUDSID : 19288
PADDR : 2EA4F58C
USER# : 61
USERNAME : UKJA
COMMAND : 0
OWNERID : 2147483644
TADDR :
LOCKWAIT :
STATUS : INACTIVE
SERVER : DEDICATED
SCHEMA# : 61
SCHEMANAME : UKJA
OSUSER : UKJA\exem
PROCESS : 12172:10844
MACHINE : EX-EM.COM\UKJA
TERMINAL : UKJA
PROGRAM : sqlplus.exe
TYPE : USER
SQL_ADDRESS : 00
SQL_HASH_VALUE : 0
SQL_ID :
SQL_CHILD_NUMBER :
PREV_SQL_ADDR : 27DAB918
PREV_HASH_VALUE : 96831227
PREV_SQL_ID : 7us1frh2wb1rv
PREV_CHILD_NUMBER : 0
MODULE : SQL*Plus
MODULE_HASH : 3669949024
ACTION :
ACTION_HASH : 0
CLIENT_INFO :
FIXED_TABLE_SEQUENCE : 114132657
ROW_WAIT_OBJ# : -1
ROW_WAIT_FILE# : 0
ROW_WAIT_BLOCK# : 0
ROW_WAIT_ROW# : 0
LOGON_TIME : 2009/06/11 13:16:42
LAST_CALL_ET : 79
PDML_ENABLED : NO
FAILOVER_TYPE : NONE
FAILOVER_METHOD : NONE
FAILED_OVER : NO
RESOURCE_CONSUMER_GROUP :
PDML_STATUS : DISABLED
PDDL_STATUS : ENABLED
PQ_STATUS : ENABLED
CURRENT_QUEUE_DURATION : 0
CLIENT_IDENTIFIER :
BLOCKING_SESSION_STATUS : NO HOLDER
BLOCKING_INSTANCE :
BLOCKING_SESSION :
SEQ# : 29
EVENT# : 256
EVENT : SQL*Net message from client
P1TEXT : driver id
P1 : 1413697536
P1RAW : 54435000
P2TEXT : #bytes
P2 : 1
P2RAW : 00000001
P3TEXT :
P3 : 0
P3RAW : 00
WAIT_CLASS_ID : 2723168908
WAIT_CLASS# : 6
WAIT_CLASS : Idle
WAIT_TIME : 0
SECONDS_IN_WAIT : 79
STATE : WAITING
SERVICE_NAME : UKJA10
SQL_TRACE : DISABLED
SQL_TRACE_WAITS : FALSE
SQL_TRACE_BINDS : FALSE
-----------------

Sessionは何もしないで、Idle状態に留まっています。原因が探せる他の方法はないでしょうか。

Oracleはshort_stackと呼ばれる機能を提供しています。short_stackは最小限のCallstack情報を見せてくれます。

SYS@ukja10> oradebug setospid 11744
Oracle pid: 23, Windows thread id: 11744, image: ORACLE.EXE (SHAD)

SYS@ukja10> oradebug short_stack
_ksdxfstk+14<-_ksdxcb+1481<-_ksdxsus+1037<-_ksdxffrz+50<-_ksdxcb+1481
<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadStart@4+795<-7C80B680
<-00000000<-719857C4<-719E4376<-62985408<-62983266<-60A08BD8<-609CCBB8
<-609AF9CD<-609ACF09<-6097E2C7<-__PGOSF126__opikndf2+781<-_opitsk+540
<-_opiino+1087<-_opiodr+1099<-_opidrv+819<-_sou2o+45<-_opimai_real+112
<-_opimai+92<-_OracleThreadStart@4+708<-7C80B680

何か意味ある部分が見えますか。この部分はどうですか。

... <-_ksdxsus+1037<-_ksdxffrz+50<- ...

私には「Flash freeze(ksdxffrz)が呼ばれてから、Sessionが停止になった(ksdxsus)」と解析されます。したがって、InstanceをResumeさせれば、問題は解決されるでしょう。

SYS@ukja10> oradebug ffresumeinst
Statement processed.

...
UKJA@ukja102> select * from dual;

D
-
X

Elapsed: 00:09:30.14

errorstackはより正確なCallstack情報を提供します。

SYS@ukja10> oradebug dump errorstack 2
Statement processed.
SYS@ukja10> oradebug tracefile_name
c:\oracle\admin\ukja10\udump\ukja10_ora_11744.trc

----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
_ksedst+38 CALLrel _ksedst1+0 1 1
_ksedmp+898 CALLrel _ksedst+0 1
_ksdxfdmp+847 CALLreg 00000000 2
_ksdxcb+1481 CALLreg 00000000 D68F43C 11 3 D68F39C D68F3EC
_ksdxsus+1037 CALLrel _ksdxcb+0 1
_ksdxffrz+50 CALLrel _ksdxsus+0 1
_ksdxcb+1481 CALLreg 00000000 D68FB20 7 1 D68FA80 D68FAD0
_ssthreadsrgruncall CALLrel _ksdxcb+0 1
back+428
_OracleOradebugThre CALLrel _ssthreadsrgruncall D68FF84
adStart@4+795 back+0
7C80B680 CALLreg 00000000
00000000 VIRTUAL 7C93EB94
719857C4 CALLrel 71983C6B
719E4376 CALLreg 00000000
62985408 CALL??? 00000000
62983266 CALLrel 6298530C F90 AAD779A 810 0
60A08BD8 CALLreg 00000000 AAAF98C AAD779A AAAFB20 0 0
609CCBB8 CALLrel 60A07EF0 AA7FAF0 B83E01C A5FED30
609AF9CD CALLrel 609CCAF0 AA7FAF0 A5FED30
609ACF09 CALLrel 609ACF48 A5FEC14 55 A5FED30 0 B83E2AC
0 3
6097E2C7 CALLrel 609ACEF4 A5FEC14 A5FED30 B83E2AC 0
__PGOSF126__opikndf CALLreg 00000000
2+781
_opitsk+540 CALLreg 00000000
_opiino+1087 CALLrel _opitsk+0 0 0
_opiodr+1099 CALLreg 00000000 3C 4 B83FC8C
_opidrv+819 CALLrel _opiodr+0 3C 4 B83FC8C 0
_sou2o+45 CALLrel _opidrv+0 3C 4 B83FC8C
_opimai_real+112 CALLrel _sou2o+0 B83FC80 3C 4 B83FC8C
_opimai+92 CALLrel _opimai_real+0 2 B83FCB8
_OracleThreadStart@ CALLrel _opimai+0
4+708
7C80B680 CALLreg 00000000

たとえ簡単なデモですが、Callstack分析の有用さを良く見せてくれる典型的な例でしょう。Callstackで使われた関数名については下のMetalink文書を参照してください。

  • 175982.1: ORA-600 Lookup Error Categories
  • 453521.1: ORA-04031 "KSFQ Buffers" ksmlgpalloc
  • 558671.1: Getting ORA-01461 while INSERT INTO WWV_THINGS

Tuesday, June 9, 2009

PGA Heap Dumpを利用したPGA メモリリークTroubleshooting

時々PGAメモリリークによりORA-4030エラーが発生する場合があります。本当の問題はORA-4030その自体ではない、メモリリークが発生する原因を探すのが易しくないという点です。

ここで、PGA Heap Dumpを利用し、メモリリークの原因を追跡する例を見ましょう。

下はFORALLを使用して効率的にデータを生成するProcedureです。


define m_string_length = 20

drop table t1 purge;
create table t1(v1 varchar2( &m_string_length ));

create or replace procedure proc1 (
i_rowcount in number default 1000000,
i_bulk_pause in number default 0,
i_forall_pause in number default 0,
i_free_pause in number default 0
)
as
type w_type is table of varchar2( &m_string_length );
w_list w_type := w_type();
w_free w_type := w_type();
begin
for i in 1..i_rowcount loop
w_list.extend;
w_list(i) := rpad('x', &m_string_length );
end loop;

dbms_lock.sleep(i_bulk_pause);

forall i in 1..w_list.count
insert into t1 values(w_list(i));

dbms_lock.sleep(i_forall_pause);
commit;
w_list := w_free;
dbms_session.free_unused_user_memory;

dbms_lock.sleep(i_free_pause);
end;
/


このProcedureを読み続けながら、メモリ使用率を観察しましょう。

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

SYS@ukja10> select
2 name, value
3 from
4 v$sesstat ss,
5 v$statname sn
6 where
7 sn.name like '%ga memory%'
8 and ss.statistic# = sn.statistic#
9 and ss.sid = 149
10 ;

NAME VALUE
------------------------------ ----------------
session uga memory 498,942,840
session uga memory max 500,053,908
session pga memory 599,907,924
session pga memory max 675,602,004

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME VALUE
------------------------------ ----------------
session uga memory 695,429,288
session uga memory max 695,429,288
session pga memory 904,191,572
session pga memory max 904,257,108

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME VALUE
------------------------------ ----------------
session uga memory 840,565,088
session uga memory max 840,565,088
session pga memory 1,077,861,972
session pga memory max 1,077,861,972


深刻なメモリリークが発生することをわかります。OracleはProcedureの実行済みの後でもメモリを解除していません。

問題はOracleがどのようなObjectについてメモリを非正常的に占有しているのか判別しにくいと言うことです。ここで試せるのがPGA Heap Dumpです。

oradebug setospid 6760
oradebug dump heapdump 1


Heap Dump File自体は読みやすいですが、長さがとても長い場合が多くあります。それで、heap_analyze.sqlを利用してサマリ結果を見ましょう。

UKJA@ukja102> @heap_analyze heap_dump_1.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 99660580 598579832 16.650
freeable 498650144 598579832 83.306
perm 181928 598579832 .030
recreate 87180 598579832 .015

Elapsed: 00:00:01.03

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
Alloc environm 4144 598579832 .001
Fixed Uga 20572 598579832 .003
KFIO PGA struct 72 598579832 .000
KFK PGA 260 598579832 .000
KJZT context 60 598579832 .000
KSFQ heap 3928 598579832 .001
KSFQ heap descr 92 598579832 .000
PLS cca hp desc 212 598579832 .000
PLS non-lib hp 18560 598579832 .003
callheap 2144 598579832 .000
external name 24 598579832 .000
joxp heap 2000 598579832 .000
kews sqlstat st 1292 598579832 .000
kgh stack 17012 598579832 .003
kjztprq struct 2068 598579832 .000
koh-kghu call h 1328 598579832 .000
kopolal dvoid 2524 598579832 .000
kpuinit env han 1584 598579832 .000
kzsna:login nam 24 598579832 .000
ldm context 12712 598579832 .002
perm 181928 598579832 .030
qmtmInit 13980 598579832 .002
session heap 498632732 598579832 83.303
99660580 598579832 16.650

24 rows selected.

Elapsed: 00:00:01.12

DS CSIZE TOTAL_SUBHEAP_SIZE RATIO
-------------------- ---------- ------------------ -------
083BD9CC 10320 498590012 .002
08563470 12436 498590012 .002
085A7600 498567256 498590012 99.995

Elapsed: 00:00:00.76

Subheap(08563470)が全体のメモリの80%以上を占めるのが見えます。次の作業はSubheap Dumpを実行することです。

oradebug dump heapdump_addr 1 0xa067600
UKJA@ukja102> @heap_analyze heap_subdump_1.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 9701516 498589224 1.946
freeable 488817960 498589224 98.040
perm 54896 498589224 .011
recreate 14852 498589224 .003

Elapsed: 00:00:00.70

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
PLS cca hp desc 400 498589224 .000
PLS non-lib hp 488740608 498589224 98.025
Session NCHAR l 552 498589224 .000
kgict 40 498589224 .000
kgicttab 44 498589224 .000
kgicu 92 498589224 .000
kgiob 1928 498589224 .000
kgiobdtb 192 498589224 .000
kgsc ht segs 5720 498589224 .001
koddcal dvoid 24 498589224 .000
kodmcon kodmc 64 498589224 .000
kodpai image 1036 498589224 .000
koh-kghu sessi 15888 498589224 .003
koh-kghu sessio 14252 498589224 .003
kokahin kgglk 140 498589224 .000
kokl lob id has 1036 498589224 .000
kokl transactio 268 498589224 .000
koklug hlctx in 24 498589224 .000
koklug hxctx in 24 498589224 .000
kpuinit env han 1584 498589224 .000
kqlpWrntoStr:st 112 498589224 .000
ksulu : ksulueo 40 498589224 .000
kwqaalag 92 498589224 .000
kwqb context me 92 498589224 .000
kwqica hash tab 92 498589224 .000
kwqidwh memory 92 498589224 .000
kwqmahal 92 498589224 .000
kxs-heap-d 1036 498589224 .000
kxs-heap-p 4148 498589224 .001
kxs-krole 780 498589224 .000
kxsFrame4kPage 28840 498589224 .006
kxsc: kkspbd0 968 498589224 .000
kxsc: kkspsc0 7756 498589224 .002
kzctxhugi1 4108 498589224 .001
kzsrcrdi 60 498589224 .000
perm 54896 498589224 .011
session languag 552 498589224 .000
system trigger 36 498589224 .000
9701516 498589224 1.946

39 rows selected.

Elapsed: 00:00:00.81

DS CSIZE TOTAL_SUBHEAP_SIZE RATIO
-------------------- ---------- ------------------ -------
08B3608C 2076 488746828 .000
08B3EAAC 488738512 488746828 99.998
08B578F4 2080 488746828 .000
08B5A114 2080 488746828 .000
0FD400B0 2080 488746828 .000

Elapsed: 00:00:00.89

同じPatternで、Subheap(08B3EAAC)が大部分のメモリを占めるものが分かります。


oradebug dump heapdump_addr 1 0x0A08EAAC

UKJA@ukja102> @heap_analyze heap_subdump_2.trc
UKJA@ukja102> set echo off

ATYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------ ---------- --------------- -------
free 483911940 488662624 99.028
freeable 4750540 488662624 .972
perm 144 488662624 .000

Elapsed: 00:00:05.03

CTYPE CSIZE TOTAL_HEAP_SIZE RATIO
------------------------------ ---------- --------------- -------
DPAGE 4750096 488662624 .972
peihstdep 260 488662624 .000
perm 144 488662624 .000
pl_iot_alloc 92 488662624 .000
pl_lut_alloc 92 488662624 .000
483911940 488662624 99.028

6 rows selected.

Elapsed: 00:00:05.40

no rows selected

Elapsed: 00:00:03.21

今、問題の原因が見えます。OracleはFORALLで使用されたメモリをfree状態に変えたにもかかわらず、そのメモリを完全に解除していないと言えます。これは間違いなくBugだと考えられます。

次のようにMetalinkで検索してみます。



検索の結果(Bug# 5866410)が上で見た現状と完璧に一致しています。

Bulk insert in PLSQL can consume a large amount of PGA memory which can lead to ORA-4030 errors.

A heapdump will show lot of free memory in the free lists which is not used but instead fresh allocations are made.


PGA Heap Dump分析がいくら有用か分かる良い例です。でも、実際には分析は見えるものより難しい場合が多くあります。理由は

  • Heap Dump Fileは長すぎる場合が多いです。適切なツールがなければ、分析はほとんど不可能です。上で紹介したheap_analyze.sqlがいい例です。
  • Heapは階層的な構造を持っているため、分析時に注意が必要です。
  • Object名を理解しにくい場合も多くあります。

このような限界にもかかわらず、特定状況ではPGA Heap Dump分析は大きい力を発揮します。そのメリトとデメリトを良く理解した後使用すれば立派な分析ツールとなるでしょう。

Friday, June 5, 2009

Query Transformationと実行計画の予測可能性

「クェリだけを見ても実行計画を予測することができるだろうか」と言う質問を時々受けます。

返事はいつも「それは純真な考えだと思います」です。

とてもシンプルに見えるSQL文でさえ不可能ものです。なぜそうでしょうか。

Oracleが積極的にQuery Transformationを実行するからです。

簡単な例で説明して見ましょう。

このSQL文はどのように実行計画が作られましょうか。


UKJA@ukja102> explain plan for
2 select /*+ */
3 outer.*
4 from ( select * from scott.emp outer
5 union all
6 select * from scott.emp outer) outer
7 where outer.sal > (select /*+ */ avg(inner.sal)
8 from scott.emp inner
9 where inner.deptno = outer.deptno
10 );

Explained.


私のデータベースには次のような実行計画に表現されます。十分に予測可能な実行計画だと思っていませんか。


-----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 87 | 9 (0)| 00:00:01 |
|* 1 | FILTER | | | | | |
| 2 | VIEW | | 28 | 2436 | 6 (0)| 00:00:01 |
| 3 | UNION-ALL | | | | | |
| 4 | TABLE ACCESS FULL| EMP | 14 | 518 | 3 (0)| 00:00:01 |
| 5 | TABLE ACCESS FULL| EMP | 14 | 518 | 3 (0)| 00:00:01 |
| 6 | SORT AGGREGATE | | 1 | 7 | | |
|* 7 | TABLE ACCESS FULL | EMP | 5 | 35 | 3 (0)| 00:00:01 |
-----------------------------------------------------------------------------

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

1 - filter("OUTER"."SAL"> (SELECT AVG("INNER"."SAL") FROM
"SCOTT"."EMP" "INNER" WHERE "INNER"."DEPTNO"=:B1))
7 - filter("INNER"."DEPTNO"=:B1)



でも、subqueryにunnestヒントを付けるものだけで実行計画に大きい変化が発生します。Subquery UnnestingによりSubqueryがInline Viewに変わってしまいます。


UKJA@ukja102> explain plan for
2 select /*+ */
3 outer.*
4 from ( select * from scott.emp outer
5 union all
6 select * from scott.emp outer) outer
7 where outer.sal > (select /*+ unnest */ avg(inner.sal)
8 from scott.emp inner
9 where inner.deptno = outer.deptno
10 );

Explained.

--------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 113 | 11 (19)| 00:00:01 |
|* 1 | HASH JOIN | | 1 | 113 | 11 (19)| 00:00:01 |
| 2 | VIEW | VW_SQ_1 | 3 | 78 | 4 (25)| 00:00:01 |
| 3 | HASH GROUP BY | | 3 | 21 | 4 (25)| 00:00:01 |
| 4 | TABLE ACCESS FULL| EMP | 14 | 98 | 3 (0)| 00:00:01 |
| 5 | VIEW | | 28 | 2436 | 6 (0)| 00:00:01 |
| 6 | UNION-ALL | | | | | |
| 7 | TABLE ACCESS FULL| EMP | 14 | 518 | 3 (0)| 00:00:01 |
| 8 | TABLE ACCESS FULL| EMP | 14 | 518 | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------------


PUSH_PREDヒントを付けるともっと極的な変化が現れます。Hash JoinがNested Loops Joinに変わり、Join条件がViewの内に入られます。これがUNION ALL PUSHED PREDICATEで表現されます。


UKJA@ukja102> select /*+ gather_plan_statistics PUSH_PRED(OUTER) */
2 outer.*
3 from ( select * from scott.emp outer
4 union all
5 select * from scott.emp outer) OUTER
6 where outer.sal > (select /*+ QB_NAME(SUB) UNNEST */ avg(inner.sal)
7 from scott.emp inner
8 where inner.deptno = outer.deptno
9 );


----------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows |
----------------------------------------------------------------------------
| 1 | NESTED LOOPS | | 1 | 1 | 12 |
| 2 | VIEW | VW_SQ_1 | 1 | 3 | 3 |
| 3 | HASH GROUP BY | | 1 | 3 | 3 |
| 4 | TABLE ACCESS FULL | EMP | 1 | 14 | 14 |
| 5 | VIEW | | 3 | 1 | 12 |
| 6 | UNION ALL PUSHED PREDICATE | | 3 | | 12 |
|* 7 | TABLE ACCESS FULL | EMP | 3 | 1 | 6 |
|* 8 | TABLE ACCESS FULL | EMP | 3 | 1 | 6 |
----------------------------------------------------------------------------

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

7 - filter(("OUTER"."SAL">"VW_COL_1" AND "OUTER"."DEPTNO"="DEPTNO"))
8 - filter(("OUTER"."SAL">"VW_COL_1" AND "OUTER"."DEPTNO"="DEPTNO"))


CBQT(Cost Based Query Transformation)を非活性化するとヒントがなくても同じ効果を得られます。


UKJA@ukja102> alter session set "_optimizer_cost_based_transformation" = off;

UKJA@ukja102> alter session set "_optimizer_push_pred_cost_based" = false;

UKJA@ukja102> explain plan for
2 select /*+ */
3 outer.*
4 from ( select * from scott.emp outer
5 union all
6 select * from scott.emp outer) outer
7 where outer.sal > (select /*+ */ avg(inner.sal)
8 from scott.emp inner
9 where inner.deptno = outer.deptno
10 );

Explained.

----------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
----------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 65 | 9 (23)|
|* 1 | HASH JOIN | | 1 | 65 | 9 (23)|
| 2 | VIEW | VW_SQ_1 | 3 | 78 | 4 (25)|
| 3 | HASH GROUP BY | | 3 | 21 | 4 (25)|
| 4 | TABLE ACCESS FULL | EMP | 14 | 98 | 3 (0)|
| 5 | VIEW | | 28 | 1092 | 4 (0)|
| 6 | UNION-ALL PARTITION| | | | |
| 7 | TABLE ACCESS FULL | EMP | 14 | 518 | 3 (0)|
| 8 | TABLE ACCESS FULL | EMP | 14 | 518 | 3 (0)|
----------------------------------------------------------------------


Oracle 10gからはQuery Transformationの大部分をOracle自身で決定します。したがって、SQL文を見るだけで実行計画を予測するのはほとんど不可能です。

重要なものはいつも実際の実行計画をきちんと確認し、SQL文がどんな順序で実行されるかを理解するのです。無理な予測は役に立たないだけでなく、むしろ危ないことになってしまうかも知れません。

ブログを始めて、、、

「Oracle性能に対する僕の知識を日本語で話たい」と言う純真な思いからこのブログを始めるようになりました。

まだ日本語が下手なのが問題ですが。。。

日本語でブログを運営する韓国人が何人もありますか。

韓国と日本の近さ、そして日本語に上手な韓国人の数を考えて見れば、これは非常に惜しいものです。

このブログは日本語の実力を育てる同時にOracle性能に対する高級知識を国際的に共有しようとする努力中の一つです。