待ちイベントに関する検証 その１
＜待ちイベントに関する検証 その１＞
ペンネーム： ダーリン
【SQL*Net message from/to client】
焼き芋が恋しい季節になりました。I can’t wait for YAKIIMO !!
しかし、「いーしやーきいもー、焼き芋っ。」の声は聞こえても、こっちに来
てくれないことには、なかなか焼き芋にありつくことができません。待てば待
っただけのありがたみはあるのですが、それが Oracle データベースへの問い
合わせの結果となると、ありがたいどころかイライラするだけです。
このメルマガではこれまで Oracle の待ちイベントに絡んだ検証をたびたび
実施してきましたが、今回は少し視点を変えて SQL の処理を追いかける形で
ポイントでの待ちイベントを追いかけてみたいと思います。
Oracle でパフォーマンスチューニングを実施するときは、いくつかアプロー
チがあります。皆さんはどこにフォーカスするでしょうか。まず、パフォーマ
ンスが変化した際のイベントがわかっていれば、その作業に着目するでしょう。
たとえば、機能を追加した場合は、新しいSQLが実行されていることでしょう。
もしかすると負荷が高いSQLだったりするかもしれません。あるいは、月次で
大量のデータが投入されたかもしれません。もしこのようにパフォーマンスが
変化したきっかけが特定できていれば、そこに注目して関連する処理を洗い出
し、場合によっては負荷の高い SQL をチューニングするといったステップが
考えられます。
では、何がどうなって遅くなったか、まったく思い当たらない場合はどうしま
しょうか。
Oracle には Wait Interface と呼ばれるいわゆる動的パフォーマンスビュー
があります。たとえば、V$SESSION（10g から Wait の情報も参照できるよう
になりました。）や、V$SYSTEM_EVENT がそうです。これらを検索することで、
Oracle データベース内(あるいはセッション内)で、何が起こっているのかを
把握することができます。
Oracle の待ち情報はこれらのビューから得ることができるので、これらをう
まく活用することで、Oracle のサボりを効果的に排除できるかも知れません。
では早速、Oracle からデータを取得してどんな待ちイベントが発生するのか
見ていきましょう。
今回 Client として DBA の皆さんには馴染み深い、SQL*Plus を利用します。
SQL> select * from test_tbl; C1 C2 C3 ----- ----- ----- 1 1 1 2 2 2 3 3 3 4 4 4 ... ... ... 99995 99995 99995 99996 99996 99996 99997 99997 99997 99998 99998 99998 99999 99999 99999 99999行が選択されました。 経過: 00:00:20.03
さて、ここではどんな待ちイベントが発生していたのでしょう。
SQL> select sid,username from v$session where username = 'TTT';
SID USERNAME
---------- ------------------------------
142 TTT
SQL> select SID,EVENT,TOTAL_WAITS,TIME_WAITED
2 , TIME_WAITED_MICRO ,WAIT_CLASS
3 from v$session_event where sid = 142
4 order by TIME_WAITED_MICRO;
SID EVENT TOTAL_WAITS TIME_WAITED
----- ------------------------------ ----------- -----------
142 SQL*Net break/reset to client 1 0
142 SQL*Net message to client 180335 101
142 SQL*Net message from client 180334 495941
TIME_WAITED_MICRO WAIT_CLASS
----------------- -------------
37 Application
1010033 Network
4959408972 Idle
あらら？
Net Service 関連の待ちだけですね。しかも待ち時間が最も大きいものは
「WAIT_CLASS」が “Idle” です。ということは、特にチューニングできるポイ
ントはなさそうですね。
たしかに、今回試した SQL はシンプル極まりない SQL です。
では、次へ……
おっとっと。
ちょっと待ってください。本当にチューニングの余地はないのでしょうか。た
しか、”SQL*Net message from client” は “Idle” イベントに分類されるとお
りクライアントからのリクエストを待機している時間です。クライアントから
リクエストがなければ Oracle は待つしかありません。これではチューニング
できないですよね。
“SQL*Net message from client” はクライアントからのリクエストを待ってい
るイベント（時間）です。ここで注意しなくてはならない点があります。クラ
イアントから Oracle に対するリクエストは、クエリーの実行毎に発生してい
るわけではありません。 SQL*Plus ではその FETCH のタイミング毎 にリクエ
ストが発生しています。
クライアント側から見た SQL の処理は、リクエストを投げてから結果が返っ
てくるまでの(通信の時間も含めた)時間が処理時間と認識されます。つまり、
アプリケーションとしては処理の最初と最後の通信時間だけでなく、その処理
中に実施されている各 FETCH の際にかかる通信の時間も処理時間に含まれる
ことを認識する必要があります。
では、FETCH 回数がどれくらいパフォーマンスに影響するかチェックしてみま
しょう。
今回試したクエリーを SQL*Plus の ARRAYSIZE だけを変えて実行してみます。
すると、、、
ARRAYSIZE クライアント側処理時間
----------- ----------------------
1 約 60 秒
15 約 20 秒
50 約 16 秒
100 約 14 秒
----------- ----------------------
ほほう。結構な違いが見られました。
ちなみに SQL*Plus のデフォルト値は 15 です。
FETCH 毎に何が起こっているのかを簡単に説明すると、
1) FETCH 毎(この場合ARRAYSIZE分の検索結果ごと)にクライアントに対して
結果を返す。
2) クライアント側でこれを受信。
3) 再度クライアントから次の結果要求を送る。
4) さらにサーバが次の検索結果を FETCH し次の結果をクライアントに返す。
という感じです。
ところで ARRAYSIZE の違いは待ちイベントに何らかの影響を与えているので
しょうか？
では ARRAYSIZE の違いと WAIT EVENT の関連を見てみましょう。
ここでは V$SESSION_EVENT ビューを使いますが、これは対象セッション接続
後からの累計値を格納していますので、各処理ごとのイベント発生状況を捉え
るためには、差分（※）を取得する必要があります。
※ 差分を取得する対象は、
TOTAL_WAITS(*)
TOTAL_TIMEOUTS
TIME_WAITED(*)
TIME_WAITED_MICRO(*)
です。
今回は(*)について着目します。
データ取得に使ったスクリプトをサンプルとしてリストしておきますので、た
めしに特定の待ちイベントの情報をとってみてください。
続きはまた来週。
V$SESSION_EVENT から情報を取得するスクリプト
# 実行前に "set serveroutput on" を忘れずに。
# Event 名と SID は適宜環境に合わせて設定してください。
～～～～～～～～～～～～～～～～～～～～～～～～～～～～～～
declare
v_event varchar2(100) := 0;
v_event_1st varchar2(100) := 0;
v_event_2nd varchar2(100) := 0;
v_total_waits number(38,0) := 0;
v_total_waits_1st number(38,0) := 0;
v_total_waits_2nd number(38,0) := 0;
v_time_waited number(38,0) := 0;
v_time_waited_1st number(38,0) := 0;
v_time_waited_2nd number(38,0) := 0;
v_time_waited_micro number(38,0) := 0;
v_time_waited_micro_1st number(38,0) := 0;
v_time_waited_micro_2nd number(38,0) := 0;
begin
select event,total_waits,time_waited, time_waited_micro
into v_event_1st,v_total_waits_1st,v_time_waited_1st, v_time_waited_micro_1st
from v$session_event
where event = ''
and sid =
order by event;
dbms_lock.sleep(30);
select event,total_waits,time_waited, time_waited_micro
into v_event_2nd,v_total_waits_2nd,v_time_waited_2nd, v_time_waited_micro_2nd
from v$session_event
where event = ''
and sid =
order by event;
v_event := v_event_2nd;
v_total_waits := v_total_waits_2nd - v_total_waits_1st;
v_time_waited := v_time_waited_2nd - v_time_waited_1st;
v_time_waited_micro := v_time_waited_micro_2nd - v_time_waited_micro_1st;
dbms_output.put_line('event=['||v_event ||'] total_waits=['||v_total_waits ||']
time_waited=['||v_time_waited ||'] time_waited_micro=['||v_time_waited_micro ||']');
end;
/
～～～～～～～～～～～～～～～～～～～～～～～～～～～～～～
目指せ世界のNo.1 !! (アジア大会じゃないよ)
茅ヶ崎にて