これは何? ORACLE の内部状態を示す情報の一つである待機イベントについて解説します待機イベントを知ることで一歩進んだパフォーマンスチューニングが出来ますまた待機イベントという切り口を通して ORACLE のアーキテクチャに対する理解を深めていきますなお ORACLE のバージョンは

Size: px

Start display at page:

Download "これは何? ORACLE の内部状態を示す情報の一つである待機イベントについて解説します待機イベントを知ることで一歩進んだパフォーマンスチューニングが出来ますまた待機イベントという切り口を通して ORACLE のアーキテクチャに対する理解を深めていきますなお ORACLE のバージョンは"

ゆりなうみのなか
5 years ago
Views:

1 ORACLE 入門講座待機イベントを知ろうアリエルネットワーク鈴木健介

2 これは何? ORACLE の内部状態を示す情報の一つである待機イベントについて解説します待機イベントを知ることで一歩進んだパフォーマンスチューニングが出来ますまた待機イベントという切り口を通して ORACLE のアーキテクチャに対する理解を深めていきますなお ORACLE のバージョンは 10.2 を想定しています

3 待機イベントってなんね? ORACLE でのセッションがある特定の待機状態にあることを表したもの待機とは? ->CPU 使用中以外すべての状態 ORACLE セッションの状態 CPU 使用中待機中 SQL 解析処理検索条件による絞込み処理ソート処理行ロック待ちディスク I/O 完了待ち他のプロセスの処理完了待ちユーザからの要求待ち

4 待機イベントを知ると何がうれしい? なんとなく ORACLE が遅いでもその原因が分からないそんなとき何が起きてて遅いのかが分かる ORACLE の内部動作を透かしてみることが出来る

5 まずは見てみよう今接続しているセッションの待機イベントを見てみる v$session(9i 以前では v$session_wait) で現在接続しているセッションの待機イベントを調べることが出来る $ sqlplus /as sysdba SQL> select sid, username, event, state from v$session; SID USERNAME EVENT STATE HANA_TEST SQL*Net message from client WAITING 22 LEOTEST SQL*Net message from client WAITING 24 HANA_TEST SQL*Net message from client WAITING 28 TOZAWA SQL*Net message from client WAITING 29 V160 SQL*Net message from client WAITING 30 LEOTEST SQL*Net message from client WAITING 32 V160 SQL*Net message from client WAITING 37 V160 SQL*Net message from client WAITING 126 SYS SQL*Net message to client WAITED SHORT TIME 以下略 103 rows selected. SQL> なにが起きているか? => 何も起きてませんなお STATE が WAITING でない場合は CPU 使用中の状態 EVENT には前回待機したイベントが表示される

6 待機イベントを見る方法待機イベントを確認する方法としては見たい尺度によって以下の方法がある採り方見方については必要に応じて後で述べる 1. 今発生している待機イベント v$session, v$session_wait 2. システム起動時からの累計 v$system_event 3. セッションごとの累計 v$session_event 4. 任意のセッションで発生した全ての待機イベント SQL トレース 5. ある期間内で発生した待機イベントの統計 AWR, Statspack, bstat/estat ( 内部では期間開始点と終了点での v$system_event の差分をとっている )

7 ここまで読んで分かったあとは自分で調べるという人のために # もうひとつ重要な情報待機イベントは最大 3 つのパラメータを持っていてイベントの詳細情報を示しているパラメータはそれぞれ P1, P2, P3 という列名で v$session から確認できる各パラメータの意味は待機イベントによって異なる例えば db file scattered read なら P1: 読み込むファイル番号 P2: 読み込みを開始するブロック番号 P3: 読み込むブロック数となるその他各待機イベントに関する説明はリファレンスマニュアルの付録に書いてある主だった待機イベントについてはパフォーマンスチューニングガイドに解説ありとはいえ書いてある内容を理解するには ORACLE のアーキテクチャに対する理解がまぁそこそこそれなりに必須なので次からで軽くおさらいする

