Oracle10gのSQLチューニングについての検証 その２
＜Oracle10gのSQLチューニングについての検証 その２＞
～v$sql活用編～
ペンネーム： りん
先週に引き続き、v$sqlのWAITイベントをチェックしていきます。
先週はAPPLICATION_WAIT_TIMEの値を見てきました。
先週はTraceを仕掛けたのですが、もっとお手軽に見る方法がないものでしょ
うか？
前回と同じように…
１．セッションAで更新 SQL> update test_table set value = '500' where id = '500'; 1行が更新されました。 ２．セッション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についても調べたいと思います。
最近、自炊にこだわる茅ヶ崎にて