Oracle10g AWRに関する検証 その４
＜Oracle10g AWR(Automatic Workload Repository)に関する検証 その４＞
～自動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秒以下の短時間の待ちは拾えない確率が非常に
高いからです。ただし、サンプリングの頻度を高くすることにより信頼性は
向上します。もちろん、パフォーマンスの低下という副作用も考慮する必要
はありますが。
以上、夏の終わりを告げるカツオちゃん、茅ヶ崎にて