« VirtualBox 4.1.2 released! 月1ペースか。:) | トップページ | 悩ませ過ぎは及ばざるがごとし #2 »

2011年8月23日 (火)

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

あるクエリを実行していて、目標時間は3秒程度のオンライン処理向けクエリ、初回だけ異常に遅いんですけど……。 と再び、大人の事情に縛られて心が痣だらけ(どんなだ)な人達からお呼びがかかりました。

こんな感じの表(索引は似たようなのが数多くありそれもイケてないといえばイケテてないが)を自己結合しているだけ(イケてるクエリとか、イケてないクエリだというのは置いといて)で実行計画もそんなに悪くないし、実行統計を見る限り
初回とそれ以降で大きく乖離しているようにも見えません。

表は次のように定義されています。

SCOTT> desc test
名前 NULL? 型
----------------------------------------- -------- ----------------------------
ID NOT NULL NUMBER(10)
SURRO_ID NOT NULL NUMBER(10)
SURRO_ACD NOT NULL CHAR(2)
SURRO_BCD NOT NULL CHAR(1)
SURRO_CCD NOT NULL CHAR(3)
SURRO_DCD NOT NULL CHAR(5)
NAME NOT NULL VARCHAR2(100)
DESCRIPTION VARCHAR2(300)
CREATED NOT NULL TIMESTAMP(6)
MODIFIED NOT NULL TIMESTAMP(6)

索引は以下のようになってます。

INDEX_NAME                     COLUMN_NAME
------------------------------ ------------------------------
IX01_TEST SURRO_ID
SURRO_ACD

IX02_TEST SURRO_ID
SURRO_BCD

IX03_TEST SURRO_ID
SURRO_CCD

IX04_TEST SURRO_ID
SURRO_DCD

PK_TEST ID

なんだか、どれも似たような索引がならんでいます。

INDEX_NAME                     INDEX_TYPE                    NUM_ROWS DISTINCT_KEYS CLUSTERING_FACTOR
------------------------------ --------------------------- ---------- ------------- -----------------
IX04_TEST NORMAL 700000 700000 7653
IX03_TEST NORMAL 700000 700000 7653
IX02_TEST NORMAL 700000 700000 7653
IX01_TEST NORMAL 700000 700000 7653
PK_TEST NORMAL 700000 700000 7653





どーーーーーーーしてでしょう。

このつづきは次回のお楽しみ。

一緒に考えてみてくらちい ;)


1回目の処理行数、処理時間、実行計画及び実行統計。


・・・中略・・・

5999行が選択されました。

経過: 00:00:48.83

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



2回目の処理行数、処理時間、実行計画及び実行統計。

1回目とくらべて随分処理時間が短いです。。。。

・・・中略・・・

5999行が選択されました。

経過: 00:00:00.08

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

・・・中略・・・

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


3回目の処理行数、処理時間、実行計画及び実行統計。

3回目も2回目と同じようです。1回目だけなぜか異常に遅い。ちなみに、Oracle11g R2 11.2.0.1.0 for Linux x86_64です。


・・・中略・・・

5999行が選択されました。

経過: 00:00:00.08

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

・・・中略・・・


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

|

トラックバック

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

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

コメント

コメントを書く