Re: Slow SQL, too many logical reads ?

From: Peter <peternybor_at_gmail.com>
Date: 1 May 2007 07:47:14 -0700
Message-ID: <1178030834.571357.275300@e65g2000hsc.googlegroups.com>

On May 1, 4:11 pm, sybrandb <sybra..._at_gmail.com> wrote:
> On May 1, 3:27 pm, 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
>
> One reason would be the optimizer isn't using all the columns.
> You would need to use dbms_xplan.display to confirm that.
>
> --
> Sybrand Bakker
> Senior Oracle DBA

Thanks, here is the dbms_xplan.display output:

SQL> explain plan for
  2 SELECT
  3 IA.IA__ICODE,IA.IA__TIMESTAMP,IA.IA__STVDATE,IA.IA__ENVDATE,   4
IA.IA_IACT1,IA.IA_IACT2,IA.IA_NOTES,IA.IA_EXECU,IA.IA_MEANI,IA.IA_SEQUE,IA.IA_REASON   5 FROM
  6 A_INDACT IA
  7 WHERE
  8 IA.IA_REASON='#EPM#Int2Int'
  9 AND IA.IA_SEQUE IN ( '17', '2', '4', '9', '11', '6', '1', '3', '10', '5', '0' )
10 AND IA.IA_IACT2 IN (

 11  	 SELECT  AA.AA__ICODE
 12  	 FROM A_ACTA AA
 13  	 WHERE
 14  	   AA.AA_IPERM='dhMPD0002CLR'
 15  	   AND AA.AA_IRSER IN ( '#EPM#PreMd', '#EPM#Pre', '#EPM#EnsInt',
'#EPM#Med' )
 16  	   AND AA.AA__DELETED='N'
 17  	 )

18 AND IA.IA__DELETED='N'
19 ;

PLAN_TABLE_OUTPUT

| Id  | Operation                       |  Name             | Rows  |

Bytes | Cost
(%CPU)|

|   0 | SELECT STATEMENT                |                   |    42 |

5670 | 16
(7)|

|   1 |  TABLE ACCESS BY INDEX ROWID    | A_INDACT          |     1
|    94 |     2
(50)|
|   2 |   NESTED LOOPS                  |                   |    42 |

5670 | 16
(7)|

|   3 |    SORT UNIQUE                  |                   |
|       |
|
|   4 |     INLIST ITERATOR             |                   |
|       |
|
|   5 |      TABLE ACCESS BY INDEX ROWID| A_ACTA            |    34 |
1394 |     4
(0)|
|*  6 |       INDEX RANGE SCAN          | MORTEN            |    34
|       |     1
(0)|
|   7 |    INLIST ITERATOR              |                   |
|       |
|
|*  8 |     INDEX RANGE SCAN            | ACURE_A_INDACT_1  |     1
|       |     1

(0)|

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT

6 - access("AA"."AA_IPERM"='dhMPD0002CLR' AND ("AA"."AA_IRSER"='#EPM#EnsInt'
OR

"AA"."AA_IRSER"='#EPM#Med' OR "AA"."AA_IRSER"='#EPM#Pre' OR
"AA"."AA_IRSER"='#EPM#PreMd')

AND
"AA"."AA__DELETED"='N') filter("AA"."AA__DELETED"='N')

8 - access("IA"."IA_IACT2"="AA"."AA__ICODE" AND "IA"."IA_REASON"='#EPM#Int2Int'
AND
("IA"."IA_SEQUE"=0 OR "IA"."IA_SEQUE"=1 OR "IA"."IA_SEQUE"=2 OR "IA"."IA_SEQUE"=3
OR

"IA"."IA_SEQUE"=4 OR "IA"."IA_SEQUE"=5 OR "IA"."IA_SEQUE"=6 OR "IA"."IA_SEQUE"=9
OR

"IA"."IA_SEQUE"=10 OR "IA"."IA_SEQUE"=11 OR "IA"."IA_SEQUE"=17)
AND "IA"."IA__DELETED"='N') Seems like the

|*  8 |     INDEX RANGE SCAN            | ACURE_A_INDACT_1  |     1
|       |     1

(0)|
is actually using all the four index columns ?

(not sure I understand the meaning of

|   7 |    INLIST ITERATOR              |                   |
|       |            |

however ?)

Peter

Received on Tue May 01 2007 - 09:47:14 CDT