pg_stat_activity shows future queries!
This morning I was working on getting some statistics on average transaction open time on a relatively underutilized host when I noticed some oddities. Periodically, I would see that my average duration of open transactions would dip below zero seconds. As I looked into it, I came across the following result from a simple query to pg_stat_activity:
postgres=# SELECT xact_start, NOW() AS now FROM pg_stat_activity WHERE xact_start IS NOT NULL; -[ RECORD 1 ]---------------------------- xact_start | 2012-09-11 19:33:41.253139+00 <-- Note this happens AFTER NOW() (i.e. in the future) now | 2012-09-11 19:33:41.252795+00 ...
Naturally, PostgreSQL isn’t predicting future queries, but it is obvious that there are some issues with recorded vs. reported transaction start times. Digging a bit deeper into src/backend/access/transam/xact.c and src/backend/postmaster/pgstat.c, it became clear to me why this behavior manifests:
1743 /* 1744 * set transaction_timestamp() (a/k/a now()). We want this to be the same 1745 * as the first command's statement_timestamp(), so don't do a fresh 1746 * GetCurrentTimestamp() call (which'd be expensive anyway). Also, mark 1747 * xactStopTimestamp as unset. 1748 */ 1749 xactStartTimestamp = stmtStartTimestamp; 1750 xactStopTimestamp = 0; 1751 pgstat_report_xact_timestamp(xactStartTimestamp);
Of course, this appears simply to be an implementation detail that probably won’t affect most users, but it’s certainly something to be aware of! For me, the solution to this is to simply normalize all negative intervals to zero and use that to calculate average current transaction duration.
September 11th, 2012 at 9:53 pm
There are several functions that you might want to take a look at.
clock_timestamp(), statement_timestamp(), and transaction_timestamp(). As you discovered now() is the same as transaction_timestamp(). statement_timestamp() is the same as the beginning of your statement and clock_timestamp() will change throughout your statement.
More info here: http://www.postgresql.org/docs/9.1/interactive/functions-datetime.html#FUNCTIONS-DATETIME-TABLE
September 11th, 2012 at 10:01 pm
Yeah, it was a bit confusing when it didn’t behave as expected and having to dive into the source.
Another fun item is that clock_timestamp() can-and-will return different results within the same query (also in the “documented but surprising the first time you see it” category)