Обсуждение: 9.4-1207 behaves differently with server side prepared statements compared to 9.2-1102

Hello,

we have switched the Postgres JDBC driver from 9.2-1102 to 9.4-1207 to keep up-to-date.

After we did this our nightly regression tests that test for performance failed
because with the new driver the tests were roughly 30% slower than with
the previous driver (some of them even more than 30%).

After enabling pg_stat_statements in your test environment we found out that some
statements read a *much* higher number of blocks for the query.

Some sample figures (from pg_stat_statements)

One statement:

1102: 710 executions, total time:   845ms, shared_blks_hit =   624765
1207: 710 executions, total time: 30538ms, shared_blks_hit = 15046689

Another one:

1102: 8600 executions, total_time:   68ms, shared_blks_hit =   49500
1102: 8600 executions, total_time: 4035ms, shared_blks_hit = 3419644

The tests have been run against Postgres 9.4.5.

As the tests don't involve any DML, table bloat could be excluded for a reason why
the number of blocks is so high.

It does not affect *all* statements - some statements (also with execution counts
substantially larger than 200) run with the same performance.

So we assumed it had something to do with the execution plans, and the only way
the driver could influence that (while the statement being exactly the same),
was through the server side prepared statements.

So we ran the tests using "prepareThreshold=0" and then the tests with 1207
ran with the same performance as with the 1102 driver.

We have not yet looked at the actual execution plans (e.g. by enabling the
auto-explain module) because using "prepareThreshold=0" is fine for us for now.

So my question is:

Is it possible that the 1207 driver does something different when preparing statements
compared to 1102 that would cause Postgres to use a completely different execution plan?

