Re: PITR on DROP DATABASE, deleting of the database directory despite the recovery_target_time set before.

2019-12-13 Thread Jean-Christophe Arnu 
Hello,

Le mar. 19 nov. 2019 à 16:15, Nicolas Lutic  a écrit :

>
> We are aware that this part is tricky and will have little effects on
> normal operations, as best practices are to use xid_target or lsn_target.
>
> I'm working with Nicolas and we made some further testing. If we use xid
target with inclusive to  false at the next xid after the insert, we end up
with the same DELETE/DROP directory behaviour which is quite confusing. One
have to choose the xid-1 value with inclusive behaviour to lake it work.

I assume this is the right first thing to document the behaviour. And give
some examples on this.

Maybe we could add some documentation in the xlog explanation and a warning
in the recovery_target_time and xid in guc doc ?

If there are better places in the docs let us know.

Thanks


-- 
Jean-Christophe Arnu

Re: PITR on DROP DATABASE, deleting of the database directory despite the recovery_target_time set before.

2019-11-19 Thread Nicolas Lutic 


On 11/19/19 1:40 AM, Craig Ringer wrote:
> On Mon, 18 Nov 2019 at 18:48, Nicolas Lutic  > wrote:
> 
> Dear Hackers,
> 
> After a drop database
> 
> 
> with FORCE?
No, we tested with PostgreSQL v 11 and we don't have this option.
>  
> 
> , he tried to recover the data on the last inserted transaction by
> using the recovery_target_time.
> The issue is the database is present in the system catalog but the
> directory was still deleted.
> Here the technical information of the database
> version 11
> default  postgresql.conf except for this options
>     wal_level = replica
>     archive_mode = on
>     archive_command = 'cp %p /tmp/wal_archive/%f '
>     log_statement = 'all'
>     log_min_messages = debug5
> 
>   
> The following method was used 
> 
>   * create cluster
> 
>   * create database
> 
>   * create 1 table 
> 
>   * create 1 index on 1 column
> 
>   * insert 1 rows
> 
>   * backup with pg_base_backup
> 
>   * insert 2 rows
> 
> autocommit? 

Yes, I forgot to mention it.

> 
>   * drop database
> 
> force?
>  
> 
>   *     Change recovery behaviour in that case to prevent all xact
> operation to perform until COMMIT timestamp is checked against
> recovery_time bound (but it seems to be difficult as
> state 
> https://www.postgresql.org/message-id/flat/20141125160629.GC21475%40msg.df7cb.dewhich
> also identifies the problem and tries to give some solutions. 
> Maybe another way, as a trivial guess (all apologises) is to
> buffer immediate xacts until we have the commit for each and
> apply the whole buffer xact once the timestamp known (and
> checked agains recovery_target_time value);
> 
>   *     The other way to improve this is to update PostgreSQL
> documentation  by specifying that recovery_target_time cannot be
> used in this case.There should be multiple places where it can
> be stated. The best one (if only one) seems to be in 
> 
> https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=doc/src/sgml/config.sgml;h=
> 
> 
> 
> 
> If this only happens when a DB is dropped under load with force, I lean
> toward just documenting it as a corner case.

This can happen in the case of a non-transactional instruction, DROP
DATABASE (with or without FORCE) is one case but there may be other cases ?

The documentation modification have to mention this case and list the
other most likely operations.

An idea, without insight knowledge of the code, in case of
recovery_target_time (only), would be to move forward each record for an
xact.

Each record that is «timestamped» can be applied but once we encounter a
non timestamped record we could buffer the following records for any
xaxts until a timestamped commit/rollback for the transaction where that
non transactionnal op appearsin. Once the commit/rollback records are
found, there's two options :
1) the commit/rollback timestamp is inside the "replay" bound, then the
whole buffer can be applied
2) the commit/rollback timestamp is beyond the upper time bound for
"replay", then  the whole buffer for that transaction could be canceled.
This can only be done on DROP DATABASE "DELETE" operation ?
Maybe, this will lead to skewed pages and this is a wrong way to do such
a thing.

