Oracle10gのSQLチューニングについての検証 その2

<Oracle10gのSQLチューニングについての検証 その2>
~v$sql活用編~
ペンネーム: りん

先週に引き続き、v$sqlのWAITイベントをチェックしていきます。

先週はAPPLICATION_WAIT_TIMEの値を見てきました。
先週はTraceを仕掛けたのですが、もっとお手軽に見る方法がないものでしょ
うか?

前回と同じように…

1.セッションAで更新
SQL> update test_table set value = '500' where id = '500';

1行が更新されました。

2.セッションBで更新
SQL> update test_table set value = '500' where id = '500';
*****ロック解放待ちが発生します*****

セッションA、セッションBの順でCommitを発行し、v$sqlを参照します。

SQL> select sql_text,application_wait_time from v$sql where application_wait_time != '0';

SQL_TEXT                                             APPLICATION_WAIT_TIME
---------------------------------------------------- ---------------------
update test_table set value = '500' where id = '500'                   993

ここまでは先週と同じです。
APPLICATION_WAIT_TIMEが9.93秒であったことはわかります。
内訳を知る為に前回は、Event Traceを仕掛けることによりトレースファイル
から更新ロックであることがわかりましたが、今回は、10gから追加された
v$session_wait_classと、v$session_eventを参照します。

まず、待ちが発生したSIDをv$sessionから探します。

SQL> select sid,username from v$session where username = 'RIN';

       SID USERNAME
---------- ------------------------------
       251 RIN

SQL> select sid,event,total_waits,time_waited 
  2  from v$session_event where sid = '251' 
  3  order by total_waits desc;

       SID EVENT                         TOTAL_WAITS TIME_WAITED
---------- ----------------------------- ----------- -----------
       251 SQL*Net message to client              14           0
       251 SQL*Net message from client            13        8365
       251 db file sequential read                 4           3
       251 enq: TX - row lock contention           4         993
       251 log file sync                           2           0

RINユーザのセッション(SID:251)には、なにやら、いろんなWAITイベントが
発生しているようです。
これらをカテゴライズするために、EVENT_IDをキーに、v$event_nameを参照し
ます。

SQL> select name,wait_class from v$event_name where event_id in 
  2  ( select event_id from v$session_event s where s.sid = '251' );

NAME                                     WAIT_CLASS
---------------------------------------- --------------------
log file sync                            Commit
db file sequential read                  User I/O
enq: TX - row lock contention            Application
SQL*Net message to client                Network
SQL*Net message from client              Idle

今回、Applicationにカテゴライズされているのは、enq: TX – row lock
contentionだけですね。
TraceやStatspackを取得しなくても1度のSQL文でAPPLICATION_WAIT_TIMEが
分かります。
順を追って書いてきましたが、一回のSQL文で見ると以下のようになります。

SQL> select en.wait_class,en.name,se.time_waited
 2      from
 3          v$event_name en, v$session_event se
 4      where
 5          en.event_id = se.event_id and
 6          en.wait_class != 'Idle' and      -- Idle イベントは除外
 7          se.sid = ( select sid from v$session where username = 'RIN' ) -- 指定のセッションID
 8      order by se.time_waited desc;

WAIT_CLASS           NAME                                     TIME_WAITED
-------------------- ---------------------------------------- -----------
Application          enq: TX - row lock contention                    993
User I/O             db file sequential read                            9
Commit               log file sync                                      0
Network              SQL*Net message to client                          0

このセッションでの、WAITイベントは、Applicationクラスの更新ロック待ち
に9.93秒。I/O処理に、0.09秒費やしたと判断できます。

では、この方法で、どんなイベントがキャッチアップできるのでしょうか?
TPC負荷プログラムを使用して、280セッションで負荷をかけてみた結果です。

v$session_eventでは、セッションが終了してしまうと最終的な結果を参照す
るのが難しそうなので、v$system_eventの差分を使用します。

実行前
SQL> select event,sum(se.total_waits),sum(se.total_timeouts),sum(se.time_waited),en.wait_class
  2 from
  3     v$system_event se, v$event_name en
  4 where
  5     se.event_id = en.event_id and
  6     en.wait_class = 'Application'
  8 group by event, wait_class
  9 order by sum(se.total_waits);

レコードが選択されませんでした。

Applicationクラスのものは存在しないようです。