8 ORACLE の登場人物その 1: プロセスユーザプロセス :ORACLE へ要求を発行するプロセス SQL*Plus とかユーザ作成の DB アプリとかサーバプロセス : ユーザプロセスの要求を受け取ってデータの処理を行うプロセスバックグラウンドプロセス :ORACLE のメンテナンス処理を担当基本的にはユーザの要求とは非同期に活動する待機イベントではサーバプロセスとバックグラウンドプロセスの状態を確認できるユーザプロセスユーザプロセス SQL データメッセージサーバプロセスサーバプロセス ORACLE バックグラウンドプロセス

9 ORACLE の登場人物その 2:SGA システムグローバルエリアの略サーバプロセスとバックグラウンドプロセス達が共通して参照できるメモリ領域 UNIX 系では共有メモリ WINDOWS ではスレッド間で共用できるメモリ領域として表現される SGA の中身としては以下の領域があるデータベースバッファキャッシュ : データをキャッシュする領域 ORACLE では一部の例外を除いてデータのやり取りはバッファキャッシュを通して行われる共有プール :SQL の解析結果をキャッシュしておく領域足りなくなると SQL がエラーになる場合がある REDO ログバッファ :REDO ログ情報 (ORACLE の更新ログ ) をバッファリングする領域 LGWR( ログライター ) バックグラウンドプロセスで逐次 REDO ログファイルに書き出されるその他 : ラージプール JAVA プールなど SGA データベースバッファキャッシュ共有プール REDO ログバッファその他

10 ORACLEの登場人物その3: ファイル群データファイル : 表や索引などデータベースオブジェクトのデータを格納する領域 UNDOデータファイル : 正確にはデータファイルの一種データの更新時に更新前のイメージを格納一時ファイル : ソート用の作業領域などに使用 REDOログファイル :REDOログを格納する領域制御ファイル : データファイルの位置など管理情報を格納以上を踏まえてまずは SQL を発行したときにどんな待機イベントが発生するか見ていく

11 SELECT 実行時の動作 1.select 文を発行 2. バッファキャッシュに欲しいブロックが存在するか確認ユーザプロセスサーバプロセスバッファキャッシュ 4. バッファキャッシュからデータを読み込む 5. 絞込みやソート処理を行う必要な場合は一時ファイルを使用する 3. キャッシュになかったらデータファイルから読込む読んだブロックはキャッシュにのせる必要に応じて複数データファイルから読み込みを行う 6. データを返す一時ファイルデータファイル

12 SELECT 実行時の動作 - 発生する待機イベント [ よく出る ] db file sequential read データファイルからの読み込み待ち 1 イベントで 1 ブロック読み込み索引経由の表アクセスなどで発生する db file scattered read データファイルからの読み込み待ち 1 イベントで複数ブロック読み込み全件検索での表アクセスで発生する [ 時々出る ] direct path read temp direct path write temp 一時ファイルに対する read/write ディスクソートが行われたときに発生する [ まれに出る ] buffer busy waits バッファ上の競合による待ち SELECT 同士では同時にデータファイルからの読み込みが必要となった場合に発生 free buffer waits バッファに乗せようとしたら空きバッファが足りなかった場合発生する変更済みのブロックがファイルに書き出されて空きができるまで待機する

13 実際に見てみよう SQL トレースを用いて (1) $ sqlplus /nolog # 下準備ディスク I/O の発生を見たいのであえてバッファキャッシュをクリアする SQL> conn /as sysdba SQL> alter system flush buffer_cache; System altered. SQL> conn suzu/suzu # SQL トレースの開始 waits=>true で待機イベントを採取できる SQL> exec dbms_monitor.session_trace_enable(waits=>true, binds=>true); PL/SQL procedure successfully completed. # トレースしたい SQL の実行ここでは索引を使った表アクセス SQL> select * from suzutab where col1 = '128'; COL1 COL # SQL トレースの停止これをしないとトレースが増え続けるので注意 SQL> exec dbms_monitor.session_trace_disable(); PL/SQL procedure successfully completed.

