NTTコムウェア株式会社 プロジェクト管理統括部　技術SE部門　DB技術グループ 坂下　徹

Oracleデータベースの性能対策の重要な機能、「Statspack」や「Oracle Enterprise Manager 10g Diagnostics Pack」(※オプションライセンス)の利用ポイントをお伝えします。使わないと"もったいない"機能です！(Diagnostics Packの有無による違いはここ)

第3回 ケーススタディ(Diagnostics Pack)

1 はじめに

前回、ある性能問題が起こっているケースをStatspackで分析しましたが、最終回となる今回は、同じ分析処理手順をDiagnostics Pack (Oracle Enterprise Manager) を使用した場合にどうなるかについて説明します。１回目の「まとめ」のなかで、StatspackとDiagnostics Packのそれぞれのメリット、デメリットを説明していますが、今回は実際の分析の流れから、その違いをより具体的にイメージしていただきたいと思います。Diagnostics PackとOracle Enterprise Managerを使用することで簡単かつ効率的な分析をすることができます。また、前回のStatspackの分析では性能問題の原因特定にまでいたりませんでしたが、今回はゴールを目指すこととしましょう。

インデックスに戻る

2 Diagnostics Packを用いた分析

StatspackとDiagnostics Packの違いをよりわかりやすくするため、今回Diagnostics Packを用いて分析する対象を、前回のStatspackで分析したものとまったく同じ期間とします。前回は説明していませんでしたが、Statspackのスナップショットと同じ時間、同じ回数だけAWRのスナップショットも取得していました（図3-1）。

図3-1 スナップショットタイミング

前回のおさらいのために、今回分析するシナリオについてもう一度説明します。

  • 複数のSQL文から構成されるアプリケーションを実行
  • そのアプリケーションの一部に性能問題を引き起こす原因をわざと埋め込んでいる
  • 分析対象はデータベース・サーバーのみ

また、使用した環境は以下の通りです（環境依存の問題はなく、あくまでも参考レベル）。

  • Oracle Database 10g Release 2 Enterprise Edition（10.2.0.3.0）
  • Linux（x86）
  • 2CPU（ハイパー・スレッディングを有効にしているため、OS上は4つに見える）
  • Memory 2G Byte
  • データベース・サイズ（全データファイルの合計サイズ）は約5G Byte

では、Diagnostics Packを用いて分析していきましょう。

インデックスに戻る

2.1 Oracle Enterprise Manager トップ・アクティビティ

まずは、Oracle Enterprise Managerのトップ・アクティビティを確認します（図3-2）。ブラウザからリンクをたどっていくだけの簡単な操作で、そのとき起こっている事象の概要を把握することができます（操作方法はこちらをご覧ください）。

グラフの分析対象時間帯（20:01～20:09）を確認すると、平均4前後のアクティブ・セッションしかないことがわかります。上位SQLの一覧を見ると、もっともランクの高いSQLは全体に対して6.31%のアクティビティを占めていることがわかります。また、それ以外のSQLは全て0.2%未満の影響しかないことがわかります。

図3-2 トップ・アクティビティ状況(拡大画像を表示)

念のため、No.1にランクされたSQL（SQL_ID：8zt0p6avg76yz）の内容を確認しましょう。SQL_IDをクリックすることで、SQLの詳細を表示することができます（図3-3）。

図3-3 SQL詳細情報(拡大画像を表示)

内容を確認すると、このSQLは前回のStatspackの分析でも見つかったSQLです。実行計画（プラン）を見ると、表をFull Scanしていることがわかります。前回の分析では、Full Scanすることは仕方ないSQLであるため索引を使用していないとの判断をしましたが、今回はどうでしょう。念のため、アドバイザを実行してその内容を確認しましょう。結果は次のとおりです（図3-4）。やはりチューニング案はないようです。

図3-4 SQL詳細情報(拡大画像を表示)

第2回目の記事では、負荷が高いSQLを特定するために、Oracle Enterprise Manager を利用せずStatspackから分析作業をおこないましたが、「Statspackレポートの作成」「Statspackレポートの分析（SQL Ordered セクションまで）」「SQLレポートの作成」「SQLレポートの分析」といったさまざまな作業を手動で実施する必要がありました。一方、今回のここまでの作業はOracle Enterprise Manager を利用した分析であり、マウスによるクリック以外手動で何かをおこなうといった作業がなく、Statspackの手動分析に比べ、非常に簡単な作業であることがおわかりいただけます。Oracle Enterprise Manager を利用していただくと、従来、チューニングになれば専門家が各種レポートを作成し、手動で分析をおこなっていたところ、Oracle Enterprise Manager を利用することにより、チューニングに慣れていない方でも簡単に作業を進められるようになり、分析作業効率の大幅な改善をおこなうことが可能になります。

ここまでの分析では状況がわかっただけで、原因の特定はまだおこなっていませんので、以降に示すアプローチで分析を続けます。

インデックスに戻る

2.2 ADDMレポート

次に、ADDMレポートを分析します。作成したADDMレポートはこちらです（レポート作成、参照方法はこちらをご覧ください。）。

今回のADDMレポートでは、4つアドバイスされています。そのアドバイス内容を要約すると次のとおりです。

FINDING 1: 100% impact (1871 seconds)
-------------------------------------
ホストCPUがボトルネックで、インスタンスがホストCPUの77%を消費しています。
CPUの待機により、全体の待機時間が長くなります。

FINDING 2: 14% impact (271 seconds)
-----------------------------------
ユーザーI/Oの長い待機時間の原因となった特定のデータベース・セグメントが見つかりました。

FINDING 3: 4.2% impact (78 seconds)
-----------------------------------
データベース処理に長時間かかるSQL文が見つかりました。

FINDING 4: 4% impact (76 seconds)
---------------------------------
SQL文のハード解析により、データベース処理時間がかなり消費されました。