実行後
SQL> select event,sum(se.total_waits) total_w,
 2  sum(se.total_timeouts) total_t,
 3  sum(se.time_waited) time_w,en.wait_class
 2  from
 3      v$system_event se, v$event_name en
 4  where
 5      se.event_id = en.event_id and
 6      en.wait_class = 'Application'
 7  group by event, wait_class
 8  order by sum(se.time_waited);

EVENT                          TOTAL_W TOTAL_T TIME_W WAIT_CLASS
------------------------------ ------- ------- ------ --------------------
enq: TX - row lock contention        8       0      6 Application

SQL> select sql_text,application_wait_time,concurrency_wait_time,user_io_wait_time,plsql_exec_time
 2  from
 3      v$sql
 4  where
 5      application_wait_time > 0;

  SQL_TEXT                                                                        
  --------------------------------------------------------------------------------
#1 BEGIN tpc_engine.tpc_stress(:1,:2); END;                                       
#2 UPDATE WAREHOUSE SET W_YTD = W_YTD + :B2 WHERE W_ID = :B1                      
#3 UPDATE DISTRICT SET D_YTD = D_YTD + :B3 WHERE D_W_ID = :B2 AND D_ID = :B1      

  APPLICATION_WAIT_TIME CONCURRENCY_WAIT_TIME USER_IO_WAIT_TIME PLSQL_EXEC_TIME
  --------------------- --------------------- ----------------- ---------------
#1                    7                   254              2847        17705118
#2                    4                    11                 0               0
#3                    3                    40                 0               0

tpc_engineパッケージ内のUpdate文が2件APPLICATION_WAIT_TIMEを検出しトー
タルで、0.07秒であることがわかります。
しかし、v$system_eventを参照すると、0.06秒となっています。
若干異なるのはなぜでしょう?

今回作成されたTraceファイルを確認してみます。

WAIT #17: nam='enq: TX - row lock contention' ela= 5041 p1=1415053318 p2=393218 p3=1061
WAIT #17: nam='enq: TX - row lock contention' ela= 830 p1=1415053318 p2=393218 p3=1103
WAIT #17: nam='enq: TX - row lock contention' ela= 654 p1=1415053318 p2=262182 p3=1625
WAIT #29: nam='enq: TX - row lock contention' ela= 5944 p1=1415053318 p2=393245 p3=1044
WAIT #29: nam='enq: TX - row lock contention' ela= 18263 p1=1415053318 p2=393218 p3=1061
WAIT #32: nam='enq: TX - row lock contention' ela= 26111 p1=1415053318 p2=393236 p3=1079
WAIT #29: nam='enq: TX - row lock contention' ela= 5031 p1=1415053318 p2=393234 p3=1083
WAIT #22: nam='enq: TX - row lock contention' ela= 2105 p1=1415053318 p2=131081 p3=1172

8件存在するので、v$system_eventのTotal_Waits=8と一致します。
elaの値を合計してみると、63979マイクロ秒、つまり0.06秒であることが判ります。
しかし、v$sqlビューは値が若干違います。

WAITの後に番号がついています。#??っていう部分です。
WAIT #17:←この部分です。

それぞれの番号が、なんのSQL文なのかを確認してみると

17…UPDATE WAREHOUSE SET W_YTD = W_YTD + :B2 WHERE W_ID = :B1
29…UPDATE WAREHOUSE SET W_YTD = W_YTD + :B2 WHERE W_ID = :B1
32…UPDATE DISTRICT SET D_YTD = D_YTD + :B3 WHERE D_W_ID = :B2 AND D_ID = :B1
22…UPDATE DISTRICT SET D_YTD = D_YTD + :B3 WHERE D_W_ID = :B2 AND D_ID = :B1

という結果でした。

それぞれのelaを合計すると

17…6525(0.01)
29…29238(0.03)
32…26111(0.03)
22…2105(0.00)

となります。
全てマイクロ秒単位なので、これを秒に変換し、小数点第3位を四捨五入して
100分の1秒以下は切り捨てたのが()の中の数字です。

それぞれのSQL文毎に集計し、突き合わせてみると

UPDATE WAREHOUSE SET W_YTD = W_YTD + :B2 WHERE W_ID = :B1→0.04秒
UPDATE DISTRICT SET D_YTD = D_YTD + :B3 WHERE D_W_ID = :B2 AND D_ID = :B1→0.03秒

となるので、v$sqlとv$system_eventの計算方法の違いによる誤差みたいですね

次回は、Application以外のWAITについても調べたいと思います。

最近、自炊にこだわる茅ヶ崎にて