Re: [HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-29 Thread Linas Virbalas
 Linas, could you capture the output of pg_controldata *and* increase the
 log level to DEBUG1 on the standby? We should then see nextXid value of
 the checkpoint the recovery is starting from.

I'll try to do that whenever I'm in that territory again... Incidentally,
recently there was a lot of unrelated-to-this-post work to polish things up
for a talk being given at PGWest 2011 Today :)

 I also checked what rsync does when a file vanishes after rsync computed the
 file list, but before it is sent. rsync 3.0.7 on OSX, at least, complains
 loudly, and doesn't sync the file. It BTW also exits non-zero, with a special
 exit code for precisely that failure case.

To be precise, my script has logic to accept the exit code 24, just as
stated in PG manual:

Docs For example, some versions of rsync return a separate exit code for
Docs vanished source files, and you can write a driver script to accept
Docs this exit code as a non-error case.

--
Sincerely,
Linas Virbalas
http://flyingclusters.blogspot.com/


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers


Re: [HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-23 Thread Linas Virbalas
On 9/22/11 6:59 PM, Euler Taveira de Oliveira eu...@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:
 
 Just show us the output of pg_start_backup and part of the standby log with
 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 0014.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/0014.history': No such file
or directory
Restoring 0013.history
2011-09-21 13:41:05 CEST LOG:  restored log file 0013.history from
archive
! 2011-09-21 13:41:05 CEST LOG:  entering standby mode
Restoring 0013000600DC
2011-09-21 13:41:05 CEST LOG:  restored log file 0013000600DC
from archive
Restoring 0013000600DB
2011-09-21 13:41:05 CEST LOG:  restored log file 0013000600DB
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 at
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 after
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 0007.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/0007.history': No such file
or directory
Restoring 0006.history
2011-09-23 09:52:31 CEST LOG:  restored log file 0006.history from
archive
2011-09-23 09:52:31 CEST LOG:  entering standby mode
Restoring 00060065
2011-09-23 09:52:31 CEST LOG:  restored log file 00060065
from archive
2011-09-23 09:52:31 CEST LOG:  redo starts at 0/6520
2011-09-23 09:52:31 CEST LOG:  consistent recovery state reached at
0/6600
2011-09-23 09:52:31 CEST LOG:  database system is ready to accept read only
connections
Restoring 00060066
mv: cannot stat `/opt/PostgreSQL/9.1/archive/00060066': No
such file or directory
Restoring 0007.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/0007.history': No such file
or directory
2011-09-23 09:52:31 CEST LOG:  streaming replication successfully connected
to primary

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers


Re: [HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-23 Thread Linas Virbalas
On 9/23/11 12:05 PM, Heikki Linnakangas
heikki.linnakan...@enterprisedb.com wrote:

 It looks to me that pg_clog/0001 exists, but it shorter than recovery
 expects. Which shouldn't happen, of course, because the start-backup
 checkpoint should flush all the clog that's needed by recovery to disk
 before the backup procedure begins to them.
 
 Yeah. What confuses me though is that we fail while trying to read from the
 clog. When do we do that during normal (non-standby) recovery?
 
 I believe the OP is setting up a standby. He didn't say if it's a hot
 standby, though. That changes the startup sequence a bit.

I confirm that it is a Hot Standby with Streaming Replication.

 One other possibility would be that the problem is somehow triggered by
 vacuum running while the start-backup checkpoint is commencing. That'd
 explain why the problem goes away with immediate checkpoints, because those
 make the windows mach smaller. But I haven't got a concrete theory of whats
 happening..
 
 Hmm, that's a good theory. The logic in SimpleLruPhysicakReadPage()
 tolerates non-existent files, because the old clog files might've been
 truncated away by a vacuum after the backup started. That's OK, because
 they will be recreated, and later deleted again, during the WAL replay.
 But what if something like this happens:
 
 0. pg_start_backup().
 1. rsync starts. It gets a list of all files. It notes that pg_clog/0001
 exists.
 2. vacuum runs, and deletes pg_clog/0001
 3. rsync starts to copy pg_clog/0001. Oops, it's gone. Instead of
 leaving it out altogether, it includes it as an empty file.

I cannot confirm that. I have tried this scenario one more time and was
observing how pg_clog/ looked on the master and standby. Here's an overview:

1. pg_start_backup('base_backup') - waiting...

2. Checking the size of pg_clog periodically on the master:

-bash-3.2$ ls -l pg_clog
total 8
-rw--- 1 postgres postgres 8192 Sep 23 14:31 
-bash-3.2$ ls -l pg_clog
total 8
-rw--- 1 postgres postgres 8192 Sep 23 14:31 
-bash-3.2$ ls -l pg_clog
total 16

3. Somewhere just before (1) step releases and we get into rsync phase, the
pg_clog size changes:

-rw--- 1 postgres postgres 16384 Sep 23 14:33 
-bash-3.2$ ls -l pg_clog
total 16
-rw--- 1 postgres postgres 16384 Sep 23 14:33 
-bash-3.2$ ls -l pg_clog
total 16
-rw--- 1 postgres postgres 16384 Sep 23 14:33 

4. The rsync does transfer the file:

...
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,881 INFO
management.script.ScriptPlugin base/16394/16405_fsm
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,881 INFO
management.script.ScriptPlugin base/16394/pg_internal.init
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,886 INFO
management.script.ScriptPlugin global/
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,886 INFO
management.script.ScriptPlugin global/12691
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,886 INFO
management.script.ScriptPlugin global/12696
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,886 INFO
management.script.ScriptPlugin global/12697
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,886 INFO
management.script.ScriptPlugin global/pg_internal.init
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,887 INFO
management.script.ScriptPlugin pg_clog/
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,887 INFO
management.script.ScriptPlugin pg_multixact/offsets/
INFO   | jvm 1| 2011/09/23 14:33:43 | 2011-09-23 14:33:43,887 INFO
management.script.ScriptPlugin pg_notify/
...

But on the standby its size is the old one (thus, it seems, that the size
changed after the rsync transfer and before the pg_stop_backup() was
called):

ls -l pg_clog/
total 8
-rw--- 1 postgres postgres 8192 Sep 23 14:31 

5. Hence, the server doesn't start and pg_log complains:

2011-09-23 14:33:45 CEST LOG:  streaming replication successfully connected
to primary
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  the database system is starting up
2011-09-23 14:33:46 CEST FATAL:  could not access status of transaction
37206
2011-09-23 14:33:46 CEST DETAIL:  Could not read from file pg_clog/ at
offset 8192: Success.

6. Now, if I do something that, of course, should never be done, and copy
this  file from master to the standby soon enough (without even
starting/stopping backup), the standby starts up successfully.

--
Hope this helps,
Linas Virbalas
http://flyingclusters.blogspot.com/


-- 
Sent via pgsql-hackers mailing list (pgsql

Re: [HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-23 Thread Linas Virbalas
 But on the standby its size is the old one (thus, it seems, that the size
 changed after the rsync transfer and before the pg_stop_backup() was
 called):

 Now that seems pretty weird - I don't think that file should ever shrink.

It seems, I was not clear in my last example. The pg_clog file doesn't shrink. 
On the contrary, when rsync kicks in it is still small, but after it completes 
and somewhere around the pg_stop_backup() call, the pg_clog file grows on the 
master. Hence, it is left smaller on the standby.

 Are you sure that the rsync isn't starting until after
 pg_start_backup() completes?

100% - the procedure is scripted in a single threaded application, so rsync is 
started only after pg_start_backup(...) returns.

 Because if you were starting it just a
 tiny bit early, that would explain the observed symptoms perfectly, I
 think.

I agree, but that is not the case.
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers


Re: [HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-22 Thread Linas Virbalas
 2.2. pg_start_backup(Obackup_under_loadš) on the master (this will take a
 while as master is loaded up);
 
 No. if you use pg_start_backup('foo', true) it will be fast. Check the
 manual.
 
 If the server is sufficiently heavily loaded that a checkpoint takes a
 nontrivial amount of time, the OP is correct that this will be not
 fast, regardless of whether you choose to force an immediate
 checkpoint.

In order to check more cases, I have changed the procedure to force an
immediate checkpoint, i.e. pg_start_backup('backup_under_load', true). With
the same load generator running, pg_start_backup returned almost
instantaneously compared to how long it took previously.

Most importantly, after doing this change, I cannot reproduce the pg_clog
error message anymore. In other words, with immediate checkpoint hot backup
succeeds under this load!

 2.3. rsync data/global/pg_control to the standby;
 
 Why are you doing this? If ...
 
 2.4. rsync all other data/ (without pg_xlog) to the standby;
 
 you will copy it again or no? Don't understand your point.
 
 His point is that exercising the bug depends on doing the copying in a
 certain order.  Any order of copying the data theoretically ought to
 be OK, as long as it's all between starting the backup and stopping
 the backup, but apparently it isn't.

Please note that in the past I was able to reproduce the same pg_clog error
even with taking a singular rsync of the whole data/ folder (i.e. without
splitting it into two steps).

 The problem could be that the minimum recovery point (step 2.3) is different
 from the end of rsync if you are under load.

Do you have ideas why does the Hot Backup operation with
pg_start_backup('backup_under_load', true) succeed while
pg_start_backup('backup_under_load') fails under the same load?

Originally, I was using pg_start_backup('backup_under_load') in order not to
clog the master server during the I/O required for the checkpoint. Of
course, now, it seems, this should be sacrificed for the sake of a
successful backup under load.

 It seems pretty clear that some relevant chunk of WAL isn't getting
 replayed, but it's not at all clear to me why not.  It seems like it
 would be useful to compare the LSN returned by pg_start_backup() with

If needed, I could do that, if I had the exact procedure... Currently,
during the start of the backup I take the following information:

pg_xlogfile_name(pg_start_backup(...))

 the location at which replay begins when you fire up the clone.

As you have seen in my original message, in the pg_log I get only the
restored WAL file names after starting up the standby. Can I tune the
postgresql.conf to include the location at which replay begins in the log?

 Could you provide us with the exact rsync version and parameters you use?

rsync -azv
version 2.6.8  protocol version 29

--
Sincerely,
Linas Virbalas
http://flyingclusters.blogspot.com/


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers


[HACKERS] Hot Backup with rsync fails at pg_clog if under load

2011-09-21 Thread Linas Virbalas
Hello,

* Context *

I'm observing problems with provisioning a standby from the master by
following a basic and documented Making a Base Backup [1] procedure with
rsync if, in the mean time, heavy load is applied on the master.

After searching the archives, the only more discussed and similar issue I
found hit was by Daniel Farina in a thread hot backups: am I doing it
wrong, or do we have a problem with pg_clog? [2], but, it seems, the issue
was discarded because of a non-standard backup procedure Deniel used.
However, I'm observing the same error with a simple procedure, hence this
message.

* Details *

Procedure:

1. Start load generator on the master (WAL archiving enabled).
2. Prepare a Streaming Replication standby (accepting WAL files too):
2.1. pg_switch_xlog() on the master;
2.2. pg_start_backup(Obackup_under_load¹) on the master (this will take a
while as master is loaded up);
2.3. rsync data/global/pg_control to the standby;
2.4. rsync all other data/ (without pg_xlog) to the standby;
2.5. pg_stop_backup() on the master;
2.6. Wait to receive all WAL files, generated during the backup, on the
standby;
2.6. Start the standby PG instance.

The last step will, usually, fail with a similar error:

2011-09-21 13:41:05 CEST LOG:  database system was interrupted; last known
up at 2011-09-21 13:40:50 CEST
Restoring 0014.history
mv: cannot stat `/opt/PostgreSQL/9.1/archive/0014.history': No such file
or directory
Restoring 0013.history
2011-09-21 13:41:05 CEST LOG:  restored log file 0013.history from
archive
2011-09-21 13:41:05 CEST LOG:  entering standby mode
Restoring 0013000600DC
2011-09-21 13:41:05 CEST LOG:  restored log file 0013000600DC
from archive
Restoring 0013000600DB
2011-09-21 13:41:05 CEST LOG:  restored log file 0013000600DB
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 at
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

The procedure works very reliably if there is little or no load on the
master, but fails very often with the pg_clog error when load generator (few
thousands of SELECTs, ~60 INSERTs, ~60 DELETEs and ~60 UPDATES per second)
is started up.

I assumed that a file system backup taken during pg_start_backup and
pg_stop_backup is guaranteed to be consistent and that missing pieces will
be taken from the WAL files, generated  shipped during the backup, but is
it really?

Is this procedure missing some steps? Or maybe this a known issue?

Thank you,
Linas

[1] http://www.postgresql.org/docs/current/static/continuous-archiving.html
[2] http://archives.postgresql.org/pgsql-hackers/2011-04/msg01132.php


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers