パフォーマンストラブルの検証 特別編
＜パフォーマンストラブルの検証 特別編＞
ペンネーム：東海道線上り電車
今週はりんが忙しいため、急遽代筆です。
現在連載中の”Oracle10g Cost Base Optimizerにまつわる検証”は今週休ま
せていただきます。では今週は最近あったパフォーマンストラブルの問題と
なぜそのようなことが起こったかを簡単に！
パフォーマンスの問題が発生した原因はV$表にあった。
とある会社からパフォーマンス悪化のチューニング依頼がありました。
処理としては売上系売上処理1件だと、3秒程度のレスポンス。売上処理同時20件
だと 1分程度のレスポンス売上処理同時 50件を超えると 10分以上のレスポンス
になってしまうといった状態のシステムです。
原因究明のため、調査開始。テスト環境でまずアプリケーションをチェック。
このようなケースだと多くが全件検索等により、リソース（テーブル）の競合
が発生しレスポンスが悪化するといった現象です。しかしながら、売上処理で
使用されている SQL 文を精査したところ一部チューニングできるところもあ
りますが、ほぼ SQL 文自体に問題はありません。
では何が原因で発生しているかのチェックが再度必要です。
そこで、レスポンスの劣化してるシステムの本番環境を検証します。
まずは WAIT EVENT のチェックからスタートです。
もろもろの WAIT EVENT をチェックしていきます。チェックしていく
中で、次のような非常におかしい数値を示しているものが見つかりました。
LATCH FREE の待ち時間が 1時間当たり 30,000秒？
ENQUE WAITS が 300回？
通常のシステムでこの数値はおかしい。アプリケーション的には LOCK WAIT
が発生するような SQL は一切ない。ということは想定外の SQL が実行されて
いるのか？
じゃー、再度システムの検証を実施、何を見ればよいのだろうか？とりあえず
どんな SQL どんなプロシージャーが実行されているのかを検証してみよう？？？
むむ・・・・
2,600,000 実行している TRIGGER がある
もっと調べると、1,000,000 以上実行している TRIGGER が山のようにでてき
た。アプリケーションだけ見ていては判らないはずだ。
売上でデータを挿入するたびに TRIGGER が動いている。これだ、更新してい
る SQL は一売上当たり5 SQL、実際の更新データ量は一売上当たり 200行、
1売上当たり 200回の TRIGGER が実行されている。この TRIGGER で実行され
ているプロシージャー・ファンクションは何だろう。
そう、この TRIGGER と同じだけ実行されているプロシージャー・ファンクシ
ョンをチェックすれば解決するはずだ。
さて、TRIGGER と同じだけ実行されているプロシージャーを発見。ソースを見
てみよう。ふむふむ、3 SQL 実行かどうもログを作成しているようだ。
2つの SELECT と 1つの INSERT、SQL の実行計画を取ってみよう。
SELECT は問題ない、INSERT も問題ないこのプロシージャーは単独で動かすと
非常にはやい。これではレスポンスへの悪化は起こらない。困った何が原因だ。
ん、Select XXXX from V$TRANSACTION ？？
何をしているんだ。アプリケーションの中から V$ 表に対してアクセスを行う
なんて。ログにトランザクション番号を書くために使用している。
ちょっと待て、V$TRANSACTION はパラレルで SELECT 出来ないんじゃないか？
ということはこの V$TRANSACTION への SELECT は全てシリアルで実行されて
いるということ？
つまり、1売上で 200行の更新 V$TRANSACTION への SELECT も 200回、同時に
50売上が実行されれば 200 * 50 = 10,000回の SELECT がシリアルで動くこと
になっている。どんどん売上処理が行われればそれだけシリアルで
V$TRANSACTION への SELECT がシリアルで実行される。
LATCH FREE の待ち時間が 1時間当たり 30,000秒？
ENQUE WAITS が 300回？
うーーーん、原因がわかった。プロシージャーから V$TRANSACTION へのSELECT
を中止。ログにはトランザクション番号は入れないでいこう。最終的にはなん
らかしらの番号は入れなければいけないが、今は売上入力できることが最重要
課題だ。
さてさて、どうなったかな。
LATCH FREE の待ち時間が 1時間当たり 2,000秒？
一気に減少した。実際のレスポンスは同時に売上処理を 50名が実行しても
5秒で帰ってくる。
チューニング完了！
チューニングはやっぱり難しい。今回は非常に勉強になった。ここ最近のパフ
ォーマンス劣化のシステムのほとんどが SQL に起因するトラブルだったため
SQL から見てしまっていた。パフォーマンス劣化の要因は多種多彩だとあら
ためて思い知らされた。
はーチューニングも無事完了。今日はきっとビールがうまいはずだ。