Wednesday, September 30, 2009

Extended Describe

Describeコマンドはテーブルの定義を確認する時によく使用します。僕はDescribeコマンドをチューニングツールの範疇に入れます。性能問題を扱って見ればオブジェクトと明確な定義を知るべき時か多いからです。


SQL*PlusのDescribeの結果に1)DDL文章自体、2)インデックスの構成、3)インデックス定義DDLたちを一緒に見るべきの場合がたくさんあります。僕はこんな機能が追加されたDescribeコマンドをExtended Describeだと呼びます。


簡単な例を通じて見ましょう。次のように8個のインデックスを持っているテーブルT1を作ります。


create table t1(c1 int, c2 int, c3 int, c4 int, c5 int);

create index t1_n1 on t1(c1);
create unique index t1_n2 on t1(c1, c3);
create index t1_n3 on t1(c1, c4);
create index t1_n4 on t1(c1, c5);
create index t1_n5 on t1(c3, c4);
create index t1_n6 on t1(c3, c4, c5);
create index t1_n7 on t1(c4, c5);
create unique index t1_n8 on t1(c5, c1);

@desc ukja t1

次のようにExtended Describe(desc.sql)コマンドを利用してテーブルの定義を見ましょうか。

UKJA@ukja1021> @desc ukja t1
UKJA@ukja1021> set echo off

OBJECT_TYPE
-------------------
TABLE

Elapsed: 00:00:00.01
Name Null? Type
------------------------------- -------- ----------------------------
1 C1 NUMBER(38)
2 C2 NUMBER(38)
3 C3 NUMBER(38)
4 C4 NUMBER(38)
5 C5 NUMBER(38)

Index 1...3...4...5...
T1_N1...............1
T1_N2...............1U 2U
T1_N3...............1 2
T1_N4...............1 2
T1_N5............... 1 2
T1_N6............... 1 2 3
T1_N7............... 1 2
T1_N8...............2U 1U

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.14

DDL
--------------------------------------------------------------------------------

CREATE TABLE "UKJA"."T1"
( "C1" NUMBER(*,0),
"C2" NUMBER(*,0),
"C3" NUMBER(*,0),
"C4" NUMBER(*,0),
"C5" NUMBER(*,0)
) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 NOCOMPRESS LOGGING
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"



Elapsed: 00:00:00.45

DDL
--------------------------------------------------------------------------------

CREATE INDEX "UKJA"."T1_N1" ON "UKJA"."T1" ("C1")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE UNIQUE INDEX "UKJA"."T1_N2" ON "UKJA"."T1" ("C1", "C3")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE INDEX "UKJA"."T1_N3" ON "UKJA"."T1" ("C1", "C4")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE INDEX "UKJA"."T1_N4" ON "UKJA"."T1" ("C1", "C5")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE INDEX "UKJA"."T1_N5" ON "UKJA"."T1" ("C3", "C4")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE INDEX "UKJA"."T1_N6" ON "UKJA"."T1" ("C3", "C4", "C5")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE INDEX "UKJA"."T1_N7" ON "UKJA"."T1" ("C4", "C5")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

CREATE UNIQUE INDEX "UKJA"."T1_N8" ON "UKJA"."T1" ("C5", "C1")
PCTFREE 10 INITRANS 2 MAXTRANS 255
STORAGE(INITIAL 10485760 NEXT 10485760 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT)
TABLESPACE "UKJA_TBS"

8 rows selected.

Elapsed: 00:00:01.28

desc.sqlファイルはここにあります。


要点はオブジェクトの定義を正確に知ることが本当に重要なものだということです。

Monday, September 28, 2009

Fixed Tableに対するクエリのチューニング

オラクル性能モニタリングしてみたらほとんど必ずだと言うほどFixed Table(X$テーブル)を問い合わせる場合ができます。Fixed Tableを読み込むというのはSGAの特定のメモリ領域を読み込むのと同じ意味です。それほど速度が速いはずです。


でもそうだと言っても性能に構わずにクエリを作成してもいいということではありません。メモリを読み込むのだといってもそのサイズが数百MBに達したら大きい性能問題が起こるはずです。こんな理由のために多いFixed Tableたちがインデックスを持っています。


UKJA@ukja1021> desc v$indexed_fixed_column
Name Null? Type
------------------------------- -------- ----------------------------
1 TABLE_NAME VARCHAR2(30)
2 INDEX_NUMBER NUMBER
3 COLUMN_NAME VARCHAR2(30)
4 COLUMN_POSITION NUMBER

例えばLCO(Library Cache Object)のリストを示しているX$KGLOBテーブルは次のように二つの列に対してインデックスを持っています。

