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

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

今回から、SQLチューニングを行う際に役立つポイントとして
Oracle10gで追加された動的性能ビューを活用してみたいと思います。

Oracle10gになってから、v$sqlビューに下記のカラムが増えています。

 APPLICATION_WAIT_TIME                              NUMBER
 CONCURRENCY_WAIT_TIME                              NUMBER
 CLUSTER_WAIT_TIME                                  NUMBER
 USER_IO_WAIT_TIME                                  NUMBER
 PLSQL_EXEC_TIME                                    NUMBER
 JAVA_EXEC_TIME                                     NUMBER

v$sqlビューにWAITの情報が入ったことで、問題のSQL文が特定しやすくなって
いるのでしょうか

Oracle10gのマニュアルを参照してみると

 
APPLICATION_WAIT_TIME:アプリケーションの待機時間
 CONCURRENCY_WAIT_TIME:同時実行性待機時間
 CLUSTER_WAIT_TIME:クラスタの待機時間
 USER_IO_WAIT_TIME:ユーザーI/O 待機時間
 PLSQL_EXEC_TIME:PL/SQL 実行時間
 JAVA_EXEC_TIME:Java 実行時間

となっていました。ちょっと淋しい感じです。

では、どんな場合に、このカラムに値が入るのでしょうか?
まず、APPLICATION_WAIT_TIMEに着目したいと思います。

Application Wait Timeは、アプリケーションの待機時間とマニュアルには記
されていましたがアプリケーション待機時間って、どんな時にカウントされる
のだろう?

よくわかんないので、とりあえずv$sqlを参照してみると

SQL_ID        APPLICATION_WAIT_TIME CONCURRENCY_WAIT_TIME CLUSTER_WAIT_TIME
------------- --------------------- --------------------- -----------------
5a84jrtg3nv2p                     0                     0                 0
cg57vukt04v4a                     0                     0                 0
3d9f1x2pd4vbn                     0                     0                 0
1vbb8mrxrsvhq                     0                     0                 0
1vbb8mrxrsvhq                     0                     0                 0
92n4nyngnwvnt                     0                     0                 0
92n4nyngnwvnt                     0                     0                 0
0ztm3p5wp8vt0                     0                     0                 0
8507xv0prsvv5                     0                    92                 0
b2tjz6yyy8vvj                     0                     0                 0
b2tjz6yyy8vvj                     0                     0                 0

CONCURRENCY_WAIT_TIMEが92のものはあるけども後は全てが0になってます。
どういう時に、この値が0ではなくなるのだろう…

とりあえず、同時に更新がかかった場合に、どの値がどう変化するのか見るた
めに2つのセッションから、同じ行に対して更新処理をしてみます。
当然、ロック待ちが発生するはずです。

(1)  セッションA.
  SQL> update test_table set value = '20' where id = '50';

  1行が更新されました。

(2)  セッションB.
  SQL> update test_table set value = '30' where id = '50';

  1行が更新されました。

(3)  セッションA.でCommit
  SQL> commit;

  コミットが完了しました。

(4)  セッションB.でCommit
  SQL> commit;

  コミットが完了しました。

ではでは、v$sqlを確認してみますと…

SQL> select * from (
  2  select sql_id,sum(executions),sum(loads),sum(application_wait_time),sum(concurrency_wait_time),sum(cluster_wait_time),count(*)
  3  from v$sql
  4  group by sql_id
  5  order by sum(application_wait_time) desc, sum(concurrency_wait_time) desc ,  sum(cluster_wait_time) desc
  6  )
  where rownum <= 10;

SQL_ID        SUM(EXECUTIONS) SUM(LOADS) SUM(APPLICATION_WAIT_TIME)
------------- --------------- ---------- --------------------------
9y5mks5rf8x0p               1          1                       1075
02zpj2z8j95z5               1          1                          0

SUM(CONCURRENCY_WAIT_TIME) SUM(CLUSTER_WAIT_TIME)        COUNT(*)
-------------------------- ---------------------- ---------------
                         0                      0               1
                         0                      0               1

お!!APPLICATION_WAIT_TIMEが1075になってる!
合計といっても、行は1行だし、Execも1回、Loadも1回なので1つのUpdate文で
10秒程WAITしているということみたいですね。

このSQL_IDをもとに、SQL_TEXTを参照してみます。(FULL_SQL_TEXTでもOKです)

SQL> select sql_text from v$sql where sql_id = '9y5mks5rf8x0p';

SQL_TEXT
--------------------------------------------------
update test_table set value = '30' where id = '50'

セッションBのSQLですね。
本番のシステムなら「こいつかぁ!」と声が出そうです。
Applicationへの応答が遅くなっている場合に、とりあえず参照するとSQLが特
定しやすくなることはわかりました。

でも、同時更新の待ち時間って、同時実行性待機時間(CONCURRENCY_WAIT_TIME)
じゃないのかなそれにアプリケーションが10秒待ったのはわかるのだけど
もっと詳しい情報とかヒントが欲しいので、Event Traceを仕掛けてみます。

まず、SYSユーザにて、v$sessionを参照し、SIDとSerial Numberを取得します。

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

       SID    SERIAL#
---------- ----------
       272          9

SQL> execute dbms_system.set_ev(272,9,10046,12,'');

PL/SQLプロシージャが正常に完了しました。

user_dump_destに設定したディレクトリのTraceファイルを見てみます。

WAIT #1: nam='enq: TX - row lock contention' ela= 2997290 p1=1415053318 p2=262179 p3=440
WAIT #1: nam='enq: TX - row lock contention' ela= 2998152 p1=1415053318 p2=262179 p3=440
WAIT #1: nam='enq: TX - row lock contention' ela= 2997673 p1=1415053318 p2=262179 p3=440
WAIT #1: nam='enq: TX - row lock contention' ela= 1754683 p1=1415053318 p2=262179 p3=440

WAIT Eventに更新エンキューが表示されています。
ela = を合計すると、10747798となりますのが、ミリ秒単位なので秒に変換し四捨五入すると
10.75秒となります。
詳細な情報はTraceを取得することにより、情報は取れますが
次回は、もっと簡単にWAIT_TIMEの情報が取れる方法を探してみたいと思います。

肩こりが激しい茅ヶ崎にて