Re: Slow SQL, too many logical reads ?

On May 2, 6:40 am, Peter <peterny..._at_gmail.com> wrote:
> On May 1, 7:15 pm, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
> > 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:
> >
> > 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

Great to hear that the rewrite helped. What the rewritten query did was to move the subquery to an inline view. If I am reading the plan correctly, the query execution time dropped from 9.731 seconds to 0.290 seconds (assuming that you are running 9i or higher).

This is my original explaination why there are so logical reads of the index blocks:
> > 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.

Pseudocode of the above explanation:
for i = 1 to ROWS_IN_SUBQUERY
  for j = 1 to NUMBER_OF_ENTRIES_IN_ACURE_A_INDACT_1

      'Read the block contents using logical read   next j
next i

I believe that the bind variables shown are system generated due to the CURSOR_SHARING parameter. As Sybrand indicates, the bind variables may be affecting performance to some extent.

Charles Hooper
IT Manager/Oracle DBA Received on Wed May 02 2007 - 18:51:38 CDT