UKJA@ukja1021> exec print_table('select * from v$indexed_fixed_column -
> where table_name = ''X$KGLOB''');
TABLE_NAME : X$KGLOB
INDEX_NUMBER : 1
COLUMN_NAME : KGLNAHSH
COLUMN_POSITION : 0
-----------------
TABLE_NAME : X$KGLOB
INDEX_NUMBER : 2
COLUMN_NAME : KGLOBT03
COLUMN_POSITION : 0
-----------------

SQL Hash Value(KGLNAHSH)とSQL ID(KGLOBT03)に対してインデックスが存在します。すなわち、X$KGLOBテーブルを問い合わせる時にはできる限りこの二つの列を使用しなければいけません。


簡単なテストを通じて性能問題を論議してみます。


1. 次のように簡単なSQL文を修行してSQL IDを抽出します。


UKJA@ukja1021> select * from t1;

no rows selected

Elapsed: 00:00:00.00
UKJA@ukja1021> col sql_id new_value sql_id
UKJA@ukja1021> select regexp_replace(plan_table_output,
2 'SQL_ID[[:blank:]]+([[:alnum:]]+),.*', '\1') as sql_id
3 from table(dbms_xplan.display_cursor)
4 where plan_table_output like 'SQL_ID%';

SQL_ID
--------------------------------------------------------------------------------
27uhu2q2xuu7r

2. KGNAOBJ(インデックス無)列とKGLOBT03(インデックス有)列を通じてX$KGLOBテーブルを問い合わせる二つのSQL文章を実行します。

UKJA@ukja1021> select count(*) from sys.xm$kglob
2 where kglnaobj = 'select * from t1';

COUNT(*)
----------
2

Elapsed: 00:00:00.06
UKJA@ukja1021>
UKJA@ukja1021> select count(*) from sys.xm$kglob
2 where kglobt03 = '&sql_id';
old 2: where kglobt03 = '&sql_id'
new 2: where kglobt03 = '27uhu2q2xuu7r'

COUNT(*)
----------
2

Elapsed: 00:00:00.01

3. 二つのSQL文章に対するTKPROFの結果です。

select count(*) from sys.xm$kglob
where kglnaobj = '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 2 0.06 0.05 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.06 0.05 0 0 0 1

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

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=59402 us)
2 FIXED TABLE FULL X$KGLOB (cr=0 pr=0 pw=0 time=43810 us)


select count(*) from sys.xm$kglob
where kglobt03 = '27uhu2q2xuu7r'

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 2 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1

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

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=167 us)
2 FIXED TABLE FIXED INDEX X$KGLOB (ind:2) (cr=0 pr=0 pw=0 time=120 us)

次のような事実がわかります。

  • Logical Readsだけでは全然違いがありません。Fixed Tableに対する問い合わせはブロックを読み込むのではなくてメモリを直接読み込むので一般的に作業を測定するために使用するLogical Readsでは観察されません。
  • 実行計画上ではFIXED TABLE FULLFIXED TABLE FIXED INDEX (ind:2)から一つ目のSQLはFull Scanを二つ目のSQLはIndex Scan(正確には二つ目のインデックス)をするのが分かります。
  • そのために一つ目のSQLは0.05秒が、二つ目のSQLは0秒が掛かりました。

伝統的にSQL文章の性能を比べる時に使用するLogical Readsがどんな意味もないのに注意する必要があります。


4. 僕がテストする時に使用するスクリプトを利用して二つの場合の性能を比べてみます。


@mon_on userenv('sid')

select count(*) from sys.xm$kglob
where kglnaobj = 'select * from t1';

@mon_off

select count(*) from sys.xm$kglob
where kglobt03 = '&sql_id';

@mon_off2
@mon_show2
...
02. time model

STAT_NAME VALUE1 VALUE2 DIFF
----------------------------------- -------------- -------------- --------------
DB time 166,458 115,196 -51,262
sql execute elapsed time 164,356 113,308 -51,048
DB CPU 134,972 103,749 -31,223
...

03. latch

LATCH_NAME D_GETS D_MISSES D_SLEEPS D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
library cache -4186 0 0 0
row cache objects -45 0 0 0
enqueues -19 0 0 0
enqueue hash chains -18 0 0 0
...

一番大きい違いはLibrary Cache Latchの獲得にあります。メモリをFull Scanしている一つ目のSQL文章がインデックスを利用する二つ目のSQL文章に比べてLatch獲得数がずっと多いです。それほど多いメモリ領域をスキャンするという意味で性能も低いし、Latch競合による同時性の問題が発生する可能性も高いです。


こんな原理を分からなくてモニタリングスクリプトを作成したら性能に致命的な結果をもたらされます。性能をモニタリングするための作業が性能を低下させる結果になるのです。多く使用されているツールたちでもこんな失敗がよく発生しています。性能問題を解決するために使用されるクエリ自体がチューニングがされていない矛盾な現状が起こります。


Dictionaryビューに対しても似ている原理が適用できます。次のポストではDictionaryビューに対するクエリの性能に対して面白い観察を見られます。参考してください。

Thursday, September 24, 2009

Parallel QueryとDirect path read,そしてLOB

パラレルにテーブルを読み込むとDirect path I/Oを使うことになります。これが一般的な真実です。


でも、テーブルのサイズが_small_table_thresholdパラメータの値より大きい時だけそうです。


NAME VALUE IS_DEFAUL SES_MODIFI
------------------------------ -------------------- --------- ----------
SYS_MODIFI
----------
DESCRIPTION
--------------------------------------------------------------------------------
_small_table_threshold 1027 TRUE true
deferred
threshold level of table size for direct reads

すなわち、このシステムではテーブルのサイズが1027ブロックより大きい場合にだけはDirect path I/Oが使われます。_small_table_thresholdパラメータの基本値はバッファキャッシュサイズの5%ぐらいです。すなわちバッファキャッシュの5%より大きいテーブルに対してだけParallel QueryでDirect path I/Oが使われます。


Direct path I/Oに関連してもう一つの隠された事実があります。Out-of-Rowで格納されたLOBデータをParallel Queryで読み込もうとします。このLOBデータはSlave Processが読み込むのですか、Coordinator Processが読み込むのですか。Coordinator Processが読み込みます


こんな複合的な事実を明確に理解しなければParallel Queryに対する10046トレース分析の時深刻な失敗をするようになります。次の簡単なテスト結果を見ましょう。


1. _small_table_thresholdパラメータの値は1027なのです。


UKJA@ukja1021> col value new_value stt
UKJA@ukja1021> @para small_table_threshold
UKJA@ukja1021> set echo off
old 9: and i.ksppinm like '%&1%'
new 9: and i.ksppinm like '%small_table_threshold%'

NAME VALUE IS_DEFAUL SES_MODIFI
------------------------------ -------------------- --------- ----------
SYS_MODIFI
----------
DESCRIPTION
--------------------------------------------------------------------------------
_small_table_threshold 1027 TRUE true
deferred
threshold level of table size for direct reads

2. テーブルのサイズが1027よりもう少し小さいように生成します。

UKJA@ukja1021> create table t1(c1 int, c2 char(2000), c3 char(2000), c4 char(1000), c5 clob)
2 lob(c5) store as (nocache nologging disable storage in row)
3 ;

Table created.

Elapsed: 00:00:00.15
UKJA@ukja1021>
UKJA@ukja1021> insert into t1
2 select level, 'x', 'x', 'x', rpad('x',4000)
3 from dual
4 connect by level <= &stt - 100
5 ;
old 4: connect by level <= &stt - 100
new 4: connect by level <= 1027 - 100

927 rows created.

Elapsed: 00:00:09.20
UKJA@ukja1021> @gather t1
UKJA@ukja1021> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
UKJA@ukja1021> select table_name, blocks
2 from user_tables
3 where table_name = 'T1';

TABLE_NAME BLOCKS
-------------------- ----------
T1 938

3. このテーブルに対してParallel Queryを修行します。Coordinator ProcessではPhysical I/Oが全然発生しません。

UKJA@ukja1021> alter system flush buffer_cache;

UKJA@ukja1021> select /*+ parallel(t1 2) small */ * from t1;

select /*+ parallel(t1 2) small */ *
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.45 1 2 0 0
Fetch 928 0.12 0.27 0 0 0 927
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 930 0.12 0.72 1 2 0 927

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

Rows Row Source Operation
------- ---------------------------------------------------
927 PX COORDINATOR (cr=2 pr=1 pw=0 time=518856 us)
0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.01 0.01
PX Deq: Parse Reply 3 0.43 0.43
SQL*Net message to client 929 0.00 0.00
SQL*Net message from client 929 0.00 0.13
PX Deq: Execute Reply 271 0.01 0.07
SQL*Net more data to client 2 0.00 0.00
PX qref latch 13 0.00 0.00
PX Deq: Signal ACK 3 0.09 0.10
enq: PS - contention 2 0.00 0.00
********************************************************************************

4. Physical I/OはSlave Processで発生します。しかしDirect path I/OではなくてConventional path I/O(db file scattered read待機イベント)が使用されるのがわかります。

select /*+ parallel(t1 2) small */ *
from
t1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.07 27.00 481 507 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.07 27.00 481 507 0 0

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

Rows Row Source Operation
------- ---------------------------------------------------
0 PX COORDINATOR (cr=0 pr=0 pw=0 time=0 us)
0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
470 PX BLOCK ITERATOR (cr=507 pr=481 pw=0 time=17523 us)
470 TABLE ACCESS FULL T1 (cr=507 pr=481 pw=0 time=166734 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Execution Msg 15 0.12 0.14
db file scattered read 39 0.02 0.19
PX Deq Credit: send blkd 845 0.19 26.32
PX qref latch 10 0.00 0.00
PX Deq Credit: need buffer 6 0.11 0.24
********************************************************************************

5. テーブルにデータを追加して_small_table_threshold値をさっと超えるようにします。

UKJA@ukja1021> insert into t1
2 select level, 'x', 'x', 'x', rpad('x',4000)
3 from dual
4 connect by level <= 200
5 ;

200 rows created.

Elapsed: 00:00:01.23
UKJA@ukja1021> @gather t1
UKJA@ukja1021> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.57
UKJA@ukja1021> select table_name, blocks
2 from user_tables
3 where table_name = 'T1';

TABLE_NAME BLOCKS
-------------------- ----------
T1 1130

6. 次のようにParallel Queryを実行します。いぜんとしてCoordinator ProcessではPhysical I/Oが観察されません。

select /*+ parallel(t1 2) big */ *
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.13 1 2 0 0
Fetch 1128 0.09 0.25 0 0 0 1127
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1130 0.09 0.38 1 2 0 1127

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

Rows Row Source Operation
------- ---------------------------------------------------
1127 PX COORDINATOR (cr=2 pr=1 pw=0 time=222619 us)
0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
PX Deq: Join ACK 2 0.00 0.00
PX Deq: Parse Reply 2 0.12 0.12
SQL*Net message to client 1129 0.00 0.00
SQL*Net message from client 1129 0.00 0.15
PX Deq: Execute Reply 311 0.01 0.02
SQL*Net more data to client 2 0.00 0.00
PX qref latch 12 0.00 0.00
PX Deq: Signal ACK 3 0.10 0.10
enq: PS - contention 2 0.00 0.00

7. 今度もSlave ProcessでPhysical I/Oが発生します。ただし、Conventional path I/OではなくてDirect path I/O(direct path read待機イベント)が発生するのが分かります。

select /*+ parallel(t1 2) big */ *
from
t1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.07 28.93 572 585 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.07 28.93 572 585 0 0

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

Rows Row Source Operation
------- ---------------------------------------------------
0 PX COORDINATOR (cr=0 pr=0 pw=0 time=0 us)
0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
569 PX BLOCK ITERATOR (cr=585 pr=572 pw=0 time=447086 us)
569 TABLE ACCESS FULL T1 (cr=585 pr=572 pw=0 time=327324 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
PX Deq: Execution Msg 15 0.04 0.32
direct path read 51 0.01 0.05
PX Deq Credit: need buffer 7 0.02 0.07
PX Deq Credit: send blkd 1025 0.08 28.38
PX qref latch 27 0.00 0.00

8. ここでもう一つの疑問があります。テーブルを定義する時Out-of-RowでLOBを生成しました。このLOBに対するPhysical I/Oはどこへ行ったんですか。LOBを実際にフェッチするものはSlave ProcessではなくてCoordinator Processなのです。ともにLOBに対するフェッチは#0番の内部的なカーソルを使用するのでCoordinator Processが修行したクエリに対するTKPROFレポートには報告されません。この問題はここで報告したことがあるんです。


従ってLOBに対するDirect path I/Oで発生するdirect path read待機イベントはCoordinator Processが残したトレースファイルに対するTKPROFレポートのサマリ情報でだけ観察されます。


OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 6 0.00 0.58 2 4 0 0
Fetch 2056 0.21 0.52 0 0 0 2054
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2066 0.21 1.11 2 4 0 2054

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 6168 0.00 0.02
SQL*Net message from client 6168 0.14 49.16
db file sequential read 20 0.02 0.17
PX Deq: Parse Reply 5 0.43 0.55
PX Deq: Execute Reply 582 0.01 0.10
SQL*Net more data to client 4 0.00 0.00
direct path read 8216 0.04 4.43
PX qref latch 25 0.00 0.00
PX Deq: Signal ACK 6 0.10 0.20
enq: PS - contention 4 0.00 0.00
PX Deq: Join ACK 2 0.00 0.00

この理由はCoordinator Processに対するトレースファイルの原本を見たら分かります。direct path read待機イベントがWAIT #0で報告されるのに注意してください。

WAIT #2: nam='PX Deq: Execute Reply' ela= 5 sleeptime/senderid=200 passes=1 p3=0
WAIT #2: nam='PX Deq: Execute Reply' ela= 6 sleeptime/senderid=200 passes=2 p3=0
WAIT #2: nam='PX Deq: Execute Reply' ela= 206 sleeptime/senderid=200 passes=3 p3
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
FETCH #2:c=0,e=501,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=511204438360
WAIT #2: nam='SQL*Net message from client' ela= 245 driver id=1413697536 #bytes=
WAIT #0: nam='direct path read' ela= 5019 file number=9 first dba=23243 block cn
WAIT #0: nam='direct path read' ela= 443 file number=9 first dba=23243 block cnt
WAIT #0: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3
*** 2009-09-24 15:42:07.328
WAIT #0: nam='SQL*Net message from client' ela= 14753 driver id=1413697536 #byte
WAIT #0: nam='direct path read' ela= 253 file number=9 first dba=23243 block cnt
WAIT #0: nam='direct path read' ela= 188 file number=9 first dba=23243 block cnt
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
WAIT #0: nam='SQL*Net message from client' ela= 609 driver id=1413697536 #bytes=
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3

Parallel QueryとLOBが一緒に使用されれば問題がかなり複雑になるのが分かります。待機イベントを分析する時はいつも気をつけなければなりません。

Thursday, September 17, 2009

SQL*net message from dblinkイベントはアイドルかネットワーク問題なのか。

次の二つの待機イベントは名前があまり似ていて多い誤解を呼び起こします。

  • SQL*Net message from client
  • SQL*Net message from dblink

SQL*Net message from client待機イベントは代表的なアイドルイベントです。するとSQL*Net message from dblinkイベントはどうでしょうか。

UKJA@ukja1106> @event 'SQL*Net message from'
UKJA@ukja1106> set serveroutput on
UKJA@ukja1106>
UKJA@ukja1106> exec print_table('select * from v$event_name where name like ''%&
1%''');
EVENT# : 289
EVENT_ID : 1421975091
NAME : SQL*Net message from client
PARAMETER1 : driver id
PARAMETER2 : #bytes
PARAMETER3 :
WAIT_CLASS_ID : 2723168908
WAIT_CLASS# : 6
WAIT_CLASS : Idle
-----------------
EVENT# : 291
EVENT_ID : 4093028837
NAME : SQL*Net message from dblink
PARAMETER1 : driver id
PARAMETER2 : #bytes
PARAMETER3 :
WAIT_CLASS_ID : 2000153315
WAIT_CLASS# : 7
WAIT_CLASS : Network
-----------------

