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

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

In addition to what has already been mentioned, "SQL*Net message from client" is 112.61 seconds for the slow database compared to 69.23 seconds for the fast database. The slow database waited 43 seconds longer for responses from the client than the fast database.

You will also note that there are fewer leaf blocks in the faster database's indexes, which indicates that the index entries are more densely packed than that of the slower database's indexes. Fewer blocks means that there will likely be fewer consistent reads.

My guess is that the fast database was recently created from an import.

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc. Received on Mon Oct 23 2006 - 12:00:39 CDT