Re: Slow SQL, too many logical reads ?

On May 2, 12:40 pm, Peter <peterny..._at_gmail.com> wrote:
> On May 1, 7:15 pm, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
>
> > On May 1, 9:27 am, Peter <peterny..._at_gmail.com> wrote:
>
> > > Have a look at the following tkprof output from a 9.2.0.4 Solaris
> > > database:
>
> > > ===========================================================================­­=
>
> > > SELECT IA.IA__ICODE,IA.IA__TIMESTAMP,IA.IA__STVDATE,IA.IA__ENVDATE,
>
> > > IA.IA_IACT1,IA.IA_IACT2,IA.IA_NOTES,IA.IA_EXECU,IA.IA_MEANI,IA.IA_SEQUE,
> > > IA.IA_REASON
> > > FROM
> > > A_INDACT IA WHERE IA.IA_REASON=:"SYS_B_00" AND IA.IA_SEQUE IN
> > > ( :"SYS_B_01",
> > > :"SYS_B_02", :"SYS_B_03", :"SYS_B_04", :"SYS_B_05", :"SYS_B_06",
> > > :"SYS_B_07", :"SYS_B_08", :"SYS_B_09", :"SYS_B_10", :"SYS_B_11" )
> > > AND
> > > IA.IA_IACT2 IN ( SELECT AA.AA__ICODE FROM A_ACTA AA WHERE
> > > AA.AA_IPERM=
> > > :"SYS_B_12" AND AA.AA_IRSER IN
> > > ( :"SYS_B_13", :"SYS_B_14", :"SYS_B_15",
> > > :"SYS_B_16" ) AND AA.AA__DELETED=:"SYS_B_17" ) AND IA.IA__DELETED=
> > > :"SYS_B_18"
>
> > > call count cpu elapsed disk query
> > > current rows
> > > ------- ------ -------- ---------- ---------- ---------- ----------
> > > ----------
> > > Parse 1 0.00 0.01 0 0
> > > 0 0
> > > Execute 1 0.00 0.00 0 0
> > > 0 0
> > > Fetch 376 1.78 9.77 665 202390
> > > 0 5623
> > > ------- ------ -------- ---------- ---------- ---------- ----------
> > > ----------
> > > total 378 1.78 9.79 665 202390
> > > 0 5623
>
> > > Misses in library cache during parse: 1
> > > Optimizer goal: CHOOSE
> > > Parsing user id: 62
>
> > > Rows Row Source Operation
> > > ------- ---------------------------------------------------
> > > 5623 TABLE ACCESS BY INDEX ROWID OBJ#(52752) (cr=202390 r=665 w=0
> > > time=9731547 us)
> > > 11530 NESTED LOOPS (cr=197278 r=665 w=0 time=9665024 us)
> > > 5906 SORT UNIQUE (cr=1333 r=0 w=0 time=58608 us)
> > > 5906 INLIST ITERATOR (cr=1333 r=0 w=0 time=33935 us)
> > > 5906 TABLE ACCESS BY INDEX ROWID OBJ#(52679) (cr=1333 r=0 w=0
> > > time=31899 us)
> > > 5906 INDEX RANGE SCAN OBJ#(77622) (cr=45 r=0 w=0 time=6901 us)
> > > (object id 77622)
> > > 5623 INLIST ITERATOR (cr=195945 r=665 w=0 time=9578266 us)
> > > 5623 INDEX RANGE SCAN OBJ#(77480) (cr=195945 r=665 w=0
> > > time=9376899 us)(object id 77480)
>
> > > ===========================================================================­­=
>
> > > I do not understand the high number of logical reads (cr=195945) in
> > > the last line.
> > > I would have expected a number closer to 5906 x 3 logical reads (as
> > > reaching an index leaf block should require 3 reads).
> > > This index (OBJ#(77480), non-unique) consists of all the (four)
> > > A_INDACT columns referenced in the where-clause.
>
> > > Why would it need 195945 logical reads on the index to find only 5623
> > > rows ?
>
> > > -- Peter
>
> > I would be tempted to try reformating the SQL statement like this to
> > see if it makes an improvement:
> > SELECT
> > IA.IA__ICODE,
> > IA.IA__TIMESTAMP,
> > IA.IA__STVDATE,
> > IA.IA__ENVDATE,
> > IA.IA_IACT1,
> > IA.IA_IACT2,
> > IA.IA_NOTES,
> > IA.IA_EXECU,
> > IA.IA_MEANI,
> > IA.IA_SEQUE,
> > IA.­IA_REASON
> > FROM
> > A_INDACT IA,
> > (SELECT DISTINCT
> > AA.AA__ICODE
> > FROM
> > A_ACTA AA
> > WHERE
> > AA.AA_IPERM='dhMPD0002CLR'
> > AND AA.AA_IRSER IN ( '#EPM#PreMd', '#EPM#Pre', '#EPM#EnsInt',
> > '#EPM#Med' )
> > AND AA.AA__DELETED='N') AA
> > WHERE
> > IA.IA_REASON='#EPM#Int2Int'
> > AND IA.IA_SEQUE IN ( '17', '2', '4', '9', '11', '6', '1', '3', '10',
> > '5', '0' )
> > AND IA.IA_IACT2=AA.AA__ICODE
> > AND IA.IA__DELETED='N';
>
> > Oracle is performing a nested loop join between the subquery and the
> > ACURE_A_INDACT_1 index blocks. For every row returned by the
> > subquery, Oracle is scanning the entries in the ACURE_A_INDACT_1 index
> > for matching entries. If one row were to be returned by the subquery
> > and the ACURE_A_INDACT_1 index contained 1000 blocks, there would be
> > 1000 logical reads. If the subquery returned two rows, there woudl be
> > 2000 logical reads, etc.
>
> > The explain plan for... that you posted is one of the variants offered
> > by DBMS_XPLAN (the typical) setting that seems to return the same plan
> > statistics that would appear in a 10053 trace file. You might want to
> > re-run the explain plan using the ALLSTATS setting so that you return
> > the plan that would appear in a 10046 trace's row source lines.
>
> > ---------------
> > ALTER SESSION SET STATISTICS_LEVEL=ALL;
>
> > (Run your query)
>
> > SELECT
> > *
> > FROM
> > TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS'));
> > ---------------
> > Compare those results with what you receive with the following:
> > ---------------
> > ALTER SESSION SET STATISTICS_LEVEL=ALL;
>
> > (Run your query)
>
> > SELECT
> > *
> > FROM
> > TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));
> > ---------------
>
> > For instance, ALLSTATS (note, might want to flush the shared pool
> > first so that Starts indicates the number of times that portion of the
> > SQL statement executed):
> > ---------------------------------------------------------------------------­------------------------------------------------------------------
> > | Id | Operation | Name | Starts | E-
> > Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | O/1/
> > M |
> > ---------------------------------------------------------------------------­------------------------------------------------------------------
> > | 1 | SORT UNIQUE | | 3 |
> > 2 | 0 |00:00:04.06 | 10055 | 3349 | 1024 | 1024 |
> > 3/0/0|
> > | 2 | UNION-ALL | | 3
> > | | 0 |00:00:04.06 | 10055 | 3349 | |
> > | |
> > |* 3 | TABLE ACCESS BY INDEX ROWID | PAYABLE | 3 |
> > 1 | 0 |00:00:04.06 | 10046 | 3348 | | |
> > |
> > |* 4 | INDEX RANGE SCAN | X_PAYABLE_2 | 3 |
> > 1 | 454K|00:00:01.07 | 828 | 276 | | |
> > |
> > | 5 | NESTED LOOPS | | 3 |
> > 1 | 0 |00:00:00.01 | 9 | 1 | | |
> > |
> > |* 6 | TABLE ACCESS FULL | PAYABLE_INST | 3 |
> > 1 | 0 |00:00:00.01 | 9 | 1 | | |
> > |
> > |* 7 | TABLE ACCESS BY INDEX ROWID| PAYABLE | 0 |
> > 1 | 0 |00:00:00.01 | 0 | 0 | | |
> > |
> > |* 8 | INDEX UNIQUE SCAN | SYS_C006820 | 0 |
> > 1 | 0 |00:00:00.01 | 0 | 0 | | |
> > |
> > ---------------------------------------------------------------------------­------------------------------------------------------------------
>
> > TYPICAL for the same SQL statement:
> > ---------------------------------------------------------------------------­-----------------------------
> > | Id | Operation | Name | Rows | Bytes
> > | Cost (%CPU)| Time | Inst |
> > ---------------------------------------------------------------------------­-----------------------------
> > | 0 | SELECT STATEMENT | | |
> > | 7 (100)| | |
> > | 1 | SORT UNIQUE | | 2 | 284
> > | 6 (67)| 00:00:01 | |
> > | 2 | UNION-ALL | | |
> > | | | |
> > |* 3 | TABLE ACCESS BY INDEX ROWID | PAYABLE | 1 | 121
> > | 2 (0)| 00:00:01 | TEST |
> > |* 4 | INDEX RANGE SCAN | X_PAYABLE_2 | 1 |
> > | 1 (0)| 00:00:01 | TEST |
> > | 5 | NESTED LOOPS | | 1 | 163
> > | 2 (0)| 00:00:01 | |
> > |* 6 | TABLE ACCESS FULL | PAYABLE_INST | 1 | 73
> > | 2 (0)| 00:00:01 | TEST |
> > |* 7 | TABLE ACCESS BY INDEX ROWID| PAYABLE | 1 | 90
> > | 0 (0)| | TEST |
> > |* 8 | INDEX UNIQUE SCAN | SYS_C006820 | 1 |
> > | 0 (0)| | TEST |
> > ---------------------------------------------------------------------------­-----------------------------
>
> > Note - in the above example, the second DBMS_XPLAN shows a very
> > efficient plan, while the first DBMS_XPLAN shows a very bad plan where
> > Oracle selected a very unselective (wrong) index.
>
> > Charles Hooper
> > IT Manager/Oracle DBA
> > K&M Machine-Fabricating, Inc.
>
> Thanks,
>
> As said earlier the index consists of all the columns used in the
> where-clause:
>
> select * from user_ind_columns
> where index_name = 'ACURE_A_INDACT_1';
>
> INDEX_NAME TABLE_NAME COLUMN_NAME COLUMN_POSITION COLUMN_LENGTH
> CHAR_LENGTH DESCEND
> ACURE_A_INDACT_1 A_INDACT IA_IACT2 1 12 12 ASC
> ACURE_A_INDACT_1 A_INDACT IA_REASON 2 12 12 ASC
> ACURE_A_INDACT_1 A_INDACT IA_SEQUE 3 22 0 ASC
> ACURE_A_INDACT_1 A_INDACT IA__DELETED 4 1 1 ASC
>
> I tried using the /*+NO_EXPAND*/ hint, but that had no effect at
> all !?
>
> Then, I tried modified the query, removing the IA.IA_SEQUE from the
> where-clause (in reality I *need* this predicate, but just to
> troubleshoot ...) and that had a very positive effect:
>
> =============================================
>
> SELECT
> IA.IA__ICODE,IA.IA__TIMESTAMP,IA.IA__STVDATE,IA.IA__ENVDATE,
> IA.IA_IACT1,IA.IA_IACT2,IA.IA_NOTES,IA.IA_EXECU,IA.IA_MEANI,
> IA.IA_SEQUE,IA.IA_REASON
> FROM
> A_INDACT IA
> WHERE
> IA.IA_REASON=:"SYS_B_0"
> --AND IA.IA_SEQUE IN ( '17', '2', '4', '9', '11', '6', '1', '3',
> '10', '5', '0' )
> AND IA.IA_IACT2 IN (
> SELECT AA.AA__ICODE
> FROM A_ACTA AA
> WHERE
> AA.AA_IPERM=:"SYS_B_1"
> AND AA.AA_IRSER IN
> ( :"SYS_B_2", :"SYS_B_3", :"SYS_B_4", :"SYS_B_5" )
> AND AA.AA__DELETED=:"SYS_B_6"
> )
> AND IA.IA__DELETED=:"SYS_B_7"
>
> call count cpu elapsed disk query
> current rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.00 0.00 0 0
> 0 0
> Execute 1 0.01 0.00 0 0
> 0 0
> Fetch 381 0.24 0.33 1 18932
> 0 5688
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 383 0.25 0.33 1 18932
> 0 5688
>
> Misses in library cache during parse: 1
> Optimizer goal: CHOOSE
> Parsing user id: 62 (EPM)
>
> Rows Row Source Operation
> ------- ---------------------------------------------------
> 5688 TABLE ACCESS BY INDEX ROWID OBJ#(52752) (cr=18932 r=1 w=0
> time=290890 us)
> 11560 NESTED LOOPS (cr=13782 r=0 w=0 time=204860 us)
> 5871 SORT UNIQUE (cr=1312 r=0 w=0 time=60987 us)
> 5871 INLIST ITERATOR (cr=1312 r=0 w=0 time=36738 us)
> 5871 TABLE ACCESS BY INDEX ROWID OBJ#(52679) (cr=1312 r=0 w=0
> time=34603 us)
> 5871 INDEX RANGE SCAN OBJ#(77622) (cr=45 r=0 w=0 time=7283 us)
> (object id 77622)
> 5688 INDEX RANGE SCAN OBJ#(77480) (cr=12470 r=0 w=0 time=119228
> us)(object id 77480)
>
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 SELECT STATEMENT GOAL: CHOOSE
> 5688 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'A_INDACT'
> 11560 NESTED LOOPS
> 5871 SORT (UNIQUE)
> 5871 INLIST ITERATOR
> 5871 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF
> 'A_ACTA'
> 5871 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'MORTEN'
> (NON-UNIQUE)
> 5688 INDEX GOAL: ANALYZED (RANGE SCAN) OF 'ACURE_A_INDACT_1'
> (NON-UNIQUE)
>
> =============================================
>
> ... now only 18932 logical reads in total (12470 from the index) !
>
> Not that it solves my problem (it certainly does not), but it may
> point to the root cause for some of you clever guys ?
>
> My original question it still unanswered:
> Why would the original query need 195945 logical reads on the index to
> find only 5623 rows ?
> Why does the modified query (now only referring to 3 out of 4 indexed
> columns in where-clause) only need 18932 logical reads (ten times less
> "work") ?
>
> -- Peter

You have

column 1 (in the index) --> bind variable
column 2 (in the index) ---> hardcoded
column 3 (in the index) ---> bind variable
column 4 ( in the index) ---> bind variable

Leaving out the condition on column2, Oracle will probably assume the cardinality is 1/NDV. In your case Oracle starts making assumptions. If I would have to deal with this I would try two things a) order the predicates correctly, so they are in order of the index, and use the corresponding hint (I believe 'ordered_predicates') b) mislead the optimizer by feeding the IN list to Tom Kytes 'Dynamic IN list' function (available at http://asktom.oracle.com)

In both cases I would use event 10053 to get a trace file with CBO's decision tree.

You simply *must* ignore part of the index, I already tried to explain this to you, not sure why you don't want to buy this.

--
Sybrand Bakker
Senior Oracle DBA