Re: IO Latency

From: Christo Kutrovsky <kutrovsky.oracle_at_gmail.com>
Date: Wed, 16 Apr 2008 16:30:40 +0400
Message-ID: <52a152eb0804160530h6041e086h4e429264e0e15859@mail.gmail.com>

Stefan,

I am also noticing in your sample that these are consequitive reads (probably range scan):

WAIT #5: nam='db file sequential read' ela= 152381 p1=817 p2=55704 p3=1
WAIT #5: nam='db file sequential read' ela= 994952 p1=817 p2=55705 p3=1
WAIT #5: nam='db file sequential read' ela= 473715 p1=817 p2=55706 p3=1
WAIT #5: nam='db file sequential read' ela= 908138 p1=817 p2=55707 p3=1
WAIT #5: nam='db file sequential read' ela= 317399 p1=817 p2=55708 p3=1
WAIT #5: nam='db file sequential read' ela= 145632 p1=817 p2=55709 p3=1

So we're not talking about randomly taking longer, but consistently IOs taking between 0.5 and 0.9 seconds. I doubt this is fibre saturation, I am thinking:

really busy box on the CPU side slowing things down
really busy SAN
really really busy IO subsystem

I am thinking the CPU saturated box is more probable, perhaps you can check CPU usage reports for the time period? If that's not it, then it must be the SAN.

I have succeeded in consistently achieving 0.3 seconds 8K reads, but I had 3000 sessions performing IO. So it's not impossible, questions is where is it happening.

And the fact that those are sequencial means that at least for 3 seconds the something was really busy.

-- 
Christo Kutrovsky
DBA Team Lead
The Pythian Group - www.pythian.com
I blog at http://www.pythian.com/blogs/



On Tue, Apr 15, 2008 at 4:31 PM, Stefan Knecht <knecht.stefan_at_gmail.com> wrote:


> Hi all

>

> I'm quite puzzled after reading some measurements taken at a client's IBM DS

> 8300 Storage subsystem:

>

> I simply checked the db file sequential reads, and their elapsed times

> (Single block, random IOs):

>  IO < 1ms: 354323 ( 83.995856 s)

> IO > 1ms < 10ms: 268747 (1579.35787 s)

> IO > 10ms: 90622 (1683.17106 s)

> IO > 100ms: 1641 (435.2602 s)

>

> Here, more than 400 seconds are spent waiting on 8k block reads taking more

> than 0.1 seconds to complete.

>

> Some of the slower IOs:

>

> WAIT #5: nam='db file sequential read' ela= 337694 p1=817 p2=30189 p3=1

> WAIT #5: nam='db file sequential read' ela= 659507 p1=817 p2=30190 p3=1

> WAIT #5: nam='db file sequential read' ela= 627676 p1=817 p2=30191 p3=1

>  WAIT #5: nam='db file sequential read' ela= 1462442 p1=817 p2=30192 p3=1

> WAIT #5: nam='db file sequential read' ela= 564961 p1=817 p2=30194 p3=1

> WAIT #5: nam='db file sequential read' ela= 301716 p1=817 p2=30195 p3=1

>  WAIT #5: nam='db file sequential read' ela= 322558 p1=817 p2=30196 p3=1

> WAIT #5: nam='db file sequential read' ela= 140098 p1=817 p2=30197 p3=1

> WAIT #5: nam='db file sequential read' ela= 207357 p1=817 p2=32992 p3=1

>  WAIT #5: nam='db file sequential read' ela= 141286 p1=817 p2=33395 p3=1

> WAIT #5: nam='db file sequential read' ela= 128484 p1=817 p2=33396 p3=1

> WAIT #5: nam='db file sequential read' ela= 154993 p1=817 p2=34657 p3=1

>  WAIT #5: nam='db file sequential read' ela= 184916 p1=817 p2=36667 p3=1

> WAIT #5: nam='db file sequential read' ela= 485711 p1=817 p2=36669 p3=1

> WAIT #5: nam='db file sequential read' ela= 213660 p1=817 p2=36670 p3=1

>  WAIT #5: nam='db file sequential read' ela= 430529 p1=817 p2=36671 p3=1

> WAIT #5: nam='db file sequential read' ela= 268854 p1=817 p2=38575 p3=1

> WAIT #5: nam='db file sequential read' ela= 206652 p1=817 p2=38576 p3=1

>  WAIT #5: nam='db file sequential read' ela= 1063243 p1=817 p2=38577 p3=1

> WAIT #5: nam='db file sequential read' ela= 1633832 p1=817 p2=38578 p3=1

> WAIT #5: nam='db file sequential read' ela= 817684 p1=817 p2=38580 p3=1

>  WAIT #5: nam='db file sequential read' ela= 592915 p1=817 p2=45003 p3=1

> WAIT #5: nam='db file sequential read' ela= 534241 p1=817 p2=45004 p3=1

