Occasional lengthy locking causing stalling on commit

G'day all,

We have a postgres 11.9 instance serving 7-8k queries/sec. In general
it's humming along with no issues (p50 patency of ~1ms; p95 ~30ms).
Lately though, we've seen occasional locking that causes all commits
to the main database to be briefly blocked and the APIs that it backs
to stall.

This is what I know so far:
  * It's happened at varying times of day over the last 3 weeks.
Around 10 significant cases (20-30 second stalls) and more shorter
ones.
  * Each time queries are blocked behind an AccessExclusiveLock on the
database (class 1262) that is itself blocked.
  * There's no change in DB throughput at the time.
  * No schema changes or any other queries are being made that would
involve an AccessExclusiveLock.
  * The blocked queries are all commit statements; our metrics show
dozens of traces each time that look perfectly normal except for a 20
second commit somewhere within them.
  * We make heavy use of listen/notify via que with ~80 notify events
per second across 16 listen channels. (https://github.com/que-rb/que)

Based on all that and the logs below, the locks in question appear to
be held while inserting NOTIFY messages on commit:
https://www.postgresql.org/message-id/3598.1363354686%40sss.pgh.pa.us

If that's the case, the real question is why a small number of those
commits are taking so much longer than expected. Any advice on how to
proceed from here much appreciated.

Cheers
Ben Hoskings
---

The observed outage here started at ~00:35:22 and ended when the
blocked locks were acquired.

2021-01-27 00:35:15.264 UTC [1554652]: [21-1] db=main,user=runtime
LOG: process 1554652 still waiting for ShareLock on transaction
3399854732 after 1000.091 ms
2021-01-27 00:35:15.264 UTC [1554652]: [22-1] db=main,user=runtime
DETAIL: Process holding the lock: 1542461. Wait queue: 1554652,
1542154, 1542496.
2021-01-27 00:35:15.264 UTC [1554652]: [23-1] db=main,user=runtime
CONTEXT: while rechecking updated tuple (#,#) in relation "devices"
2021-01-27 00:35:15.264 UTC [1554652]: [24-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.203471', "updated_at" = '2021-01-27
00:35:14.204966' WHERE "devices"."id" = #
2021-01-27 00:35:15.265 UTC [1542154]: [82-1] db=main,user=runtime
LOG: process 1542154 still waiting for ShareLock on transaction
3399854732 after 1000.098 ms
2021-01-27 00:35:15.265 UTC [1542154]: [83-1] db=main,user=runtime
DETAIL: Process holding the lock: 1542461. Wait queue: 1554652,
1542154, 1542496.
2021-01-27 00:35:15.265 UTC [1542154]: [84-1] db=main,user=runtime
CONTEXT: while rechecking updated tuple (#,#) in relation "devices"
2021-01-27 00:35:15.265 UTC [1542154]: [85-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.226635', "updated_at" = '2021-01-27
00:35:14.227932' WHERE "devices"."id" = #
2021-01-27 00:35:15.267 UTC [1542521]: [93-1] db=main,user=runtime
LOG: process 1542521 still waiting for ShareLock on transaction
3399854728 after 1000.067 ms
2021-01-27 00:35:15.267 UTC [1542521]: [94-1] db=main,user=runtime
DETAIL: Process holding the lock: 1547170. Wait queue: 1542514,
1542521.
2021-01-27 00:35:15.267 UTC [1542521]: [95-1] db=main,user=runtime
CONTEXT: while updating tuple (#,#) in relation "devices"
2021-01-27 00:35:15.267 UTC [1542521]: [96-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.257563', "updated_at" = '2021-01-27
00:35:14.258934' WHERE "devices"."id" = #
2021-01-27 00:35:15.278 UTC [1479762]: [60-1] db=main,user=runtime
LOG: process 1479762 still waiting for AccessExclusiveLock on object 0
of class 1262 of database 0 after 1000.129 ms
2021-01-27 00:35:15.278 UTC [1479762]: [61-1] db=main,user=runtime
DETAIL: Process holding the lock: 1518905. Wait queue: 1517976,
1518853, 1445675, 1518975, 1477989, 1518976, 1517975, 3018947,
1468183, 1477990, 1532581, 1474376, 1558501, 1477991, 1473039,
1468182, 1558509, 1477988, 1558516, 3019502, 1518852, 1473037,
1473038, 1547149, 1518909, 1479762, 1479765.
2021-01-27 00:35:15.290 UTC [1479765]: [51-1] db=main,user=runtime
LOG: process 1479765 still waiting for AccessExclusiveLock on object 0
of class 1262 of database 0 after 1000.110 ms
2021-01-27 00:35:15.290 UTC [1479765]: [52-1] db=main,user=runtime
DETAIL: Process holding the lock: 1518905. Wait queue: 1517976,
1518853, 1445675, 1518975, 1477989, 1518976, 1517975, 3018947,
1468183, 1477990, 1532581, 1474376, 1558501, 1477991, 1473039,
1468182, 1558509, 1477988, 1558516, 3019502, 1518852, 1473037,
1473038, 1547149, 1518909, 1479762, 1479765.
2021-01-27 00:35:15.290 UTC [1479765]: [53-1] db=main,user=runtime
STATEMENT: COMMIT
2021-01-27 00:35:15.293 UTC [1542496]: [130-1] db=main,user=runtime
LOG: process 1542496 still waiting for ShareLock on transaction
3399854732 after 1000.123 ms
2021-01-27 00:35:15.293 UTC [1542496]: [131-1] db=main,user=runtime
DETAIL: Process holding the lock: 1542461. Wait queue: 1554652,
1542154, 1542496.
2021-01-27 00:35:15.293 UTC [1542496]: [132-1] db=main,user=runtime
CONTEXT: while updating tuple (#,#) in relation "devices"
2021-01-27 00:35:15.293 UTC [1542496]: [133-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.283515', "updated_at" = '2021-01-27
00:35:14.284677' WHERE "devices"."id" = #
2021-01-27 00:35:24.507 UTC [32]: [10-1] db=,user= LOG: using stale
statistics instead of current ones because stats collector is not
responding
2021-01-27 00:35:34.698 UTC [1565612]: [1-1] db=,user= LOG: using
stale statistics instead of current ones because stats collector is
not responding
2021-01-27 00:35:34.702 UTC [32]: [11-1] db=,user= LOG: using stale
statistics instead of current ones because stats collector is not
responding
2021-01-27 00:35:35.263 UTC [3485525]: [17-1] db=main,user=datadog
LOG: using stale statistics instead of current ones because stats
collector is not responding
2021-01-27 00:35:35.263 UTC [3485525]: [18-1] db=main,user=datadog
STATEMENT: SELECT psd.datname, numbackends, xact_commit,
xact_rollback, blks_read, blks_hit, tup_returned, tup_fetched,
tup_inserted, tup_updated, tup_deleted, 2^31 - age(datfrozenxid) as
wraparound, deadlocks, temp_bytes, temp_files,
pg_database_size(psd.datname) as pg_database_size FROM
pg_stat_database psd JOIN pg_database pd ON psd.datname = pd.datname
WHERE psd.datname not ilike 'template%%%%' AND psd.datname not ilike
'rdsadmin' AND psd.datname not ilike 'azure_maintenance' AND
psd.datname not ilike 'postgres'
2021-01-27 00:35:39.293 UTC [1517976]: [40-1] db=main,user=runtime
LOG: process 1517976 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25247.913 ms
2021-01-27 00:35:39.348 UTC [1542521]: [97-1] db=main,user=runtime
LOG: process 1542521 acquired ShareLock on transaction 3399854728
after 25081.166 ms
2021-01-27 00:35:39.348 UTC [1542521]: [98-1] db=main,user=runtime
CONTEXT: while updating tuple (#,#) in relation "devices"
2021-01-27 00:35:39.348 UTC [1542521]: [99-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.257563', "updated_at" = '2021-01-27
00:35:14.258934' WHERE "devices"."id" = #
2021-01-27 00:35:39.348 UTC [1542514]: [88-1] db=main,user=runtime
LOG: process 1542514 acquired ShareLock on transaction 3399854728
after 25086.306 ms
2021-01-27 00:35:39.348 UTC [1542514]: [89-1] db=main,user=runtime
CONTEXT: while rechecking updated tuple (#,#) in relation "devices"
2021-01-27 00:35:39.348 UTC [1542514]: [90-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.225360', "updated_at" = '2021-01-27
00:35:14.226612' WHERE "devices"."id" = #
2021-01-27 00:35:39.348 UTC [1542496]: [134-1] db=main,user=runtime
LOG: process 1542496 acquired ShareLock on transaction 3399854732
after 25055.414 ms
2021-01-27 00:35:39.348 UTC [1542496]: [135-1] db=main,user=runtime
CONTEXT: while updating tuple (#,#) in relation "devices"
2021-01-27 00:35:39.348 UTC [1542496]: [136-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.283515', "updated_at" = '2021-01-27
00:35:14.284677' WHERE "devices"."id" = #
2021-01-27 00:35:39.348 UTC [1542154]: [86-1] db=main,user=runtime
LOG: process 1542154 acquired ShareLock on transaction 3399854732
after 25083.744 ms
2021-01-27 00:35:39.348 UTC [1542154]: [87-1] db=main,user=runtime
CONTEXT: while rechecking updated tuple (#,#) in relation "devices"
2021-01-27 00:35:39.348 UTC [1542154]: [88-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.226635', "updated_at" = '2021-01-27
00:35:14.227932' WHERE "devices"."id" = #
2021-01-27 00:35:39.348 UTC [1554652]: [25-1] db=main,user=runtime
LOG: process 1554652 acquired ShareLock on transaction 3399854732
after 25084.652 ms
2021-01-27 00:35:39.348 UTC [1554652]: [26-1] db=main,user=runtime
CONTEXT: while rechecking updated tuple (#,#) in relation "devices"
2021-01-27 00:35:39.348 UTC [1554652]: [27-1] db=main,user=runtime
STATEMENT: UPDATE "devices" SET "last_successful_request_at" =
'2021-01-27 00:35:14.203471', "updated_at" = '2021-01-27
00:35:14.204966' WHERE "devices"."id" = #
2021-01-27 00:35:39.445 UTC [1518853]: [62-1] db=main,user=runtime
LOG: process 1518853 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25399.688 ms
2021-01-27 00:35:39.597 UTC [1445675]: [65-1] db=main,user=runtime
LOG: process 1445675 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25550.833 ms
2021-01-27 00:35:39.751 UTC [1518975]: [57-1] db=main,user=runtime
LOG: process 1518975 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25704.969 ms
2021-01-27 00:35:39.822 UTC [1477989]: [47-1] db=main,user=runtime
LOG: process 1477989 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25775.611 ms
2021-01-27 00:35:39.912 UTC [1518976]: [42-1] db=main,user=runtime
LOG: process 1518976 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25864.312 ms
2021-01-27 00:35:40.040 UTC [1517975]: [55-1] db=main,user=runtime
LOG: process 1517975 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 25991.996 ms
2021-01-27 00:35:40.155 UTC [3018947]: [1147-1] db=main,user=runtime
LOG: process 3018947 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26104.830 ms
2021-01-27 00:35:40.207 UTC [1468183]: [40-1] db=main,user=runtime
LOG: process 1468183 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26155.200 ms
2021-01-27 00:35:40.238 UTC [1477990]: [53-1] db=main,user=runtime
LOG: process 1477990 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26181.880 ms
2021-01-27 00:35:40.256 UTC [1532581]: [27-1] db=main,user=runtime
LOG: process 1532581 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26187.341 ms
2021-01-27 00:35:40.263 UTC [1474376]: [40-1] db=main,user=runtime
LOG: process 1474376 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26191.817 ms
2021-01-27 00:35:40.272 UTC [1558501]: [3-1] db=main,user=runtime LOG:
process 1558501 acquired AccessExclusiveLock on object 0 of class 1262
of database 0 after 26192.658 ms
2021-01-27 00:35:40.279 UTC [1477991]: [61-1] db=main,user=runtime
LOG: process 1477991 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26100.590 ms
2021-01-27 00:35:40.285 UTC [1473039]: [36-1] db=main,user=runtime
LOG: process 1473039 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26106.395 ms
2021-01-27 00:35:40.308 UTC [1468182]: [45-1] db=main,user=runtime
LOG: process 1468182 acquired AccessExclusiveLock on object 0 of class
1262 of database 0 after 26128.550 ms
2021-01-27 00:35:40.329 UTC [1558509]: [3-1] db=main,user=runtime LOG:
process 1558509 acquired AccessExclusiveLock on object 0 of class 1262
of database 0 after 26143.959 ms