CliffWirt
asked on
Query runs fine in TOAD, is drastically slowed down in JDBC
I have a complex query that runs quickly in TOAD against an Oracle9i database, but slows down drastically (about 2 orders of magnitude) when run as a PreparedStatement in JDBC. The query runs fine in JDBC, however, when it is run as a Statement instead of as a PreparedStatement.
Some other peculiarities: the problem query runs fine, even as a PreparedStatement when part of the where clause takes the form of condition = such and such; it only slows down when that part of the where clause takes the form of a range, as in "where condition < such and such and condition > such and such."
The fact that the problem query runs fine in TOAD would seem to indicate that the problem lies with how the JDBC driver handles this particular PreparedStatement. I've tried substituting newer JDBC drivers, but to no effect. The query does not use timestamps in the where clause, so setTimestamp() is not an issue (I know that is one factor that can cause JDBC to slow down a PreparedStatement). We're sure it's not a network problem.
Does anyone have any ideas on what might be causing JDBC to mess up on the PreparedStatement? And what to do about it?
Unfortunately, I am not able to give the query here; I realize that will make it much more difficult to come up with suggestions.
Some other peculiarities: the problem query runs fine, even as a PreparedStatement when part of the where clause takes the form of condition = such and such; it only slows down when that part of the where clause takes the form of a range, as in "where condition < such and such and condition > such and such."
The fact that the problem query runs fine in TOAD would seem to indicate that the problem lies with how the JDBC driver handles this particular PreparedStatement. I've tried substituting newer JDBC drivers, but to no effect. The query does not use timestamps in the where clause, so setTimestamp() is not an issue (I know that is one factor that can cause JDBC to slow down a PreparedStatement). We're sure it's not a network problem.
Does anyone have any ideas on what might be causing JDBC to mess up on the PreparedStatement? And what to do about it?
Unfortunately, I am not able to give the query here; I realize that will make it much more difficult to come up with suggestions.
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Are you using binds when you run the query in TOAD? And, just as importantly, are you fetching all the rows in TOAD? I don't know how many rows you have in this result set, but TOAD by default will only fetch the first 25 or so rows, which can make TOAD seem faster than a JDBC call that is fetching all rows.
try using the optimizer hint
select /*+ first_rows */ col1,col2,......
This worked for one of my colleague
select /*+ first_rows */ col1,col2,......
This worked for one of my colleague
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER CERTIFIED SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
ToddBarry:
I did run it with bind variables in TOAD (actually, I ran it with binds in TOAD this morning, on your suggestion ... my bad that I did not think of this first ;) ). It runs lightening fast, even with binds, in TOAD.
The resultset is only 1 row (although it has to touch a humungous number of blocks to return that one row).
I did run it with bind variables in TOAD (actually, I ran it with binds in TOAD this morning, on your suggestion ... my bad that I did not think of this first ;) ). It runs lightening fast, even with binds, in TOAD.
The resultset is only 1 row (although it has to touch a humungous number of blocks to return that one row).
If the queries between TOAD and JDBC are identical (with the only difference being the :bind placeholders in TOAD and the ? bind placeholders in JDBC), I would look next to run a SQL trace (sql_trace and TKPROF) on both the TOAD and JDBC sessions and compare the differences.
ASKER
The problem is more complicated than I initially stated. Here are the dimensions of the problem as I now see it:
1) I've been working with 3 databases, Production, Staging, and Development.
2) The query with binds runs fine in TOAD against all 3 databases.
3) When run through JDBC, the query takes forever when run as a PreparedStatement against Development, but runs lightening fast as a Statement. The query takes forever when run through JDBC as a PreparedStatement against Production, but runs lightening fast as a Statement. When run through JDBC against Staging, the query runs lightening fast both as a PreparedStatement and as a Statement. The query in JDBC is identical with the one in TOAD, the only difference being the :bind placeholders in TOAD and the ? bind placeholders in JDBC.
4) Staging and Development are both recent copies of Production, Staging being a slightly more recent copy than Development. This morning, the DBA looked at the parameters of all 3 databases, and saw nothing that leaped to the eye as the cause of the problem.
5) As I mentioned above, the query contains a numeric range in the WHERE clause. The problem in Development and Production (and inside JDBC) occurs only for certain values for the range, not others. (And the values that cause problems in Development and Production work fine in Staging.)
So there are 3 dimensions to the problem: the driver, the database, and the data. (I feel like I am playing 3-dimensional chess.)
I did a level-12 Extended Trace of the query as it runs through JDBC as a PreparedStatement against Development and Staging, and ran the raw trace file through the little Profiler in Millsap's OPTIMIZING ORACLE PERFORMANCE. Here are the results I got:
Development:
Duration Pct Oracle kernel event
--------- ------ --------------------------
255.293458s 94.0% db file sequential read
36.040000s 13.3% total CPU
.006813s 0.0% SQL*Net message from client
.000004s 0.0% SQL*Net message to client
-19.826748s -7.3% unaccounted-for
--------- ------ --------------------------
271.513527s 100.0% Total Response Time
Staging:
Duration Pct Oracle kernel event
--------- ------ --------------------------
9.270000s 101.1% total CPU
.101766s 1.1% db file sequential read
.013864s 0.2% SQL*Net message from client
.0000.06s 0.0% SQL*Net message to client
-.220950s -2.4% unaccounted-for
--------- ------ --------------------------
9.164686s 100.0% Total Response Time
So in Development, most of the Response Time is being taken up by db file sequential reads. This is the case even when I run the query again and again in "rapid" succession (about every four minutes, as soon as the query returns) in JDBC; each Resource Profile shows a huge percentage of the Response Time taken up by db file sequential reads. So it seems that Oracle is ignoring the buffer cache and going to disk each time it sees the query (that is, when the query is run through JDBC and against the Development database.)
I have this vague idea forming in my head that maybe JDBC is causing some sort of buffer overflow someplace in Development and Production that it is not causing in Staging, and that it is doing so only in certain circumstances (i.e., PreparedStatement, certain data, range of values). It seems clear that there is something about Staging that is keeping Staging from choking when it receives the PreparedStatement from JDBC, something that Development and Production lack.
Can anyone form a more definite and less vague hypothesis about what might be going on?
1) I've been working with 3 databases, Production, Staging, and Development.
2) The query with binds runs fine in TOAD against all 3 databases.
3) When run through JDBC, the query takes forever when run as a PreparedStatement against Development, but runs lightening fast as a Statement. The query takes forever when run through JDBC as a PreparedStatement against Production, but runs lightening fast as a Statement. When run through JDBC against Staging, the query runs lightening fast both as a PreparedStatement and as a Statement. The query in JDBC is identical with the one in TOAD, the only difference being the :bind placeholders in TOAD and the ? bind placeholders in JDBC.
4) Staging and Development are both recent copies of Production, Staging being a slightly more recent copy than Development. This morning, the DBA looked at the parameters of all 3 databases, and saw nothing that leaped to the eye as the cause of the problem.
5) As I mentioned above, the query contains a numeric range in the WHERE clause. The problem in Development and Production (and inside JDBC) occurs only for certain values for the range, not others. (And the values that cause problems in Development and Production work fine in Staging.)
So there are 3 dimensions to the problem: the driver, the database, and the data. (I feel like I am playing 3-dimensional chess.)
I did a level-12 Extended Trace of the query as it runs through JDBC as a PreparedStatement against Development and Staging, and ran the raw trace file through the little Profiler in Millsap's OPTIMIZING ORACLE PERFORMANCE. Here are the results I got:
Development:
Duration Pct Oracle kernel event
--------- ------ --------------------------
255.293458s 94.0% db file sequential read
36.040000s 13.3% total CPU
.006813s 0.0% SQL*Net message from client
.000004s 0.0% SQL*Net message to client
-19.826748s -7.3% unaccounted-for
--------- ------ --------------------------
271.513527s 100.0% Total Response Time
Staging:
Duration Pct Oracle kernel event
--------- ------ --------------------------
9.270000s 101.1% total CPU
.101766s 1.1% db file sequential read
.013864s 0.2% SQL*Net message from client
.0000.06s 0.0% SQL*Net message to client
-.220950s -2.4% unaccounted-for
--------- ------ --------------------------
9.164686s 100.0% Total Response Time
So in Development, most of the Response Time is being taken up by db file sequential reads. This is the case even when I run the query again and again in "rapid" succession (about every four minutes, as soon as the query returns) in JDBC; each Resource Profile shows a huge percentage of the Response Time taken up by db file sequential reads. So it seems that Oracle is ignoring the buffer cache and going to disk each time it sees the query (that is, when the query is run through JDBC and against the Development database.)
I have this vague idea forming in my head that maybe JDBC is causing some sort of buffer overflow someplace in Development and Production that it is not causing in Staging, and that it is doing so only in certain circumstances (i.e., PreparedStatement, certain data, range of values). It seems clear that there is something about Staging that is keeping Staging from choking when it receives the PreparedStatement from JDBC, something that Development and Production lack.
Can anyone form a more definite and less vague hypothesis about what might be going on?
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
Now the problem is simpler than I had first thought, and I now have it partially solved.
I had made a mistake with TOAD. When the popup window appeared asking for the values of the bind variables after hitting run on the problem query, I had put single quotation marks around the String values. So of course the query returned no values, because Oracle thought the single quotation marks were part of the String. And returning no values, the query was of course much quicker than the query run through JDBC. There's egg on my face, plus my face is reddening behind all the egg. (Just so I can put the blame someplace else, I'll mention that I had STARTED OUT by leaving the single quotation marks out on the String values in the TOAD popup window, but then the DBA said 'You silly thing. Of course you have to put single quotation marks around the String values. Jeesh. You Java developers.' So egg on my DBA's face also.)
So now I see that the problem query as a PreparedStatement runs just the same in TOAD as it does in JDBC -- horribly in Development and Production, and okay (but actually not great) in Staging. The problem is not with the driver at all.
I noticed that the Explain Plan for the query used the wrong table as the driving table. So I added the /*+ ordered */ hint to change the driving table, and all of a sudden everything runs great in all three databases, Development, Staging, and Production. In all three, the queries takes just milliseconds. (I had tried the /*+ ordered */ hint before in Development and it did not work, but that was probably because the statistics for Development had not been updated yet; at that time, Development was relying on stats done before Production had been copied to it!)
But I consider my problem just partially solved -- I have a skating-on-thin-ice feeling -- because the Development and Staging databases are acting very differently in how they treat the PreparedStatement when the query has no hint. When I run the PreparedStatement without hints in Development, the query takes 5 minutes to return the 1-row result set, and consumes 259,000 physical reads (and 301,000 logical reads) in the process. As soon as the query returned, I ran it again, and then yet one more time. In all three runs, the Response Time, and the number of physical and logical reads was exactly the same. In other words, Development is unable to see that it already has everything it needs in the buffer cache -- it thinks that it has to go to disk each time it receives the query. Thus the hugely slow Response Time.
When I run the PreparedStatement without hints in Staging, the query takes 8 seconds, does a huge number of logical reads (296,000), but 0 logical reads. Staging is immediately able to see that it can use the buffer cache.
(With the hint, the logical reads go down to 11,000 in both Development and Staging, so the query takes just milliseconds.)
So why would Development be ignorant of the fact it has a buffer cache when it receives a PreparedStatement, while Staging does know that it has a buffer cache? Would bind variable peeking have something to do with this?
I need to know what Staging is doing right and what Development (and presumably Production) are doing wrong in how they handle PreparedStatements vis a vis the buffer cache. Otherwise, I am skating on thin ice.
Does anyone have a clue?
I had made a mistake with TOAD. When the popup window appeared asking for the values of the bind variables after hitting run on the problem query, I had put single quotation marks around the String values. So of course the query returned no values, because Oracle thought the single quotation marks were part of the String. And returning no values, the query was of course much quicker than the query run through JDBC. There's egg on my face, plus my face is reddening behind all the egg. (Just so I can put the blame someplace else, I'll mention that I had STARTED OUT by leaving the single quotation marks out on the String values in the TOAD popup window, but then the DBA said 'You silly thing. Of course you have to put single quotation marks around the String values. Jeesh. You Java developers.' So egg on my DBA's face also.)
So now I see that the problem query as a PreparedStatement runs just the same in TOAD as it does in JDBC -- horribly in Development and Production, and okay (but actually not great) in Staging. The problem is not with the driver at all.
I noticed that the Explain Plan for the query used the wrong table as the driving table. So I added the /*+ ordered */ hint to change the driving table, and all of a sudden everything runs great in all three databases, Development, Staging, and Production. In all three, the queries takes just milliseconds. (I had tried the /*+ ordered */ hint before in Development and it did not work, but that was probably because the statistics for Development had not been updated yet; at that time, Development was relying on stats done before Production had been copied to it!)
But I consider my problem just partially solved -- I have a skating-on-thin-ice feeling -- because the Development and Staging databases are acting very differently in how they treat the PreparedStatement when the query has no hint. When I run the PreparedStatement without hints in Development, the query takes 5 minutes to return the 1-row result set, and consumes 259,000 physical reads (and 301,000 logical reads) in the process. As soon as the query returned, I ran it again, and then yet one more time. In all three runs, the Response Time, and the number of physical and logical reads was exactly the same. In other words, Development is unable to see that it already has everything it needs in the buffer cache -- it thinks that it has to go to disk each time it receives the query. Thus the hugely slow Response Time.
When I run the PreparedStatement without hints in Staging, the query takes 8 seconds, does a huge number of logical reads (296,000), but 0 logical reads. Staging is immediately able to see that it can use the buffer cache.
(With the hint, the logical reads go down to 11,000 in both Development and Staging, so the query takes just milliseconds.)
So why would Development be ignorant of the fact it has a buffer cache when it receives a PreparedStatement, while Staging does know that it has a buffer cache? Would bind variable peeking have something to do with this?
I need to know what Staging is doing right and what Development (and presumably Production) are doing wrong in how they handle PreparedStatements vis a vis the buffer cache. Otherwise, I am skating on thin ice.
Does anyone have a clue?
ASKER
Oops. The sentence above should read: "When I run the PreparedStatement without hints in Staging, the query takes 8 seconds, does a huge number of logical reads (296,000), but 0 PHYSICAL reads."
Yes, you certainly have made progress now. To see why the query behaves one way in staging and differently in the other DBs, you can use EXPLAIN PLAN to see the execution path each is choosing.
explain plan
SET STATEMENT_ID = 'exp1'
for select co1, col2, ....;
Then you can run a query like this to see the path.
SELECT cardinality "Rows",
lpad(' ',level-1)||operation||' '||
options||' '||object_name "Plan"
FROM PLAN_TABLE
CONNECT BY prior id = parent_id
AND prior statement_id = statement_id
START WITH id = 0
AND statement_id = 'exp1'
ORDER BY id;
After you have explained the plan in both environments, you can compare the execution plan. In the one environment you might have statistics that help choose the right plan or in the other, outdated stats that cause problems. Or stats might be missing. Lost of possibilties, but looking at the execution path is the first step to understand what Oracle is doing behind the scenes.
explain plan
SET STATEMENT_ID = 'exp1'
for select co1, col2, ....;
Then you can run a query like this to see the path.
SELECT cardinality "Rows",
lpad(' ',level-1)||operation||' '||
options||' '||object_name "Plan"
FROM PLAN_TABLE
CONNECT BY prior id = parent_id
AND prior statement_id = statement_id
START WITH id = 0
AND statement_id = 'exp1'
ORDER BY id;
After you have explained the plan in both environments, you can compare the execution plan. In the one environment you might have statistics that help choose the right plan or in the other, outdated stats that cause problems. Or stats might be missing. Lost of possibilties, but looking at the execution path is the first step to understand what Oracle is doing behind the scenes.
ASKER
JRB1,
Would this give me more than what I get when I hit the 'Explain Plan' button at the bottom of the SQL Editor in TOAD?
Would this give me more than what I get when I hit the 'Explain Plan' button at the bottom of the SQL Editor in TOAD?
Nope, should be exactly the same.
ASKER
The Explain Plan for the problem PreparedStatement query is the same in both Development and Staging when no hint is used -- in both, the wrong table functions as the driving table. And in both Development and Staging the Explain Plan is the same when the /*+ ordered */ hint is used -- the right table functions as the driving table.
So the Explain Plan won't serve as a clue to what the source of the weirdness is, the weirdness being that Development seems incapable of realizing it has a buffer cache when it receives a PreparedStatement. It insists on going to disk no matter how often the PreparedStatement query is run.
So the Explain Plan won't serve as a clue to what the source of the weirdness is, the weirdness being that Development seems incapable of realizing it has a buffer cache when it receives a PreparedStatement. It insists on going to disk no matter how often the PreparedStatement query is run.
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
Last week the DBA and I considered the buffer cache, and there seemed to be nothing unusual there that would account for the trouble. I will look at it again with him when he returns Tuesday.
ASKER
Mystery solved -- I think.
The PreparedStatement query in Development was overwhelming the buffer cache because it was using the wrong Driving table. (The tables involved are huge; making matters worse, the queries have a range condition as one of the filters.) Because the buffer cache was overwhelmed each time, the query had to go to disk each time it was run.
In Staging -- at first -- the query did not go to disk each time it was run. But then, suddenly, the query started behaving in Staging exactly the same way it did in Development, going to disk each time it was run and therefore taking forever. There are half-way plausible explanations for this change in behavior in Staging -- a stress test was being run against Staging, adding data to the tables the query touches; also, Staging had just undergone a restore, the DBA tells me. I don't know the exact reason for the initial difference in behavior, but now that I know the reason for the behavior in Development, that (initial) difference seems much less disturbing to me.
The PreparedStatement query in Development was overwhelming the buffer cache because it was using the wrong Driving table. (The tables involved are huge; making matters worse, the queries have a range condition as one of the filters.) Because the buffer cache was overwhelmed each time, the query had to go to disk each time it was run.
In Staging -- at first -- the query did not go to disk each time it was run. But then, suddenly, the query started behaving in Staging exactly the same way it did in Development, going to disk each time it was run and therefore taking forever. There are half-way plausible explanations for this change in behavior in Staging -- a stress test was being run against Staging, adding data to the tables the query touches; also, Staging had just undergone a restore, the DBA tells me. I don't know the exact reason for the initial difference in behavior, but now that I know the reason for the behavior in Development, that (initial) difference seems much less disturbing to me.
I knew this from the very beginning!
I wrote:
To increase the query on the Oracle server you have to ask the DBA:
1. To investigate the Data Buffer Cache and to try to increase it if it is small and experience difficulties.
..........
I wrote:
To increase the query on the Oracle server you have to ask the DBA:
1. To investigate the Data Buffer Cache and to try to increase it if it is small and experience difficulties.
..........
where field between x and y