パフォーマンスがころころ変化するSQLの調査 - Statspack編
以前、AWRを使用できる環境で、実行計画がころころ変わる場合の
調査方法をエントリしました。
パフォーマンスがころころ変化するSQLの調査
http://d.hatena.ne.jp/nijimass/20080528/1211991024
これ、無理やり自分でSQL組んでますけど、
「awrsqrpt.sql」を使ったほうが早かったですね。確実に。
このSQLの使い方はまた今度ご説明します。
で、このエントリのなかで、
次回は、Diagnostics Pack のライセンス買ってねーよ！
って人のために、Statspackで同じような情報が
簡単に取り出せないか、実験してみたいと思います。
って書いたので今回はそれを説明してみます。
ではどうぞ。
今回は Statspack しか使用できない場合に、
実行計画がどのように変わったかを調査する方法を説明します。
ちなみに、超簡単です。
シナリオですが、すでにSQLは流し終わっている状態からスタートします。
select count(*) from test a ,test_2 b where a.col1 = b.col1;
例によってあんまり意味はないです。
test、test_2 には、1万件ずつレコードが存在し、
両テーブルにINDEXはありません。
よって、この両テーブルはおそらく HASH JOIN されます。
で、INDEXがない状態で このSQLを5秒間隔でループさせて実行し、
数分経過後 TEST テーブルの COL1 列に対して、UNIQUE INDEX を作成します。
INDEXを作成することによって、共有カーソルがINVALIDになり。
SQLの次回実行時に実行計画の再解析が行なわれます。
INDEXを作成していますので、おそらく、両テーブルの結合が
Nested Loop Join に変更されます。
で、この変化を Statspack で確認してみましょう。
という趣旨です。
では、まずPERFSTATユーザでログインして、
まずは、該当のSQLの OLD_HASH_VALUE を調べます。
V$SQLTEXT とかで確認してもいいんですが、
共有プールからエイジアウトされていたりしたら、V$SQLTEXTではダメですので、
いきなり、STATS$SQLTEXT を見に行きます。
ここには、Statspack の Snapshot を取得したときに、
SQLの情報が格納されますので、過去に実行したSQLの情報も確認できるわけです。
SQLはこれで。
col SQL_ID for a20 select OLD_HASH_VALUE ,SQL_ID ,ADDRESS ,LAST_SNAP_ID ,SQL_TEXT from STATS$SQLTEXT where SQL_TEXT like '% -- 実行したSQL -- %';
では流してみます。
[oracle@test ~]$ sqlplus perfstat/perfstat
SQL*Plus: Release 10.2.0.3.0 - Production on 木 6月 12 09:02:25 2008
Copyright (c) 1982, 2006, Oracle. All Rights Reserved.
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning and Data Mining options
に接続されました。
SQL> col SQL_ID for a20
SQL> select OLD_HASH_VALUE ,SQL_ID ,ADDRESS ,LAST_SNAP_ID ,SQL_TEXT
2 from STATS$SQLTEXT
3 where SQL_TEXT like 'select count(*) from test a ,test_2 b where a.col1 = b.col1%';
OLD_HASH_VALUE SQL_ID ADDRESS LAST_SNAP_ID
-------------- -------------------- ---------------- ------------
SQL_TEXT
--------------------------------------------------------------------------------
432994494 2wp78z9pb5m3w 2F0CAE18 114
select count(*) from test a ,test_2 b where a.col1 = b.col1
OLD_HASH_VALUE が 432994494 であるということがわかりました。
これをキーに、次はOracleが用意してくれている、「sprepsql.sql」を実行します。
これは、Statspack のもっているテーブルから、SQL関連の情報を引っ張りだしてくれる
SQL文になります。このSQLの途中で、OLD_HASH_VALUE を聞いてきます。
まぁ、実行してみましょう。
SQL> @?/rdbms/admin/sprepsql
Current Instance
~~~~~~~~~~~~~~~~
DB Id DB Name Inst Num Instance
----------- ------------ -------- ------------
1026716219 ORCL1 1 orcl1
Instances in this Statspack schema
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
DB Id Inst Num DB Name Instance Host
----------- -------- ------------ ------------ ------------
1026716219 1 ORCL1 orcl1 test
Using 1026716219 for database Id
Using 1 for instance number
Specify the number of days of snapshots to choose from
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Entering the number of days (n) will result in the most recent
(n) days of snapshots being listed. Pressing <return> without
specifying a number lists all completed snapshots.
Listing all Completed Snapshots
Snap Snap
Instance DB Name Id Snap Started Level Comment
------------ ------------ --------- ----------------- ----- --------------------
orcl1 ORCL1 114 12 6月 2008 08:5 7
5
115 12 6月 2008 09:0 7
0
116 12 6月 2008 09:0 7
5
117 12 6月 2008 09:1 7
0
Specify the Begin and End Snapshot Ids
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
begin_snapに値を入力してください: 114
Begin Snapshot Id specified: 114
end_snapに値を入力してください: 116
End Snapshot Id specified: 116
こういう感じで snap_id を聞いてきますので、
実行されていた期間を入力するようにしてください。
Specify the old (i.e. pre-10g) Hash Value ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ hash_valueに値を入力してください: 432994494 Hash Value specified is: 432994494
ここでは、OLD_HASH_VALUE を入力します。
Specify the Report Name
~~~~~~~~~~~~~~~~~~~~~~~
The default report file name is sp_114_116_432994494. To use this name,
press <return> to continue, otherwise enter an alternative.
report_nameに値を入力してください:
Using the report name sp_114_116_432994494
STATSPACK SQL report for Old Hash Value: 432994494 Module: SQL*Plus
DB Name DB Id Instance Inst Num Release RAC Host
------------ ----------- ------------ -------- ----------- --- ----------------
ORCL1 1026716219 orcl1 1 10.2.0.3.0 NO test
Start Id Start Time End Id End Time Duration(mins)
--------- ------------------- --------- ------------------- --------------
114 12-6月 -08 08:55:02 116 12-6月 -08 09:05:02 10.00
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: 436,843
19,856.5 33.09
Disk Reads: -102,388
-4,654.0 -13.90
Rows processed: 22
1.0
CPU Time(s/ms): 3
146.8
Elapsed Time(s/ms): 4
177.4
Sorts: 0
.0
Parse Calls: 22
1.0
Invalidations: 1
Version count: 1
Sharable Mem(K): 12
Executions: 22
SQL Text
~~~~~~~~
select count(*) from test a ,test_2 b where a.col1 = b.col1
Known Optimizer Plan(s) for this Old Hash Value
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Shows all known Optimizer Plans for this database instance, and the Snap Id's
they were first found in the shared pool. A Plan Hash Value will appear
multiple times if the cost has changed
-> ordered by Snap Id
First First Last Plan
Snap Id Snap Time Active Time Hash Value Cost
--------- --------------- --------------- ------------ ----------
114 12-6月 -08 08:5 12-6月 -08 08:5 26005100 4440
5 4
115 12-6月 -08 09:0 12-6月 -08 09:0 2540916765 2226
0 2
Plans in shared pool between Begin and End Snap Ids
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Shows the Execution Plans found in the shared pool between the begin and end
snapshots specified. The values for Rows, Bytes and Cost shown below are those
which existed at the time the first-ever snapshot captured this plan - these
values often change over time, and so may not be indicative of current values
-> Rows indicates Cardinality, PHV is Plan Hash Value
-> ordered by Plan Hash Value
--------------------------------------------------------------------------------
| Operation | PHV/Object Name | Rows | Bytes| Cost |
--------------------------------------------------------------------------------
|SELECT STATEMENT |----- 26005100 ----- | | | 4440 |
|SORT AGGREGATE | | 1 | 17 | |
| HASH JOIN | | 10K| 166K| 4440 |
| TABLE ACCESS FULL |TEST | 10K| 39K| 2215 |
| TABLE ACCESS FULL |TEST_2 | 10K| 136K| 2225 |
|SELECT STATEMENT |----- 2540916765 ----| | | 2226 |
|SORT AGGREGATE | | 1 | 17 | |
| NESTED LOOPS | | 10K| 166K| 2226 |
| TABLE ACCESS FULL |TEST_2 | 10K| 136K| 2225 |
| INDEX UNIQUE SCAN |TEST_IND | 1 | 4 | 0 |
--------------------------------------------------------------------------------
End of Report
すると、ペローンと出てきましたね。
一番したのところを見てもらうとわかると思いますが、
SQLの実行計画が二つ出てきてます。
「26005100」のほうは HASH JOIN、
「2540916765」のほうは NESTED LOOPになっています。
このそれぞれがどのタイミングで実行されていたか、は、
中ごろにある「Known Optimizer Plan(s) for this Old Hash Value」のセクションを見れば、
わかるかと思います。
「26005100」のほうは SnapId 114 のとき、
「2540916765」のほうは SnapId 115 のときとなっていますね。
あと、いろいろとほかにも役に立つ情報が出ていますので、
ぜひぜひ使ってみてください。
ではでは。
