postgresql lock monitoring using developer options

demo.sh

postgresql developer options are a list of configs users can play with in the sandbox environment for debugging.
i used it to study various locks taken when a statement is executed on an object
just to get things started, there is a GUC where one can enable lock tracing on a particular table only
this is cool as i dont care what else is going on in the system otherwise, but i want to learn what locks are taken by what sql statements
infact one can make use of https://pglocks.org/ to run the various statements on this site (by hussein) and understand the locks taken
these would be very useful when one is doing migrations on large objects which are blocking in nature

https://github.com/ankane/strong_migrations (is a good collection of those cases and the links to the blogs)


```

# since this is a developer option only, one needs to compile the source using the relevant trace flag LOCK_DEBUG

https://www.postgresql.org/docs/current/runtime-config-developer.html

./configure --prefix=/opt/postgresql  --with-openssl   --enable-debug  --enable-profiling --enable-cassert --enable-tap-tests  CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer -DLOCK_DEBUG -DBTREE_BUILD_STATS -DWAL_DEBUG "
make
cd /home/ubuntu/github/postgres/src/test/modules/xid_wraparound
make check PG_TEST_EXTRA='xid_wraparound'
sudo make install
sudo chown -R postgres:postgres /opt/postgresql
sudo chown -R 744 /opt/postgresql
```

#lets start
postgres@ubuntu:/tmp$ psql
psql (18devel)
Type "help" for help.

postgres=# create table t(col1 int, col2 int);
CREATE TABLE
postgres=# select 't'::regclass::oid;
  oid
-------
 16391
(1 row)

postgres=# drop table t;
DROP TABLE
postgres=# create table t(col1 int, col2 int);
CREATE TABLE
postgres=# select 't'::regclass::oid;
  oid
-------
 16394
(1 row)

postgres=# alter system set trace_lock_table = 16394;
ALTER SYSTEM
postgres=# select pg_reload_conf();
 pg_reload_conf
----------------
 t
(1 row)

postgres=# show trace_lock_table;
 trace_lock_table
------------------
 16394
(1 row)

postgres=# -- we intentionally enable client min messages to log to show things on console
postgres=# set client_min_messages TO log;
SET
postgres=# -- what we now see is any locks on table t will be logged, this will help us understand what statement causes what locks
-- intentionally request an exclusive lock to validate the debugging
postgres=# begin;
BEGIN
postgres=*# lock table t in access exclusive mode ;
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: no conflict: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  GrantLock: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOCK TABLE
-- now release by rollback
postgres=*# rollback;
LOG:  LockReleaseAll: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  LockReleaseAll: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(INVALID)
LOG:  UnGrantLock: updated: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockReleaseAll: updated: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
ROLLBACK

postgres=# -- good, now we can use generic sql statements to check for locks , this is especially useful in migration work
postgres=# insert into t select 1,1;
LOG:  LockAcquire: lock [5,16394] RowExclusiveLock
LINE 1: insert into t select 1,1;
                    ^
LOG:  LockAcquire: lock [5,16394] ExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f334f78) id(5,16394,0,0,1,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3e3f80) lock(0x7bf21f334f78) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: no conflict: proclock(0x7bf21f3e3f80) lock(0x7bf21f334f78) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  GrantLock: lock(0x7bf21f334f78) id(5,16394,0,0,1,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)
LOG:  LockRelease: lock [5,16394] ExclusiveLock
LOG:  LockRelease: found: lock(0x7bf21f334f78) id(5,16394,0,0,1,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)
LOG:  LockRelease: found: proclock(0x7bf21f3e3f80) lock(0x7bf21f334f78) method(1) proc(0x7bf21f6b7f00) hold(80)
LOG:  UnGrantLock: updated: lock(0x7bf21f334f78) id(5,16394,0,0,1,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3e3f80) lock(0x7bf21f334f78) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3e3f80) lock(0x7bf21f334f78) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f334f78) id(5,16394,0,0,1,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
INSERT 0 1

postgres=# delete from t;
LOG:  LockAcquire: lock [5,16394] RowExclusiveLock
LINE 1: delete from t;
                    ^
DELETE 1

--alter table int to bigint type change needs AccessExclusiveLock
postgres=# alter table t alter column col2 type bigint; -- common case of type change
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: no conflict: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  GrantLock: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] ShareLock
LOG:  LockAcquire: found: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(ShareLock)
LOG:  LockAcquire: found: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  LockCheckConflicts: resolved (simple): proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  GrantLock: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(120) req(0,0,0,0,1,0,0)=2 grant(0,0,0,0,1,0,0)=2 wait(0) type(ShareLock)
LOG:  LockReleaseAll: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(120)
LOG:  LockReleaseAll: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(120) req(0,0,0,0,1,0,0)=2 grant(0,0,0,0,1,0,0)=2 wait(0) type(INVALID)
LOG:  UnGrantLock: updated: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(ShareLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  UnGrantLock: updated: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockReleaseAll: updated: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3ed880) lock(0x7bf21f33f078) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f33f078) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
ALTER TABLE