SQL*Net message from clientイベントはアイドルで分類されるけど、SQL*Net message from dblinkイベントはNetworkで分類されます。そうだったらSQL*Net message from dblinkイベントを待機するというのはネットワークの性能に問題があるという意味でしょうか。


SQL*Net message from dblinkイベントを待機すると言うことは次の意味です。


  1. ローカルデータベースがSQLをリモートデータベースに転送要請します。
  2. この時ローカルデータベースはOSのAPIを呼んで該当SQL文章をネットワーク転送バッファに入れます。この短い時間の間SQL*Net message to dblinkイベントを待機します。実際のネットワーク転送にかかわらず転送バッファに入れるだけで待機イベントは終わります。
  3. ローカルデータベースは今OSのAPIを呼んでネットワーク受信バッファからデータを引き出そうとします。まだリモートデータベースがデータを送らない状態なのでSQL*Net message from dblinkイベントを待機します。
  4. リモートデータベースがデータを転送したからローカルOSがそのデータを受けてネットワーク受信バッファに入れるとローカルデータベースのSQL*Net message from dblinkイベントが終わります。

上の内容をよく理解すればSQL*Net message from dblinkイベントを待機したと言ってネットワーク転送が遅いのだと判断できないということがよく分かります。


長期間のSQL*Net message from dblinkイベントがネットワーク性能と全然構わない簡単な例を作ってみます。


1. UKJA1021データベースに次のように10,000件の件数を持つテーブルを作ります。


-- UKJA1021
drop table t1 purge;

