パフォチューしながら、twitter でつぶやいていたら、
門外不出のOracle現場ワザ (DB Magazine SELECTION)
続・門外不出のOracle現場ワザ (DB SELECTION)
の著者で、日本オラクルのテクノロジーコンサルティング本部のあの五十嵐建平さんから
@yoheia 索引ヘブン
Kempei Igarashi on Twitter: "@yoheia 索引ヘブン"
というお言葉を頂いたので、このエントリのタイトルにした。
何があったかというと、他の環境では10分程度で終わるバッチ処理が5時間経っても終わらなくて、オブジェクトの定義を比較しても差異はないし、統計情報も収集している。AWR の Top 5 Timed Events のトップが "db file sequential read" で 95 %を超えていて、遅い SQL の Buffer Gets が 1,783,366 。1,783,366 × 8192 = 14609334272 = 約13GB。という状況。あほみたいにインデックス・スキャンしていて、インスタンス全体の待ちの 95% 以上がインデックス・スキャン待ちという異常な状態。原因はパーティション表のインデックスの統計情報が収集されていなかったためで、該当パーティション表の統計情報を収集して、共有プールをフラッシュしてバッチ処理を再実行すると10分程度で終わった。統計情報恐るべし。
CBO は賢いけど、間違った情報与えられたら判断間違う。カーナビが正しい交通情報与えられなかったら、ルート選択を間違うように。
ちょっと脱線。実行計画とは？自分のイメージを書いてみる。Perl などの LL をコンパイルしたバイナリがメモリ上にのっているイメージ。mod_perl みたいな。カーナビに似ている気がする。出発地点と目標地点を入力すると、初期設定(初期化パラメータ)や道路情報(オブジェクト定義)や交通情報(オプティマイザ統計情報)から最速ルートを導きだす。
あ、このエントリについては正確性や厳密さは意識せずに、自分の思うままに書いてます。
現象
- 他の環境では10分程度で終わるバッチ処理が5時間たっても終わらない。
- 他の環境と表や索引などのオブジェクトの定義を比較しても差異なし。
- 遅い SQL は select ... insert で Buffer Gets が 1,783,366。1,783,366 × 8192 = 14609334272 = 約13GB。
- AWR の Top 5 Timed Events のトップが "db file sequential read" で 95 %を超えている。
- AWR の Buffer Hit % が 37.86。
- ヒント句を記述していないのに実行計画を見ると、パラレルクエリーになっている。
- 初期化パラメータ PARALLEL_MAX_SERVERS を 0 に設定すると、シリアル化するが実行計画が他の環境と異なる。大きなパーティション表に TABLE ACCESS BY LOCAL INDEX ROWID でアクセスしてる。
原因
- パーティション表のインデックスの統計情報が最新になっていない(last_analyzed の日時が古い)。
対処
SQL> begin dbms_stats.gather_table_stats( ownname=> 'SCOTT, tabname=> 'EMP', cascade=> TRUE, granularity=> 'ALL', estimate_percent=> 3); end; /
- 共有プールをフラッシュする。
SQL> alter system flush shared_pool;
- バッチを再実行する。→ 10 分程度で終了。
参考
- パラレルヘブン AWR レポート
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 65.77 In-memory Sort %: 100.00
Library Hit %: 96.85 Soft Parse %: 97.52
Execute to Parse %: 43.42 Latch Hit %: 99.98
Parse CPU to Parse Elapsd %: 15.84 % Non-Parse CPU: 97.42
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.35 93.63
% SQL with executions>1: 58.74 72.06
% Memory for SQL w/exec>1: 84.21 86.28
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 1,787,024 14,377 8 97.9 User I/O
CPU time 245 1.7
db file scattered read 3,849 40 10 0.3 User I/O
control file parallel write 1,219 30 25 0.2 System I/O
log file parallel write 3,021 28 9 0.2 System I/O
-------------------------------------------------------------
- パラレルヘブン実行計画
Execution Plan ------------------------------------------------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Bytes | Cost ------------------------------------------------------------------------------------------------------------------------ | 0 | INSERT STATEMENT | | | | 22254 | 1 | SEQUENCE | *******_**_*****_*** | | | | 2 | VIEW | | 1 | 356 | 22254 | 3 | SORT GROUP BY | | 1 | 249 | 22254 | 4 | FILTER | | | | | 5 | PX COORDINATOR | | | | | 6 | PX SEND QC (RANDOM) | :TQ10005 | 50 | 12450 | 188 | 7 | HASH JOIN | | 50 | 12450 | 188 | 8 | HASH JOIN | | 50 | 11950 | 171 | 9 | HASH JOIN | | 50 | 11450 | 154 | 10 | HASH JOIN | | 50 | 11150 | 137 | 11 | TABLE ACCESS BY LOCAL INDEX ROWID | *******_**_*** | 42 | 2268 | 17
- 索引ヘブン時の AWR レポート
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 38.99 In-memory Sort %: 100.00
Library Hit %: 99.97 Soft Parse %: 99.96
Execute to Parse %: 44.74 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 58.06 % Non-Parse CPU: 99.38
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 93.06 93.05
% SQL with executions>1: 91.21 91.58
% Memory for SQL w/exec>1: 95.55 95.62
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read 832,131 3,517 4 99.2 User I/O
CPU time 58 1.6
control file parallel write 1,190 26 21 0.7 System I/O
log file parallel write 647 7 11 0.2 System I/O
log file sync 273 3 12 0.1 Commit
-------------------------------------------------------------
- 索引ヘブン実行計画
----------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop | ----------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | INSERT STATEMENT | | | | 23340 (100)| | | | | 1 | SEQUENCE | *******_**_******_*** | | | | | | | | 2 | VIEW | | 1 | 356 | 23340 (5)| 00:04:41 | | | | 3 | SORT GROUP BY | | 1 | 250 | 23340 (5)| 00:04:41 | | | |* 4 | FILTER | | | | | | | | |* 5 | HASH JOIN | | 50 | 12500 | 1256 (88)| 00:00:16 | | | | 6 | TABLE ACCESS FULL | **** | 159 | 1590 | 15 (0)| 00:00:01 | | | |* 7 | HASH JOIN | | 50 | 12000 | 1240 (89)| 00:00:15 | | | | 8 | TABLE ACCESS FULL | ****_*** | 159 | 1590 | 15 (0)| 00:00:01 | | | |* 9 | HASH JOIN | | 50 | 11500 | 1225 (90)| 00:00:15 | | | | 10 | TABLE ACCESS FULL | ******* | 6 | 36 | 15 (0)| 00:00:01 | | | |* 11 | HASH JOIN | | 50 | 11200 | 1209 (91)| 00:00:15 | | | | 12 | TABLE ACCESS FULL | *******_*** | 6 | 36 | 15 (0)| 00:00:01 | | | |* 13 | TABLE ACCESS BY LOCAL INDEX ROWID | *******_**_*** | 42 | 2268 | 1091 (100)| 00:00:14 | | |
- 正常な実行計画
---------------------------------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop | ---------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | INSERT STATEMENT | | | | 547K(100)| | | | | 1 | SEQUENCE | *******_**_******_*** | | | | | | | | 2 | VIEW | | 1 | 356 | 547K (2)| 01:49:28 | | | | 3 | SORT GROUP BY | | 1 | 241 | 547K (2)| 01:49:28 | | | |* 4 | FILTER | | | | | | | | |* 5 | HASH JOIN | | 55 | 13255 | 523K (2)| 01:44:38 | | | | 6 | TABLE ACCESS FULL | **** | 159 | 1590 | 15 (0)| 00:00:01 | | | |* 7 | HASH JOIN | | 55 | 12705 | 523K (2)| 01:44:38 | | | | 8 | TABLE ACCESS FULL | ****_*** | 159 | 1590 | 15 (0)| 00:00:01 | | | |* 9 | HASH JOIN | | 55 | 12155 | 523K (2)| 01:44:37 | | | | 10 | TABLE ACCESS FULL | ******* | 6 | 36 | 15 (0)| 00:00:01 | | | |* 11 | HASH JOIN | | 55 | 11825 | 523K (2)| 01:44:37 | | | | 12 | TABLE ACCESS FULL | *******_*** | 6 | 36 | 15 (0)| 00:00:01 | | |
ちょっと説明が足りないところがあるんだけど、面倒なので、後で書く。
