前回のおさらい

前回、『正体不明のパフォーマンス悪化の謎を解き明かせ！』では、アプリケーション開発者の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さん「どうしよう……。」

 

今回はここまで。
アクセスピークの２２時まで、時間がない！
このままでは心臓に負荷が掛かりすぎて、心停止（＝システムの死亡）が発生してしまう！
このピンチをどう切り抜けるのか？！