create table t1
as
select level as c1
from dual connect by level <= 10000
;

2. 次のようにUKJA1106 --> UKJA1201データベースリンクを作ります。

create database link UKJA1021
connect to ukja identified by ukja
using 'UKJA1021'
;

3. 実行計画を見ればリモートデータベースで100%実行されるのが分かります。

explain plan for
select count(*)
from t1@ukja1021, t1@ukja1021
;

@plan
--------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time | Inst |
--------------------------------------------------------------------------------
| 0 | SELECT STATEMENT REMOTE| | 1 | 68860 (5)| 00:13:47 | |
| 1 | SORT AGGREGATE | | 1 | | | |
| 2 | MERGE JOIN CARTESIAN | | 100M| 68860 (5)| 00:13:47 | |
| 3 | TABLE ACCESS FULL | T1 | 10000 | 8 (0)| 00:00:01 | UKJA1~ |
| 4 | BUFFER SORT | | 10000 | 68851 (5)| 00:13:47 | |
| 5 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 | UKJA1~ |
--------------------------------------------------------------------------------


Note
-----
- fully remote statement
- dynamic sampling used for this statement

4. 今次のようにSQL文を実行すれば長い時間の間待機状態に落ち込んでしまいます。

-- UKJA1106
UKJA@ukja1106>
UKJA@ukja1106> select count(*)
2 from t1@ukja1021, t1@ukja1021, t1@ukja1021
3 ;
............

5. 待機イベントを見れば次のようにSQL*Net message from dblinkイベントを待機します。

SID EVENT P1 P2 P3
----- ------------------------- --------------- --------------- ----------
SECONDS_IN_WAIT
---------------
133 SQL*Net message from dbli 1413697536(0000 1(0000000000000 0(00)
nk 000054435000) 001)
9626

該当SQL文はCOUNT(*)を修行するから結果が出る前には全然データ転送が発生しません。すなわち、まだ1バイトのデータもネットワークを通じて転送されていない状態です。ネットワークでなんのデータも転送されないのでこの場合にはネットワークの性能がすっかり論外と言えます。


6. リモートデータベースでは次のようにリモートセッションがモニタリングされます。


-- UKJA1021
SID SERIAL# PROGRAM EVENT SQL_TEXT
----- ------- ---------- -------------------- ------------------------------
136 745 ORACLE.EXE SQL*Net message to c SELECT COUNT(*) FROM "T1" "A3"
lient ,"T1" "A2","T1" "A1"

7. 133番のセッションを詳しくモニタリングしてみれば次のようです。

UKJA@ukja1021> set echo off
01. basic session info
SID : 136
SERIAL# : 745
SPID : 15304
MACHINE : XXXX-3C2E2AF808
PROGRAM : ORACLE.EXE
PGA : 1154000
UGA : 680088
LAST_CALL_ET : 9696
LOGON_TIME : 2009/09/18 09:59:53
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
02. session wait
SID : 136
EVENT : SQL*Net message to client
P1 : 1413697536
P1RAW : 54435000
P2 : 1
P2RAW : 00000001
P3 : 0
P3RAW : 00
SECONDS_IN_WAIT : 9696
STATE : WAITED SHORT TIME
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
03. process info
PID : 20
PROGRAM : ORACLE.EXE (SHAD)
PGA_USED_MEM : 1037021
PGA_ALLOC_MEM : 1118413
PGA_MAX_MEM : 3245293
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
04. sql info
SID : 136
SHARABLE_MEM : 12759
PERSISTENT_MEM : 6304
RUNTIME_MEM : 5752
EXECUTIONS : 1
FETCHES : 0
BUFFER_GETS : 97
SQL_TEXT : SELECT COUNT(*) FROM "T1" "A3","T1" "A2","T1"
"A1"
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.03
05. sql plan info

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

SQL_ID 6t0k52rdrw388, child number 0
-------------------------------------
SELECT COUNT(*) FROM "T1" "A3","T1" "A2","T1" "A1"

Plan hash value: 2643210548

-----------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-----------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | 688M(100)| |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | MERGE JOIN CARTESIAN | | 1000G| 688M (5)|999:59:59 |
| 3 | MERGE JOIN CARTESIAN| | 100M| 68860 (5)| 00:13:47 |
| 4 | TABLE ACCESS FULL | T1 | 10000 | 8 (0)| 00:00:01 |
| 5 | BUFFER SORT | | 10000 | 68851 (5)| 00:13:47 |
| 6 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 |
| 7 | BUFFER SORT | | 10000 | 688M (5)|999:59:59 |
| 8 | TABLE ACCESS FULL | T1 | 10000 | 7 (0)| 00:00:01 |
-----------------------------------------------------------------------

Note
-----

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

- dynamic sampling used for this statement


24 rows selected.

Elapsed: 00:00:00.07
06. workarea info
SID : 136
OPERATION_TYPE : BUFFER
ACTIVE_TIME : 9696154331
WORK_AREA_SIZE : 131072
ACTUAL_MEM_USED : 131072
MAX_MEM_USED : 131072
-----------------
SID : 136
OPERATION_TYPE : BUFFER
ACTIVE_TIME : 9696150509
WORK_AREA_SIZE : 131072
ACTUAL_MEM_USED : 131072
MAX_MEM_USED : 131072
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
07. transaction info

PL/SQL procedure successfully completed.

待機状態がWAITED SHORT TIMEだというのは現在待機状態ではなくてCPUを占有して忙しく作業をしている状態だと言う意味です。どんな作業をしているのかはプロセス情報によく現れています。

03. process info
PID : 20
PROGRAM : ORACLE.EXE (SHAD)
PGA_USED_MEM : 1037021
PGA_ALLOC_MEM : 1118413
PGA_MAX_MEM : 3245293

上の情報をみれば現在1Gバイト以上のPGAを使用していて、最大3Gバイト以上のPGAを使用したことが分かります。すなわち大容量のCartesian Merge Joinを処理しながら忙しく働いているし、そのせいでリモートデータベースに応答できないという状態です。


