Re: logical changeset generation v3

On 2012-11-22 09:13:30 +0900, Michael Paquier wrote:
> On Thu, Nov 22, 2012 at 8:25 AM, Andres Freund <andres(at)2ndquadrant(dot)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

Ok, so youve not yet reached a consistent point.

Which means this shouldn't yet be written out:

> 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

that could already be good enough of a hint, let me check tomorrow.

> I still have the core file and its binary at hand if you want, so can send
> them at will.

If those aren't too big, its worth a try...

Greetings,

Andres

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services