BUG #4849: intermittent future timestamps

The following bug has been logged online:

Bug reference: 4849
Logged by: David Leppik
Email address: dleppik(at)vocalabs(dot)com
PostgreSQL version: 8.3.5
Operating system: Linux (CentOS 5.2)
Description: intermittent future timestamps
Details:

We are intermittently getting results from now() which are around 10 minutes
in the future. Most calls return a reasonable value. Because the erroneous
timestamps are in the future, they cannot be explained by transaction
delays.

We will shortly be testing this against PostgreSQL 8.3.7 on an Ubuntu Server
machine.

Here are four examples of the output we're seeing. This is being run with a
Java client on a different machine, where we have verified that the system
clocks are synchronized to within a matter of milliseconds. Local time
refers to the client time, and remote time refers to the result of a 'select
now()' query on PostgreSQL.

1244577512501(Tue Jun 09 14:58:32 CDT 2009) local time
1244578051692 (Tue Jun 09 15:07:31 CDT 2009) remote time.
1244577512504 (Tue Jun 09 14:58:32 CDT 2009) local time, after call.

1244580242672(Tue Jun 09 15:44:02 CDT 2009) local time
1244580951249 (Tue Jun 09 15:55:51 CDT 2009) remote time.
1244580242691 (Tue Jun 09 15:44:02 CDT 2009) local time, after call.

1244584693701(Tue Jun 09 16:58:13 CDT 2009) local time
1244585427037 (Tue Jun 09 17:10:27 CDT 2009) remote time.
1244584693701 (Tue Jun 09 16:58:13 CDT 2009) local time, after call.

1244651946466(Wed Jun 10 11:39:06 CDT 2009) local time
1244652443625 (Wed Jun 10 11:47:23 CDT 2009) remote time.
1244651946485 (Wed Jun 10 11:39:06 CDT 2009) local time, after call.

After the last example, I logged onto the server and ran 'date' from the
command line, which yielded 'Wed Jun 10 11:40:17 CDT 2009'.

We run the identical code regularly against a MySQL instance on the same
server, and have never seen the error there.

To reproduce, we:

1. Obtain a timestamp outside of PostgreSQL
2. Obtain a connection with a new transaction
3. Compare our timestamp with the result of SELECT NOW()
4. Verify that the timestamp from PosgreSQL is several minutes off from the
server's clock, by calling 'date' from the command line.

Here is the Java source code used to generate these results. It is run
using a connection obtained from a connection pool (using Apache Commons
DBCP) for this query, so the transaction is new.

private static void checkSkew(Connection con) throws SQLException {
Date remoteDate;
Date localDate1;
Date localDate2;
Statement stmt = null;
ResultSet rs = null;
try {
String query ="select now()";
stmt = con.createStatement();
rs = stmt.executeQuery(query);
localDate1=new Date();
rs.next();
remoteDate = date(rs.getTimestamp(1));
localDate2=new Date();
}
finally {
DBUtil.close(stmt, rs);
}
if (!fuzzyEquals(localDate1, localDate2,
DateUtil.SKEW_TOLERANCE_MILLIS)) {
System.err.println("DateUtil.assertClocksSynchronized: query
took too long.");
}

if (fuzzyEquals(localDate1,remoteDate,
DateUtil.SKEW_TOLERANCE_MILLIS)) {
delaySkewCheck(SKEW_CHECK_FREQUENCY);
}
else {
String message = "Database clock is not synchronized with this
machine to within "
+DateUtil.SKEW_TOLERANCE_MILLIS+" milliseconds. \n"
+localDate1.getTime()+"("+localDate1+") local time\n"
+remoteDate.getTime()+" ("+remoteDate+") remote time.\n"
+localDate2.getTime()+" ("+localDate2+") local time, after
call.\n"
+DataSourceHandler.getDatabaseEnvironment()+"
"+DataSourceHandler.getVendor()+"\n"
+"\n"
+StringUtil.stackTrace(new Error("For stack trace"));
EmailLog.error(message);
delaySkewCheck(SKEW_WARNING_FREQUENCY_MILLIS);
}
}