待機イベントというのはその名前のために逆に誤解しやすい場合が多いです。こんな場合にはCarry Millsapのポスト(Dang It, People, they're syscalls not wait)を見れば誤解を解けることができるでしょう。

Wednesday, September 16, 2009

TKPROFの結果解析の時注意すべき点 - CURSOR #0

TKPROFが「時間値」について完全な嘘をつく場合があります。とても易しく再現できます。次のテストを見てください。


1. 次のとおりにテーブルを作って、10,000件のデータをInsertするスクリプトを生成します。


drop table t1 purge;
create table t1(c1 number);

set term off
set heading off
set feedback off
set echo off
set timing off

spool insert.sql
select
'insert into t1 values(:b1);' || chr(13)
from dual
connect by level <= 10000
;
spool off

2. Insert.sqlファイルは次のような内容を含めています。

insert into t1 values(:b1);

insert into t1 values(:b1);

insert into t1 values(:b1);

insert into t1 values(:b1);
...

3.  AUTOCOMMITを活性化して、Insert.sqlを実行した後その時間を計ります。

set autocommit on

var b1 number;
exec :b1 := 1;

col hsecs new_value v_hsecs

select hsecs from v$timer;

@insert

select (hsecs-&v_hsecs)/100 from v$timer;

次のように32秒ぐらいの時間がかかりました。

UKJA@ukja1021> select (hsecs-&v_hsecs)/100 from v$timer;
old 1: select (hsecs-&v_hsecs)/100 from v$timer
new 1: select (hsecs- 139710015)/100 from v$timer

(HSECS-139710015)/100
---------------------
32.42

4.  でもTKPROFの結果は全然違います。アイドル待機時間をすべて合わせても8秒ぐらいしかなりません。なんと24秒ぐらいの違いが発生しています。

insert into t1
values
(:b1)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10000 0.48 0.28 0 0 0 0
Execute 10000 1.31 1.34 0 10007 50155 10000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20000 1.79 1.63 0 10007 50155 10000

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

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

5. この違いはどこから発生しているのでしょうか。TKPROFの結果中サマリー部分を見ると失った24秒が存在するのが分かります。

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10004 0.51 0.30 0 0 0 0
Execute 10005 1.31 1.34 0 10007 50155 10001
Fetch 4 0.00 0.00 0 0 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20013 1.82 1.64 0 10007 50155 10003

Misses in library cache during parse: 3
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 20007 0.00 0.06
SQL*Net message from client 20007 0.05 20.56
log file sync 10000 0.04 4.99

なぜ!この24秒がINSERT文章に含まれないでてサマリーのみに見えるのでしょうか。


6. TKPROFの結果が変だからその原本データを通じて原因を見つけなければいけません。次は特定のINSERT文章に対するトレース結果です。


PARSING IN CURSOR #5 len=26 dep=0 uid=61 oct=2 lid=61 tim=1397114954939 hv=78085
insert into t1 values(:b1)
END OF STMT
PARSE #5:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1397114954935
EXEC #5:c=0,e=112,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=1397114955118
WAIT #5: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
WAIT #5: nam='SQL*Net message from client' ela= 349 driver id=1413697536 #bytes=
XCTEND rlbk=0, rd_only=0
WAIT #0: nam='log file sync' ela= 359 buffer#=2403 p2=0 p3=0 obj#=-1 tim=1397114
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3
WAIT #0: nam='SQL*Net message from client' ela= 886 driver id=1413697536 #bytes=

XCTEND(Transaction End)が見えて、その次のlog file sync待機とSQL*Net message待機は#5ではなくて#0に変わってしまいます。すなわちAUTOCOMMITによって内部的に修行されるコミットによる時間はINSERT文章にふくまれなくて別途の内部カーソルで処理されるのが分かります。明示的にコミットを実行したことがないからCommit文章も全然観察されません。おかげでAUTOCOMMITによる時間はひたすらサマリー部分のみに反映されます。


TKPROF結果で報告するSQL文章の実行時間を信じられない代表的な場合です。


「AUTOCOMMITを使用する場合はほとんどないからもんだいがないだろう」と考えたら次の例を見れば考えが切り替わるでしょう。


7. 次のようにLOBタイプを定義して4Kバイトくらいのデータを追加します。サイズが4Kバイトだから別途のセグメントに貯蔵されますしdirect path readを通じて読み込むようになるはずです。


drop table t1 purge;

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;
/

8. 次のようにデータを読んでみれば1分45秒ぐらいの時間が掛かります。

UKJA@ukja1021> set autot trace -- suppress output
UKJA@ukja1021> select * from t1;

1000 rows selected.

Elapsed: 00:01:45.70

9. でもTKPROFの結果を見るとアイドル待機時間を全部合わせても0.3秒もなりません。大部分の時間は全然報告されていません。期待したdirect path readイベントはてんで見えないです。

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.09 0.12 35 1030 0 1000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1003 0.09 0.12 35 1030 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=1030 pr=35 pw=0 time=66068 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.15
db file sequential read 3 0.00 0.00
db file scattered read 1 0.02 0.02

10. 今度もやはりサマリー部分のみに時間が正確に計算されて報告されています。

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 12 0.01 0.18 0 0 0 0
Execute 12 0.04 0.14 18 147 4 2
Fetch 1012 0.15 0.19 35 1030 0 1024
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1036 0.21 0.52 53 1177 4 1026

Misses in library cache during parse: 6
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 102017 0.00 0.35
SQL*Net message from client 102016 0.02 19.69
db file sequential read 22 0.01 0.11
db file scattered read 1 0.02 0.02
direct path read 201000 0.05 47.75

11. 今度もトレース原本ファイルを見るべきでしょう。次の内容を見れば同一なパターンが観察されます。
  
select * from t1
END OF STMT
PARSE #26:c=0,e=1314,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1382035591807
EXEC #26:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1382035592024
WAIT #26: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes
WAIT #26: nam='SQL*Net message from client' ela= 473 driver id=1413697536 #b
WAIT #26: nam='db file sequential read' ela= 302 file#=7 block#=30 blocks=1
WAIT #26: nam='db file sequential read' ela= 235 file#=7 block#=9 blocks=1 o
WAIT #26: nam='db file sequential read' ela= 244 file#=7 block#=29 blocks=1
WAIT #26: nam='db file scattered read' ela= 20637 file#=7 block#=41 blocks=3
WAIT #26: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes
FETCH #26:c=0,e=22152,p=35,cr=15,cu=0,mis=0,r=1,dep=0,og=1,tim=1382035614925
WAIT #26: nam='SQL*Net message from client' ela= 287 driver id=1413697536 #b
WAIT #0: nam='direct path read' ela= 10386 file number=7 first dba=1500 bloc
WAIT #0: nam='direct path read' ela= 277 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 317 driver id=1413697536 #by
WAIT #0: nam='direct path read' ela= 354 file number=7 first dba=1500 block
WAIT #0: nam='direct path read' ela= 277 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 197 driver id=1413697536 #by
WAIT #0: nam='direct path read' ela= 288 file number=7 first dba=1500 block
WAIT #0: nam='direct path read' ela= 359 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 185 driver id=1413697536 #by

#26番で作業をしながらいざLOBをフェッチする時はいきなり#0番に変わってしまいます。従ってTKPROFで正確に反映できないようになることです。


オラクルが特定の作業を修行しながら別途のOCIコールを通じて(AUTOCOMMIT,LOBなど)処理をすべき場合、既存のカーソルとは構わずに作業が実行される場合があります。こんな場合にオラクルは#0番を与えてトレースファイルに残します。従ってTKPROFがこれをちゃんと解析できないようになるのです。


上の内容をよく理解したらTKPROFレポートが提供する時間情報を100%信じられないという私の意見に十分に共感するはずです。

Tuesday, September 15, 2009

INITRANSとMAXTRANS

セグメントの属性中同時トランザクション数を制御するINITRANSとMAXTRANSパラメータは歴史的な理由で正確な動作方式が混乱な面があります。最近のバージョンの動作方式は次のとおりです。

  • INITRANSの基本値は2で最小値も2であります。ただ、ディクショナリー(ALL_TABLESなど)には”1”の値で観察されます。でも実際の値は2であります。
  • MAXTRANSの基本値は255であり最小値の255であります。すなわち固定値です。

ここで二つの面白い質問ができます。

  1. INITRANSの実際の基本値が”1”ではなくて”2”だというのをどうすれば証明できるだろうか。
  2. MAXTRANSの値を255ではなくてもっと低くする方法はないだろうか。(255より大きい値にするのは不可能です。1バイトで表現できる最大の値だからです)

簡単なデモを通じて答えをみます。


まず次のようにテーブルを一つ作ります。INITRANS値とMAXTRANS値を各々1と5で指定しています。しかしディクショナリーには1,255で指定されているのがわかります。


UKJA@ukja1021> create table t1(c1 int)
2 initrans 1 -- 1!
3 maxtrans 5 -- 5!
4 ;

Table created.

Elapsed: 00:00:00.03
UKJA@ukja1021>
UKJA@ukja1021> select table_name, ini_trans, max_trans
2 from user_tables where table_name = 'T1';

TABLE_NAME INI_TRANS MAX_TRANS
-------------------- ---------- ----------
T1 1 255

Elapsed: 00:00:00.01
UKJA@ukja1021>
UKJA@ukja1021> insert into t1 select level from dual connect by level <= 10;

10 rows created.

Elapsed: 00:00:00.01
UKJA@ukja1021> commit;

Commit complete.

Elapsed: 00:00:00.00

一つのトランザクションを発生してからブロックダンプを修行してみます。

UKJA@ukja1021> col f# new_value fno
UKJA@ukja1021> col b# new_value bno
UKJA@ukja1021>
UKJA@ukja1021> select dbms_rowid.rowid_relative_fno(rowid) f#,
2 dbms_rowid.rowid_block_number(rowid) b#
3 from t1
4 where rownum <= 1;

F# B#
---------- ----------
8 9011

Elapsed: 00:00:00.01
UKJA@ukja1021>
UKJA@ukja1021> update t1 set c1 = 1 where c1 = 1;

1 row updated.

Elapsed: 00:00:00.00

次のように2個のITLエントリが登録されているのを見られます。今まで最大一つのトランザクションだけを発生させたのでINITRANSの実際値が2であるのが分かります。

UKJA@ukja1021> alter system dump datafile &fno block &bno;
old 1: alter system dump datafile &fno block &bno
new 1: alter system dump datafile 8 block 9011

System altered.

Elapsed: 00:00:00.01

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0005.017.000004d6 0x0080095b.01ca.19 C--- 0 scn 0x0000.0015f76c
0x02 0x0004.008.00000370 0x008001b8.0181.26 ---- 1 fsc 0x0000.00000000

さて次のように5個のトランザクションをさらに発生させます。

UKJA@ukja1021> ho type temp.sql
update t1 set c1 = &1 where c1 = &1;

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 2

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 3

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 4

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 5

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 6

MAXTRANSの値を5で指定したからこの設定が動作したら6番目のトランザクションは待機状態に落ち込まなければなりません。でも、次のように全部で6個のITLエントリが成功的に登録され、すべてのトランザクションが待機なしに成功的に修行されます。MAXTRANSは255という固定値を使用するからです。

UKJA@ukja1021> alter system dump datafile &fno block &bno;
old 1: alter system dump datafile &fno block &bno
new 1: alter system dump datafile 8 block 9011

System altered.

Elapsed: 00:00:00.06

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x000a.003.00000365 0x00800430.0212.0c ---- 1 fsc 0x0000.00000000
0x02 0x0004.008.00000370 0x008001b8.0181.26 ---- 1 fsc 0x0000.00000000
0x03 0x0003.02a.000001ef 0x00800276.0167.09 ---- 1 fsc 0x0000.00000000
0x04 0x0008.023.00000434 0x00800348.01d4.34 ---- 1 fsc 0x0000.00000000
0x05 0x0001.027.00000372 0x00800763.01bb.30 ---- 1 fsc 0x0000.00000000
0x06 0x0002.00e.00000419 0x008003d3.016d.13 ---- 1 fsc 0x0000.00000000

この255の固定値を変えることはできないでしょうか。次のようにTAB$テーブルを直接修正するによってもっと低い値に変えることができます。すなわち次のように作業を修行すればMAXTRANSの値が255ではなくて5で低くなります。

SYS@ukja1021> connect sys/oracle as sysdba
Connected.

SYS@ukja1021> col object_id new_value v_obj_id
SYS@ukja1021> col data_object_id new_value v_data_obj_id
SYS@ukja1021>
SYS@ukja1021> select object_id, data_object_id from all_objects
2 where object_name = 'T1';

OBJECT_ID DATA_OBJECT_ID
---------- --------------
54298 54298

Elapsed: 00:00:00.07
SYS@ukja1021>
SYS@ukja1021> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.07
SYS@ukja1021> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.00
SYS@ukja1021>
SYS@ukja1021> update tab$
2 set maxtrans = 5
3 where obj# = &v_obj_id and dataobj# = &v_data_obj_id
4 ;
old 3: where obj# = &v_obj_id and dataobj# = &v_data_obj_id
new 3: where obj# = 54298 and dataobj# = 54298

1 row updated.

Elapsed: 00:00:00.03
SYS@ukja1021>
SYS@ukja1021> commit;

Commit complete.

Elapsed: 00:00:00.00
SYS@ukja1021>
SYS@ukja1021> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.00
SYS@ukja1021> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.00

5で変えたMAXTRANSの設定値がちゃんと動作するのかテストしてみます。次のように同時に7個のトランザクションを作ります。いままで6個のITLエントリをもう作ったので万一5の値が動作するといえば7番目のトランザクションはITLエントリ待機(enq: TX - allocate ITL entry)状態になるはずです。

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 1

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 2

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 3

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 4

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 5

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 6

UKJA@ukja1021> ho start sqlplus ukja/ukja@ukja1021 @temp 7

UKJA@ukja1021> @wait
UKJA@ukja1021> set echo off

SID EVENT P1 P2 P3
---------- ------------------------- --------------- --------------- ----------
SECONDS_IN_WAIT
---------------
136 enq: TX - allocate ITL en 1415053316(5458 524332(0008002C 1075(00000
try 0004) ) 433)
0

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0008.02c.00000433 0x00800349.01d4.01 ---- 1 fsc 0x0000.00000000
0x02 0x0002.01d.00000419 0x008003c0.016d.17 ---- 1 fsc 0x0000.00000000
0x03 0x0007.00f.0000036f 0x00800609.0217.0c ---- 1 fsc 0x0000.00000000
0x04 0x0004.010.00000370 0x008001b8.0181.27 ---- 1 fsc 0x0000.00000000
0x05 0x0005.027.000004d6 0x0080095b.01ca.1e ---- 1 fsc 0x0000.00000000
0x06 0x0001.00b.00000372 0x00800764.01bb.01 ---- 1 fsc 0x0000.00000000

ITLが6個からその以上大きくならず7番目のトランザクションはITLエントリ待機状態になったのが分かります。


「MAXTRANSを低くする必要がなるほどいるのか」という疑問を持っている方なら次のブログポストをご覧ください。

Monday, September 14, 2009

SQLチューニングは易しいが、ORA-4031エラーの解決は難しい理由は何

周囲にSQLチューニングに上手な方たちが多いです。いくら複雑なクエリとしても数分または数時間内にチューニングできる場合が大部分です。


しかし「ORA-4031エラーの原因を探してくれて」と言われば大部分数日が経っても解決できない場合が多いです。僕ならORA-4031エラーの原因の分析を頼まれるとほかの仕事で忙しいからといって一応逃げるかも知れません。:)


