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が一緒に使用されれば問題がかなり複雑になるのが分かります。待機イベントを分析する時はいつも気をつけなければなりません。

No comments:

Post a Comment