前回のStatspack分析の考察で述べたおおよその内容がADDMレポートに記述されています。また、FINDING 2の欄の詳細内容をみてわかるとおり、「SCOTT.EMP1にアクセスが多い」とオブジェクトの特定まで自動でおこなってくれています。Statspackでは分析を人がおこなう必要があるため、ある程度Statspackを分析する人が必要でしたが、ここまでは、レポートを作成する操作方法さえわかっていればよいことになります。

（補足）ADDMの日本語レポート

今回のADDMレポートは英語で出力していますが、日本語のレポートも作成可能です。上記の4つの要約は、日本語レポートで出力した場合の各FINDING項目の内容を引用しています。SQL*PlusでADDMレポートを作成する場合、環境変数NLS_LANGの設定を変更することでレポートの言語も変更可能です。

しかし、残念ながら10g Release 2のバージョンのADDMレポートを日本語で出力すると、改行などのレイアウトが悪い、あるいは日本語の意味がやや難解になるなどの理由から、筆者は英語で出力することが多いです。たとえば、FINDING 4にある「ハード解析」はその名のとおりHard Parseのことなのですが、個人的にHard Parseという言葉に慣れていること、および世界共通で通じる言葉であるため誤解が生じないことなどの理由から、英語レポートのほうが使いやすいと思っています。

インデックスに戻る

2.3 AWRレポート

次に、AWRレポートを確認します。作成したAWRレポートはこちらです（レポート作成、参照方法はこちらをご覧ください。）。

今回は説明を省略しますが、ひととおりADDMの示している内容が正しいかどうかを確認しましょう。内容確認のポイントは前回のStatspackレポートと同じです。Load Profile、 SQL order、 Segmentの各セクションを確認すると、前回のStatspackレポートと同じような内容であることが確認できます。やはり、CPU Timeの大きいSQL文は見つかりません。

しかし、Statspackと明らかに内容が異なるセクションが見つかります。それは次の「SQL ordered by reads」です（図3-5）。

図3-5 SQL詳細情報(拡大画像を表示)

SQL Text欄の幅が小さいため、SQL文が途中で切れていますが、SQL IDのリンクをクリックすることで、SQL文の全体を確認することができます。以下の表3-1は、図3-5のSQL一覧を見やすくするためにまとめたものです。

表3-1 Complete List of SQL Text抜粋

SQL Id SQL Text
b7twbdp012nb select emp1no, ename from emp1 where emp1no = 15996
4xqb04qv3vtg7 select emp1no, ename from emp1 where emp1no = 15993
ahnqq4n2849u8 select emp1no, ename from emp1 where emp1no = 15990
7dtyn9bahqv8n select emp1no, ename from emp1 where emp1no = 15999
7d8q61r65cnhs select emp1no, ename from emp1 where emp1no = 15987
36mswpf5cfhuc select emp1no, ename from emp1 where emp1no = 15984
19wddcpnyw0bm select emp1no, ename from emp1 where emp1no = 19914
42m7brc22hpwk select emp1no, ename from emp1 where emp1no = 15989
ag1rxfdgkw116 select emp1no, ename from emp1 where emp1no = 15983
cdp18jk8u8mny select emp1no, ename from emp1 where emp1no = 15992

これらのSQLはStatspackでは見つからなかったものです。そして、特に注目すべき点は、where句で条件指定として指定されているemp1no列の比較対象がすべてリテラルを使用して、それぞれの数字が異なるだけである点です。つまり、これらのSQLは条件指定されている値は異なるものの、すべて同じタイプのSQL文であることがわかります。

（補足）Statspackレポートでは、なぜ見つからなかったのか
今回のAWRレポートで見つかるこれらのSQLは、前回のStatspackレポートの「SQL ordered by Reads」セクションでは表示されませんでした。正確に言うと「SQL ordered by Reads」セクションそのものがありませんでした。なぜでしょう。以下は、Statspackレポートに「SQL ordered by Reads」セクションが表示されたときのレポートの抜粋です。

  • SQL ordered by Reads DB/Inst: O102EE1/o102ee1 Snaps:1119-1120
  • -> End Disk Reads Threshold: 1000 Total Disk Reads:1,411
  • -> Captured SQL accounts for 210.0% of Total Disk Reads
  • -> SQL reported below exceeded 1.0% of Total Disk Reads　←★注目

一番下の欄に「SQL reported below exceeded 1.0% of Total Disk Reads」とあります。つまり、個々のSQLが全体のSQLに占める割合として1.0%に満たないものはこのセクションに表示されません。また、すべてのSQLが1.0%未満であれば、このセクションそのものがレポートに表示されないことになります。しかし、AWRレポートの各「SQL ordered」セクションにはこの記述がありません。よって、今回Statspackよりも多くのSQLを見つけることができたわけです。

では、そのSQLの内容詳細を調べるため、AWR SQLレポートを確認しましょう。ここでは、SQL Idが「b7twbdp012nbw」のAWR SQLレポートを作成します。作成したAWR SQLレポートはこちらです。

Execution Plan欄からEMP1表をFull Scanしていること、およびPlan Statistics欄からElapsed TimeとCPU Timeがほぼ同じであることがわかります。つまり、表のFull Scanをしてはいるけれど、I/Oネックではないことがわかります（図3-6）。

図3-6 SQL詳細情報

（補足）Plan Hash Valueについて

レポートにあるPlan Hash Valueは実行計画ごとに付与された値です。つまり、同じ実行計画であれば同じPlan Hash Valueが付与されます。今回は、SQL Idが「b7twbdp012nbw」のもののAWR SQLレポートですが、表3-1のほかのSQLのAWR SQLレポートを作成すると、特別な理由（*）がない限り、同じPlan Hash Valueとなります。

(*) 今回のSQLの例では、たとえばリテラルの値の違いによって使用する索引が異なる場合があれば。

さて、このSQLはなぜ表をFull Scanしているのでしょうか。EMP1表の索引を確認しましょう。

SQL> SELECT table_name, index_name, column_name, column_position
  2  FROM user_ind_columns
  3  WHERE table_name = 'EMP1'
  4  ORDER BY table_name, index_name, column_position;

TABLE_NAME INDEX_NAME      COLUMN_NAME COLUMN_POSITION
---------- --------------- ----------- ---------------
EMP1       IND_EMP1_DEPTNO DEPTNO                    1

