How do I track transactions in PostgreSQL log?

Question

I recently inherited an application that uses PostgreSQL and I have been troubleshooting issues relating to saving records in the database.

I know that PostgreSQL allows me to record the transaction ID in the log by including the special value of %x in the log_line_prefix. What I noticed, however, is that the first statement that occurs within a transaction always gets logged with a zero.

If I perform the following operations in psql,

begin;
insert into numbers (1);
insert into numbers (2);
commit;

the query log will contain the following entries:

2016-09-20 03:07:40 UTC 0 LOG:  statement: begin;
2016-09-20 03:07:53 UTC 0 LOG:  statement: insert into numbers values (1);
2016-09-20 03:07:58 UTC 689 LOG:  statement: insert into numbers values (2);
2016-09-20 03:08:03 UTC 689 LOG:  statement: commit;

My log format is %t %x and as you can see, the transaction ID for the first insert statement is 0, but it changes to 689 when I execute the second insert.

Can anyone explain why after starting a transaction PostgreSQL doesn't log the right transaction ID on the first statement? Or if I'm just doing this wrong, is there a more reliable way of identifying which queries were part of a single transaction by looking at the log file?

Answer 1

The transaction ID is assigned after the statement starts, so log_statement doesn't capture it. BEGIN doesn't assign a transaction ID, it's delayed until the first write operation.

Use the virtual txid instead, which is assigned immediately. The placeholder is %v. These are assigned immediately, but are not persistent and are backend-local.

I find it useful to log both. The txid because it matches up to xmin and xmax system column contents, etc; the vtxid to help me group up operations done in transactions.