I do a lot of “is this !#@(* really working correctly” testing. (See also: simple test for autovacuum log messages.)
Here’s a simple test to verify that log_lock_waits is configured correctly. This is essential for troubleshooting lock contention.
-- verify settings
-- log_lock_waits should be 'on'; it is off by default.
SHOW log_lock_waits;
-- lock_wait messages are LOG level messages,
-- so the default value 'warning' should suffice here
SHOW log_min_messages;
-- if you're reading this, this is most likely still set to the default 1s. That is ok. :)
SHOW deadlock_timeout;
DROP TABLE IF EXISTS lock_wait_test;
CREATE TABLE lock_wait_test
(id serial primary key
, name text)
;
-- add some data
INSERT INTO lock_wait_test(name)
VALUES
('ankeny'),('burnside'),('couch'),('davis'),('everett'),('flanders'),('glisan'),('hoyt'),('irving')
;
-- take a lock
BEGIN;
LOCK lock_wait_test IN ACCESS EXCLUSIVE MODE;
-- open up another session and run this:
SELECT * FROM lock_wait_test;
Wait deadlock_timeout, then cancel your select query.
Then go check the logs. You should have a helpful message about your lock wait, and the waiting query:
2015-05-02 16:59:23 PDT LOG: process 7617 still waiting for AccessShareLock on relation 16550 of database 12066 after 1000.161 ms at character 15
2015-05-02 16:59:23 PDT STATEMENT: select * FROM lock_wait_test;
Roll your lock back, and repeat starting with taking a lock. Instead of canceling the SELECT query, roll back your lock. This time you’ll see these messages:
2015-05-02 17:02:23 PDT LOG: process 7617 still waiting for AccessShareLock on relation 16550 of database 12066 after 1000.112 ms at character 15
2015-05-02 17:02:23 PDT STATEMENT: select * FROM lock_wait_test;
2015-05-02 17:02:26 PDT LOG: process 7617 acquired AccessShareLock on relation 16550 of database 12066 after 3920.210 ms at character 15
2015-05-02 17:02:26 PDT STATEMENT: select * FROM lock_wait_test
—
Thanks to Magnus for the suggestion.
the gabriellephant 