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

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/