| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Long wait times for db file scattered read
I'm running this query during different windows. The first run
executes in about half the time as the second. The vast majority of
wait time in both runs, and the difference wait time between the runs
comes from waits to cache blocks from one particular table. Note those
blocks have been fetched after an index scan on that table.
Does anyone know if the difference in physical reads alone would account for such a difference in wait time? What would cause such waits in either case? The Sys Admin has told me there's no I/O bottleneck at the system level.
Thanks in advance,
John
RUN #1
call count cpu elapsed disk query current rows misses
Parse 1 0.00 0.00 0 0
0 0 0
Execute 1 0.00 0.01 1 9
0 0 0
Fetch 69 181.54 751.54 518290 1875375
0 1017 0
total 71 181.54 751.55 518291 1875384
0 1017 0
| Rows Row Source Operation
| ------------ ---------------------------------------------------
| 1017 SORT GROUP BY (cr=1875375 pr=518290 pw=0 time=204.20)
| 5884 .HASH JOIN OUTER (cr=1875375 pr=518290 pw=0
time=204.15)
| 4068 ..FILTER (cr=1874535 pr=517457 pw=0 time=750.74)
| 4364 ...NESTED LOOPS OUTER (cr=1874535 pr=517457 pw=0
time=750.67)
| 4364 ....NESTED LOOPS (cr=1865942 pr=516369 pw=0
time=747.60)
| 5420 .....HASH JOIN (cr=1860520 pr=516356 pw=0 time=747.41)
| 1355 ......TABLE ACCESS FULL OBJ# DMPRODUCT (cr=5298 pr=1661
pw=0 time=3.61)
| 45140 ......NESTED LOOPS (cr=1855222 pr=514695 pw=0
time=743.62)
| 45140 .......NESTED LOOPS (cr=1674662 pr=514695 pw=0
time=739.64)
| 1 ........HASH JOIN (cr=62 pr=30 pw=0 time=0.06)
| 179 .........HASH JOIN (cr=34 pr=26 pw=0 time=0.05)
| 179 ..........TABLE ACCESS FULL OBJ# DM_REGIONTERRITORY
(cr=28 pr=26 pw=0 time=0.04)
| 53 ..........VIEW (cr=6 pr=0 pw=0 time=0.01)
| 53 ...........HASH JOIN (cr=6 pr=0 pw=0 time=0.01)
| 53 ............INDEX FAST FULL SCAN OBJ#
LANGUAGE_17162011642 (cr=3 pr=0 pw=0 time=0.00)
| 53 ............INDEX FAST FULL SCAN OBJ# XAK1LANGUAGE
(cr=3 pr=0 pw=0 time=0.00)
| 729 .........TABLE ACCESS FULL OBJ# TERRITORY (cr=28 pr=4
pw=0 time=0.00)
| 45140 ........INLIST ITERATOR (cr=1674600 pr=514665 pw=0
time=739.43)
| 45140 .........TABLE ACCESS BY INDEX ROWID OBJ# DMLEGALRIGHTS
(cr=1674600 pr=514665 pw=0 time=739.31)
| 8080060 ..........INDEX RANGE SCAN OBJ# AK7DMLEGALRIGHTS
(cr=30342 pr=30205 pw=0 time=33.35)
| 45140 .......INLIST ITERATOR (cr=180560 pr=0 pw=0 time=3.22)
| 45140 ........INDEX UNIQUE SCAN OBJ# MEDIA_15812486882
(cr=180560 pr=0 pw=0 time=2.22)
| 4364 .....INDEX UNIQUE SCAN OBJ# PK_DMPRODUCTFILTER (cr=5422
pr=13 pw=0 time=0.16)
| 4068 ....TABLE ACCESS BY INDEX ROWID OBJ# DMPRODUCT (cr=8593
pr=1088 pw=0 time=3.01)
| 4068 .....INDEX UNIQUE SCAN OBJ# XPKDMPRODUCT (cr=4069 pr=76
pw=0 time=0.33)
| 19053 ..INDEX FAST FULL SCAN OBJ# PRODUCTCAT_10247227033
(cr=840 pr=833 pw=0 time=0.44)
Event Times Count Max. Total Blocks waited on Waited Zero Time Wait Waited Accessed -------------------------------------------------------------------------- --------- --------- --------- ---------
db file sequential read (single block scan)...................... 517427 0 1.08 635.85 517427 db file scattered read (multiblock full scan).................... 113 0 0.07 0.32 864 latch free (097 cache buffers chains)............................ 40 0 0.02 0.05 latch free (092 cache buffers lru chain)......................... 1 0 0.00 0.00 SQL*Net message from client (idle)............................... 69 0 0.12 0.30 SQL*Net message to client (idle)................................. 69 0 0.00 0.00 -------------------------------------------------------------------------- --------- --------- --------- ---------
total............................................................ 517719 0 1.08 636.52 518291 non-idle waits................................................... 517581 0 1.08 636.22 518291 idle waits....................................................... 138 0 0.12 0.30 Details for wait event Times Count Max. Total Blocks 'db file sequential read (single block scan)' Waited Zero Time Wait Waited Accessed -------------------------------------------------------------------------- --------- --------- --------- ---------
europe.dmlegalrights............................................. 484460 0 1.08 613.03 484460 europe.ak7dmlegalrights.......................................... 30205 0 0.10 17.51 30205 world.dmproduct.................................................. 2671 0 0.03 4.99 2671 world.xpkdmproduct............................................... 76 0 0.02 0.24 76 europe.pk_dmproductfilter........................................ 13 0 0.01 0.05 13 dbo.productcat_10247227033....................................... 2 0 0.01 0.02 2 -------------------------------------------------------------------------- --------- --------- --------- ---------
total............................................................ 517427 0 1.08 635.85 517427 ******************************************************************************** ********************************************************************************
RUN #2
call count cpu elapsed disk query current rows misses
Parse 1 0.00 0.00 0 0
0 0 0
Execute 1 0.00 0.01 1 9
0 0 0
Fetch 69 217.14 1577.93 622969 1875375
0 1017 0
total 71 217.14 1577.94 622970 1875384
0 1017 0
| Rows Row Source Operation
| ------------ ---------------------------------------------------
| 1017 SORT GROUP BY (cr=1875375 pr=622969 pw=0 time=1577.92)
| 5884 .HASH JOIN OUTER (cr=1875375 pr=622969 pw=0
time=1577.88)
| 4068 ..FILTER (cr=1874535 pr=622136 pw=0 time=1577.12)
| 4364 ...NESTED LOOPS OUTER (cr=1874535 pr=622136 pw=0
time=1577.04)
| 4364 ....NESTED LOOPS (cr=1865942 pr=620565 pw=0
time=1569.38)
| 5420 .....HASH JOIN (cr=1860520 pr=620527 pw=0 time=1569.04)
| 1355 ......TABLE ACCESS FULL OBJ# DMPRODUCT (cr=5298 pr=3336
pw=0 time=4.35)
| 45140 ......NESTED LOOPS (cr=1855222 pr=617191 pw=0
time=1564.33)
| 45140 .......NESTED LOOPS (cr=1674662 pr=617191 pw=0
time=1559.86)
| 1 ........HASH JOIN (cr=62 pr=13 pw=0 time=0.12)
| 179 .........HASH JOIN (cr=34 pr=0 pw=0 time=0.01)
| 179 ..........TABLE ACCESS FULL OBJ# DM_REGIONTERRITORY
(cr=28 pr=0 pw=0 time=0.00)
| 53 ..........VIEW (cr=6 pr=0 pw=0 time=0.01)
| 53 ...........HASH JOIN (cr=6 pr=0 pw=0 time=0.01)
| 53 ............INDEX FAST FULL SCAN OBJ#
LANGUAGE_17162011642 (cr=3 pr=0 pw=0 time=0.00)
| 53 ............INDEX FAST FULL SCAN OBJ# XAK1LANGUAGE
(cr=3 pr=0 pw=0 time=0.00)
| 729 .........TABLE ACCESS FULL OBJ# TERRITORY (cr=28 pr=13
pw=0 time=0.10)
| 45140 ........INLIST ITERATOR (cr=1674600 pr=617178 pw=0
time=1559.60)
| 45140 .........TABLE ACCESS BY INDEX ROWID OBJ# DMLEGALRIGHTS
(cr=1674600 pr=617178 pw=0 time=1559.46)
| 8080060 ..........INDEX RANGE SCAN OBJ# AK7DMLEGALRIGHTS
(cr=30342 pr=30325 pw=0 time=49.99)
| 45140 .......INLIST ITERATOR (cr=180560 pr=0 pw=0 time=3.63)
| 45140 ........INDEX UNIQUE SCAN OBJ# MEDIA_15812486882
(cr=180560 pr=0 pw=0 time=2.56)
| 4364 .....INDEX UNIQUE SCAN OBJ# PK_DMPRODUCTFILTER (cr=5422
pr=38 pw=0 time=0.27)
| 4068 ....TABLE ACCESS BY INDEX ROWID OBJ# DMPRODUCT (cr=8593
pr=1571 pw=0 time=7.60)
| 4068 .....INDEX UNIQUE SCAN OBJ# XPKDMPRODUCT (cr=4069
pr=109 pw=0 time=0.75)
| 19053 ..INDEX FAST FULL SCAN OBJ# PRODUCTCAT_10247227033
(cr=840 pr=833 pw=0 time=0.63)
Event Times Count Max. Total Blocks waited on Waited Zero Time Wait Waited Accessed -------------------------------------------------------------------------- --------- --------- --------- ---------
db file sequential read (single block scan)...................... 619315 0 2.39 1440.64 619315 db file scattered read (multiblock full scan).................... 850 0 0.15 3.78 3655 latch free (097 cache buffers chains)............................ 7 0 0.02 0.04 latch free (092 cache buffers lru chain)......................... 8 0 0.00 0.02 latch free (156 library cache pin)............................... 1 0 0.00 0.00 SQL*Net message from client (idle)............................... 69 0 0.03 0.17 SQL*Net message to client (idle)................................. 69 0 0.00 0.00 -------------------------------------------------------------------------- --------- --------- --------- ---------
total............................................................ 620319 0 2.39 1444.65 622970 non-idle waits................................................... 620181 0 2.39 1444.48 622970 idle waits....................................................... 138 0 0.03 0.18 Details for wait event Times Count Max. Total Blocks 'db file sequential read (single block scan)' Waited Zero Time Wait Waited Accessed -------------------------------------------------------------------------- --------- --------- --------- ---------
europe.dmlegalrights............................................. 586853 0 2.39 1400.29 586853 europe.ak7dmlegalrights.......................................... 30325 0 0.23 32.81 30325 world.dmproduct.................................................. 1978 0 0.09 6.65 1978 world.xpkdmproduct............................................... 109 0 0.04 0.65 109 europe.pk_dmproductfilter........................................ 38 0 0.02 0.15 38 dbo.territory.................................................... 10 0 0.02 0.07 10 dbo.productcat_10247227033....................................... 2 0 0.01 0.02 2 -------------------------------------------------------------------------- --------- --------- --------- ---------
total............................................................ 619315 0 2.39 1440.64 619315Received on Wed Mar 17 2004 - 14:42:40 CST
 |
 |