悩ませ過ぎは及ばざるがごとし #2 Tweet

「一緒に考えてみてくらちい」タイポじゃないだすw GANTZ見てたんでつい。:)

ということで前回のつづきです。

１回目だけ異常に処理時間を要するクエリがあると相談を受けたという前振り覚えてますか？

実行計画
----------------------------------------------------------
Plan hash value: 1865103575

--------------------------------------------------------------------------------------------
| Id  | Operation                      | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |           |  5999 |   351K|  5718   (1)| 00:01:09 |
|*  1 |  HASH JOIN                     |           |  5999 |   351K|  5718   (1)| 00:01:09 |
|   2 |   INLIST ITERATOR              |           |       |       |            |          |
|*  3 |    INDEX RANGE SCAN            | IX01_TEST |  5999 | 59990 |  1935   (1)| 00:00:24 |
|*  4 |   HASH JOIN                    |           |  5999 |   292K|  3782   (1)| 00:00:46 |
|   5 |    VIEW                        |           |  5999 | 95984 |  1858   (1)| 00:00:23 |
|   6 |     HASH UNIQUE                |           |  5999 | 53991 |  1858   (1)| 00:00:23 |
|   7 |      INLIST ITERATOR           |           |       |       |            |          |
|*  8 |       INDEX RANGE SCAN         | IX02_TEST |  5999 | 53991 |  1857   (1)| 00:00:23 |
|   9 |    INLIST ITERATOR             |           |       |       |            |          |
|  10 |     TABLE ACCESS BY INDEX ROWID| TEST      |  5999 |   199K|  1923   (1)| 00:00:24 |
|* 11 |      INDEX RANGE SCAN          | IX02_TEST |  5999 |       |  1857   (1)| 00:00:23 |
--------------------------------------------------------------------------------------------

・・・中略・・・

統計
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       1897  consistent gets
          0  physical reads
          0  redo size
     247808  bytes sent via SQL*Net to client
      69769  bytes received via SQL*Net from client
        401  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       5999  rows processed

１回目とそれ以降で実行計画の差異はありません。実行統計上はrecursive callが1から0になっている程度の変化しかありません。

ですが……………………

１回目は、４８．８３秒なのに、２回目以降は、０．０８秒…

１回目の処理時間　(SQL*Plusのset timiing on　及び、set autot trace exp statにて計測）

5999行が選択されました。

経過: 00:00:48.83

２回目以降〜

5999行が選択されました。

経過: 00:00:00.08

実行統計を見ると、consistent gets 1897もそれほど多くないのに１回目だけ処理時間が長い、その差はどこに……

SQL文がどのような順序で処理されるのか、よーーーーーく思い出してください；）

リンク先にあるオラクルのマニュアルの図をざっくりまとめちゃうと以下のような感じ（BINDや、FETCHフェーズが書かれている図もよく見かけますね）

となっています。

この辺りも一緒に読むといいですよね。わかりやすいです。無料だし:)
・門外不出のOracle現場ワザ - 第4章　Oracleデータベースの頭脳 「オプティマイザ」徹底研究
・SQL文の処理におけるオプティマイザの役割
・Part2　CBOは何を見てどう判断するのか

これまでに確認できた状況証拠

• １回目だけ処理時間が異常に長い。
• 実行統計（consistent getsなど）から実行時のアクセスブロック数の差異はない。かつ、ブロック数も少ない。
• 物理読み込みは処理時間には影響していない。

これらの状況証拠とSQL文の処理フェーズから導きだせますよね。どこに処理時間を要しているか…………

ほーら、ほら。見えてきました…………………よね？　（ヒントだしてますから〜〜:)

ということで、今日はここまで、次回へつづく。

---

ここまでのあらずじ

・悩ませ過ぎは及ばざるがごとし #1