On Feb 27, 6:40 am, "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.
Hi. Do you retain and re-use your prepared Statements,
or do you create, use, and then close them?
Joe Weinstein at BEA Systems
Received on Tue Feb 27 2007 - 09:28:44 CST
