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.

On Feb 27, 6:40 am, "John.Plan...@googlemail.com"
<John.Plan...@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

On 27 Feb, 15:28, "joeNOS...@BEA.com" <joe.weinst...@gmail.com> wrote:
> On Feb 27, 6:40 am, "John.Plan...@googlemail.com"
>
>
>
>
>
> <John.Plan...@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- Hide quoted text -
>
> - Show quoted text -

The PreparedStatement is created and retained

On Feb 27, 9:40 am, "John.Plan...@googlemail.com"
<John.Plan...@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.

Considering that the largest wait event during the slow run is db file
sequential read, at 3.7 minutes, I would say that on one run the index
blocks for PRDS_IDX5 and PRJS_IDI were mostly already in the buffer
cache on the fast run, and were mostly not in the buffer cache. Also,
keep in mind that explain plans can lie when bind variables are
involved.

Assuming that PRDS.ID is a primary key, how does the performance of
this SQL statement compare with your SQL statement?
SELECT DISTINCT
PD.ID,
PD.CODE,
PD.STARTSAT,
PD.ENDSWITH,
PD.REF
FROM
PRDS PD,
PRJS PJ
WHERE
PJ.PROJ = :2
AND PD.ORD = -1
AND PD.ID=PJ.ID
ORDER BY
PD.ID,
PD.CODE;

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc.

John.Planque@googlemail.com schreef:

>
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 SELECT STATEMENT MODE: ALL_ROWS
> 0 SORT (ORDER BY)

Why all_rows? Are you using Java as a reporting tool?

And I would suspect a rewrite of:

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

To:

SELECT prds.id
, prds.code
, prds.startsat
, prds.endswith
, prds.ref
FROM
PRDS, PRJS
WHERE prds.startsat>= :1
AND prds.ord = -1
AND prds.id = prjs.id
and prjs.proj = :2
ORDER BY id,code

would be faster - in lists tend to be slow, especially when they
grow - which depends on the value of bind variable :2 (which you
did not change, so this is off topic...)
Depending on the definition, the join on id may need an outer join.
--
Regards,
Frank van Bortel

Top-posting is one way to shut me up...

On Feb 27, 1:47 pm, Frank van Bortel <frank.van.bor...@gmail.com>
wrote:
> John.Plan...@googlemail.com schreef:
>
>
>
> > Rows Execution Plan
> > ------- ---------------------------------------------------
> > 0 SELECT STATEMENT MODE: ALL_ROWS
> > 0 SORT (ORDER BY)
>
> Why all_rows? Are you using Java as a reporting tool?
>
> And I would suspect a rewrite of:
>
> 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
>
> To:
>
> SELECT prds.id
> , prds.code
> , prds.startsat
> , prds.endswith
> , prds.ref
> FROM
> PRDS, PRJS
> WHERE prds.startsat>= :1
> AND prds.ord = -1
> AND prds.id = prjs.id
> and prjs.proj = :2
> ORDER BY id,code
>
> would be faster - in lists tend to be slow, especially when they
> grow - which depends on the value of bind variable :2 (which you
> did not change, so this is off topic...)
> Depending on the definition, the join on id may need an outer join.
> --
> Regards,
> Frank van Bortel
>
> Top-posting is one way to shut me up...

It looks like the range scan on PRJS_IDI index reads a lot more data
in the second exeecution than in the first (compare *query* values
between the two executions). You should make sure that the exact same
values are bound to the second query and if so, open a case with
Oracle as this may be a bug.

On 27 Feb, 14:40, "John.Plan...@googlemail.com"
<John.Plan...@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

*******************************************
Peeked values of the binds in SQL statement
*******************************************
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
kxsbbbfp=0af369c4 bln=22 avl=02 flg=05
value=85
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=0af369dc bln=22 avl=04 flg=01
value=28529

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

*******************************************
Peeked values of the binds in SQL statement
*******************************************
kkscoacd
Bind#0
oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
No bind buffers allocated
Bind#1
oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
No bind buffers allocated

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