どうやらemp1no列に対する索引がないようです。念のため、emp1no列のカーディナリティも確認しましょう。

SQL> -- 件数確認
SQL> select count(*) from emp1;

  COUNT(*)
----------
    250000

SQL> 
SQL> -- 件数確認（emp1no列単位で）
SQL> select emp1no, count(*) from emp1
  2  group by emp1no
  3  order by count(*) desc, emp1no;

    EMP1NO   COUNT(*)
---------- ----------
         1          1
         2          1
         3          1
         4          1
         5          1
         6          1
         7          1


         8          1
         9          1
        10          1
（中略）
    249998          1
    249999          1
    250000          1

250000行が選択されました。

各レコードのemp1no列の値は、その表の中で一意の値をとっていることがわかります。つまり、この列に索引が作成されていれば表のFull Scanを避けることができ、先ほどのSQLは効率のいい処理になっていたことになります。表3-1のSQLはすべて同じタイプのSQLであるため、これらもこの索引があれば高速な処理になるはずです。今回のCPUネックである原因が、この索引がないことによる疑いが高まってきました。

インデックスに戻る

2.4 ASHレポート

対象期間の全体の統計を表していたAWRレポートの視点とは異なり、セッション単位の視点から統計を表しているのがAWRレポートです。それぞれ異なった視点で性能統計情報をとらえているので、AWRレポートではわからない事象が見つかることがありますのでこちらも確認しましょう。作成したASHレポートはこちらです。（レポート作成、参照方法はこちらをご覧ください。）

今回のASHレポートでも、性能問題を引き起こしている原因のSQLを特定するための重要なヒントを見つけることができます。先ほどはAWRレポートのSQL ordered byセクションから類似のSQLを目視で見つけ出しましたが、ASHレポートではこの分析結果を記述しているセクションがあります。Top SQL using literalsセクションでは、リテラルを使用しているために、Plan Hash Valueが同じなのに異なるSQLとして認識されているSQLを抽出してくれます（図3-7）。

図3-7 ASHレポート Top SQL using literals(拡大画像を表示)

インデックスに戻る

2.5 AWRビュー

さて、これまでの分析で「索引を使用していない非効率なSelect文があり、索引を作成することでこのSelect文のCPU時間が削減される」ことはわかりました。しかし、先ほどのAWR SQLレポートのCPU Time欄をみてもわかるとおり、個々のSelect文のCPU Timeは70ms前後とごくわずかな時間でしかありません。また、見つかった効率の悪いSQL文も、AWRレポートのSQL orderedセクションの十数個でしかありません。これでは、これらのSelect文を改善しても全体にあたえる影響が小さいため、そもそも索引を作成しても効果があまりないとも考えられます。しかし、AWRレポートのSQL orderedセクションは上位にランクされたSQL文の一覧であり、それ以下のSQL文は表示されていません。そこで、AWRレポートでは見つかっていないEMP1表をFull ScanしているSQLがほかにないかどうかを確認してみましょう。ここでAWRビューが役に立ちます（AWRビューの詳細はこちらをご覧ください）。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.sql_id,
  4    sqls.plan_hash_value,
  5    to_char(sqlt.sql_text) sql_text
  6  FROM dba_hist_sqlstat sqls,                -- それぞれのSQL統計情報
  7    dba_hist_sqltext sqlt                    -- SQL文本体
  8  WHERE sqls.sql_id = sqlt.sql_id
  9   AND sqls.snap_id = 7479           -- AWR Snap ID（AWRレポートのEnd Snap欄から）
 10   AND sqlt.sql_text like '%select emp1no,ename from emp1 where emp1no%'
 11   ORDER BY to_char(sqlt.sql_text)   -- CLOB型をSortするためにto_charを使用
 12   ;

SNAP_ID SQL_ID        PLAN_HASH_VALUE SQL_TEXT
------- ------------- --------------- ----------------------------------------------------
   7479 9vdc94p5b0qy5      2226897347 select emp1no,ename from emp1 where emp1no =  15415
   7479 8zbcvzf1zr6rk      2226897347 select emp1no,ename from emp1 where emp1no =  15416
   7479 4urb98c9fm9pv      2226897347 select emp1no,ename from emp1 where emp1no =  15418
   7479 ggu5radjs43tb      2226897347 select emp1no,ename from emp1 where emp1no =  15419
   7479 8z8n58c3g9v7p      2226897347 select emp1no,ename from emp1 where emp1no =  15420
（中略）
   7479 gu3r9k50ym0t0      2226897347 select emp1no,ename from emp1 where emp1no =  19995
   7479 47hc01srh89us      2226897347 select emp1no,ename from emp1 where emp1no =  19996
   7479 7af4b7rxt375t      2226897347 select emp1no,ename from emp1 where emp1no =  19997
   7479 f8cw5xcmx9t7f      2226897347 select emp1no,ename from emp1 where emp1no =  19998
   7479 661tydhfhz5dg      2226897347 select emp1no,ename from emp1 where emp1no =  19999

1076行が選択されました。

AWRレポートでは10程度のSelect文でしたが、同じタイプのSelect文が1076個も見つかりました。SQL文をみると、やはり検索条件のリテラル値が異なるため、Oracleからみるとすべて異なるSQL文ということになります。しかし、Plan Hash Valueがすべて同じ（2226897347）ということは、実行計画もすべて同じであり、Select文の処理内容としてはすべて同じだということがわかります。

次に、これらのSelect文が全体のCPU Timeに対してどれぐらいの影響を与えているのかを確認しましょう。次のSQL文は同じPlan Hash ValueごとにSQLをグループ化し、それぞれのCPU Timeの合計値を求める例です。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.plan_hash_value,
  4    sum(sqls.cpu_time_delta)
  5  FROM dba_hist_sqlstat sqls,
  6    dba_hist_sqltext sqlt
  7  WHERE sqls.sql_id = sqlt.sql_id
  8   AND sqls.snap_id = 7479
  9   GROUP BY sqls.snap_id, sqls.plan_hash_value
 10   ORDER BY sum(sqls.cpu_time_delta) desc
 11   ;

   SNAP_ID PLAN_HASH_VALUE SUM(SQLS.CPU_TIME_DELTA)