14 実際に見てみよう SQL トレースを用いて (2) トレースファイルが user_dump_dest に出力されていることを確認 $ ls -lrt tail -n -rwxrwx Administrators SYSTEM Aug 29 17:05 arieldb_ora_528.trc $ tkprof arieldb_ora_528.trc tkp1.txt [tkp1.txt の中身 ] select * from suzutab where col1 = '128' ( 略 ) 実行計画などの情報 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited Waited db file sequential read SQL*Net message to client SQL*Net message from client その SQL で発生した待機イベントが統計情報として出力される

15 実際に見てみよう SQL トレースを用いて (3) トレースファイルの中身を見てみる PARSING IN CURSOR #2 len=40 dep=0 uid=68 oct=3 lid=68 tim= hv= ad='1d863ec8' select * from suzutab where col1 = '128' END OF STMT PARSE #2:c=62500,e=248963,p=12,cr=30,cu=0,mis=1,r=0,dep=0,og=1,tim= BINDS #2: EXEC #2:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim= WAIT #2: nam='sql*net message to client' ela= 5 driver id= #bytes=1 p3=0 obj#=-1 tim= WAIT #2: nam='db file sequential read' ela= 172 file#=4 block#= blocks=1 obj#=59239 tim= WAIT #2: nam='db file sequential read' ela= 154 file#=4 block#= blocks=1 obj#=59239 tim= WAIT #2: nam='db file sequential read' ela= 150 file#=4 block#= blocks=1 obj#=59238 tim= FETCH #2:c=0,e=777,p=3,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim= WAIT #2: nam='sql*net message from client' ela= 296 driver id= #bytes=1 p3=0 obj#=59238 tim= FETCH #2:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim= WAIT #2: nam='sql*net message to client' ela= 3 driver id= #bytes=1 p3=0 obj#=59238 tim= WAIT #2: nam='sql*net message from client' ela= 324 driver id= #bytes=1 p3=0 obj#=59238 tim= STAT #2 id=1 cnt=1 pid=0 pos=1 obj=59238 op='table ACCESS BY INDEX ROWID SUZUTAB (cr=4 pr=3 pw=0 time=768 us)' STAT #2 id=2 cnt=1 pid=1 pos=1 obj=59239 op='index UNIQUE SCAN SYS_C (cr=3 pr=2 pw=0 time=532 us)' WAIT #0: nam='sql*net message to client' ela= 3 driver id= #bytes=1 p3=0 obj#=59238 tim= *** :04: WAIT #0: nam='sql*net message from client' ela= driver id= #bytes=1 p3=0 obj#=59238 tim= ===================== 発生した待機イベントが 1 つずつトレースされているのでより詳細な情報を得ることが出来る

16 実際に見てみよう SQL トレースを用いて (4) トレースファイルからファイル番号 4 のブロック番号 , , を読み込んでいることが分かったこれはどのオブジェクトだろう? dba_extents から確認 SQL> select segment_name, segment_type from dba_extents 2 where file_id = 4 and between block_id and (block_id+blocks-1); SEGMENT_NAME SEGMENT_TYPE SUZUIDX INDEX SQL> select segment_name, segment_type from dba_extents 2 where file_id = 4 and between block_id and (block_id+blocks-1); SEGMENT_NAME SEGMENT_TYPE SUZUIDX INDEX SQL> select segment_name, segment_type from dba_extents 2 where file_id = 4 and between block_id and (block_id+blocks-1); SEGMENT_NAME SEGMENT_TYPE SUZUTAB TABLE 索引経由の表アクセスをしていることが分かった

17 トレースを見て分かったこと ( 想像図 ) 索引 :SUZUIDX Read 1 block# μs 表 :SUZUTAB Read 3 block# μs Read 2 block# μs

18 UPDATE 実行時の動作 1.updatet 文を発行 2. バッファ上の行をロックユーザプロセスサーバプロセスバッファキャッシュログバッファ 5.update 完了を通知 3. ログバッファに REDO レコードを記録 4. バッファ上のデータを更新一時ファイルデータファイル # バッファ上にデータがない場合は SELECT と同じ動作でファイルから読み込む

