Slow SQL, too many logical reads ?

From: Peter <peternybor_at_gmail.com>
Date: 1 May 2007 06:27:24 -0700
Message-ID: <1178026044.339158.173310@n76g2000hsh.googlegroups.com>

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

Received on Tue May 01 2007 - 08:27:24 CDT