On 2012-11-22 09:13:30 +0900, Michael Paquier wrote: > On Thu, Nov 22, 2012 at 8:25 AM, Andres Freund <and...@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
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 -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