どうしてこんな現状が起きるんでしょうか。僕がよく聞いている意見は次のようです。

SQLチューニングに必要な技術は身に着けやすいんですが、ORA-4031エラーの解決に必要な内部的な知識は身に着けにくいからです

こんな意見がもっと発展すれば「SQLチューニングはやりふれている技術なのに、内部的な技術は高級技術である」のような歪曲された見解まで行けます。でも真実はぜんぜんそうではありません。

  • SQLチューニングのために身に付けるべきの知識と技法がずっと多くて複雑で難しいです。
  • ORA-4031エラーを解決するに必要な知識は不慣れかもしれませんが絶対に難しくはないです。

それじゃなぜORA-4031エラーの解決がSQLチューニングよりずっと難しいのことだと認識されているものですか。それはエンジニアの実力の問題ではなくて「データ」の問題です。

  • SQLチューニングのために収集可能なデータは多様で正確です。特に10046トレースはほとんど万能だといえます。特定のクエリのParseからFetchまで全過程を追跡できます。こんなデータを持ってもチューニングができないといえばその時こそエンジニアの実力を疑わなければなりません。
  • 反面、ORA-4031エラーの解決に必要なデータの収集はとても制約的です。せいぜいSGA Heap Dumpを修行するのです。SGA Heap Dumpは1)その負荷で収集しにくいし、2)ダンプを実行する現在の時点のスナップショットに過ぎません。3)すなわち、段階別のトレース情報はないから推理しにくいです。4)コールスタック情報も役に立ちますがやっぱり現在時点の情報に過ぎません。