Another assumption is that "DROP DATABASE" sequence can be changed for
this operation to perform correctly.

We are aware that this part is tricky and will have little effects on
normal operations, as best practices are to use xid_target or lsn_target.


> 
> -- 
>  Craig Ringer   http://www.2ndQuadrant.com/
>  2ndQuadrant - PostgreSQL Solutions for the Enterprise

Best regards

-- 
LOXODATA https://www.loxodata.com/
Consulting - Training - Support
Nicolas Lutic
Consultant trainer

Re: PITR on DROP DATABASE, deleting of the database directory despite the recovery_target_time set before.

2019-11-18 Thread Craig Ringer 
On Mon, 18 Nov 2019 at 18:48, Nicolas Lutic  wrote:

> Dear Hackers,
>
> After a drop database
>

with FORCE?


> , he tried to recover the data on the last inserted transaction by using
> the recovery_target_time.
> The issue is the database is present in the system catalog but the
> directory was still deleted.
> Here the technical information of the database
> version 11
> default  postgresql.conf except for this options
> wal_level = replica
> archive_mode = on
> archive_command = 'cp %p /tmp/wal_archive/%f '
> log_statement = 'all'
> log_min_messages = debug5
>
>
> The following method was used
>
>- create cluster
>
>
>- create database
>
>
>- create 1 table
>
>
>- create 1 index on 1 column
>
>
>- insert 1 rows
>
>
>- backup with pg_base_backup
>
>
>- insert 2 rows
>
> autocommit?

>
>
>
>- drop database
>
> force?


