| 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: PreparedStatement Performance
On 27 Feb, 14:40, "John.Plan..._at_googlemail.com"
<John.Plan..._at_googlemail.com> wrote:
> I am using Oracle 10g (10.2.0.1) on Windows (XP SP2). Within my java
> code I make extensive use of PreparedStatements (as recommended by
> just about everyone). I am experiencing odd performance whereby a
> query will sometimes run in around 100 ms and sometimes it takes in
> excess of 3 minutes. In both cases the query is exactly the same, the
> data is exactly the same and there is no additional load on the
> database (this is all running on my desktop machine).
>
> I have tried explain plan, which reports a reasonable execution plan
> that seems to make use of indexes as expected. Whenever I try to run
> this query from a sql client (e.g. SQLPLUS), it always returns
> quickly. I only experience the problem when running the query from a
> Java JDBC call making use of a PreparedStatment. Perplexed by this, I
> changed the code and rewrote it to use a Statement instead, so that
> Oracle has to reparse and recalculate the execution plan every time it
> is called. Under these circumstances, the query always runs fast (I
> never see the 3 minutes plus timing). I have tried using both the
> thin and oci drivers with the same results.
>
> This change to use Statement rather than PreparedStatement would on
> the face of it seem to solve the problem, but it is not recommended
> practice and I would rather find out why the problem is occuring and
> fix it properly.
>
> I get the feeling that Oracle is creating a bad execution plan. When
> the slow query runs, there is a lot of IO and Statspack and TKPROF
> both report a large number of reads occuring. If I flush the
> shared_pool and run the query again, it invariably ends up running
> quickly again.
>
> The following is the output from TKPROF for the query when it runs
> quickly
>
> SELECT id,code,startsat,endswith,ref
> FROM
> PRDS WHERE startsat>= :1 AND ord = -1 AND id IN (SELECT id FROM
> PRJS WHERE proj = :2) ORDER BY id,code
>
> call count cpu elapsed disk query
> current rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.00 0.00 0 0
> 0 0
> Execute 1 0.01 0.01 0 0
> 0 0
> Fetch 315 0.04 0.04 0 2319
> 0 3144
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 317 0.06 0.05 0 2319
> 0 3144
>
> Misses in library cache during parse: 1
> Misses in library cache during execute: 1
> Optimizer mode: ALL_ROWS
> Parsing user id: 124 (TEST)
>
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 SELECT STATEMENT MODE: ALL_ROWS
> 0 SORT (ORDER BY)
> 0 MERGE JOIN
> 0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
> 'PRDS' (TABLE)
> 0 INDEX MODE: ANALYZED (FULL SCAN) OF
> 'PRDS_IDX5' (INDEX)
> 0 SORT (JOIN)
> 0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
> 'PRJS' (TABLE)
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'PRJS_IDI'
> (INDEX)
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> SQL*Net message to client 316
> 0.00 0.00
> SQL*Net message from client 316
> 0.03 0.16
>
> and this is the output from TKPROF when running the same query (with
> the same bind variable values) but it running slowly
>
> SELECT id,code,startsat,endswith,ref
> FROM
> PRDS WHERE startsat>= :1 AND ord = -1 AND id IN (SELECT id FROM
> PRJS WHERE proj = :2) ORDER BY id,code
>
> call count cpu elapsed disk query
> current rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.03 0.01 0 12
> 0 0
> Execute 1 0.00 0.00 0 0
> 0 0
> Fetch 315 7.70 229.62 33719 41130
> 0 3144
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 317 7.73 229.64 33719 41142
> 0 3144
>
> Misses in library cache during parse: 1
> Optimizer mode: ALL_ROWS
> Parsing user id: 124 (TEST)
>
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 SELECT STATEMENT MODE: ALL_ROWS
> 0 SORT (ORDER BY)
> 0 MERGE JOIN
> 0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
> 'PRDS' (TABLE)
> 0 INDEX MODE: ANALYZED (FULL SCAN) OF
> 'PRDS_IDX5' (INDEX)
> 0 SORT (JOIN)
> 0 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
> 'PRJS' (TABLE)
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'PRJS_IDI'
> (INDEX)
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> SQL*Net message to client 316
> 0.00 0.00
> SQL*Net message from client 316
> 0.03 0.16
> db file sequential read 33719 0.15
> 222.16
>
> If anyone can shed any light onto this anomoly then I would be most
> grateful.
I have further information on this.
I decided to run some database tracing using event 10053 (CBO tracing), in the two cases. This is a bit of a black art to me, but was quite revealing. The main difference between the two cases was that the fast query, when building the execution plan, used bind variable peeking. My schema has statistics including histograms, which appear to enable the CBO to better judge how many hits it will get when performing a query. Here is an extract froim the 10053 trace
In the second slow case, the optimiser is building the execution plan, but is not using bind value peeking. The extract from this trace is as follows
Subsequently when calculating weightings to various excution paths, the values are quite different (because with no bind variable peeking, the optimiser assumes an even spread of values based on the number of distinct values (NDV) for a column). In my data the spread is not even.
Having looked around for details about this mysterious bind value peeking, I am led to believe that the only way that peeking will not occur is if you explicitly switch it off (setting _optim_peek_user_binds=false). I have not done this.
Can anyone shed any light as to why I see this behaviour?
Many Thanks Received on Wed Feb 28 2007 - 02:56:36 CST
 |
 |