二つの表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/
Posts
No comments:
Post a Comment