New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Prepared statement pool and Daylight Saving Time #130

Closed
skarzhevskyy opened this Issue Mar 16, 2014 · 38 comments

Comments

Projects
None yet
7 participants
@skarzhevskyy

skarzhevskyy commented Mar 16, 2014

When you try to retrieve the same Timestamp multiple times on some iteration (4th ... 17th) it may return the time that is one hour off.

data type: timestamp without time zone

The problem exists only in PostgreSql when prepared statement pool is used.

e.g. I store 2014-03-09 06:21:28 but JDBC may returns 2014-03-09 07:21:28
key is "may return". See the tests.

in Eastern Time Zone
http://www.timetemperature.com/canada/daylight_saving_time_canada.shtml

(+1 hour)
Dates: DST Begins at 2 a.m.
Hours that will produce this problem 3AM, 4AM, 5AM and 6AM

(-1 hour)
DST Ends at 2 a.m.
Hours that will produce this problem 1AM, 2AM, 3AM, and 4AM

Statement pool C3P0 or DBCP2 was used during tests.
MySQL, Oracle and HSQLDB divers do not show similar problem.

Envelopment:
Oracle Java 1.7.
postgresql-9.2-1002-jdbc4.jar or postgresql-9.3-1101-jdbc41.jar
PostgreSQL 9.1.5 (Ubuntu 12.04.4 or Windows 7 )
or PostgreSQL 9.3.3 on Windows 7

Tests provided will fail in Eastern Time Zone (e.g. NY/USA)

Tests inside pgjdbc code base. (need to add C3P0 or DBCP2 jar to classpath)
https://github.com/skarzhevskyy/pgjdbc/tree/d1b89b42fbe3d214155d3eb35a00864438ddfcf1/org/postgresql/test/other

Standalone test:
https://github.com/skarzhevskyy/pgjdbc/blob/d1b89b42fbe3d214155d3eb35a00864438ddfcf1/src/postgresql-integration/src/test/java/org/postgresql/test/other/DaylightSavingJDBC.java

with maven project since dependencies required to create statement pool
https://github.com/skarzhevskyy/pgjdbc/tree/d1b89b42fbe3d214155d3eb35a00864438ddfcf1/src/postgresql-integration

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 16, 2014

Any thoughts on why this would happen with pg and not the rest? I am thinking it has something to do with us not being threaded. Connections are actually processes and they may not see the new timezone ? That being said turning off statement caching should exhibit the same problem if the above were true ?

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 16, 2014

Can you give more details what needs to be tests? turning off statement caching on DB configuration level ?

The test above will fail in PST time zone with the same data.
Also the problem is the same regardless of system time. e.g in December it is the same.
Also JDK is not a problem Latest Oracle 1.6 or 1.6.0_05 BEA JRockit have the same results.

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 16, 2014

What I'd like to see is what the server sees. Can you get the server logs
to see what the query is ?

Dave Cramer

On Sun, Mar 16, 2014 at 3:27 PM, Vlad Skarzhevskyy <notifications@github.com

wrote:

Can you give more details what needs to be tests? turning off statement
caching on DB configuration level ?

The test above will fail in PST time zone with the same data.
Also the problem is the same regardless of system time. e.g in December it
is the same.
Also JDK is not a problem Latest Oracle 1.6 or 1.6.0_05 BEA JRockit have
the same results.

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-37767277
.

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 16, 2014

log_min_duration_statement =0
log_line_prefix = '%t %s %p %c %v'

error in java
try# 8; hour of 2014-03-09 07:21:28.0 expected 6 but was 7

I modified SQL
SELECT dval FROM test2 WHERE name = ? and trc is null or trc = ?

where trc is try# so we will see it in trace.

http://pyx4j.com/bug/postgresql-2014-03-16_155607.log

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 16, 2014

I cloned your github version and ran ant test. There were no errors. This
is on a mac running mavericks, psql 9.2.4

Are you saying it only happens with the versions and specific OS mentioned
above ?

Dave Cramer

On Sun, Mar 16, 2014 at 3:58 PM, Vlad Skarzhevskyy <notifications@github.com

wrote:

log_min_duration_statement =0
log_line_prefix = '%t %s %p %c %v'

error in java
try# 8; hour of 2014-03-09 07:21:28.0 expected 6 but was 7

I modified SQL
SELECT dval FROM test2 WHERE name = ? and trc is null or trc = ?

where trc is try# so we will see it in trace.

