Oracle10g AWRに関する検証 その4

<Oracle10g AWR(Automatic Workload Repository)に関する検証 その4>
~自動SQLチューニング機能編~
ペンネーム:ちょびひげ

前回まで、以下の2つ表に関してみてきました。

□V$ACTIVE_SESSION_HISTORY
アクティブなセッションの「待ち」と「CPUを使用している」という情報の履
歴が記録される。これらの情報はデフォルトでは1分に1回、Oracleのバック
グラウンドプロセスによって記録される。

□DBA_HIST_ACTIVE_SESS_HISTORY(WRH$_ACTIVE_SESSION_HISTORY)
v$active_session_historyの情報が定期的に書き込まれるテーブルです。
デフォルトでは単位時間当りにv$active_session_historyの1/10の情報量が
格納されます。メモリ上では保持しきれない為、書き込まれます。

今回からはOEM(Oracle Enterprise Manager 10g)とSQLチューニング用のパ
ッケージであるDBMS_SQLTUNE機能を使って、問題のあるSQLの特定を行なって
いきます。

では早速、OEMでどのように、v$active_session_historyからSQLを取得して
いるのかを見ていきます。検証環境は以下の通りです。

*********************************************************************
OS :HP-UX hp11i B.11.11
Oracle:Release 10.1.0.2.0

上記の環境にOLTP系の一定のトランザクションを実施
*********************************************************************

■OEM(上位SQL)から問題のSQLを特定
OEMではSPOT(現在)とPERIOD(過去のある期間)のSQLが見れます。ではど
のくらいの期間がSPOTかといえば、v$active_session_historyに情報を保持
している期間です。

検証に基づく勘ですが、SPOT(現在)では以下のようなSQLでv$active_sessi
on_historyからSQLの情報を取得しているようです。

SELECT 
event#, sql_id, max(sql_plan_hash_value), max(sql_opcode)
      , session_id, p1
      , current_obj#, module, action, client_id
      , DECODE(wait_time, 0, 'W', 'C')
      , COUNT(*),SUM(time_waited)
      , 'I', service_hash, session_serial#, max(user_id), max(program)
FROM  v$active_session_history 
WHERE sample_time > :3
  AND sample_time <= :4 
GROUP BY event#, sql_id, session_id, p1, current_obj#
, module, action, client_id, DECODE(wait_time, 0, 'W', 'C')
, service_hash, session_serial#

ちょっと分かりづらいので重要な部分だけを抜き出し(書き換え)ます。

□最新5分のアクティブセッション情報を取得

SELECT
sql_id
, DECODE(wait_time, 0, 'WAITING', 'ON CPU')
, COUNT(*)
, SUM(time_waited)
FROM v$active_session_history
WHERE sample_time > sysdate - 5/60/24
  AND sample_time < sysdate
GROUP BY
sql_id
, DECODE(wait_time, 0, 'WAITING', 'ON CPU')

SQL_ID           EVENT     COUNT      TIME_WAITED
---------------- --------- ---------- ----------------
                 ON CPU           327                0
                 WAITING            3            83375
0rb68wt93hyk5    ON CPU             3                0
22v14pywpjbrn    ON CPU             6                0
2b064ybzkwf1y    ON CPU             1                0
2jka7qqgy3xw7    ON CPU             2                0
2umvfdn2qu9tt    ON CPU             4                0
37nvf97dxf5jg    ON CPU             1                0
37nvf97dxf5jg    WAITING            1           299744
^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^
38scc1w4puyms    ON CPU             1                0
3918g7wvyb5bt    ON CPU             2                0
3s8mjd045m52c    WAITING            1             1373
4wv642fgmjmdm    ON CPU            21                0
7u1s6ht5bx6mp    ON CPU             5                0
83c1u36qb77zh    ON CPU            58                0
8a6vguhsfapdx    ON CPU             1                0
9gguxsq7w8cyq    ON CPU             2                0
arq6hxb184y28    ON CPU             1                0
axsbhy26rk90y    ON CPU             1                0

SQL_ID      : SQLを一意に認識する為のカラム
TIME_WAITED : 単位は1/10000秒

イベント(EVENT)が”WAITNG”の場合は、SQLが待ち状態であり、サンプリング
時点での待ち時間の合計(TIME_WAITED)が確認出来ます。

■待ち時間が長いSQLが問題?
上記のSQLを見てどのSQLが問題と思われるでしょうか?
直感的には待ち時間(TIME_WAITED)が最も長いSQL(SQL_IDが37nvf97dxf5jg)
ではないでしょうか。では、v$active_session_historyから実際に何の待ち
なのかを調べて見ます。
※ここでは時間の条件は省きます

□v$active_session_historyより、SQL(SQL_IDが37nvf97dxf5jg)待ちイベ
ントを確認

select SAMPLE_TIME, TIME_WAITED, EVENT
from v$active_session_history
where TIME_WAITED > 0
and DECODE(wait_time, 0, 'WAITING', 'ON CPU') = 'WAITING'
and SQL_ID = '37nvf97dxf5jg'
             ^^^^^^^^^^^^^

SAMPLE_TIME             TIME_WAITED EVENT
----------------------- ----------- ------------------------------
04-08-20 16:37:12.461        299744 enq: TX - row lock contention
04-08-20 16:19:37.691        532661 enq: TX - row lock contention
04-08-20 16:03:40.811        612359 enq: TX - row lock contention
04-08-20 16:01:18.671        354846 enq: TX - row lock contention

SQL_IDが”37nvf97dxf5jg”のSQLの待ちの原因は、row lock contention、つま
り”行ロック”でした。

■OEMでのSQLの待ち率(WAIT%)とは?
OEMでは全体から見たSQLの待ち率が見れます。待ち率が高いSQLほど問題があ
ると言えそうです。では、OEMではどのように待ち率を導き出しているのでし
ょうか?

■TIME_WAITEDから待ち率を計算?
単純に考えれば、TIME_WAITEDの値を元に、全体の待ち時間から、SQL毎の待ち
時間を求めていると考えられます。そうすると、さきほどのロック待ちのSQL
は全体から見た待ち率は100%に近い値になります。
※SQL_IDの無いSQLはここでは無視してください

しかし、OEMでは待ち時間が”299744″のSQL(SQL_IDが37nvf97dxf5jg)と”1373″
のSQL(SQL_IDが3s8mjd045m52c)は同じ待ち率となります。
なぜなら、COUNT数(頻度)が同じだからです。

■COUNT列が意味する事
SQL_IDとEVENTでグルーピングした結果としてのレコード数、つまりサンプリ
ングされる頻度です。頻度が高いと言う事はSQLの実行時間が長い、もしくは
、実行回数が多いと考えられます。

いずれにしも確率の問題で、どちらが正しいとは言い切れません。
なぜなら、v$active_session_historyの情報は1秒に1しかアクシブなセッシ
ョンの情報を取得しない為、1秒以下の短時間の待ちは拾えない確率が非常に
高いからです。ただし、サンプリングの頻度を高くすることにより信頼性は
向上します。もちろん、パフォーマンスの低下という副作用も考慮する必要
はありますが。

以上、夏の終わりを告げるカツオちゃん、茅ヶ崎にて