John.Planque@googlemail.com schreef:
>
> 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
>
> *******************************************
> Peeked values of the binds in SQL statement
> *******************************************
> kkscoacd
> Bind#0
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> kxsbbbfp=0af369c4 bln=22 avl=02 flg=05
> value=85
> Bind#1
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> kxsbbbfp=0af369dc bln=22 avl=04 flg=01
> value=28529
>
> 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
>
> *******************************************
> Peeked values of the binds in SQL statement
> *******************************************
> kkscoacd
> Bind#0
> oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> No bind buffers allocated
> Bind#1
> oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> No bind buffers allocated
>
> 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
>

I'd say you have a pretty strong case for Support Services...
--
Regards,
Frank van Bortel

Top-posting is one way to shut me up...

On Feb 28, 3:56 am, "John.Plan...@googlemail.com"
<John.Plan...@googlemail.com> wrote:
> On 27 Feb, 14:40, "John.Plan...@googlemail.com"
> > 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).
> >
> > 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
>
> *******************************************
> Peeked values of the binds in SQL statement
> *******************************************
> kkscoacd
> Bind#0
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> kxsbbbfp=0af369c4 bln=22 avl=02 flg=05
> value=85
> Bind#1
> oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> kxsbbbfp=0af369dc bln=22 avl=04 flg=01
> value=28529
>
> 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
>
> *******************************************
> Peeked values of the binds in SQL statement
> *******************************************
> kkscoacd
> Bind#0
> oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> No bind buffers allocated
> Bind#1
> oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> No bind buffers allocated
>
> 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

This website seems to suggest that you will see "No bind buffers
allocated" when you have disabled bind variable peeking:
http://blog.oracloid.com/2006/07/bin...no-histograms/

While that may be true, I have seen that statement in 10053 trace
files generated for the Centura SQLWindows developed ERP system that
we use, as well as ad-hoc SQL statements submitted from time to time,
even through bind variable peeking is not disabled (this is in Oracle
10.2.0.2).

>From one of my 10053 trace files:
*******************************************
Peeked values of the binds in SQL statement
*******************************************
kkscoacd
Bind#0
oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=01 csi=178 siz=32 off=0
No bind buffers allocated
Bind#1
oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=01 csi=178 siz=32 off=0
No bind buffers allocated
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
*************************************
PARAMETERS WITH ALTERED VALUES
******************************
optimizer_features_enable = 10.1.0.4
cursor_sharing = force
....
QUERY BLOCK TEXT
****************
SELECT
*
FROM
SHIPPING_LINE
WHERE
PACKLIST_ID=:"SYS_B_0"
AND CUST_ORDER_ID IN (:"SYS_B_1")

The SQL statement submitted to Oracle looked something like this:
SELECT
*
FROM
SHIPPING_LINE
WHERE
PACKLIST_ID='10101'
AND CUST_ORDER_ID IN ('ABCDE');

You will note that in the peeked bind section that I included above:
oacdty=01 mxl=32(05)

oacdty=01 indicates that a varchar2 or nvarchar2 should be expected.
mxl=32(05) indicates that the maximum length of the bind variable is
32, and that the actual data length is 5.

>From another SQL statement that was parsed with CURSOR_SHARING set to
FORCE on the same Oracle database:
Bind#19
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0500 frm=00 csi=00 siz=24 off=0
kxsbbbfp=5a5cb020 bln=22 avl=02 flg=09
value=4

Note that this time that oacdty=02 is included, like in your example,
which indicates that a number should be expected, and mxl=22(02)
indicates that the bind variable can handle a NUMBER(22) data type,
but a NUMBER(2) was actually provided.

In your case, when the SQL statement executes quickly, you will see:
oacdty=02 mxl=22(22)

And when the SQL statement executes slowly, you will see:
oacdty=02 mxl=22(00)

That seems to indicate that when you are making the initial parse
call, you may not be supplying initial bind values for the parse.

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc.

