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
