外部のアプリケーション開発会社
システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
先日、接続障害問題（ ORA-3136 ）が発生した某WEBシステムのお客様から
たろーちゃんに、電話が掛かってきました。何かあったのでしょうか？
※このシステムについては以前の『接続障害』の回を参照して下さい。
お客様「たろーさん、先日はありがとう。」
たろー「お世話になっております。こちらこそ、ありがとうございました。」
お客様「あれからリソースを増強して性能テストを続けているんだけど、データベースのパフォーマンスが出ていないみたいなんだ。」
たろー「パフォーマンスがですか。状況を詳しく教えて頂けますでしょうか？」
お客様「アプリケーションの開発は別会社に依頼していてね。話は通しておくから、たろーさんから直接ヒアリングしてくれないかな。」
たろー「はい、分かりました。」
お客様から連絡先を教えてもらい、たろーちゃんはその会社に電話でヒアリングを行うことにしました。
たろー「もしもし、データベースを構築しました、たろーと申します。」
開発者「はい、どうも。」
たろー「お客様からデータベースのパフォーマンスが出ないとお聞きしまして、色々とお話をお伺いしたいのですが。」
開発者「WEBアプリケーションからSQLを発行すると、大体３～４秒掛かるんです。複雑なSQLではなく、単純なSELECT文です。」
たろー「SQLトレースを取得して、送って頂けますか？」
開発者「SQLトレースって何ですか？そんな作業は、うちの担当外です。おたくで取得して下さい。」
たろー「え？」
開発者「アプリケーションのログなら送りますよ。それを見ればSQL処理に時間がかかっているのが分かりますんで。」
そう言うと、一方的に電話を切られてしまいました。
感じの悪い対応に、たろーちゃんは少しカチンと来ました。
たろー「失礼な会社だなー。アプリケーションが悪いのかデータベースが悪いのか、調べてみないと分からないのに。」
メールで送られてきたアプリケーションのログには、発行したSQLとそれに掛かった時間が出力されていました。そのログを見る限り、確かに３～４秒掛かっています。
たろーちゃんは、お客様に連絡を取り、性能テストで実際に使用しているデータベースサーバを調査させてもらうことにしました。
実機確認
アプリケーションのログを頼りに、実際に発行されたであろうSQLをSQL*Plus で実行してみます。
経過: 00:00:00.01
実行計画
----------------------------------------------------------
Plan hash value: 1584460160
-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 4 | 1 (0)| 00:00:01 |
|* 1 | INDEX UNIQUE SCAN| SYS_C0030122 | 1 | 4 | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------------
たろー「0.01秒。全然早いな。性能テスト時、他にリソース競合はなかったのかな？」
たろーちゃんは、性能テストを行っていたときの vmstat 等のOSリソース状況を確認することにしました。その結果、 CPU を多く消費していることが分かりました。
AWR レポート
たろーちゃんは、性能テスト時の AWR レポートを確認することにしました。
◆ AWR レポート出力イメージ（画像は12.1のものです）
たろー「待機イベントは確かにDB CPU が一番上位に来ているけど、DB Time はそんなに大きくないぞ。『SQL ordered by CPU Time』セクションの上位に、アプリケーションのログにあった例のSQLが来ていて、Executions(実行回数)が凄く多いけど、CPU Timeはそれ程でもない。まぁ INDEX UNIQUE SCAN だから、そうだよな。」
AWR レポートを見る限り、 CPU を極端に消費しているSQLは見当たりませんでした。
『OSリソース状況では CPU が多く消費されているのに、 AWR レポート上では CPU をそれ程消費していない』という矛盾に、たろーちゃんは違和感を覚えました。
他のログには？
たろーちゃんは性能テストを行っていた時間帯に絞って、アラートログ等を確認していくことにしました。
たろー「アラートログを見ても、特におかしなメッセージは無いな。リスナーログも念のため確認しておくか。えーっ…と………！」
たろーちゃんは目を疑いました。
リスナーログのサイズが尋常ではない大きさになっています。
ログはローテーションするようにしているのですが、性能テスト時間帯のリスナーログだけが膨大なサイズになっているのです。
たろー「もしかして、これは・・・！」
血液検査
こうなると、たろーちゃんの伝家の宝刀『血液検査』の出番です。
たろーちゃんは該当時間帯の V$ACTIVE_SESSION_HISTORY の情報を調べることにしました。
※ V$ACTIVE_SESSION_HISTORY に関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ！』の回をご参照下さい。
たろー「・・・やっぱりだ。間違いない！」
伝家の宝刀『血液検査』が、今回も謎を切り裂きます！
投稿者プロフィール
