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

Ok, from what I can see, here are the/some issues. You hit the nail right on the head with the CR values.

fast DB:
under fetch: query = 1,613,065
latch: cache buffers chains = 3

Slow DB:
under fetch: query = 40,083,925
latch: cache buffers chains = 2957
buffer busy waits = 11

Query is: Number of times a buffer was returned in consistent mode, that is, the data is for query only and has not been modified since the SELECT statement started.
(http://www.oreilly.com/catalog/oracle2/chapter/ch10.html#18051)

Consistant mode is: A read consistent version of the block, it has changed since the start of the query and the block has to be made read consistent. This basically means oracle had to clone the block and roll it back, slower than reading a consistent block: "As data blocks are read on behalf of the query, only blocks written with the observed SCN are used. Blocks with changed data (more recent SCNs) are reconstructed from data in the rollback segments, and the reconstructed data is returned for the query. Therefore, each query returns all committed data with respect to the SCN recorded at the time that query execution began. Changes of other transactions that occur during a query's execution are not observed, guaranteeing that consistent data is returned for each query."
(http://download-east.oracle.com/docs/cd/A81042_01/DOC/server.816/a76965/c23cnsis.htm#17882)

Slow DB has a significant number of cache buffer chain waits, possibly because it is fighting over blocks to read in the select that are being changed at the same time. Could be other blocks on the chain hogging the latch, but I doubt it.

buffer busy waits: not a lot of time but more proof you are fighting over changing blocks.

also, for size comparison, don't use dba_tables, those are statistical values and could be incorrect. You will want to select sum(bytes)/1024/1024 sz from dba_segments where segment_name='PS_TM_PEFF_GPQ';

So, what is going on in the slow database? Is it prod and fast is dev? Is the hardware comparable?

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
Received on Mon Oct 23 2006 - 11:33:01 CDT