Hi

To test my PITR-slave readonly-query patch, I continously do
insert into test ...
pg_switch_xlog()
sleep 1
on the master, and let the slave process the generated xlogs

The log output on the slave looks the following (unnecessary lines remove)

LOG: restored log file "00000001000000000000016E" from archive
LOG: REDO @ 0/16E00020; LSN 0/16E0004C: prev 0/16D00098; xid 1346: Transaction
- commit: 2007-07-12 15:43:00.686056+02
LOG: REDO @ 0/16E0004C; LSN 0/16E0008C: prev 0/16E00020; xid 0: XLOG -
checkpoint: redo 0/16E00020; tli 1; xid 0/1347;
oid 24576; multi 1; offset 0; online
LOG: REDO @ 0/16E0008C; LSN 0/16E00140: prev 0/16E0004C; xid 1350: Sequence -
log: rel 1663/1/16384
LOG: REDO @ 0/16E00140; LSN 0/16E00B88: prev 0/16E0008C; xid 1350; bkpb1: Heap
- insert: rel 1663/1/16386; tid 2/49
LOG: REDO @ 0/16E00B88; LSN 0/16F00000: prev 0/16E00140; xid 1350: XLOG - xlog
switch

LOG: restored log file "00000001000000000000016F" from archive
LOG: REDO @ 0/16F00020; LSN 0/16F0004C: prev 0/16E00B88; xid 1350: Transaction
- commit: 2007-07-12 15:43:02.159717+02
LOG: REDO @ 0/16F0004C; LSN 0/16F00098: prev 0/16F00020; xid 1352: Heap -
insert: rel 1663/1/16386; tid 2/50
LOG: REDO @ 0/16F00098; LSN 0/17000000: prev 0/16F0004C; xid 1352: XLOG - xlog
switch

LOG: restored log file "000000010000000000000170" from archive
LOG: REDO @ 0/17000020; LSN 0/1700004C: prev 0/16F00098; xid 1352: Transaction
- commit: 2007-07-12 15:43:02.26456+02
LOG: REDO @ 0/1700004C; LSN 0/17000098: prev 0/17000020; xid 1356: Heap -
insert: rel 1663/1/16386; tid 2/51
LOG: REDO @ 0/17000098; LSN 0/17100000: prev 0/1700004C; xid 1356: XLOG - xlog
switch

As you can see, the COMMIT records seems to end up being logged *after*
the xlog switch. I would have expected the order
"heap-insert, commit, switch, heap-insert, commit, switch, ...", not
"heap-insert, switch, commit, heap-insert, switch, commit, ...".

Is this the expected behaviour, or just an artefact of the implementation
of xlog switches?

greetings, Florian Pflug


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

On Thu, 2007-07-12 at 16:17 +0200, Florian G. Pflug wrote:

> To test my PITR-slave readonly-query patch, I continously do
> insert into test ...
> pg_switch_xlog()
> sleep 1
> on the master, and let the slave process the generated xlogs
>
> The log output on the slave looks the following (unnecessary lines remove)
>
> LOG: restored log file "00000001000000000000016E" from archive
> LOG: REDO @ 0/16E00020; LSN 0/16E0004C: prev 0/16D00098; xid 1346: Transaction
> - commit: 2007-07-12 15:43:00.686056+02
> LOG: REDO @ 0/16E0004C; LSN 0/16E0008C: prev 0/16E00020; xid 0: XLOG -
> checkpoint: redo 0/16E00020; tli 1; xid 0/1347;
> oid 24576; multi 1; offset 0; online
> LOG: REDO @ 0/16E0008C; LSN 0/16E00140: prev 0/16E0004C; xid 1350: Sequence -
> log: rel 1663/1/16384
> LOG: REDO @ 0/16E00140; LSN 0/16E00B88: prev 0/16E0008C; xid 1350; bkpb1: Heap
> - insert: rel 1663/1/16386; tid 2/49
> LOG: REDO @ 0/16E00B88; LSN 0/16F00000: prev 0/16E00140; xid 1350: XLOG - xlog
> switch
>
> LOG: restored log file "00000001000000000000016F" from archive
> LOG: REDO @ 0/16F00020; LSN 0/16F0004C: prev 0/16E00B88; xid 1350: Transaction
> - commit: 2007-07-12 15:43:02.159717+02
> LOG: REDO @ 0/16F0004C; LSN 0/16F00098: prev 0/16F00020; xid 1352: Heap -
> insert: rel 1663/1/16386; tid 2/50
> LOG: REDO @ 0/16F00098; LSN 0/17000000: prev 0/16F0004C; xid 1352: XLOG - xlog
> switch
>
> LOG: restored log file "000000010000000000000170" from archive
> LOG: REDO @ 0/17000020; LSN 0/1700004C: prev 0/16F00098; xid 1352: Transaction
> - commit: 2007-07-12 15:43:02.26456+02
> LOG: REDO @ 0/1700004C; LSN 0/17000098: prev 0/17000020; xid 1356: Heap -
> insert: rel 1663/1/16386; tid 2/51
> LOG: REDO @ 0/17000098; LSN 0/17100000: prev 0/1700004C; xid 1356: XLOG - xlog
> switch
>
> As you can see, the COMMIT records seems to end up being logged *after*
> the xlog switch. I would have expected the order
> "heap-insert, commit, switch, heap-insert, commit, switch, ...", not
> "heap-insert, switch, commit, heap-insert, switch, commit, ...".
>
> Is this the expected behaviour, or just an artefact of the implementation
> of xlog switches?

Can you show the exact SQL executed?

If you do INSERT ... ;select pg_switch_xlog() then the COMMIT will occur
after the switch. If you do:
INSERT ...;
select pg_switch_xlog();
then the COMMIT will occur before the switch.

If it were otherwise this would imply statements were executed prior to
the previous commit, which I hope and pray is never the case.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Simon Riggs wrote:
> On Thu, 2007-07-12 at 16:17 +0200, Florian G. Pflug wrote:
>
>> To test my PITR-slave readonly-query patch, I continously do
>> insert into test ...
>> pg_switch_xlog()
>> sleep 1
>> on the master, and let the slave process the generated xlogs
>>
>> The log output on the slave looks the following (unnecessary lines remove)
>>
>> <snipped log output>>
>>
>> As you can see, the COMMIT records seems to end up being logged *after*
>> the xlog switch. I would have expected the order
>> "heap-insert, commit, switch, heap-insert, commit, switch, ...", not
>> "heap-insert, switch, commit, heap-insert, switch, commit, ...".
>>
>> Is this the expected behaviour, or just an artefact of the implementation
>> of xlog switches?
>
> Can you show the exact SQL executed?
>
> If you do INSERT ... ;select pg_switch_xlog() then the COMMIT will occur
> after the switch. If you do:
> INSERT ...;
> select pg_switch_xlog();
> then the COMMIT will occur before the switch.

Ah, you caught me - I had forgotten that pgsql -c "<statement>"
executes the statement in one transaction.

I was just going to suggest that pg_start_backup, pg_stop_backup
and pg_switch_xlog emit a warning or even an error if called
from within a larger transaction, because that's quite certainly
not what the user wants. But since those are just plain functions,
I guess checking for that might not be trivial...

> If it were otherwise this would imply statements were executed prior to
> the previous commit, which I hope and pray is never the case.
You can relax, the bug was located in front of the screen :-)

greetings, Florian Pflug

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org