Message-ID: <1521798167.2471.21.camel@cybertec.at>
Subject: Re: Very long standby database startup after doing pg_basebackup
From: Laurenz Albe <laurenz.albe@cybertec.at>
To: Mario =?UTF-8?Q?Mahovli=C4=87?= <mariomahovlic@gmail.com>
Cc: pgsql-admin@lists.postgresql.org
Date: Fri, 23 Mar 2018 10:42:47 +0100
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>
Organization: Cybertec
Content-Type: text/plain; charset="UTF-8"
Mime-Version: 1.0
Content-Transfer-Encoding: 8bit
Precedence: bulk

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.