Horton

Thread

Commits

  1. Unpin buffer before inplace update waits for an XID to end.

  2. For inplace update durability, make heap_update() callers wait.

  1. heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE

    Noah Misch <noah@leadboat.com> — 2024-10-26T18:49:36Z

    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

  2. Re: heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE

    Noah Misch <noah@leadboat.com> — 2024-10-27T04:09:28Z

    On Sat, Oct 26, 2024 at 11:49:36AM -0700, Noah Misch wrote:
> 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.

> ... work on reproducing this.

I'm running loops of three workloads that might reproduce this, on s390x:

- A buildfarm config like buildfarm member sarus.

- A workload where autovacuum vac_update_datfrozenxid() takes >10s, but
  non-auto "VACUUM (ONLY_DATABASE_STATS)" runs in a loop under
  lock_timeout=5s.  This notices if the non-auto VACUUM ever fails to cancel
  autovacuum.  I apply the attached inplace200-bench-vac-v0.1.patch, then run
  contrib/amcheck/t/089_vac.pl.

- A workload to make vac2's deadlock detector run when an autovacuum worker is
  starting.  That's one of my candidate explanations of the events behind the
  failure log.  I apply the attached inplace190-repro-autovacuum-v0.1.patch,
  then run intra-grant-inplace-db.spec with debug_parallel_query=regress and
  autovacuum_naptime=1s.  This regularly gets vac2 to cancel autovacuum.

So far, those have seen nothing like the failed run.

I'm inclined to make isolationtester log pg_stat_activity and pg_locks
whenever a step times out.  That would have ruled out many explanations for
what happened on sarus.  However, logging on timeout won't help much until
something can reproduce the timeout.

> It's odd that a new
> auto-analyze starts every minute, each of which exits due to blocking vac2.

Every autovacuum_naptime, a new worker cancels the old one due to wanting the
old worker's LOCKTAG_DATABASE_FROZEN_IDS.  One can see this with "BEGIN; GRANT
TEMP ON DATABASE postgres TO pg_monitor;".  That open transaction's xmax
prevents vac_update_datfrozenxid() from finishing.  While that transaction
remains open, every autovacuum_naptime after the first will log a cancellation
of the previous autovacuum worker.  (This assumes each autovacuum worker,
having negligible real work to do, reaches vac_update_datfrozenxid() before
the next autovacuum_naptime.)  That's likely not ideal, but it doesn't explain
the sarus failure.

  3. Re: heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE

    Alexander Law <exclusion@gmail.com> — 2024-10-27T05:00:00Z

    Hello Noah,

27.10.2024 07:09, Noah Misch wrote:
> On Sat, Oct 26, 2024 at 11:49:36AM -0700, Noah Misch wrote:
>> 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.
>> ... work on reproducing this.

FWIW, there was a similar failure in August: [1], and I also could not
reproduce that locally, yet wrote a preliminary analysis at [2] in the
Unsorted section, in the hope to see it again and continue investigation.

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=iguana&dt=2024-08-29%2013%3A57%3A57
[2] https://wiki.postgresql.org/wiki/Known_Buildfarm_Test_Failures

Best regards,
Alexander

  4. Re: heap_inplace_lock vs. autovacuum w/ LOCKTAG_TUPLE

    Noah Misch <noah@leadboat.com> — 2024-10-27T21:40:35Z

    On Sun, Oct 27, 2024 at 08:00:00AM +0300, Alexander Lakhin wrote:
> 27.10.2024 07:09, Noah Misch wrote:
> > On Sat, Oct 26, 2024 at 11:49:36AM -0700, Noah Misch wrote:
> > > 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.
> > > ... work on reproducing this.

The attached demo reproduces $SUBJECT for me.  The clue was 'CONTEXT:  while
scanning block 0 of relation "pg_catalog.pg_database"'.  That
vacuum_error_callback() message indicated VACUUM_ERRCB_PHASE_SCAN_HEAP as the
current phase.  That implies vac2 had not reached any inplace update, any
LOCKTAG_TUPLE, or any part of vac_update_datfrozenxid().  I bet vac2 was stuck
in LockBufferForCleanup().  Concurrently, a sequence of autovacuum workers
held a buffer pin blocking that cleanup.  The demo makes two changes:

a. Start intra-grant-inplace-db.spec step vac2 just after some autovacuum
   worker is blocked on the xid of the uncommitted GRANT.  While blocked, the
   worker holds a pin on the one pg_database page.  vac2 needs
   LockBufferForCleanup($THAT_PAGE).
b. Make LockBufferForCleanup() sleep 10ms after WAIT_EVENT_BUFFER_PIN, to give
   the next autovacuum worker time to win the pinning race.

LockBufferForCleanup() waits for a pin count to fall to 1.  While waiting, its
techniques are less sophisticated than what we have for lock.c heavyweight
locks.  UnpinBufferNoOwner() notifies the cleanup waiter, but nothing stops
another backend from pinning before the cleanup waiter reacts.  We have code
to cancel an autovacuum for the purpose of liberating a heavyweight lock, but
we don't have code like that to free a pin.
pg_isolation_test_session_is_blocked() doesn't detect buffer pin blockages.


Two fix candidates look most promising:

1. Unpin before heap_inplace_lock() sleeps.
2. Change intra-grant-inplace-db.spec to test freezing only MXIDs, not XIDs.

Let's do (1), as attached.  Apart from some arguably-convoluted call stacks,
this has no disadvantages.  An earlier version did unpin.
postgr.es/m/20240822073200.4f.nmisch@google.com stopped that, arguing,
"heap_update() doesn't optimize that way".  In light of $SUBJECT, I no longer
see heap_update() as the applicable standard.  Since autovacuum can run
anytime, it has an extra duty to be non-disruptive.  heap_update() during
auto-analyze won't wait much, because analyze takes a self-exclusive table
lock and is the sole writer of stats tables.  Inplace updates during
autovacuum are different.  They do contend with other transactions.  Since we
lack code to cancel an autovacuum to free a pin, a long-lived pin in
autovacuum is more disruptive than a long-lived lock in autovacuum.

While I've not tried it, I expect (2) would work as follows.  pg_database
won't contain MXIDs, so lazy_scan_noprune() would approve continuing without
the cleanup lock.  Unlike (1), this wouldn't help concurrency outside the
test.

> FWIW, there was a similar failure in August: [1], and I also could not
> reproduce that locally, yet wrote a preliminary analysis at [2] in the
> Unsorted section, in the hope to see it again and continue investigation.
> 
> [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=iguana&dt=2024-08-29%2013%3A57%3A57
> [2] https://wiki.postgresql.org/wiki/Known_Buildfarm_Test_Failures

Thanks.  I had not known about iguana's failure.  What are the chances that
the buffer pin could explain that one?