1

We run a write-heavy application backed by PostgreSQL. Our mainline has been running against PostgreSQL 11 for years and we have started rolling out a major update that runs against PG 15. I am investigating why, with the new version, we see activity dips where database activity slows down considerably before picking up steam again. We did not see this behavior previously, under about twice the load per database server.

In the PostgreSQL logs, I can see many times that an application process apparently tries to lock pg_database. Excerpt from the log file, oid=1262 is pg_database:

2023-07-22 05:35:25 UTC LOG:  process 525961 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1353.578 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT
2023-07-22 05:35:25 UTC LOG:  process 525977 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1351.507 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT
2023-07-22 05:35:25 UTC LOG:  process 525976 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1348.369 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT
2023-07-22 05:35:25 UTC LOG:  process 525963 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1346.779 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT
2023-07-22 05:35:25 UTC LOG:  process 525979 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1342.079 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT
2023-07-22 05:35:25 UTC LOG:  process 525965 acquired AccessExclusiveLock on object 0 of class 1262 of database 0 after 1337.144 ms
2023-07-22 05:35:25 UTC STATEMENT:  COMMIT

Looking at pg_locks with classid=1262 we see that a lot is going on:

locktype|database|relation|page|tuple|virtualxid|transactionid|classid|objid|objsubid|virtualtransaction|pid    |mode               |granted|fastpath|waitstart                    
--------+--------+--------+----+-----+----------+-------------+-------+-----+--------+------------------+-------+-------------------+-------+--------+-----------------------------
object  |       0|        |    |     |          |             |   1262|    0|       0|79/1983521        |1309069|AccessExclusiveLock|false  |false   |2023-07-22 05:45:49.184 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|54/12142211       | 525979|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.228 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|203/48538         |1307275|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.813 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|53/4063448        | 525965|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.225 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|77/4747316        | 525983|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.226 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|213/45451         |1307818|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.734 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|49/452247         | 525963|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.227 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|47/497205         | 525962|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.238 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|64/3429214        | 525977|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.227 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|69/435649         | 525982|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.250 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|177/50412         |1304509|AccessExclusiveLock|true   |false   |                             
object  |       0|        |    |     |          |             |   1262|    0|       0|62/452789         | 525976|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.227 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|40/5586224        | 525958|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.226 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|344/7147751       |1305863|AccessExclusiveLock|false  |false   |2023-07-22 05:45:49.733 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|8/5603517         |1306326|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.269 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|197/56204         |1304642|AccessExclusiveLock|false  |false   |2023-07-22 05:45:49.646 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|65/453796         | 525978|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.229 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|222/50840         |1307490|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.319 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|19/14305763       |1307953|AccessExclusiveLock|false  |false   |2023-07-22 05:45:49.547 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|378/51588         |1305187|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.860 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|44/455932         | 525961|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.232 +0000
object  |       0|        |    |     |          |             |   1262|    0|       0|32/5175951        | 525889|AccessExclusiveLock|false  |false   |2023-07-22 05:45:48.228 +0000

Question: What sort of SQL command might require an AccessExclusiveLock to pg_database?

If it matters, we run very few DDL statements within our application (things like creating new partitions on partitioned tables, creating temporary tables), and never within the processes that are involved in the locks above.

Improve this question
3
  • I don't know what is going on, but it isn't the pg_database table. That has the relation oid 1262, not the classid 1262.
    – jjanes
    Commented Jul 22, 2023 at 16:07
  • According to postgresql.org/docs/current/view-pg-locks.html, pg_locks.classid references pg_class.oid, just like pg_locks.relation. Am I missing something?
    – jdx
    Commented Jul 22, 2023 at 20:34
  • So it is something described within the pg_database table, but not a lock on that table itself. But there probably isn't a database with the oid of 0, so what could it be? Maybe something to do with tablespaces, or replication?
    – jjanes
    Commented Jul 23, 2023 at 3:08

1 Answer 1

Reset to default
2

After hacking the code to throw an error when that lock is attempted to be acquired, and then running the regression tests, the only failures are in PreCommit_Notify(). So the problems seems to be with your use of the LISTEN/NOTIFY mechanism (or with something not exercised by the regression tests).

I don't know why this would have gotten worse between those versions. Can you describe your use of LISTEN/NOTIFY? Can you upgrade to an intermediate version and see where the problem was introduced?

Improve this answer
4
  • The client process uses LISTEN indeed. I can now see the log message on the old instances running Postgres 11, so this issue is likely unrelated to the grinding to a halt issue.
    – jdx
    Commented Jul 23, 2023 at 6:29
  • I was mistaken. The client process that tends to hold the locks doesn't use LISTEN. The only interaction it may have with LISTEN/NOTIFY is that it selects for update and deletes rows in a table whose inserts trigger a NOTIFY via a FOR EACH STATEMENT trigger.
    – jdx
    Commented Jul 23, 2023 at 7:20
  • These notifications are not consumed, so in itself that's a bug in our application, which exists on both newer (pg 15) and older (pg 11) instances. I've now removed the trigger and I don't see the messages anymore, after waiting long enough. I'm not sure what to make of it. If this isn't expected behaviour by Postgres, I'd be happy to run more tests if it helps. Otherwise, my problem is solved and thanks so much for the help.
    – jdx
    Commented Jul 23, 2023 at 7:20
  • Do you mean no one ever called LISTEN, or that someone did call LISTEN but never actually retrieved the messages? I don't think this change in performance is expected, but without knowing more about what is going on it is hard to propose what to test. The most likely would candidate I can think of is if the notices were being queued from inside a procedure which does its own COMMIT in a loop.
    – jjanes
    Commented Jul 24, 2023 at 17:11

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.