待ちイベントに関する検証 その2

投稿日: 2006年12月13日

<待ちイベントに関する検証 その2>
ペンネーム: ダーリン

【SQL*Net message from/to client】

さて、先週は FETCH の回数(下記コメント参照)が処理レスポンスに影響を
与えることを確認しました。今週は待ちイベントとしてはどのような変化が見
られたかを確認していきます。

※ “FETCH 回数” ≒ [FETCH SIZE] / [検索件数] で求められます。
※ [FETCH SIZE] : カーソルを利用してデータを取得する際に、検索結果を配列
などに取り出すレコード数の単位。
SQL*Plus では ARRAYSIZE を変更することで変更できます。

対象の処理:
SQL> select * from test_tbl;

上記の SQL を実行しているセッションの待ちイベントは以下のような感じで
した。

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

そこで、先週のサンプルスクリプトを実行して、上記SQLを実行しましょう。
すると、ARRAYSIZE によって以下のような値が得られたのではないでしょうか。
もちろん環境によって数値は異なることでしょうが、変化の傾向は同じではな
いかと思います。

 [SQL*Net message from client]
   ARRAYSIZE TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO
 ----------- ----------- ----------- -----------------
           1       50002       5178           51775624
          15        6669       2978(※1)      29776818
          50        2002       4050           40506611
         100        1002       3424           34237115
 ----------- ----------- ----------- -----------------
 [SQL*Net message to client]
   ARRAYSIZE TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO
 ----------- ----------- ----------- -----------------
           1       50002          22            212763
          15        6669           3             30924
          50        2002           1              7908
         100        1002           1              5293
 ----------- ----------- ----------- -----------------

どうやら ARRAYSIZE を大きく設定した方が待ち回数 ( TOTAL_WAITS ) は減少
する傾向にあります。このとき、ばらつきはあるのですが、”SQL*Net message
from client”の待ち時間は短くなる傾向にあります。ただし、ARRAYSIZE を
大きくすると先週示したとおり、全体の処理時間は短くなります。

ちょっと言い回しを変えるならば、、
———————————————————–
アプリケーションでクエリーを実行する際の FETCH SIZE を変える
と、パフォーマンスが変わる。
———————————————————–
ということです。

これは、1レコード検索するだけのクエリーを発行しているようなアプリケー
ションでは影響ありません。大量の明細を取得・表示するような画面系・帳票
系のアプリケーションや、バッチ系の処理で影響が出てきます。

今回の 待ちイベント”SQL*Net message from/to client”が変化する要因はほ
かにもないでしょうか。通信経路の問題でも待ち時間が影響を受けそうな気が
します。
それでは、イタズラしてみましょう。今回はクエリーを実行しながら、同じセ
グメント内で 200MB のファイルを FTP 転送しどのくらいの影響が出るのか見
てみました。

結論からいうと、今回の検証環境では FTP を同時実行すると 2~5 秒程度パ
フォーマンスが低下しました。このとき、待ちイベントの待ち回数 ( TOTAL_WAITS )
には変化がありませんでしたが、待ち時間は少々のばらつきとともに長くなっ
ていることを確認しています。

   ARRAYSIZE クライアント側処理時間
               FTP なし    FTP あり
 ----------- ----------- ----------
           1    約 39 秒   約 41 秒
          15    約 15 秒   約 20 秒
          50    約 15 秒   約 17 秒
         100    約 14 秒   約 16 秒
 ----------- ----------- ----------

同様に、待ち時間(TIME_WAITED)はこんな感じです。

[SQL*Net message from client] FTP なし
ARRAYSIZE TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO
———– ———– ———– —————–
1 50002 7150 71498150
15 6669 6089 60893397
50 2002 5280 52798731
100 1002 5328 53225566
———– ———– ———– —————–

 [SQL*Net message from client]  FTP あり
   ARRAYSIZE TOTAL_WAITS TIME_WAITED TIME_WAITED_MICRO
 ----------- ----------- ----------- -----------------
           1       50002       9756           97563955
          15        6669       9109           91096126
          50        2002       8621           86213048
         100        1002       9106           91058186
 ----------- ----------- ----------- -----------------

この待ちイベント(SQL*Net message from client)の変化を継続的に監視す
ると、Network障害とまではいかないまでも、トラフィックの混雑により処理
が遅延しているということを把握できるかもしれませんね。

最後に、今回どうにも気になったことに簡単に触れておきます。クライアント
側処理時間ですが、たとえば、ARRAYSIZE が 15(デフォルト)の検証では約
20 秒でした。しかし、V$SESSION_EVENT での待ち時間 ( TIME_WAITED ) はこ
のとき 29.78 秒を示しています。(※1)
こんなことがあっていいのでしょうか!?

そんなはずありません。

しかし、マニュアルには以下のように明記してあります。
————————————————————-
TIME_WAITED セッションによるイベントの合計待機時間(1/100 秒)
————————————————————-

でも、これはどうにも納得が行かないですよね。では困ったときのトレースを
とりましょう。

SQL> alter session set sql_trace=true;

SQL> select * from test_tbl;

すると、、

...................   ........................

Elapsed times include waiting on following events:
 Event waited on             Times  Max. Wait  Total Waited
 --------------------------- Waited ---------- ------------
 SQL*Net message to client     6668       0.00         0.03
 SQL*Net message from client   6668       0.04        15.97

 ...................   ........................

ということで、実際には 29.78 秒ではなく 16 秒程度の待ち時間が発生して
いたようです。クライアント側で処理時間と考えていた時間(約 20 秒)の大半
が、実はネットワーク上でのやり取りの時間だったんですね。
特に、大量データをやり取りするような処理では少々遅くてもしようがないな
ぁとあきらめる前に、一度アプリケーションの FETCH SIZE を調整してみると、
案外効果があるかも知れません。
ちなみに、ARRAYSIZE に関する検証は下記のメルマガでも触れていますのでご
参照ください。

<Oracle 9iに関する検証 その3>
~ データベース・バッファのヒット率 続き ~
https://old.insight-tec.com/mailmagazine/ora3/vol099.html

それでは今年はこの辺で。
来年もよろしくお付き合いください。

江ノ島の灯台を眺めながら
茅ヶ崎にて