8

I am running an RDS instance of PostgreSQL 9.6.3: select version(); returns PostgreSQL 9.6.3 on x86_64-pc-linux-gnu [...].

I have found that after issuing a stop from the RDS console followed by a start the database always reports that the database system was not properly shutdown, requiring recovery. This behavior has been independently verified by at least one other RDS PostgreSQL user (https://forums.aws.amazon.com/message.jspa?messageID=809401#809401).

The query

select name, setting
from pg_settings
where name in ('fsync', 'wal_sync_method', 'synchronous_commit');

reports that fsync = on, wal_sync_method = fdatasync (correct for a Linux system), and synchronous_commit = on.

I see the following in the logs after issuing a stop:

2017-10-12 16:37:36 UTC::@:[3464]:LOG: received fast shutdown request
2017-10-12 16:37:36 UTC::@:[3464]:LOG: aborting any active transactions
2017-10-12 16:37:36 UTC::@:[3515]:LOG: autovacuum launcher shutting down
2017-10-12 16:37:36 UTC::@:[3512]:LOG: shutting down
2017-10-12 16:37:36 UTC::@:[3512]:LOG: checkpoint starting: shutdown immediate
2017-10-12 16:37:36 UTC::@:[3512]:LOG: checkpoint complete: wrote 1 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.007 s, sync=0.002 s, total=0.145 s; sync files=1, longest=0.002 s, average=0.002 s; distance=16384 kB, estimate=16402 kB
2017-10-12 16:37:36 UTC::@:[3464]:LOG:  database system is shut down

And the following after issuing a start:

2017-10-12 17:05:33 UTC::@:[3293]:LOG: database system was interrupted; last known up at 2017-10-12 16:37:50 UTC
2017-10-12 17:05:33 UTC::@:[3293]:LOG: database system was not properly shut down; automatic recovery in progress
2017-10-12 17:05:33 UTC::@:[3293]:LOG: redo starts at 165/1160
2017-10-12 17:05:33 UTC::@:[3293]:LOG: unexpected pageaddr 164/D2000000 in log segment 000000010000016500000003, offset 0
2017-10-12 17:05:33 UTC::@:[3293]:LOG: redo done at 165/20000A0
2017-10-12 17:05:33 UTC::@:[3293]:LOG: last completed transaction was at log time 2017-10-12 16:50:53.823582+00
2017-10-12 17:05:33 UTC::@:[3293]:LOG: checkpoint starting: end-of-recovery immediate
2017-10-12 17:05:33 UTC::@:[3293]:LOG: checkpoint complete: wrote 2 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 3 recycled; write=0.029 s, sync=0.002 s, total=0.046 s; sync files=2, longest=0.002 s, average=0.001 s; distance=49147 kB, estimate=49147 kB
2017-10-12 17:05:33 UTC::@:[3293]:LOG: MultiXact member wraparound protections are now enabled

Given my understanding of PostgreSQL's (fast) shutdown and startup sequences, the above log messages seem to indicate that PostgreSQL is writing and completing a final checkpoint before shutdown, and then successfully shutting down.

However, based on the code at xlog.c line 6023 and xlog.c line 6503 (https://github.com/postgres/postgres/blob/ca9cfed883333d5801716eb01cf28b6b5be2b5cd/src/backend/access/transam/xlog.c; can't post more than 2 links), corresponding to the database system was interrupted [...] and database system was not properly shut down [...] log lines, respectively, it would appear that at least the pg_control file was not flushed to disk. This worries me, as I'm expecting Amazon have taken care to make sure that the volumes on which PostgreSQL data and log files are stored are fit-for-purpose (i.e. they don't report fsync completion until it is really complete).

Is there another explanation for this behavior?

  • 3
    Yeah, that's odd, and concerning. Ask AWS support and report back? – Craig Ringer Oct 18 '17 at 0:20
  • 1
    I'm not sure lack of reliable fsync() would explain it though, I'd expect to see a variety of weird intermittent corruption problems from that. It's hard to imagine that would go unnoticed. – Craig Ringer Oct 18 '17 at 0:57
  • 1
    @CraigRinger, the issue has been reported to the software development manager for RDS PostgreSQL. It may not be due to reliable fsync, that's just my hypothesis. It's also possible the instance terminates before the database engine can fsync the pg_control file. My understanding is that fsync reporting success before the data is actually written to disk is not unheard of: some drive controllers cache writes. I suspect RDS PostgreSQL uses EBS, which is SAN (or SAN like), which complicates things. – Christopher Lewis Oct 19 '17 at 19:55
  • 1
    As you're not using an open source software, it's difficult to say... My guess is that by default, stopping RDS Postgres issues a "immediate" stop whereas Postgres simply issues a "fast" stop. That means the instance can't do a checkpoint before stopping and so it has to do it on startup. (And stopping in "immediate" mode is exactly like crashing the instance FYI) – Arkhena Dec 18 '18 at 8:45

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.