• Oracle Database
• 2013.02.26
• 渡部 亮太

‘db file parallel read’ 待機イベントに遭遇

新しい年から新しい仕事を担当することになりドタバタしております。 ちょっと仕事に忙殺されていたら、いつのまにか2月もおしまい、 このままでは今月はblogを何も書いていないことになるので、・・・という わけではありませんが、最近気づいた軽い小ネタを。

社内エンジニア向けのパフォーマンスセミナーのために、連続した ブロックを single block read で読み込むような、わざと非効率な処理が 実行されるような状況を作ってSQLトレースで待機イベントを確認していました。 待機イベント 'db file sequential read' の多発を予想していましたが、 予想に反して・・・・

FETCH #140254762512424:c=1000,e=10943,p=15,cr=16,cu=0,mis=0,r=15,dep=0,og=1,plh=1883323623,tim=1358511742639742
WAIT #140254762512424: nam='SQL*Net message from client' ela= 211 driver id=1650815232 #bytes=1 p3=0 obj#=86194 tim=1358511742640040
WAIT #140254762512424: nam='db file parallel read' ela= 586 files=1 blocks=14 requests=14 obj#=86194 tim=1358511742640817
WAIT #140254762512424: nam='db file sequential read' ela= 30 file#=5 block#=14543 blocks=1 obj#=86194 tim=1358511742640983
WAIT #140254762512424: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=86194 tim=1358511742641037
FETCH #140254762512424:c=0,e=1023,p=15,cr=16,cu=0,mis=0,r=15,dep=0,og=1,plh=1883323623,tim=1358511742641155
WAIT #140254762512424: nam='SQL*Net message from client' ela= 207 driver id=1650815232 #bytes=1 p3=0 obj#=86194 tim=1358511742641430
WAIT #140254762512424: nam='db file parallel read' ela= 355 files=1 blocks=14 requests=14 obj#=86194 tim=1358511742641945
WAIT #140254762512424: nam='db file sequential read' ela= 28 file#=5 block#=2552 blocks=1 obj#=86194 tim=1358511742642102
WAIT #140254762512424: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=86194 tim=1358511742642157
FETCH #140254762512424:c=0,e=793,p=15,cr=16,cu=0,mis=0,r=15,dep=0,og=1,plh=1883323623,tim=1358511742642276
WAIT #140254762512424: nam='SQL*Net message from client' ela= 207 driver id=1650815232 #bytes=1 p3=0 obj#=86194 tim=1358511742642550
WAIT #140254762512424: nam='db file parallel read' ela= 7901 files=1 blocks=14 requests=14 obj#=86194 tim=1358511742650609
WAIT #140254762512424: nam='db file sequential read' ela= 27 file#=5 block#=14558 blocks=1 obj#=86194 tim=1358511742650781

'db file parallel read'という見慣れない待機イベントが・・・あまり情報がないのですが、 'db file'ということからデータファイルの読み出しであることは確かそう・・・。

もう少し状況を整理するために、'db file'関連の待機イベントを部分的に抜粋して・・・

'db file parallel read'   ela= 586  files=1   blocks=14 requests=14 obj#=86194 tim=1358511742640817
'db file sequential read' ela= 30   file#=5   block#=14543 blocks=1 obj#=86194 tim=1358511742640983
'db file parallel read'   ela= 7901 files=1   blocks=14 requests=14 obj#=86194 tim=1358511742650609
'db file sequential read' ela= 27   file#=5   block#=14558 blocks=1 obj#=86194 tim=1358511742650781

さらに、ブロックIDとブロック数に着目してみると・・・・

'db file sequential read' ... block#=14543
'db file parallel read'   ... blocks=14
'db file sequential read' ... block#=14558
                    14543 + 1 + 14 = 14558

以下の順序で処理が動いているように見えます。

1. 'db file sequential read' で block#=14543 を1ブロック読み込み
2. 'db file parallel read' で block#=14544～47 の14ブロックを読み込み
3. 'db file sequential read' で block#=14558 を1ブロック読み込み

ということで、どうやら連続したsingle block readの多発を防ぐために、 prefetch的な動作が動いているように推測できます。 単純に動作するのであれば、連続したブロックに対してsingle block read が実行されるところですが、先行する連続ブロックを1回のI/Oでprefetch 読み出しすることで、I/O回数を削減しているのでしょう。Oracle Database なかなか気が利いています。

動作を確認したのは 11.2.0.2 Oracle Database Express Edition です。 (そのときこの環境しかインストールしていなかったので・・・) この動作が、どのバージョンから導入されたのか調べるのは、今後の宿題とします・・・それではまた。