On Mar 1, 11:21 am, "Charles Hooper" <hooperc2...@yahoo.com> wrote:
> On Feb 28, 3:56 am, "John.Plan...@googlemail.com"
>
>
>
>
>
> <John.Plan...@googlemail.com> wrote:
> > On 27 Feb, 14:40, "John.Plan...@googlemail.com"
> > > 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).
>
> > > 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
>
> > *******************************************
> > Peeked values of the binds in SQL statement
> > *******************************************
> > kkscoacd
> > Bind#0
> > oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> > oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> > kxsbbbfp=0af369c4 bln=22 avl=02 flg=05
> > value=85
> > Bind#1
> > oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
> > oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> > kxsbbbfp=0af369dc bln=22 avl=04 flg=01
> > value=28529
>
> > 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
>
> > *******************************************
> > Peeked values of the binds in SQL statement
> > *******************************************
> > kkscoacd
> > Bind#0
> > oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> > oacflg=03 fl2=1000000 frm=01 csi=873 siz=48 off=0
> > No bind buffers allocated
> > Bind#1
> > oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
> > oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
> > No bind buffers allocated
>
> > 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
>
> This website seems to suggest that you will see "No bind buffers
> allocated" when you have disabled bind variable peeking:http://blog.oracloid.com/2006/07/bin...with-no-histog...
>
> While that may be true, I have seen that statement in 10053 trace
> files generated for the Centura SQLWindows developed ERP system that
> we use, as well as ad-hoc SQL statements submitted from time to time,
> even through bind variable peeking is not disabled (this is in Oracle
> 10.2.0.2).
>
> >From one of my 10053 trace files:
>
> *******************************************
> Peeked values of the binds in SQL statement
> *******************************************
> kkscoacd
> Bind#0
> oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
> oacflg=10 fl2=0100 frm=01 csi=178 siz=32 off=0
> No bind buffers allocated
> Bind#1
> oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
> oacflg=10 fl2=0100 frm=01 csi=178 siz=32 off=0
> No bind buffers allocated
> ***************************************
> PARAMETERS USED BY THE OPTIMIZER
> ********************************
> *************************************
> PARAMETERS WITH ALTERED VALUES
> ******************************
> optimizer_features_enable = 10.1.0.4
> cursor_sharing = force
> ...
> QUERY BLOCK TEXT
> ****************
> SELECT
> *
> FROM
> SHIPPING_LINE
> WHERE
> PACKLIST_ID=:"SYS_B_0"
> AND CUST_ORDER_ID IN (:"SYS_B_1")
>
> The SQL statement submitted to Oracle looked something like this:
> SELECT
> *
> FROM
> SHIPPING_LINE
> WHERE
> PACKLIST_ID='10101'
> AND CUST_ORDER_ID IN ('ABCDE');
>
> You will note that in the peeked bind section that I included above:
> oacdty=01 mxl=32(05)
>
> oacdty=01 indicates that a varchar2 or nvarchar2 should be expected.
> mxl=32(05) indicates that the maximum length of the bind variable is
> 32, and that the actual data length is 5.
>
> >From another SQL statement that was parsed with CURSOR_SHARING set to
>
> FORCE on the same Oracle database:
> Bind#19
> oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
> oacflg=10 fl2=0500 frm=00 csi=00 siz=24 off=0
> kxsbbbfp=5a5cb020 bln=22 avl=02 flg=09
> value=4
>
> Note that this time that oacdty=02 is included, like in your example,
> which indicates that a number should be expected, and mxl=22(02)
> indicates that the bind variable can handle a NUMBER(22) data type,
> but a NUMBER(2) was actually provided.
>
> In your case, when the SQL statement executes quickly, you will see:
> oacdty=02 mxl=22(22)
>
> And when the SQL statement executes slowly, you will see:
> oacdty=02 mxl=22(00)
>
> That seems to indicate that when you are making the initial parse
> call, you may not be supplying initial bind values for the parse.
>
> Charles Hooper
> PC Support Specialist
> K&M Machine-Fabricating, Inc.- Hide quoted text -
>
> - Show quoted text -

Another things that I have just noticed is that you have
cursor_sharing set to force while using prepared statements. Maybe you
need the setting at the database level, but it looks like you don't
need it at the session level (for this particular type of session).
You can alter the value at the session level with: ALTER SESSION SET
cursor_sharing = exact (or similar should you need it).