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