Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: Can anyone explain this huge increase in logical I./O....?

Re: Can anyone explain this huge increase in logical I./O....?

From: DA Morgan <damorgan_at_psoug.org>
Date: Mon, 23 Oct 2006 08:13:50 -0700
Message-ID: <1161616429.540230@bubbleator.drizzle.com>


mccmx_at_hotmail.com wrote:
> Oracle 10.2.0.2 SE on Windows 2003
>
> The following SQL runs against 2 different databases on 2 different
> servers. However it runs for 4 times longer on one of the DBs. tkprof
> shows that the explain plan is identical and the number of parse,
> execute, and fetch calls is identical. However the logical I/O count
> is drastically higher in the slower DB. Anyone have any ideas what is
> responsible for the huge increase in 'consistent reads' in the second
> DB below.
>
> DB One (fast):
>
> SELECT ROWID, PART_COUNT
> FROM
> PS_TM_PEFF_GPQ WHERE BUSINESS_UNIT = :1 AND PRODUCTION_DT = :2 AND
> SRG_CODE = :3 AND DEPTID = :4 AND PROCESS_CODE = :5 AND PART_NUM
> = :6
> AND PART_SFX_CD = :7 AND LINE_CODE = :8 AND CONV_SOURCE =
> 'ALC'
> AND CONV_STATUS <> 'M'
>
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 0 0.00 0.00 0 0 0
> 0
> Execute 320277 13.93 13.61 0 0 0
> 0
> Fetch 638104 20.70 18.85 16 1613065 0
> 317827
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 958381 34.64 32.46 16 1613065 0
> 317827
>
> Misses in library cache during parse: 0
> Optimizer mode: ALL_ROWS
> Parsing user id: 29
>
> Rows Row Source Operation
> ------- ---------------------------------------------------
> 317827 TABLE ACCESS BY INDEX ROWID PS_TM_PEFF_GPQ (cr=1613065 pr=16
> pw=0 time=14331876 us)
> 317827 INDEX UNIQUE SCAN PS_TM_PEFF_GPQ (cr=1281108 pr=16 pw=0
> time=8394762 us)(object id 13039)
>
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> cursor: pin S wait on X 10 0.01
> 0.09
> SQL*Net message to client 638104 0.00
> 0.96
> SQL*Net message from client 638104 0.01
> 69.23
> latch: cache buffers chains 3 0.00
> 0.00
> db file sequential read 16 0.11
> 0.18
> cursor: pin S 6 0.00
> 0.00
> ********************************************************************************
>
> DB Two (slow):
>
> SELECT ROWID, PART_COUNT
> FROM
> PS_TM_PEFF_GPQ WHERE BUSINESS_UNIT = :1 AND PRODUCTION_DT = :2 AND
> SRG_CODE = :3 AND DEPTID = :4 AND PROCESS_CODE = :5 AND PART_NUM
> = :6
> AND PART_SFX_CD = :7 AND LINE_CODE = :8 AND CONV_SOURCE =
> 'ALC'
> AND CONV_STATUS <> 'M'
>
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 0 0.00 0.00 0 0 0
> 0
> Execute 320277 16.21 15.97 0 0 0
> 0
> Fetch 638104 104.93 106.39 22 40083925 0
> 317827
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 958381 121.15 122.37 22 40083925 0
> 317827
>
> Misses in library cache during parse: 0
> Optimizer mode: ALL_ROWS
> Parsing user id: 29
>
> Rows Row Source Operation
> ------- ---------------------------------------------------
> 317827 TABLE ACCESS BY INDEX ROWID PS_TM_PEFF_GPQ (cr=40083925 pr=22
> pw=0 time=102291805 us)
> 317827 INDEX UNIQUE SCAN PS_TM_PEFF_GPQ (cr=1281108 pr=2 pw=0
> time=10103556 us)(object id 13039)
>
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> cursor: pin S wait on X 2 0.01
> 0.01
> SQL*Net message to client 638104 0.01
> 0.97
> SQL*Net message from client 638104 0.04
> 112.61
> db file sequential read 22 0.03
> 0.05
> latch: cache buffers chains 2957 0.00
> 0.05
> buffer busy waits 11 0.00
> 0.00
> cursor: pin S 2 0.00
> 0.00
> latch free 1 0.00
> 0.00
> ********************************************************************************
>
> I have confirmed that the non-default init.ora parameters are identical
>
> The row counts are identical and the block counts of the table and the
> clustering factor of the index are very close in both DBs:
>
> DB One (fast):
>
> select blocks, empty_blocks, avg_row_len from user_tables where
> table_name =
> 'PS_TM_PEFF_GPQ';
>
> BLOCKS EMPTY_BLOCKS AVG_ROW_LEN
> ---------- ------------ -----------
> 100382 0 52
>
> select BLEVEL, LEAF_BLOCKS, AVG_LEAF_BLOCKS_PER_KEY,
> AVG_DATA_BLOCKS_PER_KEY, CLUSTERING_FACTOR
> from user_indexes where table_name = 'PS_TM_PEFF_GPQ'
>
> BLEVEL LEAF_BLOCKS AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY
> CLUSTERING_FACTOR
> ------ ----------- ----------------------- -----------------------
> -----------------
> 3 88707 1 1
> 3700235
> 3 123732 1 1
> 10069887
>
>
> DB Two (slow):
>
> select blocks, empty_blocks, avg_row_len from user_tables where
> table_name =
> 'PS_TM_PEFF_GPQ';
>
> BLOCKS EMPTY_BLOCKS AVG_ROW_LEN
> ---------- ------------ -----------
> 101146 0 52
>
> select BLEVEL, LEAF_BLOCKS, AVG_LEAF_BLOCKS_PER_KEY,
> AVG_DATA_BLOCKS_PER_KEY, CLUSTERING_FACTOR
> from user_indexes where table_name = 'PS_TM_PEFF_GPQ'
>
> BLEVEL LEAF_BLOCKS AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY
> CLUSTERING_FACTOR
> ------ ----------- ----------------------- -----------------------
> -----------------
> 3 132011 1 1
> 4174537
> 3 125284 1 1
> 10603144
>
> Any help appreciated...
>
> Matt

And the high-water marks?

-- 
Daniel A. Morgan
University of Washington
damorgan_at_x.washington.edu
(replace x with u to respond)
Puget Sound Oracle Users Group
www.psoug.org
Received on Mon Oct 23 2006 - 10:13:50 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US