hang during shutdown

i recently saw a hung shutdown on a busy multi-TB production database. the
hung shutdown had some unexpected downstream impacts unrelated to core
postgres which turned a routine maintenance operation into a long dramatic
overnight incident... blowing way past our planned maint window and
spoiling my weekend... but that's another story and mainly just explains my
stubborn persistence slowly following the dominoes backwards over this past
month. :)

so far, it all started with this postgres hang during a shutdown. we didnt
capture enough diagnostics to root-cause the domino before the hang, but
the data i do have about this postgres hang is very peculiar. i'm working
on some automation to gather more diagnostics if there is a recurrence. in
the meantime i wanted to share what i do know, in case anyone else has seen
something similar.

postgres version 16.13
Ubuntu 22.04.5 LTS
kernel 5.15.0-1110-azure

between log messages and wal contents, it appears PostmasterStateMachine
transitioned into PM_WAIT_BACKENDS but never progressed beyond this for a
full 30 minutes until external automation finally killed the processes. i
think the evidence most strongly supports the idea that an autovacuum
worker was somehow wedged, but no idea where it possibly could have been
stuck. app was shut down before maint started, at hang time there were only
three open "postgres" user connections from platform automation.

here's what i have:

04:24:07 wal checkpoint. two in-progress autovacs, one is writing
FREEZE_PAGE and VISIBLE records, AI tells me this requires an xid.
RUNNING_XACTS shows single open xact 2121426339 - this must belong to the
autovac doing freeze & visibility.

04:25:09.403 immediate checkpoint (explicit from automation), same running
xid

04:25:09.808 pg logs the fast shutdown req (pg_ctl stop -m fast from
automation)

04:25:09.815 both autovac workers log "terminating autovacuum process":
die() -> ProcessInterrupts() -> ereport()

04:30:09 XLOG_SWITCH and archiver uploads segment 0x30

04:30:10 checkpooint_timeout=300s fires, 72 dirty buffers written.
RUNNING_XACTS at this time shows xid 2121426339 is still open.

04:35:10 XLOG_SWITCH and archiver uploads segment 0x31

04:55:08 external automation SIGKILL

based on the fact that we saw checkpoints and archivals a full 10 minutes
later, that's why i think it never left PM_WAIT_BACKENDS. also, there was
never any XLOG_CHECKPOINT_SHUTDOWN record or any XLOG_XACT_ABORT record
written in the whole 30 minutes.

AI tells me autovac process needs to call AbortTransaction() which calls
ProcArrayEndTransaction() to remove xid from PGPROC and also calls
RecordTransactionAbort() which should write the abort WAL record. neither
of these happen, which suggests autovac was stuck after it logs its
termination message and before it performs either of these actions. this is
not a lot of code, and my AI couldnt find any obvious places where theres
disk or network calls or anything else that could hang.

successful checkpoints suggest that both the data and the wal disks were
accepting writes, and IO was not hung on the whole. if there was a D-state
hang then it would have been just one process, while others on same device
did not hang.

i'm pretty stumped!

my plan right now is to work on the automation that fires the SIGKILL and
just have it collect and log everything it can from /proc/pid/* before the
kill. if this happens again we should get a little more info to go on.

if anyone else has thoughts or ideas to add, lmk

-Jeremy

--
http://about.me/jeremy_schneider