Re: Slow SQL, too many logical reads ?

On May 1, 7:15 pm, Charles Hooper <hooperc2...@xxxxxxxxx> wrote:
On May 1, 9:27 am, Peter <peterny...@xxxxxxxxx> 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

.

Relevant Pages

  • Re: How to force subquery being the first executed
    ... In most cases the query starts with complete execution of the heavyView ... and is then restricting the result using the subquery. ... Without the actual explain plan or any supporting detail for the ...
    (comp.databases.oracle.misc)
  • Re: Slow SQL, too many logical reads ?
    ... call count cpu elapsed disk query ... Rows Row Source Operation ... Oracle is performing a nested loop join between the subquery and the ... The explain plan for... ...
    (comp.databases.oracle.server)
  • RE: Subquery help
    ... one semicolon and that is at the very end of the SQL statement. ... shouldn't need one in the subquery. ... Jerry Whittle, Microsoft Access MVP ... The query should be bringing back multiple references between the specified ...
    (microsoft.public.access.queries)
  • Re: Queries or SQL
    ... There are many factors which may impact on JET optimization. ... A query plan which is ... optimized for my machine may not be an optimal plan for yours. ... just type the SQL statement directly into the form. ...
    (comp.databases.ms-access)
  • Re: Optimization question: Unrolling subquery into IN clause
    ... With the expanded list (without subquery) the explain plan looks ... The plan with bind variables is something like this (this is from tkprof ... and from the slightly more complex version of the query issued by ... Rows     Execution Plan ...
    (comp.databases.oracle.server)
Loading