Who receives the SetLatch() that v3 adds to autovac_recalculate_workers_for_balance() REL_19_STABLE e60ee52841d + v3, --enable-cassert --enable-injection-points ===== instrument.diff (logging only, on top of v3) ===== --- a/src/backend/postmaster/autovacuum.c (v3) +++ b/src/backend/postmaster/autovacuum.c (v3 + log) @@ -1835,6 +1835,16 @@ pg_atomic_unlocked_test_flag(&worker->wi_dobalance)) continue; + { + const char *we = pgstat_get_wait_event(worker->wi_proc->wait_event_info); + + elog(LOG, "AVLATCH caller=%s count=%d->%d target=%d self=%d already_set=%d wait=%s", + AmAutoVacuumLauncherProcess() ? "launcher" : "worker", + orig_nworkers_for_balance, nworkers_for_balance, + worker->wi_proc->pid, worker->wi_proc == MyProc, + (int) worker->wi_proc->procLatch.is_set, + we ? we : "none"); + } SetLatch(&worker->wi_proc->procLatch); } } ===== latchcount.sh ===== #!/bin/bash # Who receives the SetLatch() that v3 adds to # autovac_recalculate_workers_for_balance(), and what each target was doing # at that moment, under an ordinary autovacuum load. # # Build: v3 plus one elog(LOG) before that SetLatch() (instrument.diff), # printing the caller, the old and new count, the target pid and the # target's wait event read from its PGPROC. # # Load: 3 workers, 120 small tables (every third one with its own # autovacuum_vacuum_cost_limit, so it is not in the balance and the count # changes as workers move between tables), and one larger table with three # indexes and autovacuum_parallel_workers = 2, so a leader sometimes waits # in ParallelFinish. The tables are updated in rounds for DURATION seconds. # NDB databases get the same tables, so up to three workers run at once. # latchcount.sh [DURATION] [NDB] set -u DURATION=${1:-120} NDB=${2:-1} A=$(cd "$(dirname "$0")" && pwd) I=$HOME/pgav/i-zsinst/bin D=$(mktemp -d /tmp/claude-1000/lc.XXXX); P=55441 "$I/initdb" -D $D -A trust --no-sync -U postgres >/dev/null cat >> $D/postgresql.conf </dev/null q() { "$I/psql" -X -qAt -h /tmp -p $P -U postgres "$@"; } { for n in $(seq 1 120); do if [ $((n % 3)) = 0 ]; then opt="WITH (autovacuum_vacuum_cost_limit = 500)"; else opt=""; fi echo "CREATE TABLE s$n (id int PRIMARY KEY, v int) $opt;" echo "INSERT INTO s$n SELECT g, g FROM generate_series(1, 3000) g;" done echo "CREATE TABLE big (id int PRIMARY KEY, a int, b int, c int) WITH (autovacuum_parallel_workers = 2);" echo "INSERT INTO big SELECT g, g, g, g FROM generate_series(1, 400000) g;" echo "CREATE INDEX big_a ON big (a); CREATE INDEX big_b ON big (b); CREATE INDEX big_c ON big (c);" } > $D/setup.sql DBS=postgres for k in $(seq 2 $NDB); do q -c "CREATE DATABASE d$k"; DBS="$DBS d$k"; done for db in $DBS; do q -d $db -f $D/setup.sql; done # One round dirties every small table; every fifth round also dirties big. for n in $(seq 1 120); do echo "UPDATE s$n SET v = v + 1 WHERE id <= 500;"; done > $D/round.sql echo "UPDATE big SET a = a + 1 WHERE id % 4 = 0;" > $D/big.sql off=$(stat -c %s $D/log) end=$(( $(date +%s) + DURATION )); r=0 while [ "$(date +%s)" -lt $end ]; do for db in $DBS; do q -d $db -f $D/round.sql & done; wait if [ $((r % 5)) = 0 ]; then for db in $DBS; do q -d $db -f $D/big.sql & done; wait; fi r=$((r + 1)); sleep 2 done sleep 5 tail -c +$((off + 1)) $D/log > $A/latchcount.ndb$NDB.server.log "$I/pg_ctl" -D $D -m fast -w stop >/dev/null rm -rf $D L=$A/latchcount.ndb$NDB.server.log { echo "duration ${DURATION}s, $NDB database(s), $r update rounds" echo "tables vacuumed: $(grep -c 'automatic vacuum of table' $L)" echo " of them big (parallel): $(grep -c 'automatic vacuum of table "[a-z0-9]*.public.big"' $L)" echo "SetLatch() calls: $(grep -c AVLATCH $L)" echo " target is the caller itself: $(grep AVLATCH $L | grep -c 'self=1')" echo " target is another worker: $(grep AVLATCH $L | grep -c 'self=0')" echo " by caller:" grep AVLATCH $L | grep -o 'caller=[a-z]*' | sort | uniq -c | sed 's/^/ /' echo " other-worker targets whose latch was already set: $(grep AVLATCH $L | grep 'self=0' | grep -c 'already_set=1')" echo " ParallelFinish targets whose latch was already set: $(grep AVLATCH $L | grep 'wait=ParallelFinish' | grep -c 'already_set=1')" echo " other-worker targets, by wait event at that moment:" grep AVLATCH $L | grep 'self=0' | grep -o 'wait=[A-Za-z]*' | sort | uniq -c | sort -rn | sed 's/^/ /' echo "distinct worker pids: $(grep 'automatic vacuum of table' $L | grep -o '\[[0-9]*\]' | sort -u | wc -l)" } | tee $A/latchcount.ndb$NDB.txt ===== ./latchcount.sh 120 3 ===== duration 120s, 3 database(s), 45 update rounds tables vacuumed: 14506 of them big (parallel): 28 SetLatch() calls: 10066 target is the caller itself: 4871 target is another worker: 5195 by caller: 65 caller=launcher 10001 caller=worker other-worker targets whose latch was already set: 4724 ParallelFinish targets whose latch was already set: 1 other-worker targets, by wait event at that moment: 4635 wait=VacuumDelay 235 wait=ParallelFinish 117 wait=none 96 wait=AioIoCompletion 66 wait=WALWrite 21 wait=WalWrite 13 wait=BufferExclusive 10 wait=DataFileWrite 1 wait=WALBufMapping 1 wait=DataFileRead distinct worker pids: 148 (self=1 calls whose latch was already set: 814) ===== ./latchcount.sh 120 1 (earlier build: same log line without already_set) ===== duration 120s, 54 update rounds tables vacuumed: 6613 of them big (parallel): 12 SetLatch() calls: 2212 target is the caller itself: 2212 target is another worker: 0 by caller: 2212 caller=worker other-worker targets, by wait event at that moment: ===== sample of the log, 3 databases ===== 2026-09-24 21:35:06.263 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.263 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.263 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.268 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.268 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.268 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.268 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.268 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.274 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.274 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.274 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.274 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.274 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.279 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.279 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.280 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.280 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.280 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.285 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.285 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.285 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.285 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.285 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.290 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.290 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.290 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none 2026-09-24 21:35:06.290 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.290 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.295 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772425 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.295 -03 [3773519] LOG: AVLATCH caller=worker count=3->2 target=3772327 self=0 already_set=1 wait=VacuumDelay 2026-09-24 21:35:06.296 -03 [3773519] LOG: AVLATCH caller=worker count=2->3 target=3773519 self=1 already_set=0 wait=none