すなわちSQLチューニングのために必要なデータはあふれるほど十分ですけど、ORA-4031エラーをために必要なデータはあまりに足りないです。データが不足だから判断しにくいし従って解決も難しいこととなってしまいます。


分析のために必要な十分なデータがない状態でエンジニアとしての実力を論じるのは僥倖に頼るのに過ぎません。従って原因を探す前に解析に必要なデータを十分に収集するのを身に付ける必要があります。


僕もまた常に十分なデータを収集するに失敗して間違った解析をする場合が時々あります。自分の経験から出て来る自分だけの哲学だと思ってくださればいいです。


PS) 上のように言うといってORA-4031エラーが解決不可能な問題だという意味ではありません。適切なデータと多い経験、よい資料(例えばメタリンクのような)があったら多くの場合有意味な分析が可能です。

Thursday, September 10, 2009

インデックス生成とV$SESSION_LONGOPSビュー

こんなおもむきの質問を受けました。

インデックス生成が長い間(数分以上)修行中なのに、これをV$SESSION_LONGOPSビューを通じてモニタリングできるのか


これに対する返事はV$SESSION_LONGOPSビューに対するマニュアルである程度得られます。


多分6秒以上掛かるクェリならV$SESSION_LONGOPSビューを通じてモニタリング可能だと思われます。

       
UKJA@ukja1021> create table t2
2 as select level as c1, rpad('x',4000) as c2, rpad('x',4000) as c3
3 from dual
4 connect by level <= 1000
5 ;

Table created.

Elapsed: 00:00:01.17

-- インデックス生成時間をわざと遅延させるための関数(6秒以上)
UKJA@ukja1021> create or replace function fdelay(p1 number, p2 number)
2 return number
3 deterministic
4 is
5 begin
6 dbms_lock.sleep(p2);
7 return 1;
8 end;
9 /

Function created.

Elapsed: 00:00:00.00

セッション#1でインデックスを作る途中でセッション#2でV$SESSION_LONGOPSビューをモニタリングしてみます。

UKJA@ukja1021> -- session #1
UKJA@ukja1021> create index t2_n1 on t2(fdelay(c1,1)+c1);

結果は失望的です。6秒ではなく6分が経ってもV$SESSION_LONGOPSビューには現れません。

UKJA@ukja1021> exec print_table('select * from v$session_longops where sid = 141');

PL/SQL procedure successfully completed.

問題は何でしょうか。マニュアルで説明していないいくつかの制限があるからです。例えばこんな制限たちがあります。

  • フルテーブルスキャンの場合テーブルブロック数が10,000個以上の場合にだけモニタリングされます。
  • インデックスファストフルスキャンの場合にはインデックスブロック数が1,000個以上の場合にだけモニタリングされます。
  • ハッシュジョインはモニタリングされますけどネステッドループジョインはモニタリングされません。
  • 同じ理由でインデックスレンジスキャン等はモニタリングされません。

(細かい情報はここを参照してください)


テーブルのブルック数を20,000個まで大きくしてみましょう。


UKJA@ukja1021> -- increase the data over 10,000 block
UKJA@ukja1021> insert into t2
2 select level as c1, rpad('x',4000) as c2, rpad('x',4000) as c3
3 from dual
4 connect by level <= 20000
5 ;

20000 rows created.

Elapsed: 00:00:56.23

そして同一にモニタリングしてみれば次のようにV$SESSION_LONGOPSビューに現れます。

UKJA@ukja1021> -- session #1
UKJA@ukja1021> create index t2_n1 on t2(fdelay(c1,1)+c1);



UKJA@ukja1021> exec print_table('select * from v$session_longops where sid = 141');
SID : 141
SERIAL# : 593
OPNAME : Table Scan
TARGET : UKJA.T2
TARGET_DESC :
SOFAR : 17
TOTALWORK : 42276
UNITS : Blocks
START_TIME : 2009/09/11 09:48:48
LAST_UPDATE_TIME : 2009/09/11 09:48:57
TIMESTAMP :
TIME_REMAINING : 22372
ELAPSED_SECONDS : 9
CONTEXT : 0
MESSAGE : Table Scan: UKJA.T2: 17 out of 42276 Blocks
done
USERNAME : UKJA
SQL_ADDRESS : 2FBD3900
SQL_HASH_VALUE : 3367173127
SQL_ID : 2d01s2z4b5z07
QCSID : 0
-----------------

UKJA@ukja1021> exec print_table('select * from v$session_longops where sid = 141');

SID : 141
SERIAL# : 593
OPNAME : Table Scan
TARGET : UKJA.T2
TARGET_DESC :
SOFAR : 61
TOTALWORK : 42276
UNITS : Blocks
START_TIME : 2009/09/11 09:48:48
LAST_UPDATE_TIME : 2009/09/11 09:49:18
TIMESTAMP :
TIME_REMAINING : 20761
ELAPSED_SECONDS : 30
CONTEXT : 0
MESSAGE : Table Scan: UKJA.T2: 61 out of 42276 Blocks
done
USERNAME : UKJA
SQL_ADDRESS : 2FBD3900
SQL_HASH_VALUE : 3367173127
SQL_ID : 2d01s2z4b5z07
QCSID : 0
-----------------

ここで注意すべきのはインデックスを生成する作業自体がモニタリングされるのではなくて、インデックスを生成するためにテーブルフルスキャンをする作業がモニタリング対象ということです。インデックスリビルド作業も同じ原理でモニタリングされます。


V$SESSION_LONGOPSビューは名前だけみれば本当に有用なように見えるが、実際に使おうとすればそんなこんな制約のためにため息つくようになる時が多いですね。

Wednesday, September 9, 2009

ORA-01792: maximum number of columns in a table or view is 1000

一顧客社で多すぎる数のコラムをフェッチする長い(しかし複雑じゃない)SQL文章を動的に生成する際こんなエラーに当たりました。

ORA-01792: maximum number of columns in a table or view is 1000

このエラーに遭うことは多くないんです。エラーの定義を見れば次のようです。

01792
"maximum number of columns in a table or view is 1000"
// *Cause: An attempt was made to create a table or view with more than 1000
// columns, or to add more columns to a table or view which pushes
// it over the maximum allowable limit of 1000. Note that unused
// columns in the table are counted toward the 1000 column limit.
// *Action: If the error is a result of a CREATE command, then reduce the
// number of columns in the command and resubmit. If the error is
// a result of an ALTER TABLE command, then there are two options:
// 1) If the table contained unused columns, remove them by executing
// ALTER TABLE DROP UNUSED COLUMNS before adding new columns;
// 2) Reduce the number of columns in the command and resubmit.

問題はどんなテーブルも1000個以上のコラムを持っていないということです。では、問題は何でしょうか。


