Tracing Full SQL Statements in PostgreSQL Transactions Using Log Configuration

1. Problem Statement

DBAs often need to investigate which SQL statements belong to a specific transaction when a lock alert appears, for example an UPDATE waiting for a SELECT. Although PostgreSQL's MVCC ensures that reads do not block writes and writes do not block reads, a SELECT can still be blocked if it runs inside a transaction that already holds locks required by later UPDATE statements.

2. Log‑Related Parameters

Before digging into the logs, we review the most relevant PostgreSQL logging parameters.

The configuration options are numerous; this article focuses on the most commonly used ones in production: logging_collector , log_min_duration_statement , log_statement , log_duration , and log_line_prefix .

2.1 logging_collector

Must be set to on to write logs to files; a restart is required after changing this parameter.

2.2 log_min_duration_statement

Controls which statements are logged based on execution time:

Value

Meaning

-1

Disabled

0

Log every statement with its execution time

>0

Log only statements whose duration exceeds the threshold (in ms)

2.3 log_statement

Possible values are none , ddl , mod , all . When log_min_duration_statement > 0 , this setting determines the statement level that will be recorded.

2.4 log_duration

When set to on , PostgreSQL records the execution time of each completed statement.

2.5 log_line_prefix

This is a printf‑style string printed at the beginning of each log line. Common escape sequences include %p (process ID), %c (session ID), %l (log line number), %v (virtual transaction ID), and %x (transaction ID). These fields are essential for correlating log entries with specific sessions and transactions.

3. Log Configuration Cases

Two typical production configurations are demonstrated.

3.1 Case 1 – Full‑log mode

All statements are logged. Example configuration:

postgres@localhost ~$ psql mydb
psql (12.3)
Type "help" for help.
mydb=# show logging_collector ;
 logging_collector 
-------------------
 on
(1 row)
mydb=# show log_min_duration_statement ;
 log_min_duration_statement 
----------------------------
 0
(1 row)
mydb=#  show log_statement;
 log_statement
---------------
 none
(1 row)
postgres=# show log_duration ;
 log_duration
--------------
 off
(1 row)
mydb=# show log_line_prefix ;
         log_line_prefix        
---------------------------------
 [%u %d %a %h %m %p %c %l %v %x]
(1 row)

Sample SQL session and the resulting log entries are shown, illustrating how each statement is recorded with timestamps, process IDs, virtual transaction IDs, and durations.

3.2 Case 2 – Full‑write & partial‑read mode

Only write statements are logged in full, while read statements are logged selectively. Example configuration:

postgres@localhost ~$ psql
psql (12.3)
Type "help" for help.
postgres=# show logging_collector ;
 logging_collector 
-------------------
 on
(1 row)
postgres=# show log_min_duration_statement ;
 log_min_duration_statement 
----------------------------
 1ms
(1 row)
postgres=# show log_statement;
 log_statement
---------------
 mod
(1 row)
postgres=# show log_duration ;
 log_duration
--------------
 off
(1 row)
mydb=# show log_line_prefix ;
         log_line_prefix        
---------------------------------
 [%u %d %a %h %m %p %c %l %v %x]
(1 row)

The corresponding log output demonstrates that write statements (INSERT, UPDATE, DELETE) are logged with full details, while SELECTs appear only when they exceed the 1 ms threshold.

4. Summary of Findings

%p (process ID) and %c (session ID) map one‑to‑one, but the session ID is more distinctive in large log volumes.

BEGIN allocates a virtual transaction ID (%v); COMMIT/ROLLBACK reset the localXID to 0, while the virtual ID remains constant within the transaction.

The same virtual transaction ID can be used to locate all statements belonging to a single transaction.

Transaction ID (%x) is not reliable for full‑transaction tracing because the first statement of a transaction may report 0 even when the transaction has been assigned an ID.

5. Concrete Example – Tracing a DB Lock

A step‑by‑step demonstration shows how to locate the complete SQL sequence that caused a lock:

Identify the log file containing the query_start timestamp.

Filter by the blocking process ID (e.g., pid 5665).

Further narrow down using the session identifier ( 6061856f.1621 ).

Use the virtual transaction ID ( 3/516 ) to isolate the exact statements.

Handle multi‑line statements that appear with a leading tab character; a small Perl one‑liner can re‑assemble them.

After these steps, the full blocking transaction (process 5665) is identified, confirming that it holds the lock waited on by process 5703.

6. Overall Conclusion

Finding every SQL statement inside a transaction is a meticulous task that requires solid DBA knowledge of PostgreSQL's logging facilities, careful use of log_line_prefix escape sequences, and systematic grep‑based analysis. In high‑throughput environments the difficulty increases, but the same principles apply.

Readers are encouraged to explore deeper from the source‑code perspective to devise more efficient methods.