The 9.3 driver behaves like the 9.2 driver, so the change probably occurred from 9.2 to 9.4
(we didn't test all the 9.4 builds, only the latest)

Regards
Thomas

Here are the details: http://stackoverflow.com/a/32300222/1261287

TL;DR:  pgjdbc automatically uses server-side prepared statements
since 9.4-1202.

Vladimir

Vladimir Sitnikov schrieb am 11.01.2016 um 13:56:
> Here are the details: http://stackoverflow.com/a/32300222/1261287
>
> TL;DR:  pgjdbc automatically uses server-side prepared statements
> since 9.4-1202.

Hmm, but the previous drivers also did that, at least the documentation suggests that:

   https://jdbc.postgresql.org/documentation/92/connect.html#connection-parameters

   "The default is five, meaning start using server side prepared statements
    on the fifth execution of the same PreparedStatement object"

The difference is as follows: 1202 can cache across statement.close()
calls. 1201 can't do that.

In other words, to use server-prepared statements in previous
versions, you had to reuse the *same* PreparedStatement *object* again
and again. As soon as you issue .close() you lose your shiny
server-prepared statement.

Typical applications are written in a form of
PreparedStatement ps = con.prepareStatement(sql);
ps.excuteQuery();
ps.close();

In other words, almost always developers just recreate
PreparedStatement and close it.
The improvement of 1202 was to identify such patterns and use
server-prepared statement in such cases as well.
Vladimir

>I can't imagine why that would even happen.

That can happen in case backend uses "bad plan" for server-prepared statement.

Here are more details:
http://www.postgresql.org/docs/9.4/static/sql-prepare.html
As far as I remember, backend can switch plan on 5th or 6th execution
of server-prepared statement.

>PG DOC: If a prepared statement is executed enough times, the server may eventually decide to save and re-use a
genericplan rather than re-planning each time. This will occur immediately if the prepared statement has no parameters 

In other words, even server-prepared statements can behave differently
from one execution to another.

I've seen a couple of times when a query was fast "the first 5 times",
then backend (9.4) switched to much slower plan.
That happened with exactly the same input value.

The resolution for me was to fix query plan as desired (add offset 0
here and there) so the join order was specific.


On the other hand, I've seen impressive performance improvements for
long queries that take much longer to plan than to execute. Common
wisdom is to hide long SQL into stored procedures (they have
transparent statement cache too), however it can't easily be done for
existing application.

Vladimir

Vladimir Sitnikov schrieb am 11.01.2016 um 14:05:
> The difference is as follows: 1202 can cache across statement.close()
> calls. 1201 can't do that.
>
> In other words, to use server-prepared statements in previous
> versions, you had to reuse the *same* PreparedStatement *object* again
> and again. As soon as you issue .close() you lose your shiny
> server-prepared statement.
>

Ah, thanks.

Atenciosamente,

Edson Carlos Ericksson Richter

It's not that JDBC is slower, it is the plans that are being generated are slower. I can't imagine why that would even happen. 

JDBC doesn't really change the incoming SQL

Dave Cramer

davec@postgresintl.com

www.postgresintl.com

On 11 January 2016 at 08:29, Christian Bjørnbak <cbj@touristonline.dk> wrote:

@Vladimir but if 1202+ has become smarter than 1102 and reuse prepared statements more often how come Thomas experience the 1207 to be magnitudes slower?

Shouldn't it be the other way around?

Med venlig hilsen / Kind regards,

Christian Bjørnbak

Chefudvikler / Lead Developer
TouristOnline A/S
Islands Brygge 43
2300 København S
Denmark
TLF: +45 32888230
Dir. TLF: +45 32888235

2016-01-11 14:05 GMT+01:00 Vladimir Sitnikov <sitnikov.vladimir@gmail.com>:

The difference is as follows: 1202 can cache across statement.close()
calls. 1201 can't do that.

In other words, to use server-prepared statements in previous
versions, you had to reuse the *same* PreparedStatement *object* again
and again. As soon as you issue .close() you lose your shiny
server-prepared statement.

Typical applications are written in a form of
PreparedStatement ps = con.prepareStatement(sql);
ps.excuteQuery();
ps.close();

In other words, almost always developers just recreate
PreparedStatement and close it.
The improvement of 1202 was to identify such patterns and use
server-prepared statement in such cases as well.
Vladimir

--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc

>In my case, problema is that after optimization at server side, results get different.

Do you mean "wrong results" kind of issue?
which driver version are you using?

Generally speaking, it is worth submitting "bad performance when using
prepared statements" issues to PostgreSQL hackers team.
If just a couple of SQLs behave badly due to server-prepared
statements, then it might make sense just tune the statements in
question.
Vladimir

Dave Cramer schrieb am 11.01.2016 um 14:56:
> On 11 January 2016 at 08:54, Vladimir Sitnikov <sitnikov.vladimir@gmail.com <mailto:sitnikov.vladimir@gmail.com>>
wrote:
>
>     >I can't imagine why that would even happen.
>
>     That can happen in case backend uses "bad plan" for server-prepared statement.
>
>
> Yes, but we are talking about the same backend with the same SQL, The only difference is the driver. Is that correct
?

Correct.

Identical SQL, identical query parameters, identical order of execution, identical backend, just a different driver
version

Thomas

Dave Cramer schrieb am 11.01.2016 um 15:46:
>
> On 11 January 2016 at 09:44, Thomas Kellerer <spam_eater@gmx.net <mailto:spam_eater@gmx.net>> wrote:
>     > Yes, but we are talking about the same backend with the same SQL, The only difference is the driver. Is that
correct? 
>
>     Correct.
>
>     Identical SQL, identical query parameters, identical order of execution, identical backend, just a different
driverversion 
>
>
> Is it possible to get server logs ?

If that is helpful, I think I can arrange that.

Which logging settings would you like to have for that?

Thomas, as far as I see, you have offending queries and bind values
for them, don't you?

Can you please perform the following dance in psql or pgadmin?

PREPARE prep1207(number,number,number,number,number,number) as -- <--
data types for the bind variables
select .. $1, ... where id=$2;  -- <-- your query here

EXPLAIN ANALYZE EXECUTE prep1207(1,2,3,42,100500); -- <-- values for
bind variables
EXPLAIN ANALYZE EXECUTE prep1207(1,2,3,42,100500); -- <-- values for
bind variables
EXPLAIN ANALYZE EXECUTE prep1207(1,2,3,42,100500); -- <-- values for
bind variables
EXPLAIN ANALYZE EXECUTE prep1207(1,2,3,42,100500); -- <-- values for
bind variables
EXPLAIN ANALYZE EXECUTE prep1207(1,2,3,42,100500); -- <-- values for
bind variables

Ideally, it should reproduce the issue. In other words, 5th or 6th
execution should flip to bad plan.

Then share the plan/query.
If table names cannot be made public, you might want try
http://explain.depesz.com/ to anonymize the plan.

Vladimir

Dave Cramer schrieb am 11.01.2016 um 15:56:
> I just want to see what the server sees for SQL statements with the different drivers.
>
> The easiest way I find is to set log_min_duration to 0 which logs everything and then you can change it back
>

I'll see what I can do.

We will have to anonymize the statements somehow because for legal reasons I can't disclose them.

Thomas

I'm using 1201 driver. No matter JDK 7 or JDK 8.
Big real issue for me: after third query, the prepareThresold is hit,
and timezone data is converted "on the fly" to "timezone without
daylights" for timestamp fields.
Data is stored in database as "2015-09-30 00:00:00", in the 1st to 3rd
query returns with "2015-09-30 00:00:00", and the 4º and on returns
"2015-09-29 23:00:00".

Disabling with prepareThreshold=0 solved the problem once for all.
I had no further time to investigate and/or produce a case for asking
for a fix.

Regards,

Atenciosamente,

Edson Carlos Ericksson Richter

Em 11/01/2016 12:14, Vladimir Sitnikov escreveu:
>> In my case, problema is that after optimization at server side, results get different.
> Do you mean "wrong results" kind of issue?
> which driver version are you using?
>
> Generally speaking, it is worth submitting "bad performance when using
> prepared statements" issues to PostgreSQL hackers team.
> If just a couple of SQLs behave badly due to server-prepared
> statements, then it might make sense just tune the statements in
> question.
> Vladimir
>
>

Warning:

This only happens if your country has Daylights Saving Time active.
In Brazil, default timezone is GMT-03:00. Currently in DST, the timezone
is GMT-02:00.
This seems to affect some kind of value conversion, and subtract 1 hour
from timestamp values.

Atenciosamente,

Edson Carlos Ericksson Richter

Em 11/01/2016 14:15, Edson Richter escreveu:
> I'm using 1201 driver. No matter JDK 7 or JDK 8.
> Big real issue for me: after third query, the prepareThresold is hit,
> and timezone data is converted "on the fly" to "timezone without
> daylights" for timestamp fields.
> Data is stored in database as "2015-09-30 00:00:00", in the 1st to 3rd
> query returns with "2015-09-30 00:00:00", and the 4º and on returns
> "2015-09-29 23:00:00".
>
> Disabling with prepareThreshold=0 solved the problem once for all.
> I had no further time to investigate and/or produce a case for asking
> for a fix.
>
> Regards,
>
> Atenciosamente,
>
> Edson Carlos Ericksson Richter
>
> Em 11/01/2016 12:14, Vladimir Sitnikov escreveu:
>>> In my case, problema is that after optimization at server side,
>>> results get different.
>> Do you mean "wrong results" kind of issue?
>> which driver version are you using?
>>
>> Generally speaking, it is worth submitting "bad performance when using
>> prepared statements" issues to PostgreSQL hackers team.
>> If just a couple of SQLs behave badly due to server-prepared
>> statements, then it might make sense just tune the statements in
>> question.
>> Vladimir
>>
>>
>
>
>

Can you put more details on the APIs you use to retrieve the data?
.getTimestamp(int)?
.getTimestamp(int, Calendar)?
.getString(int)?
.getObject(int)?
Vladimir

Actually, I don't know.

I'm using EclipseLink as layer before the database.
Since my Java classes are annotated with @Temporal(TIMESTAMP), I do
understand EclipseLink will be using getTimeStamp - but I can't tell for
sure.
Also, when looking data using "pgAdmin" timestamp data appears normal.
But if querying data using NetBeans SQL explorer or ART (reporting
tool), I get exactly same issue as with EclipseLink.
I suppose NetBeans and ART use getObject, but it is mere speculation
from my side.

As said before, since prepareThreshold=0 solved my problem, and I have a
time shortage last few months, I'll try to investigate further in near
future.
Sorry not being of great help right now.

Regards,

Atenciosamente,

Edson Carlos Ericksson Richter

Em 11/01/2016 17:50, Vladimir Sitnikov escreveu:
> Can you put more details on the APIs you use to retrieve the data?
> .getTimestamp(int)?
> .getTimestamp(int, Calendar)?
> .getString(int)?
> .getObject(int)?
> Vladimir
>
>

What is the field type?
timestamp? timestamp with time zone?

Are you using the latest java timezone updates? (tzupdater)

>As said before, since prepareThreshold=0 solved my problem

Then
binaryTransferDisable=DATE,DATE_ARRAY,TIMESTAMP,TIMESTAMP_ARRAY,TIMESTAMPTZ,TIMESTAMPTZ_ARRAY,TIME,TIME_ARRAY,TIMETZ,TIMETZ_ARRAY
connection property might be better workaround.

Vladimir

This is really interesting.
I would give a try.

Regards,

Atenciosamente,

Edson Carlos Ericksson Richter

Em 11/01/2016 18:42, Vladimir Sitnikov escreveu:
> What is the field type?
> timestamp? timestamp with time zone?
>
> Are you using the latest java timezone updates? (tzupdater)
>
>> As said before, since prepareThreshold=0 solved my problem
> Then
binaryTransferDisable=DATE,DATE_ARRAY,TIMESTAMP,TIMESTAMP_ARRAY,TIMESTAMPTZ,TIMESTAMPTZ_ARRAY,TIME,TIME_ARRAY,TIMETZ,TIMETZ_ARRAY
> connection property might be better workaround.
>
> Vladimir

According to EclipseLink's sources, the type of the column must be
DATE and you are using java.sql.Date.
Is that correct?


https://github.com/eclipse/eclipselink.runtime/blob/fc5d47ec1b26dea932a26ae152de347da8ec62f9/foundation/org.eclipse.persistence.core/src/org/eclipse/persistence/platform/database/PostgreSQLPlatform.java#L329
Vladimir

Here's the fix:
https://github.com/pgjdbc/pgjdbc/commit/642b48a787098a6c5a068710bdbbf9f1b11f3aac

You can try it via Maven Central's <version>9.4.1208-SNAPSHOT</version>


I wonder if there is anybody from Portugal on the list?
Can you explain how you represent 2000-03-26 00:00:00?

As far as I understand, somewhere near 26th March Atlantic/Azores
skips from 00:00:00 to 01:00:00.
See http://www.timeanddate.com/time/change/portugal/ponta-delgada-azores
for 2000-03-26 00:00:00 -> 01:00:00

This causes troubles since java.util.Date is supposed to be 2000-03-26
00:00:00 Atlantic/Azores, however there is no such thing like
"2000-03-26 00:00:00 Atlantic/Azores" in Java.
If you try to use calendar.set(Calendar.HOUR_OF_DAY, 0), then you get
01:00:00 back.

This caused me to add exception to the expected results:

https://github.com/pgjdbc/pgjdbc/commit/642b48a787098a6c5a068710bdbbf9f1b11f3aac#diff-b318f589843d60530d1eada03263c1b0R895

Vladimir

Even though the particular case with DATE is fixed, I would still
recommend to consider timestamptz data type.

DATE has inherent timezone problems, so if you are storing time
instants, then you'd better operate on timestamptz.
See "2000-03-26 00:00:00 Atlantic/Azores problem" above.

Vladimir

> Is it possible to get server logs ?

I have picked out one of the statements that suffered from this and sanitized the logfile.

   http://sql-workbench.net/pg_jdbc_94.log

The complete statement is at the top of the file and in the messages themselves,
I have replaced each occurrence of the statement with "select ...."

The interesting thing (at least for me) is that the first few executions of the
server side statement have pretty much the same runtime as the ones before the prepare.
And then suddenly the runtime shoots through the rough going up from 1ms to 40ms or even 60ms

Regards
Thomas

>And then suddenly the runtime shoots through the rough going up from 1ms to 40ms or even 60ms

Can it be data-dependent?
Can you try using the same input values for multiple executions?

Vladimir

Vladimir Sitnikov schrieb am 12.01.2016 um 11:44:
>> And then suddenly the runtime shoots through the rough going up from 1ms to 40ms or even 60ms
>
> Can it be data-dependent?

Apparently the server chooses a bad execution plan when a server side prepared
statement is used - it is very likely because of the parameter placeholders
that don't allow Postgres to evaluate the correct cardinality and it
creates a "one size fits all plan"

My guess is that the plan that is generated using the prepared statement only
works for some input values, but not for all (a problem that Oracle has suffered
from for ages as well). As I have written previously we didn't bother to enable the
auto-explain module to see where Postgres goes wrong in the planning because using
prepareThreshold=0 is good enough for us.

Given my experience with bad plans for parametrized statements in Oracle I think it is
definitely the better choice to not use server side prepared statements - at least for
this application.

> Can you try using the same input values for multiple executions?

The tests we are running are pretty much pre-defined. Re-working them would probably be a bigger deal.
Plus I am not directly involved in that project, so I am actually relaying everything here ;)

