| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: Slow SQL, too many logical reads ?
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
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"
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") ?
 |
 |