http://pyx4j.com/bug/postgresql-2014-03-16_155607.log

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-37768259
.

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 17, 2014

I see now why this bug was not discovered before:)
I can only say where I tested before submitting bug:
Everywhere i tired tests are failing.
All computers in EDT time zone. I tried in PST on Windows with the same result.
Locale: English, United States.
Default installation of server on windows and Linux.
Default CREATE DATABASE not options.

Windows 7 64 bit on i7-4930K or i7-2860QM (different computers)
PostgreSQL 9.1.3, 9.1.5, 9.2.7, 9.3.3

Ubuntu 12.04.4 64 bit running in VMware ESX and VMware Workstation (8, 4 cores or 1 core given to VM)
PostgreSQL 9.1.5, 9.1.9

Additional dependencies for ant build

wget http://search.maven.org/remotecontent?filepath=org/apache/commons/commons-dbcp2/2.0/commons-dbcp2-2.0.jar
wget http://search.maven.org/remotecontent?filepath=org/apache/commons/commons-pool2/2.2/commons-pool2-2.2.jar
wget http://search.maven.org/remotecontent?filepath=commons-logging/commons-logging/1.1.1/commons-logging-1.1.1.jar
wget http://search.maven.org/remotecontent?filepath=c3p0/c3p0/0.9.1.2/c3p0-0.9.1.2.jar

I can only try to run the same tests on Mac in one week.

I will ask DBA to reproduce the problem on PostgreSQL 9.2.x on some other version of Linux.

@polobo

This comment has been minimized.

polobo commented Mar 17, 2014

I would suggest eliminating all pooling and seeing if the bug is still
present.

David J.

EDIT: My bad, responded without reading...pooling is configurable and indeed is a component of the problem.

@polobo

This comment has been minimized.

polobo commented Mar 17, 2014

Also, why are you using "dval timestamp" when you obviously care about timezone information? "timestamptz" or "timestamp with time zone" are the appropriate types here.

Maybe the combination of pooling and data type are causing an adverse reaction?

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 17, 2014

No Statements pooling - no problem.
timestamp with time zone - no problem.

the reason why I use 'timestamp without time zone' is the application itself. It is SAS different clients - different time zones. I may consider changing it depending on outcome of this thread.

@and0

This comment has been minimized.

and0 commented Mar 17, 2014

Here are my test results, bug confirmed, hope it helps.

https://gist.github.com/and0/9594530

@polobo

This comment has been minimized.

polobo commented Mar 17, 2014

Somehow when the prepared select statement becomes named the issue manifests. No pool required to replicate the behavior (in theory, haven't had a chance to setup an test it myself).

Its does seem isolated to the driver since a simple:

PREPARE s1 AS SELECT ('2014-03-09 06:21:28 EDT'::timestamptz)::time;
EXECUTE s1;

Returns "06:21:28" as expected.

The issue seems to have to reside at converting whatever response the server is providing into java.sql.Timestamp instance.

I don't see how threading the "new time zone" have any play; a store non-time-zoned time is coming back as two different values depending on whether the select statement has been executed via a named prepared statement.

@polobo

This comment has been minimized.

polobo commented Mar 17, 2014

For those who haven't run this can someone dump some ResultMetaData information for both the good and bad results to see what the result thinks it is dealing with.

EDIT: And just for kicks make the query:

SELECT dval, dval::text AS dval_text FROM test WHERE name = ?;

It's nice to see what PostgreSQL thinks without having to go through translation.
/EDIT

Thanks!

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2014

As suggested by David
To catch the problem one just need to execute the same PreparedStatement 5 times.
Here the test:
https://github.com/skarzhevskyy/pgjdbc/blob/master/org/postgresql/test/other/PreparedStatementDaylightSavingTest.java

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2014

tested this:
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamp) as val") -> will fail on 5th try.
prepareStatement(""SELECT ('2014-03-09 06:21:28 EDT'::timestamp)::time as val") -> work fine.
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamptz) as val") -> work fine.


prepareStatement("SELECT val, val::text AS val_text FROM dls1test");
val_text on 5th iteration returned correctly as 2014-03-09 06:21:28 ;

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 23, 2014

OK, So I have narrowed it down to:

The first 4 executions use Strings, The 5 switches to binary, then I am
figuring there is a problem with the conversion to timestamp

Dave Cramer

On Sat, Mar 22, 2014 at 9:54 PM, Vlad Skarzhevskyy <notifications@github.com

wrote:

