外部のアプリケーション開発会社

システムの「心臓」こと、Oracle Databaseに日々携わるたろーちゃん。
先日、接続障害問題( ORA-3136 )が発生した某WEBシステムのお客様から
たろーちゃんに、電話が掛かってきました。何かあったのでしょうか?
※このシステムについては以前の『接続障害』の回を参照して下さい。

お客様「たろーさん、先日はありがとう。」
たろー「お世話になっております。こちらこそ、ありがとうございました。」
お客様「あれからリソースを増強して性能テストを続けているんだけど、データベースのパフォーマンスが出ていないみたいなんだ。」
たろー「パフォーマンスがですか。状況を詳しく教えて頂けますでしょうか?」
お客様「アプリケーションの開発は別会社に依頼していてね。話は通しておくから、たろーさんから直接ヒアリングしてくれないかな。」
たろー「はい、分かりました。」

お客様

お客様から連絡先を教えてもらい、たろーちゃんはその会社に電話でヒアリングを行うことにしました。

たろー「もしもし、データベースを構築しました、たろーと申します。」
開発者「はい、どうも。」
たろー「お客様からデータベースのパフォーマンスが出ないとお聞きしまして、色々とお話をお伺いしたいのですが。」
開発者「WEBアプリケーションからSQLを発行すると、大体3~4秒掛かるんです。複雑なSQLではなく、単純なSELECT文です。」
たろー「SQLトレースを取得して、送って頂けますか?」
開発者「SQLトレースって何ですか?そんな作業は、うちの担当外です。おたくで取得して下さい。」
たろー「え?」
開発者「アプリケーションのログなら送りますよ。それを見ればSQL処理に時間がかかっているのが分かりますんで。」

開発者

そう言うと、一方的に電話を切られてしまいました。
感じの悪い対応に、たろーちゃんは少しカチンと来ました。

たろー「失礼な会社だなー。アプリケーションが悪いのかデータベースが悪いのか、調べてみないと分からないのに。」


メールで送られてきたアプリケーションのログには、発行したSQLとそれに掛かった時間が出力されていました。そのログを見る限り、確かに3~4秒掛かっています。
たろーちゃんは、お客様に連絡を取り、性能テストで実際に使用しているデータベースサーバを調査させてもらうことにしました。

実機確認

アプリケーションのログを頼りに、実際に発行されたであろう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 に関しては以前の記事『正体不明のパフォーマンス悪化の謎を解き明かせ!』の回をご参照下さい。

たろー「・・・やっぱりだ。間違いない!」


伝家の宝刀『血液検査』が、今回も謎を切り裂きます!

投稿者プロフィール

たろーちゃん
たろーちゃん
株式会社システムサポート インフラソリューション事業部に在籍するPlatinumホルダー。
Oracle Databaseのパフォーマンスチューニングを得意とする。
データベースは Oracle 以外興味がないという変わり者。
一番嫌いなエラーメッセージは CRS-02625。
連載「心臓外科医の術式」を執筆。