IO Latency

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


=========================


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