tested this:
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamp) as val")
-> will fail on 5th try.
prepareStatement(""SELECT ('2014-03-09 06:21:28 EDT'::timestamp)::time as
val") -> work fine.
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamptz) as val")

-> work fine.

prepareStatement("SELECT val, val::text AS val_text FROM dls1test");
val_text on 5th iteration returned correctly as 2014-03-09 06:21:28 ;

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-38370578
.

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 23, 2014

And here is the code in question:

if (!timestamptz) {

        if (tz == null) {

            tz = defaultTz;

        }

        millis -= tz.getOffset(millis);

    }

This does not have timezone information so the driver tries to "fix" it.
The question is should it be doing this? Clearly it doesn't if we don't use
binary, but I'm concerned that changing this behaviour is going to break a
lot of code ?

Dave

Dave Cramer

On Sun, Mar 23, 2014 at 10:04 AM, Dave Cramer davecramer@gmail.com wrote:

OK, So I have narrowed it down to:

The first 4 executions use Strings, The 5 switches to binary, then I am
figuring there is a problem with the conversion to timestamp

Dave Cramer

On Sat, Mar 22, 2014 at 9:54 PM, Vlad Skarzhevskyy <
notifications@github.com> wrote:

tested this:
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamp) as val")
-> will fail on 5th try.
prepareStatement(""SELECT ('2014-03-09 06:21:28 EDT'::timestamp)::time as
val") -> work fine.
prepareStatement("SELECT ('2014-03-09 06:21:28 EDT'::timestamptz) as

val") -> work fine.

prepareStatement("SELECT val, val::text AS val_text FROM dls1test");
val_text on 5th iteration returned correctly as 2014-03-09 06:21:28 ;

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-38370578
.

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2014

To me this looks like the the server side problem and not driver.
Do you know what are the counterpart functions there?

Can you please point me to the wire protocol specs. For me it is confusing that in toTimeBin function driver is reading timeOffset form the stream while in toTimestampBin there are no such things.


Also keep in mind.
Hours that will produce this problem 3AM, 4AM, 5AM and 6AM
Looks like server is switching to proper time zone 4 hours later then expected...

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2014

We will try to reproduce the problem in perl. See what this will bring.

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 23, 2014

I have a solution already I will create a PR shortly for you to test

Dave Cramer

On Sun, Mar 23, 2014 at 12:22 PM, Vlad Skarzhevskyy <
notifications@github.com> wrote:

We will try to reproduce the problem in perl. See what this will bring.

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-38387272
.

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 23, 2014

Vlad,

Can you test this #133 ?

At this point this works on my computer. But opens up the question: Should
we be using getDSTSavings everywhere ?

Dave

Dave Cramer

On Sun, Mar 23, 2014 at 12:40 PM, Dave Cramer davecramer@gmail.com wrote:

I have a solution already I will create a PR shortly for you to test

Dave Cramer

On Sun, Mar 23, 2014 at 12:22 PM, Vlad Skarzhevskyy <
notifications@github.com> wrote:

We will try to reproduce the problem in perl. See what this will bring.

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-38387272
.

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2014

Timestamp write and read tested and it works as expected for every hour in last 5 years.
As to "getDSTSavings everywhere" I'm not qualified to answer this question.

@davecramer

This comment has been minimized.

Member

davecramer commented Mar 23, 2014

Vlad,

thanks for finding this problem and for testing it.

Cheers,

Dave Cramer

On Sun, Mar 23, 2014 at 3:37 PM, Vlad Skarzhevskyy <notifications@github.com

wrote:

Timestamp write and read tested and it works as expected for every hour in
last 5 years.
As to "getDSTSavings everywhere" I'm not qualified to answer this question.

Reply to this email directly or view it on GitHubhttps://github.com//issues/130#issuecomment-38394480
.

@davecramer davecramer closed this Apr 25, 2014

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Jul 13, 2014

Dave I see you reverted the changes.
#133

Also the bug still exist in latest version 9.3-1102-jdbc41.

Will you be reopening the bug and we need to create a new one ?

@davecramer

This comment has been minimized.

Member

davecramer commented Jul 13, 2014

Vlad,

Can you comment on #134 Look at the
emails about getOffset including the timezone offset?

I'll do another release if we can get to the bottom of this

Dave Cramer

On 13 July 2014 13:38, Vlad Skarzhevskyy notifications@github.com wrote:

Dave I see you reverted the changes.
#133 #133

Also the bug still exist in latest version 9.3-1102-jdbc41.

Will you be reopening the bug and we need to create a new one ?


Reply to this email directly or view it on GitHub
#130 (comment).

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Jul 13, 2014

I will think about this. Will keep you posted.

Please reopen the bug anyway.

@davecramer

This comment has been minimized.

Member

davecramer commented Jul 13, 2014

Not sure how to reopen it. I'll look at whatever you find though

Dave Cramer

On 13 July 2014 14:28, Vlad Skarzhevskyy notifications@github.com wrote:

I will think about this. Will keep you posted.

Please reopen the bug anyway.


Reply to this email directly or view it on GitHub
#130 (comment).

@ringerc ringerc reopened this Jul 14, 2014

@ringerc

This comment has been minimized.

Member

ringerc commented Jul 14, 2014

Reopened.

I've read through the thread, though I haven't run the test cases. It seems clear that the issue is with PgJDBC when using server-side prepared statements, so if you set:

?prepareThreshold=0

in your JDBC URL the issue should go away, and if you set it to 1 the problem should occur immediately, rather than requiring 5 iterations.

(I think we're going to need to change the prepare threshold default to 1 in a future release; behaviour changes caused by the switch are too common despite the best efforts of everyone involved).

As for what the driver is doing with the timestamp - all PostgreSQL returns for timestamp without time zone is a uint64 with some pretty formatting (or, with the binary protocol, just the uint64). You should receive exactly what you originally supplied. For timestamp with time zone the server applies the server's time zone offset from the TimeZone GUC to the value before sending it, so any DST changes will be applied by the server.

In either case the local Java runtime's time zone should have absolutely zero effect. If the local Java environment's time zone is being considered in any way that's a clear bug.

@ringerc

This comment has been minimized.

Member

ringerc commented Jul 14, 2014

Your test case uses timestamp without time zone, so the driver should be doing nothing to it beyond applying any necessary epoch adjustment. The driver doesn't know the tz info and should leave it as null, as a timestamp without time zone is just a point in wall-clock time, not absolute real-time.

regress=> SELECT TIMESTAMP WITHOUT TIME ZONE '2014-03-09 06:21:28', TIMESTAMP WITH TIME ZONE '2014-03-09 06:21:28';
      timestamp      |      timestamptz       
---------------------+------------------------
 2014-03-09 06:21:28 | 2014-03-09 06:21:28+08

Fixing this probably requires a backward compatibility connection string option, though.

@megothss

This comment has been minimized.

megothss commented Jan 7, 2016

Any news on this? I've bumped on this problem today.

@davecramer

This comment has been minimized.

Member

davecramer commented Jan 7, 2016

Can you provide a test case to show us what you are seeing. Most times this is just unexpected behaviour

@megothss

This comment has been minimized.

megothss commented Jan 12, 2016

I've prepared a small test case without all the dependencies I'm using in my project. I've used the latest driver with PostgreSQL 9.4.5 and JDK8.

package com.megothss;

import java.sql.*;

public class Main {

    public static void main(String[] args) throws SQLException, ClassNotFoundException {
        Class.forName("org.postgresql.Driver");

        try (Connection connection = DriverManager.getConnection("jdbc:postgresql:postgres?user=postgres")) {
            try (PreparedStatement pstmt = connection.prepareStatement("SELECT ?::INT4 AS attempt, CURRENT_TIMESTAMP::TIMESTAMPTZ;")) {
                for (int i = 0; i < 10; i++) {
                    pstmt.setInt(1, i);
                    try (ResultSet rs = pstmt.executeQuery()) {
                        rs.next();
                        System.out.println(String.format("Attempt %d = %s", rs.getInt(1), rs.getString(2)));
                    }
                }
            }
        }
    }
}

The following output was produced

Attempt 0 = 2016-01-12 00:08:54.675522-02
Attempt 1 = 2016-01-12 00:08:54.688394-02
Attempt 2 = 2016-01-12 00:08:54.68878-02
Attempt 3 = 2016-01-12 00:08:54.689082-02
Attempt 4 = 2016-01-12 00:08:54.689514-02
Attempt 5 = 2016-01-12 00:08:54.689854
Attempt 6 = 2016-01-12 00:08:54.690442
Attempt 7 = 2016-01-12 00:08:54.690715
Attempt 8 = 2016-01-12 00:08:54.690986
Attempt 9 = 2016-01-12 00:08:54.69127

As you can see, I've got the expect output until attempt 4. After that the timezone information is missing. I can also confirm that the ?prepareThreshold=0 workaround works.

vlsi added a commit that referenced this issue Jan 12, 2016

fix: binary timestamptz -> getString should add +XX zone offset to te…
…xt representation

Note: tstz in binary is sent without timezone, thus arameterStatus(TimeZone = GMT-01:00) is used to track connection's time zone

closes #130
@vlsi

This comment has been minimized.

Member

vlsi commented Jan 12, 2016

@megothss , thanks for the test.
I've added a case to the current test suite, and it does reproduce the problem: #490

testGetTimestamp(org.postgresql.test.jdbc2.TimezoneTest)  Time elapsed: 0.017 sec
junit.framework.ComparisonFailure: tstz -> getString, binary
expected:<2005-01-01 1[5:00:00+03]> but was:<2005-01-01 1[3:00:00.0]>
    at junit.framework.Assert.assertEquals(Assert.java:100)
    at junit.framework.TestCase.assertEquals(TestCase.java:261)
    at org.postgresql.test.jdbc2.TimezoneTest.testGetTimestamp(TimezoneTest.java:149)

Are you interested finishing that PR?
To fix the issue, <=BE ParameterStatus(TimeZone =...) response parsing should be added, the time zone should be stored in connection and eventually reused when converting tstz to string.

vlsi added a commit that referenced this issue Mar 22, 2016

fix: binary timestamptz -> getString should add +XX zone offset to te…
…xt representation

Note: tstz in binary is sent without timezone, thus arameterStatus(TimeZone = GMT-01:00) is used to track connection's time zone

closes #130

vlsi added a commit that referenced this issue Mar 22, 2016

fix: binary timestamptz -> getString should add +XX zone offset to te…
…xt representation

Note: tstz in binary is sent without timezone, thus arameterStatus(TimeZone = GMT-01:00) is used to track connection's time zone

closes #130

vlsi added a commit that referenced this issue Mar 22, 2016

fix: binary timestamptz -> getString should add +XX zone offset to te…
…xt representation

Note: tstz in binary is sent without timezone, thus arameterStatus(TimeZone = GMT-01:00) is used to track connection's time zone

closes #130
@vlsi

This comment has been minimized.

Member

vlsi commented Mar 23, 2016

Any volunteers to check if #490 resolves "timestamp vs timezone issue"?

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 23, 2016

Thanks, I will get the commit mentioned in #490 and will run my original tests to see if it solves the problem.
ETA two days.

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 24, 2016

Hi Vladimir I believe I'm missing something.
I run my tests used to submit this issue. And they failed with driver versions until 9.3-1104.
Starting from 9.4-1206 the tests are no-longer failing. The same for PR #490
Setting value preparethreshold=0,1,2,3 also can't make them fail...

the code is using the binary encoded timestamp value. When I set breakpoints there..

Any suggestions what was the change applied in 9.3-1104 release ?

@vlsi

This comment has been minimized.

Member

vlsi commented Mar 24, 2016

Well, 9.4-1204 includes #387. It should fix most of timestamp issues.

#490 fixes just the issue mentioned in #130 (comment)

@skarzhevskyy

This comment has been minimized.

skarzhevskyy commented Mar 24, 2016

Sorry
Since my original problem was with timestamp (not timestampz) and the comment is about TIMESTAMPTZ I can't actually verity that the problem there is corrected by your change.
While running the code I do observe the timezone is present all the time.

Since the original issue is resolved the bug should be definitely closed.

@vlsi

This comment has been minimized.

Member

vlsi commented Mar 24, 2016

thanks for testing

davecramer added a commit that referenced this issue Nov 7, 2017

add test for identity, fix isAutoincrement in postgresql 10 fixes #130 (
#1004)

* add test for identity, fix isAutoincrement in postgresql 10 fixes #130

rhavermans added a commit to bolcom/pgjdbc that referenced this issue Jul 13, 2018

add test for identity, fix isAutoincrement in postgresql 10 fixes pgj…
…dbc#130 (pgjdbc#1004)

* add test for identity, fix isAutoincrement in postgresql 10 fixes pgjdbc#130

rhavermans added a commit to bolcom/pgjdbc that referenced this issue Jul 13, 2018

add test for identity, fix isAutoincrement in postgresql 10 fixes pgj…
…dbc#130 (pgjdbc#1004)

* add test for identity, fix isAutoincrement in postgresql 10 fixes pgjdbc#130
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment