« 悩ませ過ぎは及ばざるがごとし #1 | トップページ | 悩ませ過ぎは及ばざるがごとし #3 »

2011年8月24日 (水)

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

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

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

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

実行計画
----------------------------------------------------------
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


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

ですが……………………

1回目は、48.83秒なのに、2回目以降は、0.08秒…

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


5999行が選択されました。

経過: 00:00:48.83

2回目以降〜


5999行が選択されました。

経過: 00:00:00.08

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


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

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


20110823_142232



となっています。


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

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

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

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

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


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




ここまでのあらずじ

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

|

トラックバック

この記事のトラックバックURL:
http://app.cocolog-nifty.com/t/trackback/106341/52548196

この記事へのトラックバック一覧です: 悩ませ過ぎは及ばざるがごとし #2:

コメント

コメントを書く