postgres=# -- mimic open transaction in other session
postgres=# \! psql -c 'BEGIN; INSERT INTO t VALUES (2,2); select pg_sleep(10000);' &
postgres=# vacuum full t; -- this needs a access exclusive lock but wont get it
LOG:  LockAcquire: lock [5,16394] AccessShareLock
LOG:  LockRelease: lock [5,16394] AccessShareLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(RowExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed830) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b8250) hold(0)
LOG:  GrantLock: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(8) req(0,0,1,0,0,0,0)=1 grant(0,0,1,0,0,0,0)=1 wait(0) type(RowExclusiveLock)
LOG:  LockAcquire: found: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(8) req(0,0,1,0,0,0,0)=1 grant(0,0,1,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: conflicting (simple): proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  WaitOnLock: sleeping on lock: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(8) req(0,0,1,0,0,0,0)=2 grant(0,0,1,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
^CCancel request sent
Cancel request sent
LOG:  LockReleaseAll: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
BEGIN
LOG:  LockReleaseAll: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(INVALID)
LOG:  UnGrantLock: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockReleaseAll: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
ERROR:  canceling statement due to user request
postgres=# select pg_cancel_backend(pid) from pg_stat_activity where query ~ 'sleep' and pid <> pg_backend_pid();
 pg_cancel_backend
-------------------
(0 rows)

postgres=# select pg_cancel_backend(pid) from pg_stat_activity where query ~ 'begin' and pid <> pg_backend_pid();
 pg_cancel_backend
-------------------
(0 rows)

postgres=# vacuum full t;
LOG:  LockAcquire: lock [5,16394] AccessShareLock
LOG:  LockRelease: lock [5,16394] AccessShareLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: no conflict: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  GrantLock: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: lock [5,16394] ShareLock
LOG:  LockAcquire: found: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(ShareLock)
LOG:  LockAcquire: found: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  LockCheckConflicts: resolved (simple): proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  GrantLock: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(120) req(0,0,0,0,1,0,0)=2 grant(0,0,0,0,1,0,0)=2 wait(0) type(ShareLock)
LOG:  LockReleaseAll: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(120)
LOG:  LockReleaseAll: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(120) req(0,0,0,0,1,0,0)=2 grant(0,0,0,0,1,0,0)=2 wait(0) type(INVALID)
LOG:  UnGrantLock: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(ShareLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  LockReleaseAll: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(INVALID)
LOG:  LockRelease: lock [5,16394] AccessExclusiveLock
LOG:  LockRelease: found: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOG:  LockRelease: found: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  UnGrantLock: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
VACUUM
                                     ^
postgres=# alter table t add column col3 int;
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockAcquire: new: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: new: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockCheckConflicts: no conflict: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  GrantLock: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(AccessExclusiveLock)
LOG:  LockAcquire: lock [5,16394] AccessExclusiveLock
LOG:  LockReleaseAll: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(100)
LOG:  LockReleaseAll: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(100) req(0,0,0,0,0,0,0)=1 grant(0,0,0,0,0,0,0)=1 wait(0) type(INVALID)
LOG:  UnGrantLock: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(AccessExclusiveLock)
LOG:  UnGrantLock: updated: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  LockReleaseAll: updated: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
LOG:  CleanUpLock: deleting: proclock(0x7bf21f3ed880) lock(0x7bf21f33efd0) method(1) proc(0x7bf21f6b7f00) hold(0)
LOG:  CleanUpLock: deleting: lock(0x7bf21f33efd0) id(5,16394,0,0,0,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)
ALTER TABLE