前回のおさらい
前回「SQL簡易パフォーマンス診断」では、情報が全くないなげっぱなしジャーマンからの無茶苦茶な依頼に対して、インスタンス起動時からのSQLカーソルに関する基本的なパフォーマンス統計情報を参照することができる「V$SQLSTATS」を用いて解決したというお話をしました。
どんな内容だったかなぁ？というかたは、上記リンクから改めて確認してくださいね。
アプリケーション開発者からの相談
システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
そんなたろーちゃんのところに、アプリケーション開発者のAさんが訪ねてきました。
Aさんは、たろーちゃんの同期社員です。
さて、何があったのでしょうか？
Aさん「たろーちゃん、ちょっと時間ある？」
たろー「うん、どうしたの？」
Aさん「既にカットオーバーして動いているWEBシステムがあるんだけど、一部のエンドユーザ様から『ページが表示されるのが遅いときがある』ってクレームが来てるんだよ。」
たろー「ありゃ」
Aさん「ただ、何が原因なのかサッパリ分からなくて・・・。」
たろー「アプリケーションのログから何か分からないの？」
Aさん「そ、それが・・・あまり大きな声じゃ言えないんだけど、詳細なログを出力するような作りになっていなくてさ・・・。アプリケーションに問題があるのか？データベースに問題があるのか？サッパリ分からないんだよ。」
たろー「原因が何なのか突き止めないといけないね。」
Aさん「どうしたらいいかな？」
たろー「まずアプリケーションのログに、どこで時間が掛かっているか？ハッキリと分かるよう処理時間を出力するような修正を加えてみては？」
Aさん「いやー、それって、プログラムに手を入れるってことだよね？もうカットオーバーされちゃってるし、予算もないし、プログラムを修正できる人もいないんだよねー。」
たろー「………。」
「原因が分からないけどシステムが遅い」という漠然とした相談を受けるDBAの方もいらっしゃるのではないでしょうか？
しかも今回は、原因切り分けのためのログ出力のアプリケーション修正すら出来ないというケース。
さて「心臓外科医」のたろーちゃんは、このあと、どうするのでしょうか？
WEBシステムの特徴
たろー「WEBシステムってことは原則、２４時間３６５日動いてるシステムなんだよね？」
Aさん「うん、そうだよ。」
たろー「とりあえずデータベースを調べてみるから、遅かった時間帯を教えてくれる？」
Aさん「いや、それがマチマチなんだよ。」
たろー「？」
Aさん「このWEBシステムは、夜の２２時頃がアクセスのピークで、朝方４時頃が一番アクセスが少ないんだ。」
たろー「うん。それで？」
Aさん「でも遅いと言われているのは時間帯に関係なく、夜の２２時頃でも朝方４時頃でも起きているみたいなんだ。」
たろー「なんだって？」
Aさん「もう、わけがわからないよ。」
たろー「とりあえずOSチームに依頼して、全時間帯の各サーバーのリソース状況を調べてもらおう。」
時間帯を絞るため、たろーちゃんはOSチームと連携を取り、WEBサーバ、アプリケーションサーバ、データベースサーバ、ストレージサーバのCPU使用率やメモリ使用量の確認を行うことにしました。
リソースに問題？
OSチームから連携された資料を、たろーちゃんとAさんは共に確認していきます。
たろー「１日を通して、どのサーバも山谷はあるけど、頭打ちはしてないな。」
Aさん「うん。ピークの２２時にどのサーバもCPUが多く使われているけど、１００％使い切ってるわけじゃない。メモリにも余裕があるよ。」
たろー「アクセスの少ない朝４時なんか、CPUスカスカだね。」
Aさん「もしかしてネットワークトラフィックの問題かな？」
たろー「それも考慮して、ネットワークチームにも調査を依頼してきたよ。でも回線は輻輳（混雑）していなかった。」
Aさん「どうしてこれで、『遅い』って現象が発生するんだ？？」
たろー「…うーむ。」
Aさん「特定のページが遅いっていうなら分かるんだけど、色んなページで『遅い』って言われてるんだよねー。」
たろー「え？特定のページだけじゃないの？」
Aさん「うん。検索画面だとかトップ画面だとか、来てるクレームはマチマチなんだ。」
たろー「ということは、発行されてるSQLも・・・。」
Aさん「当然、別々。」
分からないことだらけ。
この時点で、前回ご紹介したV$SQLSTATSを確認しても突出して遅いSQLは見当たりませんでした。
さて、どうする？
とにかくできるところから
このOracle Database は 11gR2 Enterprise Editionのシングルインスタンス構成であり、幸いにも有償オプションの Oracle Diagnostics Pack が購入されていました。
そのためAWR（Oracle Database 10gより提供された新機能です。 8iから提供されているStatspackツールが取得していたデータに加え、稼働統計やワークロード情報のスナップショットなどOracle Database 10gの実際の使用履歴そのものを自動的に取得し、リポジトリに格納しています。）が使えるので、たろーちゃんは２４時間分のAWRレポートの確認を始めることに・・・。
◆AWRレポート出力イメージ（※画像は 12c のものです。）
Aさん「このHTMLは何だい？」
たろー「これはAWRレポートと言って、データベースのパフォーマンス状況を分析できるんだよ。」
Aさん「そんな便利な物があるのか。」
たろー「これを見れば大抵のことは分かるんだ。けれども・・・。」
Aさん「けれども？」
たろー「今回はAWRレポートを見ても、これといっておかしな点が見つからないんだ。
例えば、この『SQL ordered by Elapsed Time』ってセクションが時間がかかっているSQLの一覧なんだけど、突出したものがない。」
Aさん「どれどれ・・・。あー、このSQLは検索画面だな。で、次はトップ画面のSQLだ。」
たろー「これらのSQLを見て、何か思い当たることはないかな？」
Aさん「うーん・・・試しに今、SQL*Plus で実行してみるか。」
Aさん（カタカタカタ）
Aさん「いや、問題ない。すぐに結果が返ってくる。遅くないよ。」
たろー「そうか・・・。（SET AUTOTRACE TRACEONLY で実行統計を取ってみたけど、キャッシュにヒットしている訳ではなさそうだ。それでも十分早い。）」
AWRでも歯が立たない謎。
あまりの謎の多さに、半ば諦めムードが漂い始めていた。。。
たろー「ちょっと缶コーヒー買ってくる。」
Aさん「ああ、俺がおごるよ。」
休憩室のソファーに腰を掛けて窓の外の景色を眺め、自販機で買った缶コーヒーを飲み、頭を空っぽにして考える。
脳内で the mysterious mallets の BGM （とある謎解きドラマの挿入歌）が流れ始めてきた・・・。
たろー（２４時間３６５日動いてるWEBシステム・・・。）
たろー（時間帯もマチマチなレスポンス悪化・・・。）
たろー（発生するページもマチマチ・・・。）
たろー（キャッシュにヒットしている訳でもないのに、十分早いレスポンス・・・。）
たろー（デフォルト６０分で取得されているAWRスナップショット・・・。）
たろー（・・・・・・！！)
Aさん「どした？」
今回はここまで。
この不可解な謎は、俺が必ず解いてみせる！
ジッチャンの名にかけて！！
あ、あれ。。。？なんだかテイスト変わってきてないですか？！たろーちゃん！
マーケティングチームが焦りだしています。（著作権調査とかキャラクター設定とか色々）
次回予告
原因究明！
お楽しみに。
投稿者プロフィール
