Prepared statement pool and Daylight Saving Time

[skarzhevskyy]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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

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

[polobo]

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]

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]

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]

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]

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]

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]

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]

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

[davecramer]

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]

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]

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]

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
.

[skarzhevskyy]

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]

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]

I will think about this. Will keep you posted.

Please reopen the bug anyway.

[davecramer]

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]

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]

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]

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

[davecramer]

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

[megothss]

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]

@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]

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

[skarzhevskyy]

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]

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]

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

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

[skarzhevskyy]

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]

thanks for testing