Oracle10gのSQLチューニングについての検証 その１
＜Oracle10gのSQLチューニングについての検証 その１＞
～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) セッションＡ． SQL> update test_table set value = '20' where id = '50'; 1行が更新されました。 (2) セッションＢ． SQL> update test_table set value = '30' where id = '50'; 1行が更新されました。 (3) セッションＡ．でCommit SQL> commit; コミットが完了しました。 (4) セッションＢ．で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'
セッションＢの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の情報が取れる方法を探してみたいと思います。
肩こりが激しい茅ヶ崎にて