Regards
Thomas

>My guess is that the plan that is generated using the prepared statement only
works for some input values, but not for all (a problem that Oracle has suffered
from for ages as well).

I think the problem is as follows:
1) During initial runs in server-prepared mode PG still uses exact
values to plan the query
2) It turns out that for certain conditions PG properly understands
that certain conditions are bad.
I bet $1 = '180', $2 = '1' returns lots of rows, thus backend chooses
to start with $3 = '7728'.
3) Later backend creates generic plan. That one does not include
knowledge of exact $1 and &2 values. Thus backend estimates the
cardinality differently.
That results a plan flip.

Note: in Oracle (9-10) bind peeking worked in another way.
There, a plan built for the first bind values was reused for all the
subsequent executions.
That makes more sense for me since that gives at least some stability
(it avoids sudden plan flips).

I'll try to file a case to hackers list to check what they say on the plan flip.

PS. The sad thing is JDBC does have room for "SQL-injection-safe,
non-server-prepared query". In other words, plain java.sql.Statement
does not have "setXXX" methods, and PreparedStatement has no
user-provided API to convey "please, do not use server-prepared
statement as the plan is very data-dependent".

PPS. I do not think the plan is data-dependent in the particular case.
I bet the same plan works for all the values that particular
application uses. It is just PG's fault that plan flip happens.

