| 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, 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
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.
SELECT
*
FROM
TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS'));
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.
Received on Tue May 01 2007 - 12:15:02 CDT
 |
 |