heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE - Mailing list pgsql-hackers

intra-grant-inplace-db.spec got a novel failure today:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sarus&dt=2024-10-26%2014%3A08%3A58

The isolationtester_waiting query is supposed to detect that step vac2 is
blocked.  vac2 didn't finish within the timeout, but isolationtester_waiting
never considered it blocked.  Most-relevant postmaster.log lines:

===
2024-10-26 14:22:51.791 UTC [2444667:6] isolation/intra-grant-inplace-db/s1 LOG:  statement: BEGIN;
2024-10-26 14:22:51.791 UTC [2444667:7] isolation/intra-grant-inplace-db/s1 LOG:  statement: 
        GRANT TEMP ON DATABASE isolation_regression TO regress_temp_grantee;
    
2024-10-26 14:22:51.791 UTC [2444668:6] isolation/intra-grant-inplace-db/s2 LOG:  statement: VACUUM (FREEZE);
2024-10-26 14:22:51.813 UTC [2444663:1] LOG:  skipping analyze of "pg_attribute" --- lock not available
2024-10-26 14:22:51.815 UTC [2444666:7] isolation/intra-grant-inplace-db/control connection LOG:  execute
isolationtester_waiting:SELECT pg_catalog.pg_isolation_test_session_is_blocked($1, '{2444667,2444668,2444669}')
 
2024-10-26 14:22:51.815 UTC [2444666:8] isolation/intra-grant-inplace-db/control connection DETAIL:  Parameters: $1 =
'2444668'
[... omitting most other lines from PID 2444666: >37000 isolationtester_waiting calls ...]
2024-10-26 14:22:51.851 UTC [2444663:2] LOG:  skipping analyze of "pg_class" --- lock not available
2024-10-26 14:22:51.892 UTC [2444663:3] LOG:  skipping analyze of "pg_depend" --- lock not available
2024-10-26 14:23:52.833 UTC [2444663:4] ERROR:  canceling autovacuum task
2024-10-26 14:23:52.833 UTC [2444663:5] CONTEXT:  while updating tuple (0,20) in relation "pg_database"
2024-10-26 14:24:52.768 UTC [2447791:1] ERROR:  canceling autovacuum task
2024-10-26 14:24:52.768 UTC [2447791:2] CONTEXT:  while updating tuple (0,20) in relation "pg_database"
2024-10-26 14:25:52.777 UTC [2451018:1] ERROR:  canceling autovacuum task
2024-10-26 14:25:52.777 UTC [2451018:2] CONTEXT:  while updating tuple (0,20) in relation "pg_database"
2024-10-26 14:26:52.789 UTC [2454071:1] ERROR:  canceling autovacuum task
2024-10-26 14:26:52.789 UTC [2454071:2] CONTEXT:  while updating tuple (0,20) in relation "pg_database"
2024-10-26 14:27:16.322 UTC [2442306:1] LOG:  checkpoint starting: time
2024-10-26 14:27:52.798 UTC [2457311:1] ERROR:  canceling autovacuum task
2024-10-26 14:27:52.798 UTC [2457311:2] CONTEXT:  while updating tuple (0,20) in relation "pg_database"
2024-10-26 14:28:51.755 UTC [2444666:37889] isolation/intra-grant-inplace-db/control connection LOG:  execute
isolationtester_waiting:SELECT pg_catalog.pg_isolation_test_session_is_blocked($1, '{2444667,2444668,2444669}')
 
2024-10-26 14:28:51.755 UTC [2444666:37890] isolation/intra-grant-inplace-db/control connection DETAIL:  Parameters: $1
='2444668'
 
2024-10-26 14:28:51.810 UTC [2463672:1] [unknown] LOG:  connection received: host=[local]
2024-10-26 14:28:51.812 UTC [2444668:7] isolation/intra-grant-inplace-db/s2 ERROR:  canceling statement due to user
request
2024-10-26 14:28:51.812 UTC [2444668:8] isolation/intra-grant-inplace-db/s2 CONTEXT:  while scanning block 0 of
relation"pg_catalog.pg_database"
 
2024-10-26 14:28:51.812 UTC [2444668:9] isolation/intra-grant-inplace-db/s2 STATEMENT:  VACUUM (FREEZE);
===

I would have expected these locking-relevant events:

- GRANT stamped a pg_database tuple with an xmax.
- auto-analyze sought to update the same tuple, so it acquired LOCKTAG_TUPLE
  and entered XactLockTableWait(xmax-from-GRANT).
- Non-auto VACUUM from step vac2 blocked on acquiring LOCKTAG_TUPLE.
  pg_isolation_test_session_is_blocked() considers this not blocked, since
  blocking on autovacuum doesn't count for test output purposes.
- Deadlock detector notices auto-analyze is blocking vac2, hence "canceling
  autovacuum task" after 1s.
- vac2 finishes its LOCKTAG_TUPLE acquisition and enters
  XactLockTableWait(xmax-from-GRANT).
- pg_isolation_test_session_is_blocked() now considers vac2 blocked.

The timeout suggests some subset of that didn't happen.  It's odd that a new
auto-analyze starts every minute, each of which exits due to blocking vac2.  I
likely got something wrong in commit aac2c9b or its parent (2024-09-24).  I'll
work on reproducing this.

Thanks,
nm