From: Laurenz Albe <laurenz.albe@cybertec.at>
To: Mario Mahovlić <mariomahovlic@gmail.com>
Cc: pgsql-admin@lists.postgresql.org
Subject: Re: Very long standby database startup after doing pg_basebackup
Date: Fri, 23 Mar 2018 10:42:47 +0100
Message-ID: <1521798167.2471.21.camel@cybertec.at> (raw)
In-Reply-To: <CAG9x_sTTariBA2MQCcQrfqm=RhzXUOy2=hN2wZcnR5u19xXVzA@mail.gmail.com>
References: <CAG9x_sT2mgYF8PU+4o3hMXsqDT4SQj2ms2tWB69Qek8wbdrxOg@mail.gmail.com>
<1521705321.2459.24.camel@cybertec.at>
<CAG9x_sTTariBA2MQCcQrfqm=RhzXUOy2=hN2wZcnR5u19xXVzA@mail.gmail.com>
Mario Mahovlić wrote:
> Thank you for the reply, we will try using perf to see what exactly is going on.
> As for the log file all we get from it (even when log level is set to debug5) is this:
>
> > >>> Starting postgres...
> > LOG: database system was interrupted; last known up at 2018-03-20 08:25:18 UTC
> > FATAL: the database system is starting up
> > psql: FATAL: the database system is starting up
> > >>> Db replication is still not accessible on *NODE* (trying 17255 times)
> > ..... * This goes on for 6 hours *
> > LOG: entering standby mode
> > LOG: redo starts at 4B/A000028
> > LOG: consistent recovery state reached at 4B/A000130
> > LOG: database system is ready to accept read only connections
> > LOG: started streaming WAL from primary at 4B/B000000 on timeline 35
> > DEBUG: CommitTransaction
> > DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
> > DEBUG: StartTransactionCommand
> > DEBUG: StartTransaction
> > ...
>
> Lines with >>> are from our own scripts we use for startup and database management.
>
> So basically on startup all we get in logs is:
> LOG: database system was interrupted; last known up at 2018-03-20 08:25:18 UTC
> FATAL: the database system is starting up -> every time we query db until it starts up successfully
>
> Is there any other way to log more detail during postgres startup?
>
> As i said in initial mail we use -X stream option when doing pg_basebackup, here is exact pg_basebackup command that is being run:
>
> > INFO: executing: '/usr/lib/postgresql/9.6/bin/pg_basebackup -l "repmgr base backup" -D /var/lib/postgresql/data -h *NODE_IP* -p *PORT* -U *USER* -c fast -X stream '
>
> So yes, we do copy the WAL files, and there is at most 30GB of them (that is how much we keep), however even if database had to restore all of them 6 hours seems a bit much.
Sorry, I missed the pg_basebackup command.
The strange thing is that you see the message "entering standby mode" only six
hours after startup. This message is written when recovery *starts*, so
(as expected) it is not that recovery takes long.
By the way, you should add %m to your log_line_prefix so we see *when* messages
are logged.
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-admin@postgresql.org
Cc: laurenz.albe@cybertec.at, mariomahovlic@gmail.com, pgsql-admin@lists.postgresql.org
Subject: Re: Very long standby database startup after doing pg_basebackup
In-Reply-To: <1521798167.2471.21.camel@cybertec.at>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox