Oracle10g AWRに関する検証 その5

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

前回はOEM(上位SQL)で問題のSQLを特定している部分をみました。ただし、
v$active_session_historyへデータを入れる頻度が1秒間隔であるため、待ち
時間に関する信頼性は低いという懸念あります。

今回は別の視点から待ちが発生しているSQLを追っていきます。ターゲットと
なる表は以下の待ちに関するメトリック情報(ある期間での計測値)の履歴を
持つ表です。ポイントは累積値ではなく差分値であるという事です。

□V$EVENTMETRIC
過去60秒の各イベントの待ち時間を保持
□V$WAITCLASSMETRIC
過去60秒の各イベント・クラスの待ち時間を保持
□V$WAITCLASSMETRIC_HISTORY
過去1時間の各イベント・クラスの待ち時間を、60秒毎に保持

ちなみにこれらの表の元表は同じx$kewmevmvです。
ではV$EVENTMETRICから検索してみましょう。検証環境は前回と同じです。

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

上記の環境にOLTP系の一定のトランザクションを実施
※前回と同様のトランザクションを実行
*********************************************************************

ちなみにv$eventmetricは60秒以上前は保持していません。やはりデータ量が
多くなるからではないでしょうか。このような表は定期的に手動でロギング
するのがいいかもしれません。

□v$eventmetric よりメモリ上にある過去60秒間の待ちイベントの情報を検索

select
n.wait_class
, n.name
, e.TIME_WAITED/100 TIME_WAITED    -- 単位を秒に変換
, e.WAIT_COUNT  WAIT_COUNT
from v$eventmetric e , v$event_name n
where e.event# = n.event#
and e.event_id = n.event_id
and e.wait_count > 0
and n.wait_class <> 'Idle'         -- Idle イベントを除外
order by e.time_waited desc

WAIT_CLASS           NAME                           TIME_WAITED WAIT_COUNT
-------------------- ------------------------------ ----------- ----------
Commit               log file sync                          .67        955
Application          enq: TX - row lock contention          .25          1
System I/O           control file parallel write            .11         26
Concurrency          latch: library cache                    .1         55
Network              SQL*Net message to client              .06      33447
User I/O             db file sequential read                .05         19
Application          SQL*Net break/reset to client          .03        260
Other                latch free                               0          1
System I/O           control file sequential read             0         10
Network              SQL*Net more data from client            0          7
Network              SQL*Net more data to client              0          4

1分間の待ち時間の累積値をみると、commitによる”log file sync”が最も長
い時間で、0.67秒となっています。待ちが発生した回数は955回ですので、1
回当りの待ち時間は約0.0067秒です。一方のロック待ち(enq: TX – row lock
contention)が発生した回数は、1回ですが、1回当りの待ち時間は”log file
sync”と比較してはるかに大きな値となっています(0.25秒)。

■システム全体でみると一番の問題はcommitによる”log file sync”です。
??本当にそうでしょうか?バッチ処理のような処理であれば、バッチ処理
全体の処理時間の短縮を行う為にcommitの回数を減らす等がチューニングポ
イントになるかもしれません。しかし、OLTP系の処理であれば、一番の問題
はロック待ちによって0.25秒も待たされているユーザがいる事ではないでし
ょうか?つまりトランザクションの特性も考慮する必要があります。

単純に考えると、以下の事が言えそうです。
OLTP系の処理であればSQL単体の待ち時間が長いSQLからアプローチする。
バッチ系の処理であれば待ち時間の累積値からアプローチする。

もちろん、実際のチューニングを実施する場合は両方からアプローチが必要
です!

ある時間での待ち時間が分かれば、v$active_session_historyから待ちイベ
ントを指定してSQLを特定出来ます。もちろん”サンプリングされていた場合”
という条件が付きます。

■待ち時間だけではなくCPU処理時間も見る
ここまで、待ちイベントだけに注目してきましたが、最後にCPUの使用状況が
どうなっているか見てみます。v$eventmetricは1分間の情報しかないので、
v$waitclassmetric_history とv$sysmetric_historyをみます。これらの表は
1時間の履歴を1分毎に保持しています。

□過去1時間の1分毎でのCPU使用時間、及び待ち時間を確認

select
  to_char(w.begin_time,'yyyymmdd hh24:mi')      BEGIN_TIME
  , n.wait_class                                WAIT_CLASS
  , w.time_waited/100                           TIME
from
  v$waitclassmetric_history w,
  (select distinct wait_class#, wait_class from v$event_name) n
where w.wait_class# = n.wait_class#
  and n.wait_class <> 'Idle'
 UNION ALL
select
  to_char(begin_time,'yyyymmdd hh24:mi')        BEGINE_TIME
  , 'CPU Usage'                                 WAIT_CLASS
  , value*60/100                                TIME
from v$sysmetric_history
where metric_name = 'CPU Usage Per Sec' and group_id = 2
order by BEGIN_TIME, TIME desc


BEGIN_TIME     WAIT_CLASS                 TIME
-------------- -------------------- ----------
20040827 17:02 CPU Usage                    24  ←CPU
20040827 17:02 Commit                       .9
20040827 17:02 System I/O                  .18
20040827 17:02 User I/O                     .1
20040827 17:02 Network                     .06
20040827 17:02 Application                 .03
20040827 17:02 Configuration               .02
20040827 17:02 Other                         0
20040827 17:02 Concurrency                   0
20040827 17:02 Scheduler                     0
20040827 17:02 Cluster                       0
20040827 17:02 Administrative                0
20040827 17:03 CPU Usage                    24  ←ココから1分後の統計
20040827 17:03 Commit                      .69
20040827 17:03 System I/O                  .08
20040827 17:03 Network                     .07
20040827 17:03 User I/O                    .04
20040827 17:03 Application                 .02
20040827 17:03 Concurrency                 .01
・
・
<以下省略>

CPUでの処理時間25に対して待ち時間は約1 の割合です。それほど深刻な状況
では無いといえそうです。大量のディスクI/Oが発生してディスクのビジー率
が100%に張り付いているような環境では、I/O待ち時間がCPU処理時間が1:1の
割合となります。このような環境ではチューニングを行う事によるレスポン
スが大き改善される可能性が高いと言えます。

以上、去り行く夏、4度目の秋来たる茅ヶ崎にて