Re: logical changeset generation v3 - Mailing list pgsql-hackers

From Michael Paquier
Subject Re: logical changeset generation v3
Date
Msg-id CAB7nPqRD20A288_xmLgbA_dFOZ_3hGufaebDsFebSzxaxhSQkQ@mail.gmail.com
Whole thread Raw
In response to Re: logical changeset generation v3  (Andres Freund <andres@2ndquadrant.com>)
Responses Re: logical changeset generation v3  (Andres Freund <andres@2ndquadrant.com>)
List pgsql-hackers


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

pgsql-hackers by date:

Previous
From: Gavin Flower
Date:
Subject: Re: auto_explain WAS: RFC: Timing Events
Next
From: Andres Freund
Date:
Subject: Re: logical changeset generation v3