エラーの定義をよく見ればテーブルだけでなくビューも1000個以上のコラムを持つことができないということが分かります。顧客社に問い合わせてSQL文をお願いしました。SQL文はこんなパタンでした。


select * from (
select b,
decode(a, 1, 1) as c1,
decode(a, 2, 2) as c2,
...
decode(a, 1000, 1000) as c1000
from t1
)


  • SQL文を動的に生成する過程で(多分不必要な)インラインビューを宣言しています。
  • インラインビューは絶妙に1000個をかすかに超える数のコラムを動的に宣言します。

簡単なテストを通じてこれを証明してみます。


次のようにインラインビュー内で1000個以上のコラムを動的に宣言する場合にはORA-01792エラーが発生します。


UKJA@ukja1021> declare
2 v_cursor sys_refcursor;
3 v_sql varchar2(32767);
4 begin
5 v_sql := 'select * from (select ';
6 for idx in 1 .. 1000 loop
7 v_sql := v_sql || rpad('1',10, '1') || ' as c'|| idx || ', ';
8 end loop;
9 v_sql := v_sql || '1 from dual)';
10
11 open v_cursor for v_sql;
12 close v_cursor;
13 end;
14 /
declare
*
ERROR at line 1:
ORA-01792: maximum number of columns in a table or view is 1000
ORA-06512: at line 11

しかしインラインビューを除いた場合には正常的に遂行されます。

Elapsed: 00:00:00.06
UKJA@ukja1021>
UKJA@ukja1021> declare
2 v_cursor sys_refcursor;
3 v_sql varchar2(32767);
4 begin
5 v_sql := 'select ';
6 for idx in 1 .. 1000 loop
7 v_sql := v_sql || rpad('1',10, '1') || ' as c'|| idx || ', ';
8 end loop;
9 v_sql := v_sql || '1 from dual';
10
11 open v_cursor for v_sql;
12 close v_cursor;
13 end;
14 /

PL/SQL procedure successfully completed.

一つの問題は1000個の制限を判断する段階がOptimizationの段階ではなくてParseの段階、すなわちSyntax確認段階ということです。従ってMERGEヒントなどを通じてインラインビューを無理に除いてみてもORA-01792エラーを避けることができません。


幸いにこの場合には不必要なインラインビューを除くのだけで簡単に解決できましたけど、そうではなかったらかなり頭の痛い問題となったかもしれません。

Monday, September 7, 2009

Oracle11gR2のデータウェアハウス新機能

題目はデータウェアハウスだとなっていますけど、Oracle11gR2の新機能が簡単明瞭によく説明されています。

関心ある方たちはきっと読んでみてください。


あまり多い機能が紹介されているので要略はむずかしいですけど、用心して使用してみるべきいくつかの機能たちが目にかかります。


  • In-Memory Parallel Execution: 並列実行のI/Oは本来はバッファキャッシュをバイパスします。でも11gR2からはOracleが多様なファクターを考慮してバッファキャッシュの使用するかしないかを決めます。RACでは適当なサイズのセグメントに対する並列実行は各ノードが適当な分量くらいバッファキャッシュに格納してパラレルに読み込むようになります。誤って使用すればむしろ性能低下が心配されます。この外にも並列実行に関連して多い新機能が追加されましたが、みんな厳密な検証が必要です。


  • Recursive WITH clause: 多くの場合にCONNECT BY句を代替するように見えます。どのような原理で再起的に使用できるかは研究の必要性があります。


  • LISTAGG関数: 行で存在する一連の値を一つのリストに縛ってあげる関数ができましたね。クェリはどんどん簡単になっています。しかし、やっぱりどんな原理で動作するのか、性能のわなはないのか確認が必要です。

Thursday, September 3, 2009

TKPROFレポート解析時時間に注意しよう。

SQL*Traceとその友達のTkprofはとても使用しやすいし、愛らしい友達ですけど、”時間”については時々混乱をあげています。よく接するようになるSQL*Traceの時間誤謬は次のようです。


  • 測定誤謬(Measurement Error): Oracleは0.01秒(1Centisecod)のTick単位で時間を計ります。従って多い測定誤謬が発生するしかありません。同じ実行時間0.0005秒とはいえTickにどのように掛かっているのかによって違いに計られます。
  • CPU待機時間: 通常待機時間といえば競合が発生してCPUを占有しないで待機する時間のことを言います。でも、CPU自体を獲得するため待機する時間もあります。この時間はOracleの測定の範囲自体を超える値です。同時使用者が多いシステムではこの値による誤謬がもっと大きくなります。
  • CURSOR#0時間: Oracleが内部的に実行する特定のクエリはCURSOR#0に表現されます。例えば、LOBデータをFetchする過程は父母Cursorとは別個でCURSOR#0という内部Cursorを使用するようになります。
  • まだOracleが計算しない待機時間: Oracleの内部に待機が発生する際、まだ待機イベントで記録されない場合もあります。こんな場合は当然に待機時間から抜けるようになります。
  • その他等々

次のテストは測定誤謬を見せてあげています。

create table t1
as
select level as c1, level as c2, level as c3, level as c4, level as c5
from dual
connect by level <= 1000;

select * from t1;

-- 1st実行
select *
from
t1

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

-- 2nd実行
select *
from
t1

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

-- 3rd実行
select *
from
t1

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


-- 4th実行
select *
from
t1

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

大分不正確に見えるのでしょう。


でも、こんな時間誤謬はOracleの誤りというよりはアーキテクチャー次元の問題に違いです。続けて補完していくはずですが、完全な測定は絶対に期待してはいけません。それで解析をする実力が重要だということです。

Wednesday, September 2, 2009

Oracle11gR2のPlan Diff機能

Oracle11gR2の出たという知らせにコミュニティーたちが熱くなっています。リリース2が出るによってOracle11gの時代が到来したと言えます。


OracleオプティマイザチームでOracle11gR2の新機能の一つのPlan Diffを紹介しています。


まだ11gR2をインストールしなかったので検証はできなかったけど、デモだけ見れば場合によって多分実用的なリポートを提供しないかという期待を持つようになります。


Diff,すなわちCase1とCase2の性能ファクターを比較するのは僕が一番愛用する性能分析技法の中一つです。


NAME VALUE1 VALUE2 DIFF
---------------------------------------- ------------ ------------ ------------
session logical reads 17,376,991 133,035 -17,243,956
db block gets from cache 15,764,933 102,971 -15,661,962
db block gets 15,764,933 102,971 -15,661,962
consistent changes 6,024,802 17,697 -6,007,105
db block changes 6,024,814 17,710 -6,007,104
consistent gets from cache 1,612,058 30,064 -1,581,994
consistent gets 1,612,058 30,064 -1,581,994
free buffer requested 1,432,143 49 -1,432,094
calls to get snapshot scn: kcmgss 480,030 40,019 -440,011
lob writes 120,008 10,004 -110,004
lob writes unaligned 119,962 10,004 -109,958
lob reads 60,001 10,001 -50,000
...

LATCH_NAME D_GETS D_MISSES D_SLEEPS D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
cache buffers chains -45091211 0 0 -1399062
object queue header operation -2864253 0 0 0
cache buffers lru chain -2864138 0 0 0
simulator hash latch -164417 0 0 0
simulator lru latch -112459 0 0 -51952
...



これ以外にもOracle10gはAWRに貯蔵された性能データを比較分析できる機能を提供しています。本当に強力な機能です。


Oracle11gR2早く使用してみたいですね。