---------- --------------- ------------------------
      7479      2226897347                 67683422
      7479      1396384608                 56715018
      7479               0                 10152213
      7479      2294000873                  3895490
      7479       903671040                  3455418
      7479      2129037341                  2152354
      7479      1678141231                  2080399
      7479      3098115615                  1003961
      7479      1716221123                   895512
      7479       477378112                   513225
      7479      3608337542                   384118
（中略）
      7479      2519196099                      531
      7479      3091659676                      493
      7479      1884964958                      343
      7479      2957467528                      278
      7479      3183103679                      179

238行が選択されました。

Plan Hash Valueが2226897347は、先ほどのSelect文のものです。つまり、これらのSelect文は個々のCPU Timeは小さいけれど、それぞれを合計したCPU Timeは全体に対してもっとも大きな割合を占めていることが確認できました。しかも、今回のSelect文は索引を作成するだけで改善できるという、対策そのものも難しいものではありません。もちろん、索引を作成することによるほかのSQL文への影響を考慮する必要があるにしても、作成を検討する価値はあると判断してよいでしょう。

ちなみに2番目のSQLは、図3-3ですでに見つけている対策効果が低いと判断したSQLです（以下参照）。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.sql_id,
  4    sqls.plan_hash_value,
  5    to_char(sqlt.sql_text) sql_text
  6  FROM dba_hist_sqlstat sqls,
  7    dba_hist_sqltext sqlt
  8  WHERE sqls.sql_id = sqlt.sql_id
  9   AND sqls.snap_id = 7479
 10   AND sqls.plan_hash_value = 1396384608  -- Plan Hash Valueをキーに検索
 11   ORDER BY to_char(sqlt.sql_text)
 12   ;

SNAP_ID SQL_ID        PLAN_HASH_VALUE SQL_TEXT
------- ------------- --------------- -----------------------------------------------------
   7479 8zt0p6avg76yz      1396384608 SELECT COUNT(ename) FROM emp3 WHERE emp3no = 1

今回、AWRビューを使用することで、AWRレポートでは見つからなかったSelect文と、それらの全体に対する影響度を確認することができました。

1回目の「4.4 Automatic Workload Repository(AWR)ビュー」で説明したとおり、AWRビューは、AWRレポートやADDMレポートとは違う観点で分析することができるため、このようにより詳しく確認したい場合に便利です。今回紹介した以外にもAWRビューにはたくさんの種類があるため、高度な技術者にとっては、ほかにも使用方法を探すという楽しみ（？）もあります。StatspackレポートやAWRレポートでは推測の域までしか分析できなかったものを、より確信に近づけてくれるのがAWRビューであると思っています。

インデックスに戻る

3 このシナリオのまとめ

3.1 考察と対策案

さて、分析結果をまとめましょう。ポイントを整理すると次のようになります。

  • EMP1表へのアクセスが大量にある。
  • そのEMP1表へのアクセスの多くは索引を使用せずにSelectしている。
  • それらのSelect文は索引を作成するだけで改善するものである。
  • 検索条件のリテラル値が異なるため、個々のSQL文は違うものと判断されていた。結果として、AWRレポートのSQL ordered by CPU Timeなどで上位にランクされず、原因の特定が難しかった。

そこで、EMP1表のemp1no列に対して索引を作成することにしました。

インデックスに戻る

3.2 対策実施と効果確認

それでは対策の効果を見ていきましょう。索引を作成し、まったく同じアプリケーションを実行しました。まずはOracle Enterprise Manager のトップ・アクティビティの結果を確認します（図3-8）。アプリケーションの実行時間は索引作成前の約8分に対して、索引作成後は約3分と改善されました。また、グラフのCPU Timeの面積がとても小さくなっていることがわかります。

図3-8 トップ・アクティビティの比較(拡大画像を表示)

（補足）瞬間的な事象の確認

余談となりますが、図3-8のトップ・アクティビティのグラフの8:15前後を見ると、一時的にCPUが高くなっているのがわかります。これは、今回の性能改善の対策として実施した「索引作成」処理と「統計情報取り直し」処理です。StatspackやAWRのレポートでは、瞬間的な事象をとらえにくいと前に説明しましたが、トップ・アクティビティ画面ではこのような小さな事象までとらえることができます。もちろん、ASHレポートやV$ACTIVE_SESSION_HISTORYビューを確認すると、より詳細な内容を確認することが可能です。

CPU使用率は次のようになりました（図3-9）。やはりCPU使用率が100%になっている時間が短くなり、大きく改善していることがわかります。

図3-9 CPU使用率の比較

索引作成前と作成後のAWR期間比較レポートも確認してみましょう。作成したAWR期間比較レポートはこちらです。Top 5 Eventを確認すると、CPU timeが1/10以下になっていることがわかります（図3-10）。

図3-10 AWR期間比較レポートTop 5 Timed Events(拡大画像を表示)

また、問題となっていたEMP1表への大量のアクセスは、Logical、 Physical共に95%以上も改善していることがわかります（図3-11）。

図3-11 AWR期間比較レポート Top 5 Segments Comparison (Logical/Physical Reads)

最後に、参考までに索引作成後のAWRレポートをご確認ください。今回、索引の作成だけでもかなり改善されましたが、さらにチューニングしたい場合はHard Parseをターゲットとすべきでしょう。Time Model Statisticsセクションを確認すると、Hard Parseで46.60%を占めていることがわかります（図3-12）。これまでの分析ですでに見つかっていますが、リテラルを使用した多数のSelect文に対し、バインド変数を使用するように修正するといった対策が考えられます。

図3-12 AWRレポートTime Model Statistics

インデックスに戻る

3.3 たねあかし

今回のシナリオで実行していた処理の内容は以下のとおりです。

次のSQLを約２万回実行（CPU使用率を高めていた原因となったSQL）

