PostgreSQL has some runtime parameters we can use to monitor long running queries; we can set log_min_duration_statement to log any statements that take longer than the value in milliseconds we set. But what can we do if we have an application that keeps a long running transaction open but is mainly just ‘<IDLE> in transaction’? Perhaps it’s pinning that transaction open whilst it performs some long running action elsewhere? We can use a monitoring tool like Nagios to show long running transactions, but the activity they actually do won’t be logged by postgres unless they’re blocking somewhere. What comes to mind here, is distributed transaction managers playing up.

For example here if we set log_min_duration_statement to 0 postgres will log every query we issue, and we’ll see a message like this in the log:

[postgres]
LOG: duration: 3.475 ms statement: SELECT * FROM pg_stat_database where datname=’TEST’
[/postgres]

We can set statement_timeout to forcefully prevent applications running queries that take longer than we would like them to, so any statement that exceeds statement_timeout in milliseconds will be cancelled, for example:

[postgres]
TEST=# set statement_timeout = ‘2ms’;
SET
TEST=# SELECT * FROM pg_stat_database where datname=’TEST’;
ERROR: canceling statement due to statement timeout
[/postgres]

Obviously setting such a low value is not much use, but a typical use case for this would be in a busy web application where a user is likely to have gone away after 10 seconds anyway, in which case we could alter the applications user to have a statement_timeout somewhere around 10 seconds.

To log blocking queries we can set log_lock_waits to on, in which case postgres will log details of blocking queries when it checks for deadlock after the deadlock_timeout interval (default 1 second). We’ll see a message something like this in the log depending on the type of lock:

[postgres]
LOG: process 16532 still waiting for ShareLock on transaction 311823400 after 1000.147 ms
STATEMENT: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
[/postgres]

The above tells us that after 1 second our statement was still waiting on a lock, this is not to be confused with deadlock; the deadlock_timeout parameter factors into this only because postgres may as well output this information whilst it is doing the work to check for deadlock anyway. Actual deadlock would look something like this:

[postgres]
LOG: process 4465 detected deadlock while waiting for ShareLock on transaction 311824216 after 1000.158 ms
STATEMENT: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
ERROR: deadlock detected
DETAIL: Process 4465 waits for ShareLock on transaction 311824216; blocked by process 16532.
Process 16532 waits for ShareLock on transaction 311824207; blocked by process 4465.
Process 4465: UPDATE balls SET name = ‘TEST’ WHERE id = 5;
Process 16532: UPDATE balls SET name = ‘TEST2’ WHERE id = 6;
[/postgres]

Whilst all of the above is useful for tracking down problems, the one thing that we can’t do do with runtime parameters is timeout or log long running transactions, and perhaps even log the statements that may only persist for short periods within the transaction. In most cases we’d be using some sort of monitoring platfom like nagios, cacti or munin to monitor transaction times along with everything else (including query times and locks mentioned above), but sometimes it’d be nice to see that information in the postgres logs too.

Generally if some application is keeping long running or idle transactions open, then it’s the application that needs to be fixed. But when that’s out of your hands you can just feel a bit stuck whilst you wait for that to happen, I’ve a pl/pgsql function that can be scheduled to log some information, and even cancel/terminate sessions. The function can be downloaded here or here

For example if we want to log information on long running transactions, we could run the following:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’);
NOTICE: long_xact pid: 4465 duration: 431.325747 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
NOTICE: long_xact pid: 16532 duration: 327.438302 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
pg_log_long_xact
—————
(0 rows)
[/postgres]

If we want to see if either of these is waiting on the other:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true);
NOTICE: long_xact pid: 4465 duration: 471.885373 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
NOTICE: long_xact pid: 16532 duration: 367.997928 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
NOTICE: long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 471.885373 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 311824482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
pg_log_long_xact
—————
(0 rows)
[/postgres]

We can set the level of raise it uses (in hindsight the default should probably have been LOG), or have it output the details as text:

[postgres]
TEST=# \t off
Showing only tuples.
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’);
long_xact pid: 4465 duration: 574.477076 ms user: glyn application: psql client: [local] statement: <IDLE>; in transaction
long_xact pid: 16532 duration: 470.589631 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 574.477076 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 311824482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
[/postgres]

If we’re really having issues, we can make it start cancelling statements on each run, starting with those that have been blocking for the longest else those that have been running for the longest duration. As of pg 9.3 there’s now a lock_timeout parameter that will abort any statement waiting longer than the specified number of milliseconds, which is much better, but even post 9.3 the above function can be useful (Note that the difference here is that the above function will attempt to abort the blocking transaction rather than the waiting statement, or if there is no locking just the longest transaction. Obviously not to be used in haste.):

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’);
long_xact pid: 4465 duration: 895.57988 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact unable to cancel backend with pid: 4465
long_xact pid: 16532 duration: 791.692435 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 895.57988 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 31182
4482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
[/postgres]

In this case it can’t cancel the blocking statement as it is idle in trasaction, so there’s nothing to cancel, but we can pass another timeout to start terminating backends after:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’, ’15 minutes’);
long_xact pid: 4465 duration: 1026.90736 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact terminated backend with pid: 4465
long_xact pid: 16532 duration: 923.019915 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
[/postgres]

On out next run it has “resolved” the issue, I say “resolved” because it’s removed the blocking session:

[postgres]
TEST=#\t on
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’, ’15 minutes’);
pg_log_long_xact
—————
(0 rows)
[/postgres]

By default the function only cancels/terminates the longest running blocker, or longest running transaction, we can be more forceful than that by passing an extra parameter to tell it to cancel statements/terminate backends of all long running transactions it finds (I’ve lowerd the timeouts purely because I had to restart the transactions/statements):

[postgres]
TEST=#\t off
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ‘2 minutes’, ‘3 minutes’, true);
long_xact pid: 19065 duration: 187.279089 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact terminated backend with pid: 19065
long_xact pid: 16532 duration: 184.251569 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact cancelled backend with pid: 16532
(4 rows)
[/postgres]

What would be nice to see in addition to the lock_timeout parameter would be a blocker_timeout parameter that would function just like the lock_timeout but abort the blocking session. Obviously such a parameter could just cause more havoc if the offending application just keeps retrying the blocking operation, or worse you have it set and it aborts the restructure you’ve been waiting hours for. But I think in some instances it could be useful, set to a large enough value we could kill the offending blocking transaction and let all the others complete.

Update 30/09/2016 – Postgres 9.6 adds idle_in_transaction_session_timeout which allows us to automatically terminate any transactions that sit idle for longer than the value in milliseconds we set.