少しは涼しくなり始めたものの、まだまだ残暑が続いていたある日、RACの全ノードでCPU高負荷が発生したとの連絡を受けました。
事象が発生したのは前日夕方でアプリにログインしにくい状況だったとの事ですが、連絡が入ったのが夜間だったので他のメンバーがDBが正常に稼働している事と、topの結果からCPUを消費しているのがサーバプロセスである事を確認。
その後、負荷が落ち着いたので翌日以降、詳細に原因を調査する運びとなりました。
数年前から稼働している本番環境で、構成は以下の通りです。
さっそくAWRレポートを確認します。
DB全体で見てもCPU時間がDB時間の43%を占めており、それ以外には特に問題になりそうな待機イベントはありませんが、CPU負荷についてはノード間で多少のバラつきが見られます。
I# | Num CPUs | CPU Cores | CPU Sckts | Load Begin | Load End | % Busy | % Usr | % Sys | % WIO | % Idl | Busy Time (s) | Idle Time (s) | Total Time (s) | Memory (M) | End CPUs | End Cores | End Sckts | End Memory (M) |
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
1 | 8 | 8 | 1 | 1.46 | 18.65 | 75.58 | 73.99 | 1.34 | 0.23 | 24.42 | 43,412.38 | 14,027.39 | 57,439.77 | 129,071.36 | ||||
2 | 8 | 8 | 1 | 2.51 | 7.61 | 78.16 | 76.77 | 1.18 | 0.02 | 21.84 | 44,881.89 | 12,544.77 | 57,426.66 | 129,071.36 | ||||
3 | 8 | 8 | 1 | 1.35 | 31.02 | 76.00 | 74.58 | 1.22 | 0.02 | 24.00 | 43,638.28 | 13,777.21 | 57,415.49 | 129,071.36 | ||||
4 | 8 | 8 | 1 | 1.54 | 7.28 | 75.33 | 73.94 | 1.18 | 0.02 | 24.67 | 43,255.96 | 14,169.42 | 57,425.38 | 129,071.36 | ||||
Sum | 175,188.51 | 54,518.79 | 229,707.30 |
CPU高負荷の調査なので、まずSQL ordered by CPU Time (Global)を確認します。
Total | Per Execution | Percentage of Total | |||||||||||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
CPU (s) | Elapsed (s) | IOWait (s) | Gets | Reads | Rows | Cluster (s) | Execs | CPU (s) | Elapsed (s) | IOWait (s) | Gets | Reads | Rows | Cluster (s) | DB CPU | DB time | IO Wait | Gets | Reads | Cluster | Execs |
50,822.48 | 311,591.46 | 16.27 | 8,787,357,189 | 56,801 | 51,577 | 992.18 | 2,508 | 20.26 | 124.24 | 0.01 | 3,503,730.94 | 22.65 | 20.56 | 0.40 | 30.87 | 24.69 | 0.10 | 27.46 | 0.01 | 3.62 | 0.07 |
13,108.61 | 75,606.98 | 1,845.87 | 2,476,663,681 | 39,870,544 | 53,863 | 14,065.82 | 35,192 | 0.37 | 2.15 | 0.05 | 70,375.76 | 1,132.94 | 1.53 | 0.40 | 7.96 | 5.99 | 11.37 | 7.74 | 10.28 | 51.25 | 0.97 |
12,418.45 | 68,952.72 | 9,293.93 | 681,534,779 | 258,993,663 | 4,855 | 636.30 | 1,372 | 9.05 | 50.26 | 6.77 | 496,745.47 | 188,770.89 | 3.54 | 0.46 | 7.54 | 5.46 | 57.23 | 2.13 | 66.79 | 2.32 | 0.04 |
4,177.91 | 11,135.52 | 34.42 | 1,966,367 | 7,099 | 351 | 0.20 | 354 | 11.80 | 31.46 | 0.10 | 5,554.71 | 20.05 | 0.99 | 0.00 | 2.54 | 0.88 | 0.21 | 0.01 | 0.00 | 0.00 | 0.01 |
4,079.67 | 10,488.53 | 36.03 | 2,192,617 | 16,711 | 361 | 4.91 | 365 | 11.18 | 28.74 | 0.10 | 6,007.17 | 45.78 | 0.99 | 0.01 | 2.48 | 0.83 | 0.22 | 0.01 | 0.00 | 0.02 | 0.01 |
4,065.50 | 10,367.52 | 34.49 | 1,984,332 | 7,109 | 351 | 0.74 | 356 | 11.42 | 29.12 | 0.10 | 5,573.97 | 19.97 | 0.99 | 0.00 | 2.47 | 0.82 | 0.21 | 0.01 | 0.00 | 0.00 | 0.01 |
上位3つのSQLのCPU使用時間が4位以下と桁違いなので、上位3つを調査対象とします。
Top SQL with Top Eventsを確認すると、調査対象の3SQLがCPU + Wait for CPUのイベントでリストアップされています。
Plan Hash | Executions | % Activity | Event | % Event | Top Row Source | % Row Source |
---|---|---|---|---|---|---|
2161638631 | 114 | 38.78 | CPU + Wait for CPU | 38.76 | MAT_VIEW ACCESS - FULL | 31.33 |
1102321024 | 7442 | 6.02 | CPU + Wait for CPU | 4.72 | TABLE ACCESS - FULL | 3.44 |
866674186 | 2608 | 5.40 | CPU + Wait for CPU | 4.25 | LOAD AS SELECT | 1.71 |
負荷が高くなった時間帯でAPサーバからのセッション数が4倍程度に増えているので、セッション数の増加に伴ってSQL実行数が増え、CPU高負荷となった可能性があります。
更なる調査には比較対象のAWRレポート、および3つの被疑SQLのSQLレポートが必要になるので、取得を依頼しました。
事象発生時のAWRレポートとSQLレポート、および比較対象として前日同時刻のAWRレポートとSQLレポートがあるのがベストでしたが、やり取りに時間がかかってしまい、保存期間を過ぎてしまったので、同日夜のレポートが送られてきました。
その時間帯は既に負荷が下がっており、なおかつ3つのSQLレポートは取得できていたので、これを比較対象として調査します。
その結果、分かったのは以下の通りです。
- CPU時間が上位2位と3位のSQLについては、実行計画と1実行あたりのCPU時間がほぼ同じで実行回数が大幅に増えているので、実行回数の増加がCPU負荷の増加につながったと考えられる。
- CPU時間最上位のSQLについては実行回数はほぼ同じだが、1実行あたりのCPU時間が約20倍となっている。
- CPU時間最上位のSQLについて、高負荷時と正常時では実行計画が異なる為、不適切な実行計画によって高負荷の原因となった可能性が高い。
実際に高負荷時と平常時の実行計画を比較すると、高負荷時にはあるマテリアライズド・ビューに対するMAT_VIEW ACCESS FULLが行われており、正常時はINDEX RANGE SCANとなっています。
実行計画上ではそのマテリアライズド・ビューに対するフルスキャンのコストが低く見積もられている(80byte)為、フルスキャンが選択されたと考えられますが、そのマテリアライズド・ビューに対する論理読み込みがトータルで24GB程度なので、統計情報が正しくなかった可能性があります。
そのマテリアライズド・ビューのデータ量が急激に増えていなかったか、AP側で確認してもらう事になりました。
そしてその確認結果ですが。
本来インデックスを作成してから実行する手順であったものを作成なしで実行したため、フルスキャンが実行されてしまったとのことでした・・・
・・・ええとつまり、インデックスを作成し忘れたという事ですか・・・?
このSQLは前の週に正常な速度でほぼ同数、実行されていたので、以前から動いていた事になります。
どういう運用になっているのか不明ですが、どうやら定期的にインデックスを再作成しており、問題発生時にはその手順が抜けてしまったようです。
と言うか、17時台に高負荷が発生し、その後収まって遅くとも23時台には平常になっていたので、アプリケーション・ベンダー側ではインデックスを作成し忘れた事にどこかの時点で気づいて作成していたという事ですよね?
人間なのだから誰しもミスはあると思いますが、黙っているのは宜しくないと思います。
CPU高負荷になってもサーバが持ちこたえてくれたのでログインが遅くなる程度で済みましたが、これでノードダウンが発生していたとしたら・・・
サーバさん、持ちこたえてくれて有難う(涙)