select emp1no,ename from emp1 where emp1no = n

・n は0～19999までの値（5セッションに分割して同時に並列実行）

・索引がないため表をFull Scanをしてしまう

・EMP1表のレコード数は25万件、サイズはテーブル全体で約27Mbyte

その他さまざまなSQL実行（索引の問題がなく、直接性能問題とは関係のないSQL）

25万件の表を2万回もFull Scanしているようでは性能問題を引き起こしても仕方ありません。索引を作成するだけで、セグメントへのアクセスが劇的に削減されたことも納得できます。大量のブロックから検索条件にマッチするレコードを探し出すために、CPU Timeを大きく費やしていたことになります。しかし、ここで次のような2つ疑問がのこります。

  1. StatspackレポートやAWRレポートの各SQL Orderedセクションに、この問題のSQLが上位にランクされなかったのはなぜか（SQL Ordered by Reads以外のセクションに表示されなかったのはなぜか）
  2. 2万回も実行したのに、AWRビューの検索結果では1076件しか見つからなかったのはなぜか

まず、1についてです。今回のSelect文はバインド変数を用いずに、リテラルで検索条件の値を指定していました。リテラルを使用するとその値が異なるだけで、それぞれのSelect文は違うSQLとして認識されます。結果として、まったく同じ実行計画のSQLであっても、個々のSelect文の負荷はとても小さいため、SQL Orderedセクションなどのランキングの上位に現れませんでした。このように、実行回数が多くて、ちりも積もれば山となるような処理に対してバインド変数を使用していないと、問題となるSQL文を見つけにくくなるという問題が生じることがあります。
一般的に、バインド変数を使用することの目的として、「Parse効率を上げること」がよくいわれますが、今回の例のように、「同じ種類のSQLをひとまとめにして分析をしやすくしたい」といった目的でも重要だといえます。

2については次節で詳しく説明します。

（補足）バインド変数とは

バインド変数を使用することで、同じ種類のSQL文を再利用することができます。
バインド変数の値が違うだけであれば同じSQLとして認識されるため、実行後にV$SQLのレコードも増加しません。
しかし、リテラルを使用している場合はそれぞれ別のSQLとして認識されるため、V$SQLのレコードも追加されます。

（実行例）
SQL> -- 試験開始前のV$SQL内容確認（レコードがないことを確認）
SQL> SELECT sql_text, executions, parse_calls FROM v$sql
  2  WHERE sql_text LIKE '%select empno from emp where empno%'
  3   AND sql_text NOT LIKE '%v$sql%';

レコードが選択されませんでした。

SQL> -- バインド変数使用例
SQL> variable num number;
SQL> execute :num:=7566;

PL/SQLプロシージャが正常に完了しました。

SQL> select empno from emp where empno=:num;

     EMPNO
----------
      7566

SQL> execute :num:=7567;

PL/SQLプロシージャが正常に完了しました。

SQL> select empno from emp where empno=:num;

     EMPNO
----------
      7567

SQL> -- リテラル使用例
SQL> select empno from emp where empno=7566;

     EMPNO
----------
      7566

SQL>
SQL> select empno from emp where empno=7567;

     EMPNO
----------
      7567

SQL>
SQL> -- 実行結果確認
SQL> SELECT sql_text, executions, parse_calls FROM v$sql
  2  WHERE sql_text LIKE '%select empno from emp where empno%'
  3   AND sql_text NOT LIKE '%v$sql%';

SQL_TEXT                                 EXECUTIONS PARSE_CALLS
---------------------------------------- ---------- -----------
select empno from emp where empno=:num            2           2　←再利用されている
select empno from emp where empno=7567            1           1　←再利用されていない
select empno from emp where empno=7566            1           1　←再利用されていない

インデックスに戻る

4 AWRスナップショット

AWRのスナップショットの内容を詳しく知ることで、分析結果をより精度の高いものとすることができます。前回、「5 Statspackのスナップショットの工夫」でStatspackのスナップショットについて触れました。しかし、「前回のスナップショット作成時から次のスナップショットを取得する前までにShared Poolからなくなってしまった情報」については説明していなかったため、詳しくみていくこととしましょう。ここではAWRのスナップショットで説明していますが、Statspackでも同じような考え方となりますので参考にしてください。

4.1 スナップショット間隔の工夫

先ほどの「たねあかし」の通り、今回分析したシナリオでは、表をFull ScanするSelect文が2万回も実行されていました。しかし、AWRビューからそのSQLを検索したところ、わずか1076件しか見つかりませんでした。なぜでしょう。そこで、ある実験をしてその理由を明らかにしたいと思います。

● 実験概要

今回実施する試験で使用するテスト・アプリケーションは以下のとおりです。

  • 実行計画が同じとなるSelect文を1万回実行させる
  • ただし、実行させるSelect文はリテラルを使用し、リテラル値を0から9999まで順番に実行させる（バインド変数未使用であり、Oracleデータベースへはすべて異なるSQLとして認識させる）
実行したSQL
select emp1no,ename from emp1 where emp1no = NNNNN
（NNNNNはリテラル値)

また、スナップショットの作成を次の2回とします（図3-13）。

  • 1回目：テスト・アプリケーションの開始、終了それぞれ1回ずつスナップショットを作成
  • 2回目：テスト・アプリケーションの開始、終了それぞれ1回ずつに加え、実行中にも数回スナップショットを作成

つまり、同じ処理に対してスナップショット作成のタイミング、回数を変えた場合、AWRに保存される内容にどのような違いがあるのかを調べます。

図3-13 試験概要

1回目は14:09に開始し、14:17に終了しています。2回目は14:26に開始し、14:35に終了しています。実行させたテスト・アプリケーションは前述の1万回のSelect文であり、まったく同じ処理をさせています。それぞれのスナップショットに割り振られたSnap IDは以下のとおりです。

SQL> SELECT snap_id, end_interval_time FROM dba_hist_snapshot
  2  WHERE snap_id IN(7882, 7883, 7884, 7885, 7886, 7887, 7888)
  3  ORDER BY snap_id;

   SNAP_ID END_INTERVAL_TIME
