SELECT文－Parse, Execute, Fetchどの段階？

大部分のSELECT文はFetch段階で多くの時間とI/Oを使うようになります。例として、次のTkprof結果を見てください。

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.03          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.15       0.26        172        161          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.17       0.29        172        161          0           1

とても一般的な結果でしょう。SQL文は次のようです。

select max(t1.c1), max(t2.c2) from t1, t2
where rownum <= 100000
order by t2.c2, t1.c1

今度は次の結果を見てください。いかがですか。なぜFetch段階じゃなくてParse段階で大部分の時間を使っていますか。

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1    300.10     353.29         90       7060          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4    300.10     353.29         90       7060          0           1

正答はハードパースです。ハードパースのために発生するOptimization過程はParse段階に属するのでTkprof結果でもParse段階に記録されます。SQL文は次のようです(500個のテーブルをジョインするように動的に生成されたSQL文です）。

select count(*) from T_HEAP_DUMP, T_ALERT_ANALYZE, T_MON_TEMP, T_MON_TIME_TEMP,
T_MON_LATCH_TEMP, T_MON_EVENT_TEMP, T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP,
CHAINED_ROWS, TT1, TT2, T1, T_SMALL, EXT_ORAUS, T_SMALL_WITH_SMALL_ROW,
T_TARGET2, T_ORAUS, T_TARGET1, T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG,
T_SMALL_LOB, T_BIG_LOB, T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP,
T_ALERT_ANALYZE, T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP,
T_MON_EVENT_TEMP, T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2,
T1, T_SMALL, EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP,  dual where 1 = 0

次はどうですか。なぜ今回はParse段階でもFetch段階でもなくてExecute段階で大部分の時間を使っていますか。

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1    322.45     368.33          3       6725          0           0
Fetch        2      0.00       0.01          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4    322.45     368.34          3       6725          0           1

正答はBind Peekingです。Bind Peekingが使われるとParse段階ではなくてExecute段階でOptimizationが行われます。従ってTkprof結果でもExecute段階に記録されます。

select count(*) from T_HEAP_DUMP, T_ALERT_ANALYZE, T_MON_TEMP, T_MON_TIME_TEMP,
T_MON_LATCH_TEMP, T_MON_EVENT_TEMP, T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP,
CHAINED_ROWS, TT1, TT2, T1, T_SMALL, EXT_ORAUS, T_SMALL_WITH_SMALL_ROW,
T_TARGET2, T_ORAUS, T_TARGET1, T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG,
T_SMALL_LOB, T_BIG_LOB, T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP,
T_ALERT_ANALYZE, T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP,
T_MON_EVENT_TEMP, T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2,
T1, T_SMALL, EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP, T_MON_MUTEX_TEMP, CHAINED_ROWS, TT1, TT2, T1, T_SMALL,
EXT_ORAUS, T_SMALL_WITH_SMALL_ROW, T_TARGET2, T_ORAUS, T_TARGET1,
T_SMALL_WITH_BIG_ROW, T_SMALL_WITH_LOB, T_NO_LOG, T_SMALL_LOB, T_BIG_LOB,
T_NOLOB, T3, T_LOB, T_NO_LOB, T_TARGET, T2, T_HEAP_DUMP, T_ALERT_ANALYZE,
T_MON_TEMP, T_MON_TIME_TEMP, T_MON_LATCH_TEMP, T_MON_EVENT_TEMP,
T_MON_ROWCACHE_TEMP,  dual where rownum = :b1

Tkprofの結果を解析する時はやっぱりいろいろなところに気にしなければならないと言う良い例の一つです。

TKPROFの結果解析の時注意すべき点 - CURSOR #0

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

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