CODEWITHSUNDEEP
javapostgresqleclipselinkjpa-2.0
iXô
iXô

Reputation: 1181

After 9 queries to database, the time to perform the same query is multiplied by 7

I am using PostgreSQL (9.4.8) on Windows 7 32. I am accessing the database via Eclipselink 2.6.3 and JDBC driver 9.4.1208 on JDK 8u72.

I am performing a simple count query (build with the Criteria API). The first query is taking some times, no problem for that, after that, the next 8 queries taking slightly less time, and it is great. Then for the 9th query the response is taking 7x times of the previous query, and will never go down.

Here an extract of my logs : 

[EL Fine]: sql: 2016-07-04 17:19:42.658--ServerSession(13112008)--Connection(27980113)--SELECT now()
INFO  - SELECT now() = 2016-07-04 17:19:41.8
[EL Fine]: sql: 2016-07-04 17:19:42.691--ServerSession(13112008)--Connection(27980113)--SELECT version()
INFO  - SELECT version() = PostgreSQL 9.4.8, compiled by Visual C++ build 1800, 32-bit
INFO  - JDBC Version = PostgreSQL 9.4.1208

[EL Fine]: sql: 2016-07-04 17:19:42.738--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:42.726, 2016-07-04 17:19:42.726]
1 - count : 788166 - 3974
[EL Fine]: sql: 2016-07-04 17:19:46.244--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:46.241, 2016-07-04 17:19:46.241]
2 - count : 788166 - 1500
[EL Fine]: sql: 2016-07-04 17:19:49.745--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:49.742, 2016-07-04 17:19:49.742]
3 - count : 788166 - 1495
[EL Fine]: sql: 2016-07-04 17:19:53.242--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:53.239, 2016-07-04 17:19:53.239]
4 - count : 788166 - 1481
[EL Fine]: sql: 2016-07-04 17:19:56.723--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:56.72, 2016-07-04 17:19:56.72]
5 - count : 788166 - 1497
[EL Fine]: sql: 2016-07-04 17:20:00.219--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:00.217, 2016-07-04 17:20:00.217]
6 - count : 788166 - 1484
[EL Fine]: sql: 2016-07-04 17:20:03.705--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:03.703, 2016-07-04 17:20:03.703]
7 - count : 788166 - 1498
[EL Fine]: sql: 2016-07-04 17:20:07.203--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:07.201, 2016-07-04 17:20:07.201]
8 - count : 788166 - 1498
[EL Fine]: sql: 2016-07-04 17:20:10.701--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:10.7, 2016-07-04 17:20:10.7]
9 - count : 788166 - 1491
[EL Fine]: sql: 2016-07-04 17:20:14.193--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:14.192, 2016-07-04 17:20:14.192]
10 - count : 788166 - 7550
[EL Fine]: sql: 2016-07-04 17:20:23.742--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:23.741, 2016-07-04 17:20:23.741]
11 - count : 788166 - 7553
[EL Fine]: sql: 2016-07-04 17:20:33.296--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:33.295, 2016-07-04 17:20:33.295]
12 - count : 788166 - 7567
[EL Fine]: sql: 2016-07-04 17:20:42.864--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:42.863, 2016-07-04 17:20:42.863]
13 - count : 788166 - 7545

As you can see, the first query takes 3974 ms, the next ones is around 1500ms, then it just to > 7500ms !

What could go wrong ? The database doesn't takes much more cpu power when the problem occurs, nor does my program.

Upvotes: 3

Views: 124

Answers (1)

Laurenz Albe
Laurenz Albe

Reputation: 248295

This looks like PostgreSQL using a generic plan that performs worse than the plan used before.

If you use a java.sql.PreparedStatement, the JDBC driver will substitute the parameters for the first 4 executions and create a server-side prepared statement as of the 5th execution, which will be used ever after (assuming you use the default value of 5 for the connection parameter prepareThreshold).

For the next 5 executions, the PostgreSQL server will create individual plans for this statement, substituting the actual parameters passed.

Then it will create a generic plan (with placeholders instead of the query parameters), and if the query optimizer estimates that this generic plan will not perform worse than the specific plans used up to then, this generic plan will be used ever after.

So in this case, the first 9 executions will use a different plan than the following executions, and if the query optimizer made the wrong choice, you can see a performance drop after that.

I see two options for you:

  • use PREPARE on the PostgreSQL command line to create a prepared statement for your query, then, using EXPLAIN (ANALYZE) EXECUTE, compare the execution plans used for the first 5 executions with the execution plan for the generic query used afterwards (you can tell the generic query from the placeholders $1, $2 etc.).
    Hopefully you can then figure out why the generic plan is worse and improve your query.

  • The simple way: read the documentation how to disable server side prepare statements for this query by setting prepareThreshold to 0.

Upvotes: 3

Related Questions