---------- ------------------------
      7882 2007/04/18 14:09:36.117　← 1回目の開始時点
      7883 2007/04/18 14:17:43.274　← 1回目の終了時点
      7884 2007/04/18 14:26:52.606　← 2回目の開始時点
      7885 2007/04/18 14:28:53.532　← 2回目実行中
      7886 2007/04/18 14:30:55.246　← 2回目実行中
      7887 2007/04/18 14:32:56.711　← 2回目実行中
      7888 2007/04/18 14:35:24.854　← 2回目の終了時点

7行が選択されました。

作成した1回目のAWRレポートはこちら、作成した2回目のAWRレポートはこちらです。これらの期間を比較対象としたAWR期間比較レポートはこちらです。今回の実験の分析はより細かいレベルまで分析するため基本的にはAWRビューを利用しますので、これらのレポートは参考レベルとしてご確認ください。

では、スナップショットの回数を変えることでどのような違いがあるかを確認していきましょう。

● 保存SQLの比較

まず、スナップショットのタイミング（Snap ID）ごとに保存されているSQLの数を確認します。Snap IDが7883であるものに1回目の実行時のSQLが保存されており、Snap IDが7885から7888までの4つに2回目の実行時のSQLが保存されていますので、それをWhere句で指定しています。また、調査対象のSQLの内容もlike句で指定しました。実行したSQLと検索結果は以下のとおりです。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.plan_hash_value,
  4    count(*)
  5  FROM dba_hist_sqlstat sqls,
  6    dba_hist_sqltext sqlt
  7  WHERE sqls.sql_id = sqlt.sql_id
  8   AND sqls.snap_id in (7883,7885,7886,7887,7888) -- スナップショットID
  9   AND sqlt.sql_text like '%select emp1no,ename from emp1 where emp1no%'
 10   GROUP BY snap_id, sqls.plan_hash_value
 11   ORDER BY sqls.snap_id
 12   ;

SNAP_ID PLAN_HASH_VALUE   COUNT(*)
------- --------------- ----------
   7883      2226897347       1583 ←1回目の試験
   7885      2226897347       1330 ←2回目の試験（snap_id = 7885）
   7886      2226897347       1521 ←2回目の試験（snap_id = 7886）
   7887      2226897347       1312 ←2回目の試験（snap_id = 7887）
   7888      2226897347       1501 ←2回目の試験（snap_id = 7888）

1回目の試験で保存されたSQL文は1583件であり、2回目の試験で保存されたSQL文は4つあわせて合計5664件です。Snap IDそれぞれ1つずつに対して保存されているSQLの数には大きな差はありませんが、結果として、2回目の試験分のSQLは1回目に比べて多く保存されていることがわかります。つまり、同じ処理を実行していても、その間のスナップショット作成回数を変えることで保存されるSQLの数が異なることになります。

ではなぜ異なるのでしょうか。そこで、次にそれぞれ保存されているSQLの内容を詳しく見ていきましょう。まず1回目に保存されたSQLの一覧を検索します。検索結果は以下のとおりです。やはり、先ほどと同じく1583種類のSQLが見つかりました（SQLの実行結果すべてを確認したい場合はこちら）。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.sql_id,
  4    sqls.plan_hash_value,
  5    to_char(sqlt.sql_text) sql_text
  6  FROM dba_hist_sqlstat sqls,
  7    dba_hist_sqltext sqlt
  8  WHERE sqls.sql_id = sqlt.sql_id
  9   AND sqls.snap_id = 7883 -- スナップショットID
 10   AND sqlt.sql_text like '%select emp1no,ename from emp1 where emp1no%'
 11   ORDER BY snap_id,to_char(sqlt.sql_text)
 12   ;

SNAP_ID SQL_ID        PLAN_HASH_VALUE SQL_TEXT
------- ------------- --------------- -----------------------------------------------------
   7883 0w8277hpkq1b3      2226897347 select emp1no,ename from emp1 where emp1no =  6780
   7883 35u0gvbpt4246      2226897347 select emp1no,ename from emp1 where emp1no =  6783
   7883 bamsjfv44w1qt      2226897347 select emp1no,ename from emp1 where emp1no =  6784
   7883 3yhpaqv5dm79w      2226897347 select emp1no,ename from emp1 where emp1no =  6788
   7883 fjxdxfxw541z9      2226897347 select emp1no,ename from emp1 where emp1no =  6801
（中略）
   7883 a6b8z8bawpdru      2226897347 select emp1no,ename from emp1 where emp1no =  9995
   7883 d021xwwkxx9wj      2226897347 select emp1no,ename from emp1 where emp1no =  9996
   7883 9p34nj6szq7ws      2226897347 select emp1no,ename from emp1 where emp1no =  9997
   7883 6ktuktwq40d8r      2226897347 select emp1no,ename from emp1 where emp1no =  9998
   7883 fp25wk5cwdqpk      2226897347 select emp1no,ename from emp1 where emp1no =  9999

1583行が選択されました。

次に、同じように2回目の実行で保存されたSQLを調べます。検索結果は以下のとおりです。こちらも、先ほどと同じく5664種類のSQLが見つかりました（SQLの実行結果すべてを確認したい場合はこちら）。

SQL> SELECT
  2    sqls.snap_id,
  3    sqls.sql_id,
  4    sqls.plan_hash_value,
  5    to_char(sqlt.sql_text) sql_text
  6  FROM dba_hist_sqlstat sqls,
  7    dba_hist_sqltext sqlt
  8  WHERE sqls.sql_id = sqlt.sql_id
  9   AND sqls.snap_id in (7885,7886,7887,7888) -- スナップショットID
 10   AND sqlt.sql_text like '%select emp1no,ename from emp1 where emp1no%'
 11   ORDER BY snap_id,to_char(sqlt.sql_text)
 12   ;

