pg_commandhistory

pg_commandhistory is a small tool to track the SQL command history inside running transactions in PostgreSQL.

It is intended as a debugging tool only!

The typical usecase is when there is an application that "leaks" connections that end up in state idle in transaction, where it might be necessary to know more than just the last command (which can be seen through pg_stat_activity as of PostgreSQL 9.2) to identify where in the code the problem shows up.

Note that the tool will track all queries (but not utility statements) that run in the session. There is no bounds check, so if you run it with transactions with millions of statements in them, it's going to use a lot of memory!

Installation

Installation is simple, as it's a PGXS style build::

pg_commandhistory$ make install

Unfortunately, PGXS doesn't have support for the "plugins" directory structure, so you need to manually link the library in there

pg_commandhistory$ mkdir `pg_config --libdir`/plugins
pg_commandhistory$ ln -s `pg_config --libdir`/pg_commandhistory.so `pg_config --libdir`/plugins/

To enable the module, you need to edit postgresql.conf and set

local_preload_libraries = 'pg_commandhistory'

Note that it does not work to load the module using shared_preload_libraries, it must be done locally in the backend. And yes, in PostgreSQL 9.3 and earlier this means an extra debugging line in your log for every connection - this is a backend issue that has been fixed for PostgreSQL 9.4.

Usage

Once enabled through local_preload_libraries, collection of data starts for all transactions. To get a dump, figure out the pid of the backend in question (typically using ps) and then send that backend the SIGUSR2 signal

$ kill -USR2 23638

Once this signal is sent, the extension will dump the information into the standard PostgreSQL logs, where you will get something like

2014-01-13 08:50:41 CET LOG:  Dumping SQL history for 23638
2014-01-13 08:50:41 CET LOG:  2: 08:50:37 () select 42;
2014-01-13 08:50:41 CET LOG:  2: 08:50:34 () select 3;
2014-01-13 08:50:41 CET LOG:  3: 08:50:32 () select 1;
2014-01-13 08:50:41 CET LOG:  End of SQL history dump for 23638

Note that the list of queries is dumped in reverse, with the most recent query written first.

Configuration parameters

You can set a value of the parameter pg_commandhistory.tag at any point during your session. The value of this parameter will be recordet at each query and written to the log before the SQL query. This allows for easier tracking through the application. For a tag value of foobar, the output looks like this:

2014-01-13 14:28:16 CET LOG:  Dumping SQL history for 26353
2014-01-13 14:28:16 CET LOG:  1: 14:28:09 (foobar) select 3;
...