Re: Inordinate IO wait times

Jim,

I had a similar problem, but on HP running against an XP1024 via a SAN. Oracle reported unacceptability long reads while the SAN guys said the disk array was performing fantastically.

The problem ended up being caused by our volume manager (Veritas). It was using a default read-ahead value when random I/O was done (something I never really saw the purpose of), but it calculated 128mb as it's default read-ahead value (product of read_nstream and read_pref_io). This meant that Oracle was trying to do "db file seq reads" and the volume manager was asking the disk array for 128mb each time.

Symptoms were very low logical reads to high block reads (sar -b shows you this).

Solution was to adjust settings in our tunefstab file (read_nstream=1 & read_pref_io=64k worked well).

Good luck,

Scott Hutchinson
Interact Analysis Ltd

Quoting oracle-l-bounce_at_freelists.org:

>
> We are on Oracle 9.2 on solaris. In looking at a trc files (both raw
> and via tkprof I see IO wait times as high as 1.19 seconds per IO.
> (I put the ,'s in
> for easier reading) ela/1million cumulative
>
> WAIT #1: nam='db file sequential read' ela=
> 1,188,929 p1=163 p2=241404 p3=1 1.188929 1.188929
> WAIT #1: nam='db file sequential read' ela=
> 1,183,896 p1=158 p2=347805 p3=1 1.183896 2.372825
> WAIT #1: nam='db file sequential read' ela=
> 1,175,133 p1=163 p2=236918 p3=1 1.175133 3.547958
> WAIT #1: nam='db file sequential read' ela=
> 1,174,606 p1=158 p2=65952 p3=1 1.174606 4.722564
> WAIT #1: nam='db file sequential read' ela=
> 1,170,150 p1=163 p2=244818 p3=1 1.17015 5.892714
> WAIT #1: nam='db file sequential read' ela=
> 1,074,119 p1=164 p2=241569 p3=1 1.074119 6.966833
> WAIT #1: nam='db file sequential read' ela=
> 1,068,852 p1=158 p2=1135 p3=1 1.068852 8.035685
>
> Or from a different tkprof report(same query)
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.03 0.02 0 0 0
> 0
> Execute 1 0.00 0.00 0 0 0
> 0
> Fetch 1 38.34 66.67 83667 1007156 0
> 1
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 3 38.37 66.70 83667 1007156 0
> 1
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> SQL*Net message to client 3 0.00
> 0.00
> SQL*Net message from client 3 127.31
> 127.38
> db file sequential read 83667 1.18
> 39.54
> SQL*Net break/reset to client 1 0.00
> 0.00
> ************************************************************************
> ********
>
> The SQLNet messages are due in part ot executing one statement at a time
> so throw those out.
>
> Any ideas? We are on a SAN. The SAN guy claims this can't be
> happening.
> Thanks,
> Jim
> --
> http://www.freelists.org/webpage/oracle-l
>

::This message sent using the free Web Mail service from http://TheName.co.uk

--
http://www.freelists.org/webpage/oracle-l