SNAP_ID SQL_ID        PLAN_HASH_VALUE SQL_TEXT
------- ------------- --------------- -----------------------------------------------------
   7885 9bymqgyftpgwu      2226897347 select emp1no,ename from emp1 where emp1no =  0
   7885 75cy4gzmjyhk0      2226897347 select emp1no,ename from emp1 where emp1no =  1
   7885 1zr9vxnazv19h      2226897347 select emp1no,ename from emp1 where emp1no =  10
   7885 ahru7rxm2u73r      2226897347 select emp1no,ename from emp1 where emp1no =  1000
   7885 58tf424t14qur      2226897347 select emp1no,ename from emp1 where emp1no =  1001
（中略）
   7885 gy37wq1j04huv      2226897347 select emp1no,ename from emp1 where emp1no =  996
   7885 9yz8mfc4sa20n      2226897347 select emp1no,ename from emp1 where emp1no =  997
   7885 fpw0xxmtuspyv      2226897347 select emp1no,ename from emp1 where emp1no =  999
   7886 4ygwwss6kyyuu      2226897347 select emp1no,ename from emp1 where emp1no =  2519
   7886 d5puxfcxwvt6m      2226897347 select emp1no,ename from emp1 where emp1no =  2521
   7886 9z7bq3zuczujc      2226897347 select emp1no,ename from emp1 where emp1no =  2523
（中略）
   7886 g88dnz7ghp6f8      2226897347 select emp1no,ename from emp1 where emp1no =  4829
   7886 cs8ras2dbuuzp      2226897347 select emp1no,ename from emp1 where emp1no =  4830
   7886 3byubzr180ry3      2226897347 select emp1no,ename from emp1 where emp1no =  4831
   7887 azgtnwfgfma47      2226897347 select emp1no,ename from emp1 where emp1no =  4839
   7887 fnfn8wbrk30km      2226897347 select emp1no,ename from emp1 where emp1no =  4840
   7887 c0avjwhmnjnkp      2226897347 select emp1no,ename from emp1 where emp1no =  4841
（中略）
   7887 5x3m1ma9yc0uy      2226897347 select emp1no,ename from emp1 where emp1no =  6388
   7887 0j75s4vr7sbna      2226897347 select emp1no,ename from emp1 where emp1no =  6389
   7887 2ncdqm15cftx3      2226897347 select emp1no,ename from emp1 where emp1no =  6390
   7888 bfyctd17gj82q      2226897347 select emp1no,ename from emp1 where emp1no =  7571
   7888 8jd9btnnqn73m      2226897347 select emp1no,ename from emp1 where emp1no =  7572
   7888 3vwjh9x6sq7wu      2226897347 select emp1no,ename from emp1 where emp1no =  7575
（中略）
   7888 a6b8z8bawpdru      2226897347 select emp1no,ename from emp1 where emp1no =  9995
   7888 d021xwwkxx9wj      2226897347 select emp1no,ename from emp1 where emp1no =  9996
   7888 9p34nj6szq7ws      2226897347 select emp1no,ename from emp1 where emp1no =  9997
   7888 6ktuktwq40d8r      2226897347 select emp1no,ename from emp1 where emp1no =  9998
   7888 fp25wk5cwdqpk      2226897347 select emp1no,ename from emp1 where emp1no =  9999

5664行が選択されました。

ここで、検索されたSQL文とSnap IDの関係を見ると、次の2点に気づきます。

  • 1回目の試験の結果では、emp1no列の条件として指定したリテラル値が大きいもののほうが多い（6780がもっとも小さい値であり、9999に近づけば近づくほど抜け落ちている番号が少ない）。
  • 2回目の試験の結果ではSnap IDが小さいものにはリテラル値も小さい値のものが保存されている（1回目に保存されていなかった6780以下のものも保存されている）。

これらの現象の理由として、スナップショット作成時のShared Poolの状態の影響が挙げられます。スナップショット実行時に参照されるのは、V$SQLなどのShared Pool上にあるデータです。逆にいえば、Shared Poolからなくなってしまったデータは、スナップショットでも当然保存されません。

今回の試験ではリテラル値を0から順番に9999まで実行しています。1回目の試験ではリテラル値の小さいSQLは保存されていないことがわかります。つまり、さまざまなSQLを実行していくなかでShared Poolの領域を上書きし、値の小さいものはおそらく、スナップショット作成時にはShared Poolから消滅してしまっていたために、AWRに保存できなかったのであろうと推測されます（図3-14）。逆に、2回目の試験ではスナップショット間隔が1回目の試験より短いので、Shared Poolから消滅する前に保存できたSQLが多いわけです。

図3-14 AWRに保存されるSQL（イメージ）(拡大画像を表示)

このように、スナップショット間隔を短くすることでより多くのSQLをAWRに保存することができます。StatspackのスナップショットもShared Poolから参照していることにかわりはないので、基本的には同じことがいえます。

● スナップショットのオーバーヘッド
では、スナップショット間隔を短くすればするほどよいのでしょうか。もちろんそんなことはありません。スナップショットの処理そのものの負荷を考慮する必要が当然あります。ここではそれを見てみましょう。そこで、先ほどの1回目と2回目の試験期間を比較対象としたAWR期間比較レポートを確認します。作成したレポートはこちらです。

まずTop 5 Timed Eventsセクションを確認します（図3-15）。今回の実験では、スナップショット取得間隔（トータル取得回数）を変えて計測しましたが、図3-15 から、スナップショット取得回数を増やすにともない CPU Timeとdb file scattered readが増えていることが見て取れます。これは スナップショット取得のために、内部表や索引を読む分だけ、db file scattered readが若干あがり、その分のCPUtimeが上がったことに起因しています。スナップショットの間隔を短くすることで情報量が増えますが、逆にCPU負荷が上がるということがいえます。

図3-15 AWR期間比較レポートTop 5 Timed Events(拡大画像を表示)

次に、Top 5 Segments Comparisonセクションを確認します（図3-16）。試験SQLのアクセス対象であるEMP1表はほとんど差がないのに対し、WRH$の文字列で始まるオブジェクトに対するアクセスが増えていることがわかります。これらのオブジェクトはAWRの内部表に対する索引です。つまり、スナップショット回数が増えたことでこれらのアクセスも増えたということになります。

