PostgreSQL · advanced
How to test PostgreSQL statement timeout without hiding locks
This guide explains how to verify PostgreSQL statement_timeout behavior in isolation from lock-wait latency, so engineers can prove that a deadline fired against an intended statement rather than being masked by a concurrent lock. It frames verification as a controlled experiment with three observable boundaries: timer enforcement, error surface, and preserved evidence in pg_stat_activity and pg_stat_statements.
The symptoms
- •statement_timeout appears not to fire because the client observes a "canceling statement due to statement timeout" error after a delay dominated by lock acquisition rather than query execution
- •Tests of statement_timeout intermittently pass or fail depending on whether another transaction holds a conflicting lock at the moment the test query runs
- •Evidence in pg_stat_activity shows the timed-out backend waiting on a lock for most of the elapsed wall-clock time, with query_start far in the past and wait_event_type set to Lock
- •PostgreSQL log_min_duration_statement or auto_explain output attributes the abort to lock_timeout rather than to statement_timeout, even though the application intended only a statement-level deadline
- •Repeated runs of the same query produce inconsistent row counts in pg_stat_statements because the timeout fired on different statements, masking the test's true variance
Likely causes
- •Test environment conflates lock_timeout (which caps lock-wait) with statement_timeout (which caps total elapsed time), so the observed cancel reflects whichever deadline expired first
- •The verification query is blocked by a long-held row or relation lock from a separate session, inflating wall-clock time and obscuring whether statement_timeout would have fired on an unblocked run
- •Lock acquisition itself is being measured as part of statement timing, so the deadline appears to "succeed" by stopping a wait that had no useful work to interrupt
- •Evidence collection scripts read pg_stat_activity after the cancel, conflating the post-cancel idle state with the actual wait state the deadline interrupted
- •Lock_timeout is left unset at the session level, so a blocking transaction silently extends the effective deadline beyond the intended statement_timeout budget
First ten minutes
- 01Capture the current value of statement_timeout and lock_timeout for the target session and database, recording whether each was set at the role, database, or session level via pg_settings
- 02List active backends in pg_stat_activity and record their state, wait_event_type, wait_event, and query_start so any blocking lock is identified before the test query runs
- 03Resolve or isolate any session that holds a lock on the relations the verification query will touch, so the test runs against an unblocked path
- 04Set both statement_timeout and lock_timeout to the intended test values for the verification session only, using SET LOCAL inside a transaction so other workloads are unaffected
- 05Run a baseline short query on the same relation to confirm execution returns promptly and to capture the unblocked timing envelope the deadline must beat
Evidence to collect
- •pg_settings rows for statement_timeout, lock_timeout, and idle_in_transaction_session_timeout, including their source (session, user, database) and reset_val
- •pg_stat_activity snapshot showing wait_event_type, wait_event, state, query_start, and xact_start for both the verification backend and any potential blockers
- •PostgreSQL log line containing the SQLSTATE and message text for the canceled statement, plus the duration reported by log_min_duration_statement or auto_explain if enabled
- •pg_locks rows for the verification session's pid, including locktype, mode, granted, and the relation or tuple identifiers held or awaited
- •pg_stat_statements row for the timed-out query, capturing calls, total_exec_time, and rows so the post-test variance can be compared to the unblocked baseline
Where to look
- •Server-level timeout boundary: pg_settings for statement_timeout and lock_timeout, where the GUC hierarchy (postgresql.conf, ALTER ROLE/DATABASE, SET) determines which value the backend actually enforces
- •Per-backend behavior boundary: pg_stat_activity joined to pg_locks on pid, where wait_event_type=Lock and granted=false indicate the deadline is being consumed by a wait rather than by execution
- •Catalog and statistics boundary: pg_stat_database and pg_stat_statements, where total_exec_time and blk_read_time reveal whether I/O or planning, not the deadline, dominated the canceled run
- •Logging boundary: PostgreSQL log directory and log_line_prefix output, where the SQLSTATE 57014 family and the duration field document the precise moment and cause of the cancel
- •Plan boundary: EXPLAIN (without ANALYZE) output for the verification query, used to confirm the unblocked plan is bounded before any timeout is applied
Diagnostic steps
- 01Compare the elapsed wall-clock time between query_start and the cancel log line against the configured statement_timeout value; a large gap with wait_event_type=Lock points to a lock-wait, not an execution-budget overrun
- 02Reproduce the query against a relation guaranteed not to be locked, and confirm the deadline fires within a tight envelope of the configured value plus planning overhead; failure here indicates the timeout is not actually enforced for this session
- 03Run the same query with statement_timeout unset and lock_timeout set to a value well above statement_timeout; if the cancel still appears with SQLSTATE 57014, the verification is exercising lock_timeout, not statement_timeout
- 04Inspect pg_locks for the timed-out pid after the cancel; a granted=false entry on a relation or tuple lock at cancel time proves the deadline interrupted a wait, which is the exact failure mode this guide isolates
- 05Cross-check pg_stat_statements.total_exec_time across runs; if variance collapses only after locks are removed, the original test was masking the deadline's true target
- 06Validate that the cancel log line names "statement timeout" rather than "lock timeout" or "idle-in-transaction timeout" so the evidence matches the intended deadline
Common mistakes
- •Setting statement_timeout on the session but leaving lock_timeout at zero or unlimited, so a blocking transaction silently stretches the effective deadline and the cancel arrives from the wrong source
- •Asserting success because the client saw SQLSTATE 57014 without checking which timeout the server reported, conflating statement_timeout, lock_timeout, and idle_in_transaction_session_timeout cancels
- •Reading pg_stat_activity after the cancel and reporting the idle state as evidence the timeout "worked," when the relevant wait_event and query_start were overwritten on transaction end
- •Re-running the verification query against a shared test database without isolating the relation, so other engineers' sessions become invisible blockers that skew every run
- •Trusting total_time in pg_stat_statements as proof of deadline enforcement, since it aggregates execution across calls and does not distinguish a canceled run from a completed one
Safe fixes
- •Run the verification inside a transaction with SET LOCAL statement_timeout and SET LOCAL lock_timeout pinned to the intended test values, so the change reverts on COMMIT or ROLLBACK and cannot leak into other sessions
- •Acquire a session-scoped advisory lock on a stable key for the duration of the verification, so concurrent test runners cannot become silent blockers on the same relations
- •Pair the timed query with a short, unblocked baseline and require the deadline to fire within the configured value plus a small planning overhead; otherwise treat the run as inconclusive and re-check pg_settings
- •Capture pg_stat_activity and pg_locks snapshots immediately before and after the cancel, and archive the cancel log line, so the evidence trail records wait_event and SQLSTATE rather than relying on client-side timing
- •Use EXPLAIN (without ANALYZE) to bound the plan of the verification query so a deadline that fires inside planning is recognized as a planning-bound timeout rather than an execution-bound one
Prove the fix
- 01The cancel log line reports SQLSTATE 57014 with the message text naming statement timeout, and the elapsed duration is within a tight envelope of the configured statement_timeout value
- 02pg_stat_activity at the moment of cancel shows wait_event_type distinct from Lock, and pg_locks shows no granted=false entries for the verification pid, proving the deadline interrupted execution rather than a wait
- 03The same verification query run against an unblocked relation produces identical cancel timing across at least three runs, with the variance attributable only to planning and not to lock acquisition
- 04pg_stat_statements rows for the verification query show consistent total_exec_time across runs, indicating the deadline fired deterministically on the intended statement rather than on whichever work happened to be in flight
- 05Re-running the verification with lock_timeout set well below statement_timeout produces a log line naming lock timeout, confirming the two deadlines are independently observable and not aliased in the test
Prevention and next steps
- •Adopt a verification harness that pins both statement_timeout and lock_timeout per session, records pg_stat_activity and pg_locks snapshots, and asserts the SQLSTATE message text rather than relying on wall-clock timing alone
- •Maintain a dedicated relation or schema for timeout tests so unrelated workloads cannot introduce locks that silently extend the effective deadline during a verification run
- •Document the expected SQLSTATE 57014 message text and duration envelope for each statement_timeout value used in tests, so regressions in enforcement surface as observable diffs in CI logs
- •Periodically audit pg_settings across roles and databases to confirm that ALTER ROLE/DATABASE overrides do not silently mask the session-level values used by the verification harness
Safe commands and checks
SELECT name, setting, unit, source, reset_val FROM pg_settings WHERE name IN ('statement_timeout','lock_timeout','idle_in_transaction_session_timeout');
SELECT pid, state, wait_event_type, wait_event, query_start, xact_start FROM pg_stat_activity WHERE datname = current_database() ORDER BY query_start;
SELECT pid, locktype, mode, granted, relation::regclass FROM pg_locks WHERE pid = <pid> ORDER BY granted DESC, locktype;
BEGIN; SET LOCAL statement_timeout = '<ms>'; SET LOCAL lock_timeout = '<ms>'; <verification query>; ROLLBACK;
SELECT query, calls, total_exec_time, rows FROM pg_stat_statements WHERE query ILIKE '<verification query pattern>' ORDER BY calls DESC LIMIT 5;
EXPLAIN (FORMAT TEXT, ANALYZE FALSE, BUFFERS FALSE) <verification query>;
SELECT pg_backend_pid(); -- obtain <pid> for use in pg_locks and pg_stat_activity joins