Re: logical changeset generation v3

On Thu, Nov 22, 2012 at 8:25 AM, Andres Freund <andres@2ndquadrant.com>wrote:

> I really don't understand whats going on here then. Youve said you made
> sure that there is a catalog snapshot. Which means you would need
> something like:
> WARNING:  connecting to postgres
> WARNING:  Initiating logical rep
> LOG:  computed new xmin: 16566894
> LOG:  start reading from 3/E62457C0, scrolled back to 3/E6244000
> LOG:  found initial snapshot (via running xacts). Done: 1
> WARNING:  reached consistent point, stopping!
> WARNING:  Starting logical replication
> LOG:  start reading from 3/E62457C0, scrolled back to 3/E6244000
> LOG:  found initial snapshot (via running xacts). Done: 1
>
> in the log *and* it means that snapbuild->state has to be
> CONSISTENT. But the backtrace youve posted:
>
> #3  0x000000000070c409 in SnapBuildTxnIsRunning
> (snapstate=0x19e4f10,xid=0) at snapbuild.c:877
> #4  0x000000000070b8e4 in SnapBuildProcessChange
> (reorder=0x19e4e80,snapstate=0x19e4f10, xid=0, buf=0x1a0a368,
> relfilenode=0x1a0a450) at snapbuild.c:388
> #5  0x000000000070c088 in SnapBuildDecodeCallback
> (reorder=0x19e4e80,snapstate=0x19e4f10, buf=0x1a0a368) at snapbuild.c:732
>
> shows pretty clearly that snapstate *can't* be consistent because line
> 387ff is:
>       else if (snapstate->state < SNAPBUILD_CONSISTENT &&
>                SnapBuildTxnIsRunning(snapstate, xid))
>                 ;
> so #3 #4 can't happen at those line numbers with state == CONSISTENT.
>
Still this *impossible* thing happens.
Here are some more information on the logs I get on server side:

Yes I have the logical replication correctly initialized:
[629 0] LOG:  database system was shut down at 2012-11-22 09:02:42 JST
[628 0] LOG:  database system is ready to accept connections
[633 0] LOG:  autovacuum launcher started
[648 0] WARNING:  connecting to postgres
[648 0] WARNING:  Initiating logical rep
[648 0] LOG:  computed new xmin: 684
[648 0] LOG:  start reading from 0/178C1B8, scrolled back to 0/178C000

And I am also getting logs of this type with pg_receivellog:
BEGIN 698
table "pgbench_accounts": UPDATE: aid[int4]:759559 bid[int4]:8
abalance[int4]:-3641 filler[bpchar]:
table "pgbench_tellers": UPDATE: tid[int4]:93 bid[int4]:10
tbalance[int4]:-3641 filler[bpchar]:(null)
table "pgbench_branches": UPDATE: bid[int4]:10 bbalance[int4]:-3641
filler[bpchar]:(null)
table "pgbench_history": INSERT: tid[int4]:93 bid[int4]:10 aid[int4]:759559
delta[int4]:-3641 mtime[timestamp]:2012-11-22 09:05:34.535651
filler[bpchar]:(null)
COMMIT 698

Until the assertion failure:
TRAP: FailedAssertion("!(((xid) >= ((TransactionId) 3)) &&
((snapstate->xmin_running) >= ((TransactionId) 3)))", File: "snapbuild.c",
Line: 878)
I still have the core file and its binary at hand if you want, so can send
them at will.
I have not been able to read your code yet, but there should be something
you are missing.

Thanks,
-- 
Michael Paquier
http://michael.otacoo.com