>
>- Change recovery behaviour in that case to prevent all xact
>operation to perform until COMMIT timestamp is checked against
>recovery_time bound (but it seems to be difficult as state
>
> https://www.postgresql.org/message-id/flat/20141125160629.GC21475%40msg.df7cb.de
>which also identifies the problem and tries to give some solutions.  Maybe
>another way, as a trivial guess (all apologises) is to buffer immediate
>xacts until we have the commit for each and apply the whole buffer xact
>once the timestamp known (and checked agains recovery_target_time value);
>
>
>- The other way to improve this is to update PostgreSQL
>documentation  by specifying that recovery_target_time cannot be used
>in this case. There should be multiple places where it can be stated.
>The best one (if only one) seems to be in
>
> https://git.postgresql.org/gitweb/?p=postgresql.git;a=blob;f=doc/src/sgml/config.sgml;h=
>
> 
>
>
If this only happens when a DB is dropped under load with force, I lean
toward just documenting it as a corner case.

-- 
 Craig Ringer   http://www.2ndQuadrant.com/
 2ndQuadrant - PostgreSQL Solutions for the Enterprise

PITR on DROP DATABASE, deleting of the database directory despite the recovery_target_time set before.

2019-11-18 Thread Nicolas Lutic 
Dear Hackers,

A customer reported a strange behaviour on a PITR restoration. 
After a drop database, he tried to recover the data on the last inserted
transaction by using the recovery_target_time.
The issue is the database is present in the system catalog but the
directory was still deleted.
Here the technical information of the database
version 11
default  postgresql.conf except for this options
    wal_level = replica
    archive_mode = on
    archive_command = 'cp %p /tmp/wal_archive/%f '
    log_statement = 'all'
    log_min_messages = debug5

  
The following method was used 

  * create cluster

  * create database

  * create 1 table 

  * create 1 index on 1 column

  * insert 1 rows

  * backup with pg_base_backup

  * insert 2 rows

  * drop database

  * stop instance

  * found the last inserted transaction timestamp(|'2019-11-13
11:49:08.413744+01'|) before drop database

  * replace $datadir by a pg_base_backup archive

  * edit recovery.conf

  * |restore_command = 'cp /tmp/wal_archive/%f "%p"'|

  * |recovery_target_time = '2019-11-13 11:49:08.413744+01'|

  * |recovery_target_inclusive = true|

  * |restart cluster|

|
|
|
|
|I tried to understand what's happening, when we analyse the
postgresql.log (log_min_message = debug5), we can see that  |
|
|
|the recovery stopped before transaction 574 (repository database) so at
transaction 573 being the last insert, but the database directory was
still deleted.|
|
|
|
|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  remove KnownAssignedXid 572|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000178 for
Transaction/COMMIT: 2019-11-13 11:49:08.248928+01|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 573
latestObservedXid 572|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/30001A0 for
Heap/INSERT: off 3|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 573
latestObservedXid 573|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/30001F8 for
Btree/INSERT_LEAF: off 3|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 573
latestObservedXid 573|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000238 for
Transaction/COMMIT: 2019-11-13 11:49:08.413744+01|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 573
latestObservedXid 573|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000238 for
Transaction/COMMIT: 2019-11-13 11:49:08.413744+01|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  remove KnownAssignedXid 573|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000238 for
Transaction/COMMIT: 2019-11-13 11:49:08.413744+01|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 574
latestObservedXid 573|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000260 for
Heap/DELETE: off 4 KEYS_UPDATED|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  prune KnownAssignedXids to 574|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/3000730 for
Standby/RUNNING_XACTS: nextXid 575 latestCompletedXid 573
oldestRunningXid 574; 1 xacts: 574|
|
|
|2019-11-13 11:55:12.732 CET [30666] DEBUG:  record known xact 574
latestObservedXid 574|
|
|
|2019-11-13 11:55:12.732 CET [30666] CONTEXT:  WAL redo at 0/30007D8 for
Database/DROP: dir 16384/1663|
|
|
|2019-11-13 11:55:12.738 CET [30666] LOG:  recovery stopping before
commit of transaction 574, time 2019-11-13 11:49:10.683426+01|
|
|
|2019-11-13 11:55:12.738 CET [30666] LOG:  recovery has paused|
|
|
|
|
|
|

By analysing the wal file with pg_waldump 

|rmgr: Heap    len (rec/tot): 54/   198, tx:    572, lsn:
0/0328, prev 0/02F8, desc: INSERT off 2, blkref #0: rel
1663/16384/16385 blk 0 FPW|
|
|
|rmgr: Btree   len (rec/tot): 53/   133, tx:    572, lsn:
0/03F0, prev 0/0328, desc: INSERT_LEAF off 2, blkref #0: rel
1663/16384/16388 blk 1 FPW|
|
|
|rmgr: Transaction len (rec/tot): 34/    34, tx:    572, lsn:
0/03000178, prev 0/03F0, desc: COMMIT 2019-11-13 11:49:08.248928 CET|
|
|
|rmgr: Heap    len (rec/tot): 87/    87, tx:    573, lsn:
0/030001A0, prev 0/03000178, desc: INSERT off 3, blkref #0: rel
1663/16384/16385 blk 0|
|
|
|rmgr: Btree   len (rec/tot): 64/    64, tx:    573, lsn:
0/030001F8, prev 0/030001A0, desc: INSERT_LEAF off 3, blkref #0: rel
1663/16384/16388 blk 1|
|
|
|rmgr: Transaction len (rec/tot): 34/    34, tx:    573, lsn:
0/03000238, prev 0/030001F8, desc: COMMIT 2019-11-13 11:49:08.413744 CET|
|
|
|rmgr: Heap    len (rec/tot): 59/  1227, tx:    574, lsn:
0/03000260, prev 0/03000238, desc: DELETE off 4 KEYS_UPDATED , blkref
#0: rel 1664/0/1262 blk 0 FPW|
|
|
|rmgr: Standby len (rec/tot): 54/    54, tx:  0, lsn:
0/03000730, prev 0/03000260, desc: RUNNING_XACTS nextXid 575
latestCompletedXid 573 oldestRunningXid 574; 1 xacts: 574|
|
|
|rmgr: XLOG    len (rec/tot):    106/