I have a script db_running.sh that shows me what queries are currently running on a server and what queries are blocking them, if any. One thing I’ve finally gotten around to questioning is why my script sometimes gives a negative age for the queries, eg:

$ db_running.sh
 datname | procpid | usename  |                                                 sql                                                  |       age        |  query_ip   | L? | locktype | hold_sql | blocker_ip
---------+---------+----------+------------------------------------------------------------------------------------------------------+------------------+-------------+----+----------+----------+------------
 ntm     |   20163 | postgres | <IDLE> in transaction                                                                                | 00:00:00.455019  | 172.17.0.51 | f  |          |          |
 ntm     |   20535 | postgres | <IDLE> in transaction                                                                                | 00:00:00.004358  | 172.17.0.23 | f  |          |          |
 ntm     |   19974 | postgres | COMMIT                                                                                               | -00:00:00.001497 | 172.17.0.53 | f  |          |          |
 ntm     |   20116 | postgres | select contacts0_.customer_poid as customer9_1_, contacts0_.contact_poid as contact1_1_, contacts0_. | -00:00:00.0051   | 172.17.0.21 | f  |          |          |
(4 rows)

I am calculating the age via:

select … , current_timestamp-s.query_start as age, …

The current_timestamp function I’m using will get the time at the start of the current transaction (i.e. my select statement) so that it does not change for each row being returned (doco reference). This is pretty much always want you want.

However when querying the pg_stat_activity view, it does not actually return the session details as at the start of your transaction but rather it returns the session details as at the time you first query it inside your transaction. Or in the words of the documentation:

“information about the current queries of all sessions is collected when any such information is first requested within a transaction”

What I guess is happening is that my select query starts, gets the current_timestamp value, then a few milliseconds later calls the pg_stat_activity view which can potentially see sessions that started just after my original select started. Hence current_timestamp – query_start becomes negative!

A quick scan of the available date/time functions revealed clock_timestamp() which always returns the timestamp at the time the function is called and is not transaction aware. This sounds like a good alternative for my script, and testing it out confirms my theory:

$ db_running.sh
 datname | procpid | usename  |                                                 sql                                                  |       age        |      age2       | client_addr | L? | locktype | hold_sql | client_addr
---------+---------+----------+------------------------------------------------------------------------------------------------------+------------------+-----------------+-------------+----+----------+----------+-------------
 ntm     |   14874 | postgres | <IDLE> in transaction                                                                                | 00:00:09.15277   | 00:00:09.161446 | 172.17.0.52 | f  |          |          |
 ntm     |   14770 | postgres | COMMIT PREPARED '4871251_B/sBAG7s7uFhcHBsaW4wMy1nbGFzcyxycHAtc2l0ZWItbm9kZTAzLWluc3QwMixQMzM3MDE=_YX | 00:00:00.027994  | 00:00:00.036554 | 172.17.0.53 | f  |          |          |
 ntm     |   14873 | postgres | COMMIT                                                                                               | 00:00:00.009249  | 00:00:00.017878 | 172.17.0.52 | f  |          |          |
 ntm     |   13361 | postgres | <IDLE> in transaction                                                                                | -00:00:00.004689 | 00:00:00.004038 | 172.17.0.21 | f  |          |          |
(4 rows)

I’ve yet to see a negative value re-appear after using this new function. My OCD can breathe a little easier now

You can download my db_running.sh script here.