> WAIT #5: nam='db file sequential read' ela= 413292 p1=817 p2=45007 p3=1

>  WAIT #5: nam='db file sequential read' ela= 230145 p1=817 p2=45011 p3=1

> WAIT #5: nam='db file sequential read' ela= 381934 p1=817 p2=45012 p3=1

> WAIT #5: nam='db file sequential read' ela= 181148 p1=817 p2=45076 p3=1

>  WAIT #5: nam='db file sequential read' ela= 110949 p1=817 p2=45314 p3=1

> WAIT #5: nam='db file sequential read' ela= 162128 p1=817 p2=45317 p3=1

> WAIT #5: nam='db file sequential read' ela= 4087470 p1=817 p2=47846 p3=1

>  WAIT #5: nam='db file sequential read' ela= 2523277 p1=817 p2=47847 p3=1

> WAIT #5: nam='db file sequential read' ela= 543395 p1=817 p2=47848 p3=1

> WAIT #5: nam='db file sequential read' ela= 306027 p1=817 p2=48300 p3=1

>  WAIT #5: nam='db file sequential read' ela= 290364 p1=817 p2=48301 p3=1

> WAIT #5: nam='db file sequential read' ela= 209011 p1=817 p2=48774 p3=1

> WAIT #5: nam='db file sequential read' ela= 162027 p1=817 p2=49262 p3=1

>  WAIT #5: nam='db file sequential read' ela= 991631 p1=817 p2=49308 p3=1

> WAIT #5: nam='db file sequential read' ela= 1597445 p1=817 p2=49309 p3=1

> WAIT #5: nam='db file sequential read' ela= 361672 p1=817 p2=49310 p3=1

>  WAIT #5: nam='db file sequential read' ela= 125203 p1=817 p2=49311 p3=1

> WAIT #5: nam='db file sequential read' ela= 871656 p1=817 p2=50141 p3=1

> WAIT #5: nam='db file sequential read' ela= 620677 p1=817 p2=50142 p3=1

>  WAIT #5: nam='db file sequential read' ela= 231273 p1=817 p2=50352 p3=1

> WAIT #5: nam='db file sequential read' ela= 127751 p1=817 p2=51652 p3=1

> WAIT #5: nam='db file sequential read' ela= 153915 p1=817 p2=53935 p3=1

>  WAIT #5: nam='db file sequential read' ela= 100457 p1=817 p2=55332 p3=1

> WAIT #5: nam='db file sequential read' ela= 222074 p1=817 p2=55359 p3=1

> WAIT #5: nam='db file sequential read' ela= 138484 p1=817 p2=55360 p3=1

>  WAIT #5: nam='db file sequential read' ela= 152381 p1=817 p2=55704 p3=1

> WAIT #5: nam='db file sequential read' ela= 994952 p1=817 p2=55705 p3=1

> WAIT #5: nam='db file sequential read' ela= 473715 p1=817 p2=55706 p3=1

>  WAIT #5: nam='db file sequential read' ela= 908138 p1=817 p2=55707 p3=1

> WAIT #5: nam='db file sequential read' ela= 317399 p1=817 p2=55708 p3=1

> WAIT #5: nam='db file sequential read' ela= 145632 p1=817 p2=55709 p3=1

>  WAIT #5: nam='db file sequential read' ela= 782488 p1=817 p2=55890 p3=1

> WAIT #5: nam='db file sequential read' ela= 453189 p1=817 p2=55891 p3=1

> WAIT #5: nam='db file sequential read' ela= 977405 p1=817 p2=55892 p3=1

>  WAIT #5: nam='db file sequential read' ela= 553599 p1=817 p2=55893 p3=1

>

> How the hell can an 8k IO, on a state-of-the-art SAN take 4 seconds to

> complete ????'

>

> Anyone ever see something like this, or has a potential explanation ??

>

> Cheers

>

> Stef

>

>

> --

> =========================

>

> Stefan P Knecht

> Senior Consultant

> Infrastructure Managed Services

>

> Trivadis AG

> Europa-Strasse 5

> CH-8152 Glattbrugg

>

> Phone +41-44-808 70 20

> Fax +41-808 70 12

> Mobile +41-79-571 36 27

> stefan.knecht_at_trivadis.com

> http://www.trivadis.com

>

> OCP 9i/10g SCSA SCNA

> =========================




-- 
Christo Kutrovsky
DBA Team Lead
The Pythian Group - www.pythian.com
I blog at http://www.pythian.com/blogs/
--
http://www.freelists.org/webpage/oracle-l

Received on Wed Apr 16 2008 - 07:30:40 CDT

This message: [ Message body ]
Next message: Charles Schultz: "Re: Help me solve this cardinality puzzle"
Previous message: Christo Kutrovsky: "Help me solve this cardinality puzzle"
In reply to: Stefan Knecht: "IO Latency"
Next in thread: Stefan Knecht: "Re: IO Latency"

Contemporary messages sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

Original text of this message