本番リリースして1年ほどの環境で、F/Oが発生したので原因を調べて欲しいとの連絡がありました。
環境は以下の通りです。
![オラクルマスター教科書 Gold DBA Oracle Database Administration2【電子書籍】[ 株式会社コーソル企画＆マーケティング部 ]](https://thumbnail.image.rakuten.co.jp/@0_mall/rakutenkobo-ebooks/cabinet/5916/2000011195916.jpg?_ex=128x128 "オラクルマスター教科書 Gold DBA Oracle Database Administration2【電子書籍】[ 株式会社コーソル企画＆マーケティング部 ]")
この環境では自作シェルスクリプトでGIやDBの状態監視を行い、問題があれば一定のルールに従って待機系サーバにF/Oさせる事になっています。
今回、F/Oの直接原因となったのはevmの状態監視コマンドのタイムアウトでした。
なのでevmや他のGIのログを確認しましたが、GI側で問題が発生していたようなログは出ていませんでした。
また、こういう時に大概あやしいのはOS高負荷なので、OS情報を確認します。
この環境ではAHF(Autonomous Health Framework)*1を導入しているので、ログを収集して送って貰います。
まずtopを確認した所、F/O発生時刻ころに load averageが100近くまで急騰しているのがわかりました。論理CPU7コアのサーバなので、とんでもない高負荷です。
この高負荷の結果、evmの状態監視コマンドのタイムアウトとなりF/Oにつながったのはまず間違いありません。
また、この時topの上位にはオラクルのサーバープロセスが記録されており、psやpidstatで見ても同じ結果でした。
さらに言えば、100近い load averageが記録された直前5分ほどの記録が抜けていました。
つまり、topやpsの記録もできないほど高負荷だったという事でしょう。
監視シェルスクリプトがF/O実行を決定した時にはまずDBインスタンスを停止し、停止が必要なすべてのプロセスを停止してからF/Oを行う仕組みになっているので、100近い load averageが記録された時には負荷が下がり始めていたと思われます。
その前の記録が抜けていた時間帯のload averageはもっと高かった事でしょう。
直接原因が分かったので、次になぜCPU高負荷になったか調べます。
オラクルのサーバープロセスが原因と思われるので、無駄とは知りつつAWRを送って貰いました。
…が、やはり負荷が高かったせいと、インスタンス停止してしまったせいで高負荷時のレポートは取れていませんでした。
なので次にASH(Active Session History)レポートと、ASHダンプを取って貰いました。
こちらは動的パフォーマンス・ビューのV$ACTIVE_SESSION_HISTORYに1秒ごとに記録され、10秒ごとのスナップショットがDBA_HIST_ACTIVE_SESS_HISTORYに記録されるので、AWRレポートよりは粒度が細かい為、今回のような状況でも役立つと期待できます。
ASHレポートとASHダンプの取得方法は以下のドキュメントの通りです。
Active Session History(ASH) 情報の取得方法(KROWN:127934) (ドキュメントID 1742219.1)
ASH レポートの取得方法(KROWN:137755) (ドキュメントID 1747326.1)
ASHレポートでは「Top SQL with Top Events」セクションで、「Evnet」が「CPU + Wait for CPU」となっているSQLを確認します。
問題の起きたサーバには8つのDBがあるのですが、その全てのDBで3つのSQLが共通してレポートされている事がわかりました。
次にASHダンプを検証環境のDBにインポートします。
元DBは8つありますが、今回はサーバ全体の高負荷が問題となっているので、8つのダンプファイルをまとめて一つのテーブルにインポートしました。
statusが「ON CPU」のセッションをサンプリング・タイムごとに集計すると、高負荷となった時間帯でコア数を超えるセッションが確認できました。
CPUコア数を超えるプロセスが同時にCPUを要求すればOSによってキューイングされる事になるので、load averageが上がり、高負荷となります。
先ほど、ASHレポートで確認した3つのSQLに絞って見てみると、これらは9時ちょうどに開始し、DB停止までずっと「ON CPU」だった事がわかりました。
また、それはpsで確認した結果とも一致します。（psでは発行したSQLまでは特定できませんが）
ここまで絞り込めれば、後は9時ちょうどに全DB同時に開始するバッチ処理が無いか、レポートされた3SQLがそれに該当していないか、APチームに確認してもらうだけです。
確認してもらった結果、問題の3SQLは月初処理で全DB同時に開始するバッチで動いていた事が判明した為、シリアル実行に切り替えるか、開始時刻をずらすか検討してくれる事で幕引きとなりました。
ちなみにですが、最近、Oracle社サポートに問い合わせを上げると、問い合わせ内容の如何にかかわらずTFAデータの取得を（自動的に）求められます。
TFAが導入されておらず、新規インストールもできない環境ではTFAを使用せずにアラートログやトレースファイルを取っても良いのですが、TFAで取得したファイルだとOracle側である程度自動で調査ができるらしいので、Oracle社としてはTFAで取ってくれと言ってくる訳ですね。
トレース収集以外にもOS負荷情報が自動で取れて今回のようなケースで非常に役立つので、初期構築時に導入しておくのがお勧めです。
*1:Trace File Analyzer (TFA) と ORAchk/EXAchk を含むツールで、トレースファイル収集に役立つ他、OSの負荷状況を定期的に監視している
