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％信じられないという私の意見に十分に共感するはずです。
Posts