Vladimir

I'm using "PostgreSQL 9.4.4 on x86_64-unknown-linux-gnu, compiled by
gcc (GCC) 4.4.7 20120313 (Red Hat 4.4.7-11), 64-bit"

Vladimir

Vladimir Sitnikov wrote:
> >My guess is that the plan that is generated using the prepared statement only
> works for some input values, but not for all (a problem that Oracle has suffered
> from for ages as well).
> 
> I think the problem is as follows:
> 1) During initial runs in server-prepared mode PG still uses exact
> values to plan the query
> 2) It turns out that for certain conditions PG properly understands
> that certain conditions are bad.
> I bet $1 = '180', $2 = '1' returns lots of rows, thus backend chooses
> to start with $3 = '7728'.
> 3) Later backend creates generic plan. That one does not include
> knowledge of exact $1 and &2 values. Thus backend estimates the
> cardinality differently.
> That results a plan flip.
> 
> Note: in Oracle (9-10) bind peeking worked in another way.
> There, a plan built for the first bind values was reused for all the
> subsequent executions.
> That makes more sense for me since that gives at least some stability
> (it avoids sudden plan flips).
> 
> I'll try to file a case to hackers list to check what they say on the plan flip.

I didn't look at the specific query, but I have seen cases like that before.

During the first 5 executions, PostgreSQL generates a specific plan
and remembers the *estimated* cost.
After that, the cost for the generic plan (with $1, $2, ...) is
estimated and compared to the average of the estimated costs of
the previous specific plans.
If the generic plan is no worse, it is used from then on.