19 UPDATE 実行時の動作 - 発生する待機イベント [ よく出る ] enq: TX - row lock contention 行ロック待ち別のセッションと同一行を更新しようとしている場合がほとんどレアなケースとしては一意制約がついている列に重複した値を更新しようとしているケースでも同じ待機イベントになる [ 時々出る ] buffer busy waits SELECT 以外の DML 同士では同一ブロックに対するメモリ上の更新が同時に行われた場合に発生 [ まれに出る ] log buffer space REDO ログバッファに書き込もうとしたら空きがなかった場合に発生する LGWR プロセスが REDO ログファイルに書き出しをして空きが出来るまで待機する

20 enq: TX を見てみるその 1 ケース 1 通常の行競合 [ セッション 1] SQL> update suzutab set col2=col2+1 where col1 = 1; 1 row updated. [ セッション 2] SQL> update suzutab set col2=col2+1 where col1 = 1; => 待機状態になる [ セッション 3] SQL> select sid, username, event from v$session where username = 'SUZU'; SID USERNAME EVENT SUZU SQL*Net message from client 142 SUZU enq: TX - row lock contention 確かに enq: TX が発生する

21 enq: TX を見てみるその 2 ケース 2 重複行の更新 [ セッション 1] SQL> insert into suzutab (col1) values (10000); 1 row created. (col1 には一意制約がついている ) [ セッション 2] SQL> insert into suzutab (col1) values (10000); => セッション 1 が commit されればエラーになるがまだの場合待機状態になる [ セッション 3] SQL> select sid, username, event from v$session where username = 'SUZU'; SID USERNAME EVENT SUZU SQL*Net message from client 142 SUZU enq: TX - row lock contention

22 COMMIT 実行時の動作 1commit 文を発行 2.LGWR にログの書き出しを依頼ユーザプロセスサーバプロセスバッファキャッシュログバッファ 4. ログ書き出しの完了を通知 3. ログバッファの内容を REDO ログファイルに書き出し LGWR 5.commit 完了を通知一時ファイルデータファイル REDO ログファイル

23 UPDATE 実行時の動作 - 発生する待機イベント [ よく出る ] log file sync LGWR からの応答待ちほとんどの場合 commit すると必ず発生する

24 その他の主な待機イベント [ アイドルイベント ] SQL*Net message from client ユーザプロセスからの応答待ち要するに何もしていない [ バックグラウンドプロセスのイベント ] db file parallel write DBWR によるデータファイルへの書き出し完了待ち基本的にはユーザセッションと非同期に実施されるが待機時間が長い場合には影響を与える場合もある log file parallel write LGWR による REDO ログファイルへの書出し完了待ち待機時間が長いとユーザセッションでの log file sync 待ちが長くなる [SGA 上の競合による待機 ] library cache pin 共有プール上のライブラリキャッシュに対するロック SQL の解析が多い場合に発生する latch free SGA 上の領域に対するロック解放待ち小さい領域を短時間ロックしているのが普通どの領域で競合しているかによって原因が異なる

25 AWR, Statspack, bstat/estat で見る待機イベント (1) 任意の 2 点で採取したスナップショット間の差分を整形して出力したもの待機イベント以外にも様々な統計情報が出力される DB 起動 snap1 snap2 snap4 snap3 始点に snap1, 終点に snap3 を指定 snap1 から snap3 の期間の DB 稼動状況のレポート出力

26 AWR, Statspack, bstat/estat で見る待機イベント (2) Statspack レポートの待機イベントセクション Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time CPU time db file sequential read control file parallel write 1, control file sequential read db file scattered read

27 終わりに ORACLE の待機イベントについて説明しましたパフォーマンスを解析するにあたって待機イベントを知っておくと何かと便利です

~~~~~~~~~~~~~~~~~~ wait Call CPU time 1, latch: library cache 7, latch: library cache lock 4, job scheduler co

072 DB Magazine 2007 September ~~~~~~~~~~~~~~~~~~ wait Call CPU time 1,055 34.7 latch: library cache 7,278 750 103 24.7 latch: library cache lock 4,194 465 111 15.3 job scheduler coordinator slave wait