Обсуждение: BUG #4849: intermittent future timestamps
The following bug has been logged online:
Bug reference: 4849
Logged by: David Leppik
Email address: dleppik@vocalabs.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);
}
}
"David Leppik" <dleppik@vocalabs.com> writes:
> 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.
Postgres is just reporting what it got from gettimeofday(), so your beef
is with the kernel (or perhaps with glibc) and/or the hardware you're
using. I think I've heard of kernel bugs causing this type of issue.
regards, tom lane
Never mind. Turns out the bug was in our own code (read: me, personally, being stupid) to convert a java.sql.Timestamp to java.sql.Date. Why it works at all in MySQL... I don't even want to know. Why is it we can spend weeks looking at a bug, and we can't find it until we decide to blame it on someone else? David On Jun 10, 2009, at 11:58 AM, Tom Lane wrote: > "David Leppik" <dleppik@vocalabs.com> writes: >> 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. > > Postgres is just reporting what it got from gettimeofday(), so your > beef > is with the kernel (or perhaps with glibc) and/or the hardware you're > using. I think I've heard of kernel bugs causing this type of issue. > > regards, tom lane -- David Leppik VP of Software Development Vocal Laboratories, Inc. dleppik@vocalabs.com
David Leppik <dleppik@vocalabs.com> wrote: > Never mind. Turns out the bug was in our own code (read: me, > personally, being stupid) to convert a java.sql.Timestamp to > java.sql.Date. Why it works at all in MySQL... I don't even want > to know. java.sql.Date or java.util.Date? (You don't show your imports, so it's impossible to tell from the code snippet.) If it's java.util.Date, I can't immediately see why your errors would be greater than one second. If it's java.sql.Date, you're probably in territory where the behavior is undefined, but it's hard to see where you would get the results you showed. Perhaps there's an opportunity for us to make the PostgreSQL JDBC driver behave more sanely in this circumstance? > Why is it we can spend weeks looking at a bug, and we can't find > it until we decide to blame it on someone else? It's probably a corollary to the tendency to see our own gaffs when reading the post coming back from the list much more clearly than they appeared before clicking "send". :-/ -Kevin
My typo. Converting java.sql.Timestamp to java.util.Date was buggy on my end. David On Jun 10, 2009, at 1:00 PM, Kevin Grittner wrote: > David Leppik <dleppik@vocalabs.com> wrote: >> Never mind. Turns out the bug was in our own code (read: me, >> personally, being stupid) to convert a java.sql.Timestamp to >> java.sql.Date. Why it works at all in MySQL... I don't even want >> to know. > > java.sql.Date or java.util.Date? (You don't show your imports, so > it's impossible to tell from the code snippet.) If it's > java.util.Date, I can't immediately see why your errors would be > greater than one second. If it's java.sql.Date, you're probably in > territory where the behavior is undefined, but it's hard to see where > you would get the results you showed. Perhaps there's an opportunity > for us to make the PostgreSQL JDBC driver behave more sanely in this > circumstance? > >> Why is it we can spend weeks looking at a bug, and we can't find >> it until we decide to blame it on someone else? > > It's probably a corollary to the tendency to see our own gaffs when > reading the post coming back from the list much more clearly than they > appeared before clicking "send". :-/ > > -Kevin -- David Leppik VP of Software Development Vocal Laboratories, Inc. dleppik@vocalabs.com