前回のおさらい
前回、『正体不明のパフォーマンス悪化の謎を解き明かせ！』では、アプリケーション開発者のAさんからの相談に対して、V$ACTIVE_SESSION_HISTORY による Oracle Databaseの「血液検査」で見事パフォーマンス問題を解決したというお話をしました。
どんな内容だったかなぁ？というかたは、上記リンクから改めて確認してくださいね。
監視オペレータからの連絡
システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
一日の業務を終え、帰り支度をしているたろーちゃんに、監視オペレータから電話が掛かってきました。
さて、何があったのでしょうか？
監視オペレータ「Oracle Database のサーバで、CPU使用率８５％以上の状態が１５分継続しています。ご確認をお願いします。」
ここのシステムでは、CPU使用率８５％以上の状態が１５分続くと、監視オペレータから連絡が来るようになっています。
さて、何が起こっているのでしょうか？
たろー「あれ？このサーバは、Aさんのシステムで使っている Oracle Database だな。
Aさん、まだ会社にいるかな？」
※Aさんのシステムについては以前の『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回を参照して下さい。
たろーちゃんは、まずOSリソース状況から、Oracle Database 関連のプロセスがCPUを消費しているのを確認しました。次に、AWRレポートを使用して、負荷の高いSQLを発見しました。今まで見たことのないSQLだったので、たろーちゃんはAさんに確認することにしました。
Aさん「なんだい、たろーちゃん。何かあった？」
たろー「さっき監視オペレータからデータベースのCPU使用率が高いって連絡があったんだ。AWRレポートを調べてみると、このSQLがCPUに負荷を掛けてることが分かったんだけど、見たことのないSQLでさ。Aさん何か知ってる？」
Aさん「これは・・・。今朝リリースした機能のSQLだな。」
たろー「今朝？」
Aさん「うん。前にも話したけど、このWEBシステムは夜２２時がアクセスのピークで、朝４時が一番アクセスが少ないんだ。だから、リリース作業を今日の朝４時に行ったんだよ。」
たろー「だから見たことのないSQLだったのか。」
Aさん「夜になって徐々にアクセスが増えてきたから、今になってCPU監視に引っ掛かったんだな。」
たろー「なるほど・・・。ちょっと実行計画を見てみるか。」
経過: 00:00:03.38 実行計画 ---------------------------------------------------------- Plan hash value: 2621382011 ----------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 95 | 59 (2)| 00:00:01 | | 1 | SORT AGGREGATE | | 1 | 95 | | | | 2 | VIEW | VW_DAG_1 | 1 | 95 | 59 (2)| 00:00:01 | | 3 | HASH GROUP BY | | 1 | 21 | 59 (2)| 00:00:01 | | 4 | VIEW | VM_NWVW_0 | 1 | 21 | 59 (2)| 00:00:01 | | 5 | HASH GROUP BY | | 1 | 257 | 59 (2)| 00:00:01 | | 6 | NESTED LOOPS | | | | | | | 7 | NESTED LOOPS | | 1 | 257 | 58 (0)| 00:00:01 | | 8 | NESTED LOOPS | | 1 | 201 | 56 (0)| 00:00:01 | | 9 | NESTED LOOPS | | 1 | 164 | 54 (0)| 00:00:01 | |* 10 | TABLE ACCESS FULL | PARA8 | 1 | 26 | 3 (0)| 00:00:01 | |* 11 | TABLE ACCESS FULL | KEKKA | 1 | 138 | 51 (0)| 00:00:01 | |* 12 | TABLE ACCESS BY INDEX ROWID| KIHON | 1 | 37 | 2 (0)| 00:00:01 | |* 13 | INDEX RANGE SCAN | KIHON_KEY | 1 | | 1 (0)| 00:00:01 | |* 14 | INDEX RANGE SCAN | PARA8_KEY | 1 | | 1 (0)| 00:00:01 | |* 15 | TABLE ACCESS BY INDEX ROWID | PARA5 | 1 | 56 | 2 (0)| 00:00:01 | ----------------------------------------------------------------------------------------------------- 統計 ---------------------------------------------------------- 3080 recursive calls 0 db block gets 9097 consistent gets 0 physical reads 0 redo size 721 bytes sent via SQL*Net to client 524 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
たろー「１実行あたり 3.38 秒か。WEBシステムにしては長い時間だな。physical reads(ディスクから読み込んだブロック数) が０だから全てバッファキャッシュにヒットしてるんだろうけど、その分、CPUパワーが必要になる。『塵も積もれば山となる』で、アクセスが増加してきて今の状態になったんだな。」
Aさん「むむむ・・・。どうしたらいいかな？」
たろー「ぱっと見て、気になるのは NESTED LOOPS 結合 で TABLE ACCESS FULL が発生している箇所だ。」
＜再掲＞
-----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 95 | 59 (2)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 95 | | |
| 2 | VIEW | VW_DAG_1 | 1 | 95 | 59 (2)| 00:00:01 |
| 3 | HASH GROUP BY | | 1 | 21 | 59 (2)| 00:00:01 |
| 4 | VIEW | VM_NWVW_0 | 1 | 21 | 59 (2)| 00:00:01 |
| 5 | HASH GROUP BY | | 1 | 257 | 59 (2)| 00:00:01 |
| 6 | NESTED LOOPS | | | | | |
| 7 | NESTED LOOPS | | 1 | 257 | 58 (0)| 00:00:01 |
| 8 | NESTED LOOPS | | 1 | 201 | 56 (0)| 00:00:01 |
| 9 | NESTED LOOPS | | 1 | 164 | 54 (0)| 00:00:01 |
|* 10 | TABLE ACCESS FULL | PARA8 | 1 | 26 | 3 (0)| 00:00:01 |
|* 11 | TABLE ACCESS FULL | KEKKA | 1 | 138 | 51 (0)| 00:00:01 |
|* 12 | TABLE ACCESS BY INDEX ROWID| KIHON | 1 | 37 | 2 (0)| 00:00:01 |
|* 13 | INDEX RANGE SCAN | KIHON_KEY | 1 | | 1 (0)| 00:00:01 |
|* 14 | INDEX RANGE SCAN | PARA_KEY | 1 | | 1 (0)| 00:00:01 |
|* 15 | TABLE ACCESS BY INDEX ROWID | PARA5 | 1 | 56 | 2 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------
たろー「テーブルの結合順序を変更して、HASH結合 にしたらどうだろうか？ ヒント句 を埋め込んで、と。」
経過: 00:00:00.06 実行計画 ---------------------------------------------------------- Plan hash value: 1287118567 ----------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ----------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 95 | 60 (4)| 00:00:01 | | 1 | SORT AGGREGATE | | 1 | 95 | | | | 2 | VIEW | VW_DAG_1 | 1 | 95 | 60 (4)| 00:00:01 | | 3 | HASH GROUP BY | | 1 | 21 | 60 (4)| 00:00:01 | | 4 | VIEW | VM_NWVW_0 | 1 | 21 | 60 (4)| 00:00:01 | | 5 | HASH GROUP BY | | 1 | 257 | 60 (4)| 00:00:01 | | 6 | NESTED LOOPS | | | | | | | 7 | NESTED LOOPS | | 1 | 257 | 59 (2)| 00:00:01 | | 8 | NESTED LOOPS | | 1 | 220 | 57 (2)| 00:00:01 | |* 9 | HASH JOIN | | 1 | 194 | 55 (2)| 00:00:01 | |* 10 | TABLE ACCESS FULL | PARA5 | 1 | 56 | 3 (0)| 00:00:01 | |* 11 | TABLE ACCESS FULL | KEKKA | 1006 | 135K| 51 (0)| 00:00:01 | |* 12 | TABLE ACCESS BY INDEX ROWID| PARA8 | 1 | 26 | 2 (0)| 00:00:01 | |* 13 | INDEX RANGE SCAN | PARA8_KEY | 1 | | 1 (0)| 00:00:01 | |* 14 | INDEX RANGE SCAN | SKIHON_KEY | 1 | | 1 (0)| 00:00:01 | |* 15 | TABLE ACCESS BY INDEX ROWID | KIHON | 1 | 37 | 2 (0)| 00:00:01 | ----------------------------------------------------------------------------------------------------- 統計 ---------------------------------------------------------- 260 recursive calls 0 db block gets 294 consistent gets 0 physical reads 0 redo size 721 bytes sent via SQL*Net to client 523 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed
たろー「ほら！ 3.38 秒から0.06 秒になったよ。recursive calls も3080から260に減ったし、consistent gets も9097から 294 に減ったから、CPU負荷も減る筈だよ。」
Aさん「すごいな、たろーちゃん。」
たろー「とりあえず、アプリケーションから発行しているSQLに、このヒント句を埋め込んでよ。」
Aさん「・・・。」
たろー「どうしたの？」
Aさん「・・・すぐにアプリケーションの修正が出来ないんだ。」
たろー「え？！」
Aさん「ソースコードは社内の別サーバで厳重にバージョン管理されていて、俺にはそのソースコードに対するアクセス権限が無いんだ。アクセスできる人は、今日は早朝作業だったからもう帰っちゃったよ。」
たろー「なんだって？！」
Aさん「しかも、このアプリケーションは Java で作られていてさ。コンパイルされて生成された classファイルを反映するには、アプリケーションサーバの再起動も必要なんだ。アプリケーションサーバを再起動出来る人も帰っちゃった…。」
たろー（うわぁ………。）
たろー「このままじゃ、アクセスピークの２２時が来たら、データベースは負荷に耐えられないよ。」
Aさん「どうしよう……。」
今回はここまで。
アクセスピークの２２時まで、時間がない！
このままでは心臓に負荷が掛かりすぎて、心停止（＝システムの死亡）が発生してしまう！
このピンチをどう切り抜けるのか？！
投稿者プロフィール
