| 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 7, 11:15 am, "Jonathan Lewis" <jonat..._at_jlcomp.demon.co.uk>
wrote:
> "Charles Hooper" <hooperc2..._at_yahoo.com> wrote in message
> > Just out of curiosity, do you think that DBMS_XPLAN is retrieving its
> > source data by querying V$SQL_PLAN_STATISTICS_ALL (or the underlying
> > views), and when the LAST keyword is specified, only returns those
> > columns which are prefixed with LAST_ ?
> > The reason that
> > I ask is that
> > I am currently investigating performance problems with a packaged
> > application that is running against Oracle 10.2.0.2. Due to bind
> > variable peeking, and the fact that the packaged application is either
> > not supplying bind variable values during the initial parse call, or
> > is specifying out of bounds values, Oracle is selecting to perform an
> > index range scan using an index on a column that contains only two
> > distinct values, when it should be using the index on the primary key
> > column to retrieve table data. Oracle selects the correct index if
> > bind variable peeking is disabled. I am trying to develop a logical
> > approach to determine which SQL statements need to have an outline
> > developed when bind variable peeking is disabled at the session
> > level.
>
> > Charles Hooper
> > IT Manager/Oracle DBA
> > K&M Machine-Fabricating, Inc.
>
> Charles,
>
> I see Mladen has already answered your question.
> For more details, you could check the script
> $ORACLE_HOME/rdbms/admin/dbmsxplan.sql
>
> The disappearance of the READS column is simply based
> on the fact that the pl/sql attempts (as far as I can tell) to
> hide any column where the value is always zero.
>
> Would event 10132 help with the problem of identifying
> isolating queries where inconsistency with the supply of
> bind variables was causing problems. I'd be interested
> to hear of any cases where you can see a consistent
> pattern with bind variables disappearing - I think I had
> some email recently from someone who was seeing the
> same problem.
>
> --
> Regards
>
> Jonathan Lewishttp://jonathanlewis.wordpress.com
>
> Author: Cost Based Oracle: Fundamentalshttp://www.jlcomp.demon.co.uk/cbo_book/ind_book.html
>
> The Co-operative Oracle Users' FAQhttp://www.jlcomp.demon.co.uk/faq/ind_faq.html
(Trying not to hijack this thread for an unrelated topic...)
Jonathan, thanks for the comments. I am digging into the situation that I reported earlier, after performing additional analysis. It looks like I am stumbling into an optimizer bug related to bind variables and an index that contains one distinct value. The packaged application apparently causes Oracle 10.2.0.2 (Oct 2006 patch) to perform two parse calls for each SQL statement. For the first parse call, bind variable values are not specified ("No bind buffers allocated" appears in the Peeked Binds section of a 10053 trace). For the second parse call, bind variable values are specified ("No bind buffers allocated" does not appear in the Peeked Binds section of a 10053 trace). What is a bit hard to understand is why the cost based optimizer stops using a highly selective index, and instead uses an index that contains one distinct value. If the SQL statement is rewritten to not use bind variables, but instead use constants in place of the bind variables, with the same values specified during the second parse call, Oracle continues to use them highly selective index, as it did when bind variable values were not specified during the parse.
>From the 10053 trace when bind variable values were not specified, a
section with these values appears:
Access Path: index (UniqueScan)
Index: SYS_C006880
resc_io: 2.00 resc_cpu: 22674
ix_sel: 1.5368e-005 ix_sel_with_filters: 1.5368e-005
Cost: 2.00 Resp: 2.00 Degree: 1
Access Path: index (AllEqUnique)
Index: SYS_C006880
resc_io: 2.00 resc_cpu: 22674
ix_sel: 1.5423e-005 ix_sel_with_filters: 1.5423e-005
Cost: 2.00 Resp: 2.00 Degree: 1
Access Path: index (AllEqRange)
Index: X_RECEIVABLE_3
resc_io: 1287.00 resc_cpu: 71639006
ix_sel: 1 ix_sel_with_filters: 1
Cost: 1299.58 Resp: 1299.58 Degree: 1
One row Card: 1.00
Best:: AccessPath: IndexUnique Index: SYS_C006880
Cost: 2.00 Degree: 1 Resp: 2.00 Card: 1.00 Bytes: 0
Note that the ix_sel for the X_RECEIVABLE_3 index is 1.
The same section of the 10053 trace when bind variable values are
specified:
Access Path: index (UniqueScan)
Index: SYS_C006880
resc_io: 2.00 resc_cpu: 22324
ix_sel: 1.5368e-005 ix_sel_with_filters: 1.5368e-005
Cost: 2.00 Resp: 2.00 Degree: 1
Access Path: index (AllEqUnique)
Index: SYS_C006880
resc_io: 2.00 resc_cpu: 22324
ix_sel: 1.5423e-005 ix_sel_with_filters: 1.5423e-005
Cost: 2.00 Resp: 2.00 Degree: 1
Access Path: index (AllEqRange)
Index: X_RECEIVABLE_3
resc_io: 2.00 resc_cpu: 22299
ix_sel: 7.7114e-006 ix_sel_with_filters: 7.7114e-006
Cost: 2.00 Resp: 2.00 Degree: 1
Best:: AccessPath: IndexRange Index: X_RECEIVABLE_3
Cost: 2.00 Degree: 1 Resp: 2.00 Card: 0.00 Bytes: 0
Note that the ix_sel for the X_RECEIVABLE_3 index is now 7.7114e-006, which makes this index with one distinct value the most selective index.
>From the 10053 trace, the original plan, when bind variable values
were not specified:
+-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | ---------------------------------------------------------- +-----------------------------------+ | 0 | SELECT STATEMENT | | | | 4 | | | 1 | SORT AGGREGATE | | 1 | 40 | | | | 2 | NESTED LOOPS | | 1 | 40 | 4 | 00:00:01 | | 3 | TABLE ACCESS BY INDEX ROWID | RECEIVABLE | 1 | 20 | 2 | 00:00:01 | | 4 | INDEX UNIQUE SCAN | SYS_C006880 | 1 | | 1 | 00:00:01 | | 5 | TABLE ACCESS BY INDEX ROWID | RECV_MEMO_APPLY | 1 | 20 | 2 | 00:00:01 | | 6 | INDEX RANGE SCAN | X_RECV_MEMO_APP_1| 1 | | 1 | 00:00:01 | ---------------------------------------------------------- +-----------------------------------+
4 - access("I"."INVOICE_ID"=:1)
5 - filter("A"."APPLY_DATE"<=:2)
6 - access("A"."INV_INVOICE_ID"=:1)
>From the 10053 trace when bind variable values were specified:
+-----------------------------------+ | Id | Operation | Name | Rows | Bytes | Cost | Time | ----------------------------------------------------------- +-----------------------------------+ | 0 | SELECT STATEMENT | | | | 4 | | | 1 | SORT AGGREGATE | | 1 | 40 | | | | 2 | TABLE ACCESS BY INDEX ROWID | RECV_MEMO_APPLY | 1 | 20 | 2 | 00:00:01 | | 3 | NESTED LOOPS | | 1 | 40 | 4 | 00:00:01 | | 4 | TABLE ACCESS BY INDEX ROWID | RECEIVABLE | 1 | 20 | 2 | 00:00:01 | | 5 | INDEX RANGE SCAN | X_RECEIVABLE_3 | 1 | | 1 | 00:00:01 | | 6 | INDEX RANGE SCAN | X_RECV_MEMO_APP_1| 1 | | 1 | 00:00:01 | ----------------------------------------------------------- +-----------------------------------+
DBMS XPLAN output when bind variable values are specified: SQL_ID 417an1wrphkc2, child number 0
and a.apply_date <= :2 and a.inv_invoice_id =
i.invoice_id and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :
3 and ENTITY_ID = :4
Plan hash value: 1967837802
| Id | Operation | Name | Starts |E-Rows | A-Rows | A-Time | Buffers |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.38 | 4684 | |* 2 | TABLE ACCESS BY INDEX ROWID | RECV_MEMO_APPLY | 1 | 1 | 0 |00:00:00.38 | 4684 | | 3 | NESTED LOOPS | | 1 | 1 | 2 |00:00:00.38 | 4684 | |* 4 | TABLE ACCESS BY INDEX ROWID| RECEIVABLE | 1 | 1 | 1 |00:00:00.38 | 4682 | |* 5 | INDEX RANGE SCAN | X_RECEIVABLE_3 | 1 | 1 | 65070 |00:00:00.13 | 119 | |* 6 | INDEX RANGE SCAN | X_RECV_MEMO_APP_1 | 1 | 1 | 0 |00:00:00.01 | 2 | --------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
2 - filter("A"."APPLY_DATE"<=:2)
4 - filter(("I"."RECV_GL_ACCT_ID"=:3 AND "I"."INVOICE_ID"=:1 AND
"I"."TOTAL_AMOUNT"<>0 AND
"I"."STATUS"<>'X'))
DBMS XPLAN when bind variables are replaced with contants that had the
same value as the bind variables:
SQL_ID 2nj9wq0b995ws, child number 0
and a.apply_date <= '05-MAY-2007' and
a.inv_invoice_id = i.invoice_id
and i.status != 'X' and i.total_amount != 0 and i.recv_gl_acct_id
= '110' and
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 5 | | 2 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 5 | |* 3 | TABLE ACCESS BY INDEX ROWID| RECEIVABLE | 1 | 1 | 1 |00:00:00.01 | 3 | |* 4 | INDEX UNIQUE SCAN | SYS_C006880 | 1 | 1 | 1 |00:00:00.01 | 2 | |* 5 | TABLE ACCESS BY INDEX ROWID| RECV_MEMO_APPLY | 1 | 1 | 0 |00:00:00.01 | 2 | |* 6 | INDEX RANGE SCAN | X_RECV_MEMO_APP_1 | 1 | 1 | 0 |00:00:00.01 | 2 | -------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
3 - filter(("I"."TOTAL_AMOUNT"<>0 AND "I"."STATUS"<>'X' AND "I"."RECV_GL_ACCT_ID"='110' AND
"ENTITY_ID"='1'))
4 - access("I"."INVOICE_ID"='66722')
5 - filter("A"."APPLY_DATE"<='05-MAY-2007')
6 - access("A"."INV_INVOICE_ID"='66722')
It would seem that the two DBMS XPLANs should be identical since the same values were specified for both queries. The plan where constants were supplied is identical to the plan where bind variable values were not specified during the initial parse call. If I disable bind variable peeking, the highly selective index is used.
The SQL statement above is not the only statement in the packaged application that is affected by this problem. I have not experiemented with a 10132 trace, but I will see if any additional information can be obtained from such a trace.
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Received on Mon May 07 2007 - 12:55:37 CDT
 |
 |