図3-16 AWR期間比較レポートTop 5 Segments(拡大画像を表示)

まとめ

AWRのスナップショットはShared Poolのデータを参照しているので、Shared Poolにない情報は保存できません。SQLの情報を多く保存したいのであれば、スナップショットを作成する間隔を短くするなどの工夫が必要であることがわかります。しかし、スナップショットの負荷も無視できないため、情報量を増やすことと負荷を下げることは、トレードオフの関係にあることを意識する必要があります。そこで、「通常運用時は1時間に1回程度とし、より詳細な情報を取得する必要がある場合のみスナップショットの間隔を短くする」などの工夫が必要となります。基本的なこととして、「AWRは実行されたすべてのSQLを保存することを目的とした機能ではない」ことを忘れないようにしましょう。

インデックスに戻る

4.2 AWRスナップショット・パラメータ

Statspackのスナップショットにはさまざまなパラメータが用意されていると前回説明しましたが、AWRにも同じようなパラメータが用意されています。すでに、第1回「4.1 Automatic Workload Repository (AWR) 」の「（補足）収集レベルについて」でAWRのスナップショット・パラメータについて説明しましたが、ここでは、まだ説明していないパラメータについて説明したいと思います。それがDBMS_WORKLOAD_REPOSITORY.MODIFY_SNAPSHOT_SETTINGSのTOPNSQLパラメータです。このパラメータは、スナップショット実行時に収集されるSQL数のしきい値を設定することができます。StatspackではSQL数を制御するパラメータが多数存在していましたが、AWRではこの1つに集約され、シンプルになりました。

TOPNSQLパラメータの説明

「Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス10g リリース2（10.2）」の「DBMS_WORKLOAD_REPOSITORY.MODIFY_SNAPSHOT_SETTINGSプロシージャのパラメータ」説明抜粋より抜粋

NUMBERの場合

Top N SQLのサイズ。 SQL基準（経過時間、CPU時間、解析コール、共有可能メモリ、バージョン・カウント）ごとにフラッシュするTop SQLの数。この設定の値は、統計レベルまたはフラッシュ・レベルによる影響を受けず、AWR SQLコレクションに対するシステムのデフォルト動作より優先されます。 この設定の最小値は30で、最大値は100000000です。NULLを指定すると、現在の設定が維持されます。

VARCHAR2の場合

ユーザーはDEFAULT、MAXIMUM、Nの値を指定できます。ここで、Nは、SQL基準ごとにフラッシュするTop SQLの数です。 DEFAULTを指定すると、システムは統計レベルTYPICALのTop 30および統計レベルALLのTop 100のデフォルト動作に戻ります。 MAXIMUMを指定すると、システムはカーソル・キャッシュ内のSQLの完全なセットを取得します。 数値Nを指定することは、NUMBER型を使用してTop N SQLを設定することと同じです。 この引数にNULLを指定すると、現在の設定が維持されます。

設定方法や設定の確認方法は以下のとおりです。

実行例

SQL> -- TOPNSQLを1万に設定
SQL> BEGIN
  2  DBMS_WORKLOAD_REPOSITORY.MODIFY_SNAPSHOT_SETTINGS
  3  (topnsql => 10000);
  4  END;
  5  /

PL/SQLプロシージャが正常に完了しました。

SQL> select * from DBA_HIST_WR_CONTROL;

      DBID SNAP_INTERVAL      RETENTION          TOPNSQL
---------- ------------------ ------------------ ----------
2384218455 +00000 01:00:00.0  +00007 00:00:00.0       10000

SQL> -- TOPNSQLをDEFAULTに設定
SQL> BEGIN
  2  DBMS_WORKLOAD_REPOSITORY.MODIFY_SNAPSHOT_SETTINGS
  3  (topnsql => 'DEFAULT');
  4  END;
  5  /

PL/SQLプロシージャが正常に完了しました。

SQL> select * from DBA_HIST_WR_CONTROL;

      DBID SNAP_INTERVAL      RETENTION          TOPNSQL
---------- ------------------ ------------------ ----------
2384218455 +00000 01:00:00.0  +00007 00:00:00.0  DEFAULT

（補足）Shared Poolとの関係

仮にTOPNSQLを大きな値にしていても、「4.1 スナップショット間隔の工夫」の実験のとおりShared PoolにそのSQLが存在しなければAWRにSQLを保存することができません。Shared PoolにSQLが十分に残っている状況で、AWRに保存するSQLの数を調節したい場合にTOPNSQLを設定しましょう。なお、4.1の実験はTOPNSQLを10000に増やした設定で実験しました。デフォルト設定値は、「TOPNSQLパラメータの説明」のとおりstatistics_level = typicalの場合は30です

インデックスに戻る

5 おわりに

これまで、3回にわたってStatspackおよびDiagnostics Packを使用したOracleデータベース性能監視機能について説明しました。そのなかでも、2回目、3回目ではあるシナリオをベースとした実際の分析手法を説明しました。今回取り扱ったシナリオの性能問題となった原因は、さまざまなケースにかならず当てはまるというわけではありません。しかし、StatspackやAWRレポートなどの分析方法そのものはさまざまなケースに当てはまるポイントを中心に説明しているため、多くのケースで役に立つものと考えています。とはいえ、実際に分析するという経験はとても重要です。私自身、これまで膨大な量のStatspackレポートを分析してきたからこそDiagnostics Packの便利さを理解していると感じています。

また、「4 AWRスナップショット」でも説明しているとおり、StatspackやAWRは実行されたすべてのSQLを保存するための機能ではありません。性能監視機能に限ったことではありませんが、大切なのはそれぞれの機能の特徴をよく理解し、その時に必要とされるもっとも適した機能を選択することです。

性能分析手法と分析のための道具（機能）を知っているか、知っていないかによって、技術者としての能力に大きな差が生まれます。皆様にとって今回のこの記事がその知識を増やすことに少しでもお役立ていただけたのであれば幸いです。まだこれらの機能を使用してみたことのない方もぜひお試しください。

インデックスに戻る