The problem is that only estimates are compared.
The performance drop from the sixth execution on usually means that
the cost estimate for the generic plan is off.

It would be helpful to create a prepared statement, and on the sixth
execution capture the output of
EXPLAIN (ANALYZE, BUFFERS) EXECUTE mystmt(args);

Analyzing that should help you find out where things go wrong.

Yours,
Laurenz Albe

On 12/01/16 11:26, Vladimir Sitnikov wrote:
>> My guess is that the plan that is generated using the prepared statement only
> works for some input values, but not for all (a problem that Oracle has suffered
> from for ages as well).
>
> I think the problem is as follows:
> 1) During initial runs in server-prepared mode PG still uses exact
> values to plan the query
  Most types in the driver map directly but date time parameters are
special. There may be others treated as a special case.

  I think you'll find initial executions (Bind) use the paramater type
org.postgresql.core.Oid.UNSPECIFIED for the date time.
https://github.com/pgjdbc/pgjdbc/blob/master/pgjdbc/src/main/java/org/postgresql/jdbc/PgPreparedStatement.java#L1426
> 2) It turns out that for certain conditions PG properly understands
> that certain conditions are bad.
> I bet $1 = '180', $2 = '1' returns lots of rows, thus backend chooses
> to start with $3 = '7728'.
  At the threshold a ParameterDescribe is issued by the front end. The
