前回のおさらい

前回、「正体不明のパフォーマンス悪化の謎を解き明かせ！(1/2)」では、結局パフォーマンス悪化の原因がわからないまま、最後、何かたろーちゃんが閃いた？！というところで終わりました。
果たしてたろーちゃんは、パフォーマンス悪化を解消できるのでしょうか？

原因究明

たろー（カタカタカタ）
Aさん「どうしたんだよ、いきなり慌てて。」
たろー「やっぱりだ。ちょっとこれを見てよ。」
Aさん「どれどれ・・・ん？！これはどういうこと？！実行計画も全く一緒なのに！」

たろー「・・・。謎　は　、全　て　解　け　た　！」

 

 

キャラ設定が困る。。。by マーケティングチーム

この後、二人はストレージサーバ管理者のところに赴き、事情を説明。
ストレージの調査をしてもらうことにしました。

数日後、ストレージサーバ管理者から連絡があり、Oracle Databaseで利用しているストレージサーバのファームウェアが古く、バグが発見されたとのこと。
すぐにファームウェアのバージョンアップを行ったところ、事象は再現しなくなりました。

 

根本原因は分かりましたが、たろーちゃんは何を調べたのでしょうか？？

Oracle Databaseに用意されている動的パフォーマンスビュー(V$)

たろーちゃんが調べたのは
V$ACTIVE_SESSION_HISTORYという動的パフォーマンスビューでした。

これには、１秒おきにアクティブなデータベース・セッションのスナップショットが取得されています。

AWRスナップショットは６０分間隔で取得されていました。
AWRレポートは2つの時点の間の各種統計をレポートとして出力します。

しかし、瞬間的に発生する事象は分析しきれないといった弱点があります。

例えば今回のように、ある事象が短時間に起こったときです。
実際にはその間に性能トラブルが発生しているのですが、
AWRレポートは2つの時点の間（今回はデフォルトの６０分）の合計として捉えるため、その事象が、ある特定の時間に集中していることを見つけ出すことができないのです。

たろーちゃんのアプローチ

1. AWRレポートから『SQL ordered by Elapsed Time（経過時間が長いSQL）』及び『SQL ordered by User I/O Wait Time（サーバー・プロセスのI/O待機時間が長いSQL）』の上位に来ているSQLに狙いを定める。
2. そのSQLのSQL_IDを元に V$ACTIVE_SESSION_HISTORY を検索し、どれくらい処理に時間が掛かっているのか確認する。
3. その結果、すぐにレスポンスが返っているケースと、数十秒掛かっているケースがあることが分かった。
   その時の待機イベントが、『db file sequential read』であることも判明。
4. すぐにレスポンスが返っているケースと、数十秒掛かっているケースのSQLレポートを確認し、実行計画に差異が無いことを確認。
5. SQL*Plusで繰り返し再現テストを行い、すぐにレスポンスが返っているケースと、数十秒掛かっているケースの再現に成功。勿論、バッファキャッシュにヒットしておらず、どちらもディスクに読み取りに行っているのを SET AUTOTRACE TRACEONLY の実行統計、及びevent 10046 level 12のSQLトレースから確認。
6. 更にV$ACTIVE_SESSION_HISTORY を『db file sequential read』で見ていくと、他にもこの待機イベントで待機が発生しているSQLが散見された。

以上のことから
『シーケンシャルリードを行う時、ストレージに何かが起きている』
との仮説が成り立つ。

ストレージのシーケンシャルリードに原因があったため、特定のWEBページではなく、色んなページで性能トラブルが発生していたのも、これで説明がつきます。
しかも毎回遅い訳ではなく、早い時もあり（むしろ早い時のほうが多い）、AWRレポート上で突出することがなく、原因判明までかなりのステップを要しました。
前回ご説明したV$SQLSTATSにも早い時と遅い時の合算値が表示されていたため、表面化しませんでした。

私が Oracle Databaseの中で１番好きな動的パフォーマンスビューが、今回ご紹介したV$ACTIVE_SESSION_HISTORYです。

V$ACTIVE_SESSION_HISTORYとDBA_HIST_ACTIVE_SESS_HISTORY

V$ACTIVE_SESSION_HISTORYは1秒間に１回のサンプリング情報を参照することができますが、それはどこに格納されているのでしょうか？

答えはSGA内のASHバッファと呼ばれる領域に格納されています。
但しメモリ上なので、永続的に保持することは出来ません。

この情報は、MMONバックグラウンドプロセスが、AWRスナップショットを出力するタイミングでDBA_HIST_ACTIVE_SESS_HISTORY に書き出します。
但し、１秒間に１回のサンプリングデータではなく、１０秒間に１回のサンプリングデータにまとめられます。

V$ACTIVE_SESSION_HISTORY に残っていない過去のデータは、DBA_HIST_ACTIVE_SESS_HISTORY を参照するとよいでしょう。DBA_HIST_ACTIVE_SESS_HISTORYの保存期間はAWRスナップショットと同一です。

参考までに、V$ACTIVE_SESSION_HISTORY を使用したサンプルコードを掲載しておきます。

サンプルコード 
SET NEWPAGE 0
SET SPACE 0
SET PAGESIZE 0
SET LINESIZE 32767
SET ECHO OFF
SET FEEDBACK OFF
SET HEADING OFF
SET VERIFY OFF
SET TRIMSPOOL ON
SET TAB OFF

SELECT  TO_CHAR(HIS.SAMPLE_TIME, 'YYYY/MM/DD HH24:MI:SS')
       ,HIS.SQL_ID
       ,TXT.SQL_TEXT
       ,HIS.SESSION_STATE
       ,HIS.EVENT
       ,HIS.WAIT_TIME
       ,HIS.TIME_WAITED
       ,HIS.PROGRAM
       ,HIS.MODULE
       ,HIS.SESSION_ID
       ,HIS.SESSION_SERIAL#
  FROM V$ACTIVE_SESSION_HISTORY HIS
  LEFT JOIN V$SQLSTATS TXT ON (HIS.SQL_ID = TXT.SQL_ID)
 ORDER BY HIS.SAMPLE_TIME

※注意：V$ACTIVE_SESSION_HISTORYを使用するには、Enterprise Edition かつ Oracle Diagnostics Pack オプションが必要です。

今回の「心臓外科医の術式」いかがだったでしょうか？

V$ACTIVE_SESSION_HISTORYはSQL（データの流れ＝血液の状態）を詳細に記録していますので、
これを見ればシステムで何が起きているか全て解ると言っても過言ではありません。

これってまるで、「血液検査」みたいじゃないですか？
心臓は血管を通して、全ての臓器と繋がっています。

今回問題があったのはストレージサーバでしたが、「血液検査」をすることで、ストレージサーバの異変に気付くことが出来ました。

これが「データベースは心臓」だと、たろーちゃんが豪語する理由の１つなのです。

でも、アプリケーション内で『何に時間がかかっているか？』
しっかりログに出力するように設計してよ・・・（苦笑）
そうしたら、もっと早く原因を突き止められたのに。