Indexがあれば、いいってもんじゃない。中身がたいせつ Tweet
さて、JPOUG Advent Calendar、２５番目の扉を開けます。
ネタは、そう、やはり、索引です。:)
以下のようなバッチ処理があったと思ってくださいな。
リリース直後、データが少ない状態で統計情報をロックしたまま数年が経過したバッチ処理、リリース当初は特に目立った遅延問題も発生せず安定していた（らしい）。
ところが、ところがです。
最近は、少しでも処理量が増加しようものなら１００％遅延するという状況となっていた。
関係者へのヒアリングから、どうやら、グルグル系のバッチであることが見えてきました。（またか！w)
AWRレポートから問題となるSQL文（グルグル回るところが一番怪しいんですけどね、大抵は）を特定しました。（以下参照）
Execution Plan
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 843 (100)| |
| 1 | SORT AGGREGATE | | 1 | 19 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| HOGE | 1 | 19 | 843 (1)| 00:00:11 |
| 3 | INDEX RANGE SCAN | HOGE_I01 | 1 | | 842 (1)| 00:00:11 |
-----------------------------------------------------------------------------------------
Full SQL Text
SQL ID SQL Text
------------ -----------------------------------------------------------------
43a7z10a4ckx SELECT COUNT(1) FROM HOGE WHERE
CATEGORY = :B4 AND CLASS = :B3 AND SUBCLASS = :B2 AND ID = :B5
AND SUBID = :B1 AND IS_DELETED = 0
実行計画だけを見ていると、Index Range Scan？、なにが問題なの？（キリっ という感じがしますが、
それに騙されてはいけいけないんです。
次のセクションを見てください。
（本来１０万回実行されるのですが終わらないので途中でキャンセルしましたw、約１時間で５０００回も回ってません。）
Plan 1(PHV: 468154321)
----------------------
Plan Statistics DB/Inst: DISCUS/discus Snaps: 129-130
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
Stat Name Statement Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms) 3,185,031 640.9 99.8
CPU Time (ms) 3,092,467 622.2 99.8
Executions 4,970 N/A N/A
Buffer Gets 7.7276E+07 15,548.5 99.9
Disk Reads 13,999 2.8 93.4
Parse Calls 1 0.0 0.0
Rows 4,969 1.0 N/A
User I/O Wait Time (ms) 92,540 N/A N/A
Cluster Wait Time (ms) 0 N/A N/A
Application Wait Time (ms) 0 N/A N/A
Concurrency Wait Time (ms) 0 N/A N/A
Invalidations 0 N/A N/A
Version Count 1 N/A N/A
Sharable Mem(KB) 22 N/A N/A
-------------------------------------------------------------
Index Range Scanで平均Rows=1の割にBuffer Getsが異常に多い、処理時間のほとんどがCPU処理時間。
これらがなにを意味するのか............
確認のためexplain planで取得した実行計画のPredicate Informationを見てみると..
Plan hash value: 468154321
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 19 | 795 (1)| 00:00:10 |
| 1 | SORT AGGREGATE | | 1 | 19 | | |
|* 2 | TABLE ACCESS BY INDEX ROWID| HOGE | 1 | 19 | 795 (1)| 00:00:10 |
|* 3 | INDEX RANGE SCAN | HOGE_I01 | 1 | | 794 (1)| 00:00:10 |
-----------------------------------------------------------------------------------------
PLAN_TABLE_OUTPUT
---------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("IS_DELETED"=0)
3 - access("CATEGORY"=TO_NUMBER(:V1) AND "CLASS"=TO_NUMBER(:V2) AND
"SUBCLASS"=TO_NUMBER(:V3) AND "ID"=TO_NUMBER(:V4) AND "SUBID"=TO_NUMBER(:V5))
filter("ID"=TO_NUMBER(:V4) AND "SUBID"=TO_NUMBER(:V5))
索引アクセス時にID列とSUBID列でフィルタ処理が行われています。:) この部分の比率が非常に大きい。
ようするに大量のデータを読み込み、フィルタ処理でそのほとんどを捨てている！！！
（もったいない、もったいないです。もったいないお化けが出てきそうです）
索引を見てみます。
INDEX_NAME COLUMN_NAME
------------------------------ --------------------
HOGE_I01 CATEGORY
HOGE_I01 CLASS
HOGE_I01 SUBCLASS
HOGE_I01 STATUS
HOGE_I01 ID
HOGE_I01 SUBID
索引の先頭３列（CATEGORY,CLASS,SUBCLASS）でデータ数をカウントしてみると、400,000行ありました...
４０万行から、たった１行を取り出すフィルタリングを１０万回繰り返している...グルグル系恐るべし（＠＠）
解決方法は....
索引の列順を入れ替えれば解決するはず！！！
status列はカーディナリティが非常に低い列であることは確認ずみであつたため最後尾に移動しました。
先頭５列(CATEGORY,CLASS,SUBCLASS,ID,SUBID）でほぼデータが絞りこめるようになるはずです。
（AWRレポートのRowsを見ると最終的には１行or０行となることが確認できます）
作り直した索引は以下のようになります。
STATUS列が最後になっているところがポイントです。違いはたったそれだけです。
（Index Only Accessではありませんよ、今回は。Index Only Accessでグルグルをギリギリまでチューニングしなくても十分な効果が得られたのでこれ以上なにもしません。）
INDEX_NAME COLUMN_NAME
------------------------------ --------------------
HOGE_I02 CATEGORY
HOGE_I02 CLASS
HOGE_I02 SUBCLASS
HOGE_I02 ID
HOGE_I02 SUBID
HOGE_I02 STATUS
索引を作り直した後はご覧の通り、じゃじゃ〜〜〜〜〜〜ん！
想定１７時間程度のダメバッチが３０分ほどで終了しました。ニッコリ。CPUにも随分優しくなってますね。
Plan 1(PHV: 2833120447)
-----------------------
Plan Statistics DB/Inst: DISCUS/discus Snaps: 131-132
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
Stat Name Statement Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms) 1,846,702 18.5 99.2
CPU Time (ms) 43,208 0.4 89.1
Executions 100,000 N/A N/A
Buffer Gets 3,971,771 39.7 99.1
Disk Reads 290,822 2.9 99.1
Parse Calls 1 0.0 0.0
Rows 100,000 1.0 N/A
User I/O Wait Time (ms) 1,830,618 N/A N/A
Cluster Wait Time (ms) 0 N/A N/A
Application Wait Time (ms) 0 N/A N/A
Concurrency Wait Time (ms) 0 N/A N/A
Invalidations 0 N/A N/A
Version Count 1 N/A N/A
Sharable Mem(KB) 22 N/A N/A
-------------------------------------------------------------
Execution Plan
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 5 (100)| |
| 1 | SORT AGGREGATE | | 1 | 19 | | |
| 2 | TABLE ACCESS BY INDEX ROWID| HOGE | 1 | 19 | 5 (0)| 00:00:01 |
| 3 | INDEX RANGE SCAN | HOGE_I02 | 1 | | 4 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
Full SQL Text
SQL ID SQL Text
------------ -----------------------------------------------------------------
43a7z10a4ckx SELECT COUNT(1) FROM HOGE WHERE CATEGORY = :B4 AND CLASS = :B3 AN
D SUBCLASS = :B2 AND ID = :B5 AND SUBID = :B1 AND IS_DELETED = 0
念のためexplain plan でも確認してみます。ご覧の通りフィルタリングはis_deleted列のみでindex range scan時のフィルタリングは全く発生していません。
もったいないお化けを退治できましたv
Plan hash value: 2833120447
-----------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 19 | 5 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 19 | | |
|* 2 | TABLE ACCESS BY INDEX ROWID| HOGE | 1 | 19 | 5 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | HOGE_I02 | 1 | | 4 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------
PLAN_TABLE_OUTPUT
---------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("IS_DELETED"=0)
3 - access("CATEGORY"=TO_NUMBER(:B4) AND "CLASS"=TO_NUMBER(:B3) AND
"SUBCLASS"=TO_NUMBER(:B2) AND "ID"=TO_NUMBER(:B5) AND "SUBID"=TO_NUMBER(:B1))
複合索引の列順って、ほんとうに大切ですよね :)
NOTE:
今回のような遅延ケースでは索引を適切に再構成するほかに、ヒントでIndex skip scanを強制する方法もありますが、索引を適切な列の並びに再構成する方法と比べ劣るのも事実です。
大人の事情に金縛りに合うこともあるでしょうし.....。状況に合わせて使い分けるとよいと思います。
これで、JPOUG Advent Calendarの全ての小窓は開かれました。
メリークリスマス、そして、良いお年をお迎えください。
最後に、Pipelined Table Function で Christmas Tree ☆☆☆☆
| 固定リンク | 0
コメント