NTTコムウェア株式会社 プロジェクト管理統括部 技術SE部門 DB技術グループ 坂下 徹
Oracleデータベースの性能対策の重要な機能、「Statspack」や「Oracle Enterprise Manager 10g Diagnostics Pack」(※オプションライセンス)の利用ポイントをお伝えします。使わないと"もったいない"機能です！(Diagnostics Packの有無による違いは ここ)
第2回 ケーススタディ（Statspack）
- INDEX -
- 1 はじめに
- 2 シナリオ概要
- 3 Statspackレポートの分析
- 3.1 Snapshot
- 3.2 Load Profile
- 3.3 Instance Efficiency Percentages
- 3.4 Top 5 Timed Events
- 3.5 SQL ordered
- 3.6 Tablespace IO Stats
- 3.7 Segments
- 4 考察
- 4.1 事象の概要
- 4.2 そのほか気になる点
- 5 Statspackのスナップショットの工夫
- 6 まとめ
1 はじめに
前回、StatspackとDiagnostics Packの特徴と使用方法を説明しました。しかし、それぞれの設定方法やレポートの出力方法がわかっていても、分析することができなければ意味がありません。そこで、今回と次回で、分析方法について説明したいと思います。
StatspackやAWRなどの性能関連のレポートには様々な情報が数多く記述されています。しかし、初心者の方は「どこを見ればいいのだろう？」とかえって混乱し、性能分析を難しく考えてしまいかねません。筆者自身も初めてStatspackレポートを見たとき、情報量が多すぎてどこから読めばいいのかわからずに困惑したのを覚えています。最終的には経験がものをいう世界ですが、うまく分析するためのコツを押さえれば、効率的かつ的確に分析できるようになります。
これから、あるシナリオの性能分析を実際のレポートを見ながら説明します。もちろん、今回扱うシナリオが全てのケースにあてはまるわけではありませんが、全体的な流れをイメージしていただければよいかと思います。今回は、Oracleデータベースの全てのEditionで使用できるStatspackで説明したいと思います。Diagnostics Packを使用した分析は次回行いますのでお楽しみに。
2 シナリオ概要
今回、分析対象とするのは「CPU使用率が高く、このままでは将来の業務量増加に耐えられない危険性がある」という想定のシナリオです(図2-1）。
図2-1 データベース・サーバのCPU使用率状況
このシナリオは次のような条件で環境を作成しています。
- 複数のSQL文から構成されるアプリケーションを実行
- そのアプリケーションの一部に性能問題を引き起こす原因をわざと埋め込んでいる
- 分析対象はデータベース・サーバのみ
また、使用した環境は以下の通りです。とても小さな環境を使用していますが、これらの環境条件は今回のサンプルの性能問題とは直接関係ないものです。あくまでも参考レベルとお考えください。
- Oracle Database Enterprise Edition（10.2.0.3.0）
- Linux（x86）
- 2CPU（ハイパースレッディングを有効にしているため、OS上は4つに見える）
- メモリ 2GB
- データベース・サイズ（全データファイルの合計サイズ）は約5GB
なお、ここで取り扱うシナリオは、意図的に性能問題を起こさせていますが、実際の分析イメージをつかんでいただくために筆者が実際に分析を依頼された過去のケースに近い事象を再現したものです。 では、さっそく分析を始めましょう。
3 Statspackレポートの分析
先ほどのCPU使用率が100％になっている時間帯のStatspackレポートを作成しました（補足：作成方法は前回の記事の「 3.3 レポート作成」の「Statspack レポート」欄参照）。作成したレポートが こちらです。これからこのレポートを分析していきますが、まずご自分で分析してみたい方は、以下の説明を読み進む前にレポートを分析してみてください。なお、前回説明したように、Statspackのスナップショットレベルを7にしています。
実行例（Level 7 での取得例）
SQL> connect perfstat/********
SQL> execute statspack.snap(i_snap_level => 7)PL/SQLプロシージャが正常に完了しました。
ではここから、分析のポイントをレポートに記述されている順に説明します。Statspackレポートでは様々なセクションに分けて記述されています。ここでは、レポートの中の重要なポイントのみ説明しています。説明していない内容の詳細は、前回紹介したspdoc.txtなどのマニュアルをご覧ください。
3.1 Snapshot
Snapshotセクションには、そのレポート対象期間に関する情報が記述されています。まずは分析しようとしているStatspackレポートが、正しい時間帯のレポートかを必ず確認しましょう。今回はサンプルのアプリケーションを実行する開始前、終了後にそれぞれスナップショットを取得しています。よって、このレポートは図2-1のCPU使用率が100％ になっている時間帯を全て含んでいるものです。
Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- -------------------
Begin Snap: 1109 02-Apr-07 20:01:08 24 12.5
End Snap: 1110 02-Apr-07 20:09:21 24 12.7
Elapsed: 8.22 (mins)3.2 Load Profile
このセクションには、レポート対象期間中の1秒当たり、トランザクション当たりの統計情報が表示されています。ただし、単一のレポートを見ているだけでは比較対象がなくて相対的な評価は難しいため、他の時間帯や他のInstanceのレポートと比較するとよいでしょう。たとえば、「Logons」の値が異常に高い場合、「コネクションプーリングが実装されていないのでは？」などという分析の参考になります。 今回は他のレポートとの比較は行っていませんが、このレポートからは「Physical readsがPhysical writesに比べてとても多い」、つまり「書き込み処理に比べて、読み込み処理が多かったのだろう」といったことが読み取れます。
Load Profile Per Second Per Transaction
~~~~~~~~~~~~ --------------- ---------------
Redo size: 11,202.52 2,661.61
Logical reads: 109,025.27 25,903.35
Block changes: 49.34 11.72
Physical reads: 6,628.61 1,574.89
Physical writes: 4.18 0.99
User calls: 290.65 69.05
Parses: 116.82 27.75
Hard parses: 53.77 12.78
Sorts: 8.10 1.92
Logons: 0.04 0.01
Executes: 130.14 30.92
Transactions: 4.213.3 Instance Efficiency Percentages
このセクションでは各ヒット率を確認することができます。特にBuffer Hit率、Library Hit率などのメモリヒット率は必ず確認しましょう。ここではとても気になる点が見つかります。Library Hit率とSoft Parse率がとても悪い点です。Soft Parseとは、SQLの解析時に既にLibrary Cacheに解析済みのSQLが存在するため、新たに解析処理を行う必要がなかったことをいいます。よって、Soft Parse率が低いということは、新たな解析をしている（Hard Parse）処理が多かったことを意味します。解析結果はLibrary Cacheに保存されるため、その結果Library Hit率も低いと推測されます。または、逆にLibrary Cacheが小さくてParse結果を保存できるSQLの数が少なかったためにHard Parseが多発したとも考えられます。今回、CPU使用率が高いことが問題視されていますが、Parse処理はCPU timeに関係するので何らかの影響があるかもしれません。では、「Shared Poolを大きくすればいい」のでしょうか。まだ、レポートの一部しか確認していないので、もう少し分析を進めてから結論を出すことにしましょう。
Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 99.01 Redo NoWait %: 100.00
Buffer Hit %: 93.92 In-memory Sort %: 100.00
Library Hit %: 60.87 Soft Parse %: 53.97
Execute to Parse %: 10.24 Latch Hit %: 98.31
Parse CPU to Parse Elapsd %: 89.83 % Non-Parse CPU: 96.163.4 Top 5 Timed Events
このセクションには、どのようなイベント（待機イベント）が多かったのか、その上位5つが記述されています。これはOracleの内部でどのような処理待ちで時間がかかっていたかを表すため、とても重要な情報です。1番目にあるCPU timeとは、その名の通り、OracleがCPUを使用して何らかの処理をした時間を表しています。今回の環境では論理的なCPU数が4つなので、1つのCPU当たり
1,543秒 ÷ 4CPU ≒ 6.4分/CPU
の時間を要しています。今回の分析対象期間は8.4分なので、OracleのCPU timeが処理時間の大半を占めていることがわかります。今回のシナリオでは、このCPU timeを大きくしている原因をつきとめ、それを解消することが性能分析の目的となります。
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
CPU time 1,543 82.9
read by other session 532,940 194 0 10.4
db file scattered read 464,025 56 0 3.0
db file sequential read 558,568 20 0 1.1
latch: cache buffers chains 3,042 13 4 .7
-------------------------------------------------------------（補足）性能問題箇所の切り分けについて
エンドユーザから性能に関するクレームがある場合、「レスポンスが悪いのでなんとかして」などといわれるのが普通でしょう。つまり、「データベース・サーバが遅いのでなんとかして」などと具体的なボトルネック箇所をいわれることはまずありません。よって、性能問題が発生したときの最初の作業は、どのサーバにボトルネックがあるのかという切り分け作業になります。
次に、あるサーバがボトルネックであることがわかった場合、そのサーバ内のどのアプリケーションがボトルネックかの特定が必要です。ここで注意したいのは、データベース・サーバのCPU使用率が高いからといって、Oracleが原因だと決め付けてはいけない点です。Oracleではなく、データベース・サーバにある他のアプリケーションが原因である可能性もあります。他のアプリケーションが原因なのに、Oracleのチューニングを行うことに
意味はありません。よって、サーバ内のアプリケーション単位での原因の切り分けは忘れないようにしてください。
今回のシナリオでは、データベース・サーバにあるOracle以外のアプリケーションがCPU使用率を高めているわけではなく、Oracleの処理がCPU timeを占めているため、このままOracleの分析を進めましょう。次に、CPU time以外のイベントにも目を向けてみましょう。CPU timeに比べて他のイベントの%Total Call Timeの割合は低いのですが、これらのイベントを分析することが性能分析のケースで重要なヒントとなることが多いようです。CPU time以外のそれぞれのイベントを分析するためには、マニュアルなどにより、その待機イベントの意味を理解する必要があります。Oracle Database 10g Release 2（以下、10g R2）の場合は「Oracle Database リファレンス 10gリリース2（10.2）」の「C Oracle待機イベント」や、「Oracle Database パフォーマンス・チューニング・ガイド 10g リリース2（10.2）」を参照してください。 なお、この欄のTop 5イベントの結果ですが、実際のケースでもよくあるイベントが発生しているので、もう少し説明したいと思います。今回表示されたそれぞれのイベント（CPU time以外）の意味は次の通りです。
- read by other session セッションが、別のセッションによって現在バッファキャッシュに読み込まれているバッファをリクエストする場合に発生します（10g R1より前のバージョンでは、buffer busy waitという、バッファ待機の他の理由に分類）
- db file scattered read 次に説明するdb file sequential readと似ていますが、このイベントではセッションは複数のデータ・ブロックを読み込んでいます。 表のFull ScanやINDEX FAST FULL SCAN等の処理で発生します。初期化パラメータDB_FILE_MULTIBLOCK_READ_COUNTに設定されている値が一度に読み込める最大のブロック数です。
- db file sequential read セッションは、データベースから順次読み取りが実行されているあいだ、待機します。このイベントは、制御ファイルの再構築、データベース・ファイルヘッダーのダンプ、およびデータベース・ファイルヘッダーの取得にも使用されます。db file scattered readと異なり、1ブロックずつ読み込みます。
- latch: cache buffers chains Oracleの内部ロック（ラッチ）に関する待機イベントの一種です。このラッチは、バッファキャッシュでバッファリストを保護する場合に使用します。これらのラッチは、バッファの検索・追加、およびバッファキャッシュからバッファを削除する場合に使用します。このラッチの競合は、競合度の高い（ホットな）ブロックが存在することを意味します。
ここで考えられることは次の2点です。
- read by other sessionやlatch: cache buffers chainsのように、並列処理に影響する待機イベントが発生している
- db file scattered readがdb file sequential readよりも上位にランクされており、無駄なFull Scanが発生している疑いがある
今回はCPU使用率が高いことが問題ですが、この時点では、前者の事象については「CPU timeの取り合いのための処理でCPU使用率が高いのでは」との疑いをもち、後者では「処理対象のデータが多いためにCPU使用率が高いのでは」との疑いをもつことができます。ここで注意することは、「I/Oが多い」＝「DiskネックでありCPUネックではない」と勘違いしてはいけないという点です。もちろんDiskネックであるケースは多いのですが、ストレージ側のキャッシュやファイルシステムのキャッシュにあるデータも、Oracleから見るとI/Oであることに変わりはありません。キャッシュ上にあるデータを処理する場合、一般的にボトルネックはDiskではなくCPUです。
3.5 SQL ordered
このセクションには、遅いSQLの一覧が表示されます。たとえば、CPU時間が最も長かったSQLが「SQL ordered by CPU」の欄に表示されます。
SQL ordered by CPU DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> Total DB CPU (s): 1,523
-> Captured SQL accounts for 5.4% of Total DB CPU
-> SQL reported below exceeded 1.0% of Total DB CPU
CPU CPU per Elapsd Old
Time (s) Executions Exec (s) %Total Time (s) Buffer Gets Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
56.72 1,000 0.06 3.7 77.97 1,557,001 528477046
Module: SQL*Plus
SELECT COUNT(ename) FROM emp3 WHERE emp3no = 1このSQLは「SQL ordered by CPU」だけではなく、「SQL ordered by Elapsed」（処理時間の長い順）や「SQL ordered by Gets」（Buffer Gets数の多い順）にも見ることができますので、このSQLは負荷の高いSQLだと判断できます。スナップショットのレベルを6以上にしていたので、StatspackのSQLレポートも作成してみましょう（補足：作成方法は前回の記事の「 3.3 レポート作成」の「Statspack SQLレポート」欄参照）。作成したStatspackのSQLレポートは こちらです。 実行計画を見ると表のFull Scanをしていることがわかります。
--------------------------------------------------------------------------------
| Operation | PHV/Object Name | Rows | Bytes| Cost |
--------------------------------------------------------------------------------
|SELECT STATEMENT |----- 1396384608 ----| | | 869 |
|SORT AGGREGATE | | 1 | 9 | |
| TABLE ACCESS FULL |EMP3 | 521K| 1M| 869 |
--------------------------------------------------------------------------------Select文のWhere句を見るとemp3noを検索条件としているので、このemp3表のemp3no列に索引を作成すればよいのでしょうか。実は違います。既にこの列に索引は作成していました。
SQL> select table_name,index_name,column_name,column_position
2 from user_ind_columns
3 where table_name = 'EMP3'
4 order by table_name,index_name,column_position;
TABLE_NAME INDEX_NAME COLUMN_NAM COLUMN_POSITION
---------- ---------- ---------- ---------------
EMP3 IND_EMP3 EMP3NO 1では、なぜ索引を使用しなかったのでしょう。この列は以下の通りカーディナリティが低いため、Oracleが索引を使用するより表のFull Scanを選択したほうがよいと判断したためです。
SQL> select count(*),emp3no from emp3 group by emp3no;
COUNT(*) EMP3NO
---------- ----------
131072 1
131071 2
1 5細かいことをいえば、「ビットマップインデックス」や「索引構成表」「パーティション表」など、これらをチューニングする手段はたくさんあります。しかし、このSQLのCPU timeはわずか56.72秒です。データベース全体のCPU timeは1,523秒とあるので、このSQLのCPU timeが全体のCPU timeに占める割合は%Total欄にある通り3.7％でしかありません。よって、このSQLをチューニングしても、全体の割合から考えてその効果をほとんど期待できないことになります。また、SQL orderedの欄に表示されている他のSQLも同じ観点で見ると、全体に対する影響はとても小さいものだということがわかります。
SQL ordered by CPU DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> Total DB CPU (s): 1,523
-> Captured SQL accounts for 5.4% of Total DB CPU
-> SQL reported below exceeded 1.0% of Total DB CPU
CPU CPU per Elapsd Old
Time (s) Executions Exec (s) %Total Time (s) Buffer Gets Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
56.72 1,000 0.06 3.7 77.97 1,557,001 528477046
Module: SQL*Plus
SELECT COUNT(ename) FROM emp3 WHERE emp3no = 1先ほどのSelect文をチューニング対象の候補としつつも、Statspackレポートをさらに見ていきましょう。
（補足）10g R2の新しいSQL Orderedセクション
10g R2のStatspackレポートでは、SQL Orderedセクションに次の新しい2つの項目が追加されました。
- SQL ordered by Elapsed
- SQL ordered by CPU
処理時間やCPU時間の長いSQLをチューニングしたいため、これらのSQLを特定したいというケースはよくあると思います。しかし、10g R1以前のバージョンでは、SQL ordered by Getsなどから間接的に処理時間の長いSQLを探す必要がありました。この2つの項目の追加によって、これらのSQLを特定する作業がより容易になったといえます。10g R1におけるAWRの登場によりStatspackの影が薄くなりましたが、Statspackの機能拡張も継続されていますので注目してみてください。
3.6 Tablespace IO Stats
このセクションでは、表領域単位のI/O量を確認することができます。今回の環境では全ての表と索引をUSERSに作成しているため、あまり意味のある情報は得られませんが、複数の表領域を使用しているときは、どの表領域へのアクセスが多いかを把握することができます。また、Disk I/Oとあわせて評価したい場合は、この次の欄の「File IO Stats」とあわせて分析するとよいでしょう。今回は省略します。
Tablespace IO Stats DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
->ordered by IOs (Reads + Writes) desc
Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
USERS
1,021,641 2,072 0.1 3.2 3 0 532,785 0.4
SYSAUX
641 1 0.0 1.0 827 2 0 0.0
SYSTEM
243 0 0.0 1.0 21 0 0 0.0
UNDOTBS1
11 0 0.0 1.0 61 0 0 0.0
-------------------------------------------------------------3.7 Segments
このセクションでは、セグメント単位の統計を確認することができます。スナップショットのレベルが7以上であれば、この欄が表示されます。先ほどの「Tablespace IO Stats」では全ての表や索引をUSERS表領域に作成していたため、どのオブジェクトのI/Oが多いのかがわかりませんでした。しかし、ここではどの表や索引かまで特定できるため、とても分析がしやすくなります。
Segments by Logical Reads DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
-> End Segment Logical Reads Threshold: 10000
-> Pct Total shows % of logical reads for each top segment compared with total
logical reads for all segments captured by the Snapshot
Subobject Obj. Logical Pct
Owner Tablespace Object Name Name Type Reads Total
---------- ---------- -------------------- ------------ ----- ------------ -----
SCOTT USERS EMP1 TABLE 51,853,184 96.6
SCOTT USERS EMP3 TABLE 1,558,448 2.9
SCOTT USERS IND_EMP1_DEPTNO INDEX 132,416 .2
SCOTT USERS PK_EMP2 INDEX 29,264 .1
SCOTT USERS PK_DEPT INDEX 9,696 .0
-------------------------------------------------------------
Segments by Physical Reads DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
-> End Segment Physical Reads Threshold: 1000
Subobject Obj. Physical Pct
Owner Tablespace Object Name Name Type Reads Total
---------- ---------- -------------------- ------------ ----- ------------ -----
SCOTT USERS EMP1 TABLE 3,266,706 100.0
SYS SYSAUX WRH$_SQL_PLAN TABLE 323 .0
SYS SYSTEM HISTGRM$ TABLE 81 .0
SYS SYSAUX WRH$_SQLTEXT TABLE 67 .0
SYS SYSAUX WRH$_SQL_PLAN_PK INDEX 60 .0
-------------------------------------------------------------さて、分析に戻りましょう。これらを見ると、ここで初めてEMP1表に対する読み込み処理がとても多いことがわかります。特に注目するべき点は、「Physical Reads」が全体のほぼ100％を占めていることです。先ほどの「Top 5 Timed Events」でも触れた「無駄なFull Scanが発生しているのでは」という疑いと関連付けられます。よって、このEMP1にアクセスしているSQLを探すことが次の分析ターゲットとなります。 そこで、先ほどの「SQL ordered」欄からEMP1にアクセスしているSQLを探してみると、次のSQLが見つかります。
SQL ordered by Executions DB/Inst: O102EE1/o102ee1 Snaps: 1109-1110
-> End Executions Threshold: 100 Total Executions: 64,158
-> Captured SQL accounts for 55.6% of Total Executions
-> SQL reported below exceeded 1.0% of Total Executions
CPU per Elap per Old
Executions Rows Processed Rows per Exec Exec (s) Exec (s) Hash Value
------------ --------------- ---------------- ----------- ---------- ----------
（中略）
10,000 10,000 1.0 0.00 0.00 4111966515
Module: SQL*Plus
select distinct emp1.deptno from emp1, dept where emp1.deptno =
dept.deptno and dept.deptno = 10念のため、Statspack SQLレポートも作成してみましょう。作成したレポートは こちらです。レポートを見てみると、実行回数（Executions）は1万回と多いのですが、合計のCPU処理時間（CPU Time）は4秒とごくわずかです。また、実行計画を見ると、EMP1に対しては索引へのアクセスのみであり、肝心な表へのアクセスはないようです。よって、残念ながら（？）このSQLはCPU使用率を高めている原因ではないようです。
STATSPACK SQL report for Old Hash Value: 4111966515 Module: SQL*Plus
（中略）
SQL Statistics
~~~~~~~~~~~~~~
-> CPU and Elapsed Time are in seconds (s) for Statement Total and in
milliseconds (ms) for Per Execute
% Snap
Statement Total Per Execute Total
--------------- --------------- ------
Buffer Gets: 140,000 14.0 .26
Disk Reads: 0 0.0 .00
Rows processed: 10,000 1.0
CPU Time(s/ms): 4 .4
Elapsed Time(s/ms): 4 .4
Sorts: 0 .0
Parse Calls: 10,000 1.0
Invalidations: 0
Version count: 1
Sharable Mem(K): 12
Executions: 10,000
（中略）
--------------------------------------------------------------------------------
| Operation | PHV/Object Name | Rows | Bytes| Cost |
--------------------------------------------------------------------------------
|SELECT STATEMENT |----- 2294000873 ----| | | 14 |
|SORT UNIQUE NOSORT | | 1 | 6 | 14 |
| NESTED LOOPS | | 5K| 30K| 12 |
| INDEX UNIQUE SCAN |PK_DEPT | 1 | 3 | 0 |
| INDEX RANGE SCAN |IND_EMP1_DEPTNO | 5K| 15K| 12 |
--------------------------------------------------------------------------------
End of Report4 考察
これまでの分析で次のようなことがわかりました。
4.1 事象の概要
- Top 5 Timed EventsのCPU timeが大きいことから、Oracleの処理がCPU使用率を占めていることに間違いなさそう
- 特定のObject（EMP1）へのLogical reads処理が大量に発生していることから、EMP1へアクセスしているSQL文は疑わしい
- しかし、Statspackからは問題となるSQL文は見つからない
4.2 そのほか気になる点
- Top 5 Timed Eventsでdb file scattered readが上位にRankされている（無駄な処理をしている疑いあり）
- Library Hit率が悪い、またSoft Parse率も悪い
EMP1へのアクセスが最も疑わしいことまではわかりましたが、残念ながら、今回のStatspackレポートのみでは原因の特定までにはいたりませんでした。また、Hard Parseが多い原因となるSQLも特定しなければなりません。 次にとるべきアクションとしては、この見つからなかったSQLを発見するために、より詳細なログを取得するように準備を進めることになります。具体的には、Statspackのスナップショットの取得の仕方を工夫する（後述）、あるいはV$SESSIONやV$SQLなどを定期的に検索し、Statspackよりも詳細なログを取得するなどの対策が考えられます。また、アプリケーションのソースコードから直接EMP1にアクセスしているSQL文を検索することも必要かもしれません。
5 Statspackのスナップショットの工夫
先ほどのStatspackレポートでは、EMP1にアクセスしているSQL文が見つかりませんでした。なぜでしょうか。それはStatspackレポートに表示されるのは、ある条件を超える事象のみという仕組みになっているからです。仮に全ての処理をStatspackで出力しようとすると、スナップショットの処理そのものが性能に与える影響を無視できなくなります。そこで、スナップショットの処理の負荷に制限をかけているわけです。また、Statspackレポートは人が見るためのものなので、ページ数が膨大にならないようにする目的もあります。 具体的には、Statspackでは主に次のような要因でデータのフィルタリング（ロス）が発生します。
(1)前回のスナップショット作成時から次のスナップショットを取得する前までにShared Poolからなくなってしまった情報 (2)スナップショットパラメータにて指定された閾値を下回る場合 (3)Statspackレポート作成のためのスクリプト（spreport.sql）であらかじめ設定されている閾値を下回る場合（例：Top 5 Timed Events欄に6位以下のEventは表示されない etc.）
(3)は残念ながらspreport.sqlの仕様であるため、変更することはできません。しかし、(1)と(2)はある程度の工夫が可能です。(1)はAWRにも共通する内容になりますので、次回お話しします。 ここでは(2)についてお話しします。Statspackではスナップショットを取得する際に様々なパラメータを指定することができます。スナップショットレベルをDefaultの5から7に変更したのもその一つです。スナップショットの負荷が低いのでもっと情報を多く取得したいという場合は各パラメータの閾値を下げ、スナップショットの負荷が高いので情報量を減らしたい場合は、閾値を上げるなどの設定が考えられます。
（参考）Statspackのスナップショットパラメータ（10g Release 2）
以下、spdoc.txtより抜粋
5.6. Input Parameters for the SNAP and MODIFY_STATSPACK_PARAMETERS procedures
Parameters able to be passed in to the statspack.snap and
statspack.modify_statspack_parameter procedures are as follows:
Range of Default
Parameter Name Valid Values Value Meaning
------------------ ------------ ------- -----------------------------------
i_snap_level 0,5,6,7,10 5 Snapshot Level
i_ucomment Text <blank> Comment to be stored with Snapshot
i_executions_th Integer >=0 100 SQL Threshold: number of times
the statement was executed
i_disk_reads_th Integer >=0 1,000 SQL Threshold: number of disk reads
the statement made
i_parse_calls_th Integer >=0 1,000 SQL Threshold: number of parse
calls the statement made
i_buffer_gets_th Integer >=0 10,000 SQL Threshold: number of buffer
gets the statement made
i_sharable_mem_th Integer >=0 1048576 SQL Threshold: amount of sharable
memory
i_version_count_th Integer >=0 20 SQL Threshold: number of versions
of a SQL statement
i_seg_phy_reads_th Integer >=0 1,000 Segment statistic Threshold: number
of physical reads on a segment.
i_seg_log_reads_th Integer >=0 1,0000 Segment statistic Threshold: number
of logical reads on a segment.
i_seg_buff_busy_th Integer >=0 100 Segment statistic Threshold: number
of buffer busy waits for a segment.
i_seg_rowlock_w_th Integer >=0 100 Segment statistic Threshold: number
of row lock waits for a segment.
i_seg_itl_waits_th Integer >=0 100 Segment statistic Threshold: number
of ITL waits for a segment.
i_seg_cr_bks_sd_th Integer >=0 1000 Segment statistic Threshold: number
of Consistent Reads blocks served by
the instance for the segment*.
i_seg_cu_bks_sd_th Integer >=0 1000 Segment statistic Threshold: number
of CUrrent blocks served by the
instance for the segment*.
i_session_id Valid sid 0 (no Session Id of the Oracle Session
from session) to capture session granular
v$session statistics for
i_modify_parameter True,False False Save the parameters specified for
future snapshotsたとえば、i_executions_thのDefault値は100なので、SQLの実行回数が100回以下のものに関してはスナップショットを実行しても情報が取得されません。これを1回以上実行されたものを対象としたい場合、次のようにパラメータを指定します。
実行例（スナップショットレベル7、かつ実行回数1回以上のSQLを取得対象とする場合） SQL> connect perfstat/******** SQL> execute statspack.snap(i_snap_level => 7, i_executions_th => 0) PL/SQLプロシージャが正常に完了しました。
なお、先ほど説明した通り、全てのパラメータの設定を0にするとスナップショットの負荷が高くなることと、Statspackレポートが大きくなってしまうというデメリットがあることを理解した上で値を設定しましょう。
（補足）スナップショットパラメータのDefault値変更
スナップショットパラメータはi_modify_parameterパラメータをTrueにしたり、
STATSPACK.MODIFY_STATSPACK_PARAMETERプロシージャを使用することで、Default値を変更する
ことができます。また、現在のDefault値はSTATS$STATSPACK_PARAMETERを参照することで確認で
きます。いつも同じ閾値設定を使用する場合、スナップショット作成時にわざわざパラメータを
設定することを省略したい場合に便利です。
（実行例）i_executions_thのDefault値を0に変更
SQL> select EXECUTIONS_TH from STATS$STATSPACK_PARAMETER;
EXECUTIONS_TH
-------------
100
SQL> execute statspack.modify_statspack_parameter(i_executions_th => 0)
PL/SQLプロシージャが正常に完了しました。
SQL> select EXECUTIONS_TH from STATS$STATSPACK_PARAMETER;
EXECUTIONS_TH
-------------
06 まとめ
Statspackレポートを分析することで、メモリのヒット率や、I/Oの状況、負荷の高いSQLの確認など、ある一定期間における全体的な性能状況の概要を知ることができます。Statspackレポートには今回説明した内容以外にも、SGA、PGAのサイズに関するアドバイス情報や、各Eventの統計情報詳細が記述されたセクションもありますので、必要に応じて確認しましょう。しかし、今回取り上げたセクションは多くのケースで重要な情報となりますので、これらは少なくとも一通りチェックすることをお勧めします。
今回確認したStatspackレポートセクション
- Snapshot
- Load Profile
- Instance Efficiency Percentages
- Top 5 Timed Events
- SQL ordered
- Tablespace IO Stats
- Segments
今回のテーマはStatspackでしたので、Statspackレポートだけを使用して分析しました。しかし、もちろん実際の分析ではこれだけを使用すればよいわけではありません。vmstat、sar、iostatなどのOSパフォーマンス分析用のツールや、V$SESSION、V$SQLなど、より詳細な情報を取得することが必要なケースもあります。場合によっては、パフォーマンスへの影響を承知の上でSQL Traceを使用することもあるでしょう。重要なのは、それぞれのツールの特徴や使用方法を十分に理解し、その場面に応じてそれらを使い分けることです。決してStatspackだけでパフォーマンス分析を行おうとは考えないように注意してください。
さて次回は、この同じシナリオをDiagnostics Optionの各機能を使用して分析します。今回のStatspackでは不十分であった分析や面倒な操作が、Diagnostics Packを使用した場合にどれだけ改善されるかをご理解いただけると思います。また次回の分析で、今回の性能問題を引き起こしている原因の特定も行いますので、こちらももうしばらくお待ちください。