back end returns the actual type used to store the parameter. The front
end stores the updated parameter type information.
> 3) Later backend creates generic plan. That one does not include
> knowledge of exact $1 and &2 values. Thus backend estimates the
> cardinality differently.
  Subsequent Bind messages use the replaced parameter type. The back end
switches to a new plan using the updated type information.

  I could be wrong on this as the codebase has changed dramatically in
recent weeks.

Jeremy
> That results a plan flip.
>
> Note: in Oracle (9-10) bind peeking worked in another way.
> There, a plan built for the first bind values was reused for all the
> subsequent executions.
> That makes more sense for me since that gives at least some stability
> (it avoids sudden plan flips).
>
> I'll try to file a case to hackers list to check what they say on the plan flip.
>
> PS. The sad thing is JDBC does have room for "SQL-injection-safe,
> non-server-prepared query". In other words, plain java.sql.Statement
> does not have "setXXX" methods, and PreparedStatement has no
> user-provided API to convey "please, do not use server-prepared
> statement as the plan is very data-dependent".
>
> PPS. I do not think the plan is data-dependent in the particular case.
> I bet the same plan works for all the values that particular
> application uses. It is just PG's fault that plan flip happens.
>
> Vladimir
>
>


--
Jeremy Whiting
Senior Software Engineer, JBoss Performance Team
Red Hat

------------------------------------------------------------
Registered Address: RED HAT UK LIMITED, 64 Baker Street, 4th Floor, Paddington. London. United Kingdom W1U 7DF
Registered in UK and Wales under Company Registration No. 3798903  Directors: Michael Cunningham (US), Charles Peters
(US),Matt Parson (US) and Michael O'Neill(Ireland) 

Jeremy,

The issue is easily reproducible in plain psql.
It has nothing to do with jdbc driver.
It has nothing to do with date-time either.

> I think you'll find initial executions (Bind) use the paramater type org.postgresql.core.Oid.UNSPECIFIED for the date
time.

Does $1 = '180', $2 = '1' or $3 = '7728' look like a date-time value?

Vladimir