From: Linas Virbalas <linas.virbalas@continuent.com>
To: Euler Taveira de Oliveira <euler@timbira.com>
CC: Robert Haas <robertmhaas@gmail.com>, Florian Pflug <fgp@phlo.org>,
	"pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Date: Fri, 23 Sep 2011 01:02:19 -0700
Subject: Re: Hot Backup with rsync fails at pg_clog if under load
Thread-Topic: Hot Backup with rsync fails at pg_clog if under load
Thread-Index: Acx5xx2p4UACGeSJXkGt0/nCbz/b/w==
Message-ID: <CAA217BB.1E2F3%linas.virbalas@continuent.com>
In-Reply-To: <4E7B5B64.3070206@timbira.com>
Accept-Language: en-US
Content-Language: en
acceptlanguage: en-US
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

On 9/22/11 6:59 PM, "Euler Taveira de Oliveira" <euler@timbira.com> wrote:

>> If needed, I could do that, if I had the exact procedure... Currently,
>> during the start of the backup I take the following information:
>>=20
> Just show us the output of pg_start_backup and part of the standby log wi=
th
> the following message 'redo starts at' and the subsequent messages up to =
the
> failure.

Unfortunately, it's impossible, because the error message "Could not read
from file "pg_clog/0001" at offset 32768: Success" is shown (and startup
aborted) before the turn for "redo starts at" message arrives.

For comparison purposes, here is the log from the original message:

2011-09-21 13:41:05 CEST LOG:  database system was interrupted; last known
up at 2011-09-21 13:40:50 CEST
Restoring 00000014.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/00000014.history': No such fil=
e
or directory
Restoring 00000013.history
2011-09-21 13:41:05 CEST LOG:  restored log file "00000013.history" from
archive
! 2011-09-21 13:41:05 CEST LOG:  entering standby mode
Restoring 0000001300000006000000DC
2011-09-21 13:41:05 CEST LOG:  restored log file "0000001300000006000000DC"
from archive
Restoring 0000001300000006000000DB
2011-09-21 13:41:05 CEST LOG:  restored log file "0000001300000006000000DB"
from archive
2011-09-21 13:41:05 CEST FATAL:  could not access status of transaction
1188673
2011-09-21 13:41:05 CEST DETAIL:  Could not read from file "pg_clog/0001" a=
t
offset 32768: Success.
2011-09-21 13:41:05 CEST LOG:  startup process (PID 13819) exited with exit
code 1
2011-09-21 13:41:05 CEST LOG:  aborting startup due to startup process
Failure

As you can see, there is no "redo starts at" message. If we compare this to
a healthy standby startup, we can see that the "pg_clog" error appears afte=
r
the "entering standby mode", but before the "redo starts at", hence the
latter is not reached. Healthy log example:

2011-09-23 09:52:31 CEST LOG:  database system was interrupted; last known
up at 2011-09-23 09:52:15 CEST
Restoring 00000007.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/00000007.history': No such fil=
e
or directory
Restoring 00000006.history
2011-09-23 09:52:31 CEST LOG:  restored log file "00000006.history" from
archive
2011-09-23 09:52:31 CEST LOG:  entering standby mode
Restoring 000000060000000000000065
2011-09-23 09:52:31 CEST LOG:  restored log file "000000060000000000000065"
from archive
2011-09-23 09:52:31 CEST LOG:  redo starts at 0/65000020
2011-09-23 09:52:31 CEST LOG:  consistent recovery state reached at
0/66000000
2011-09-23 09:52:31 CEST LOG:  database system is ready to accept read only
connections
Restoring 000000060000000000000066
mv: cannot stat `/opt/PostgreSQL/9.1/archive/000000060000000000000066': No
such file or directory
Restoring 00000007.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/00000007.history': No such fil=
e
or directory
2011-09-23 09:52:31 CEST LOG:  streaming replication successfully connected
to primary

--
Best regards,
Linas Virbalas
http://flyingclusters.blogspot.com/