Re: logical decoding - reading a user catalog table - Mailing list pgsql-hackers

On 11/17/2014 11:34 AM, Andres Freund wrote:
> Hi,
>
> Kevin: CCed you, because it doesn't really look like a logical decoding
> related issue.
>
> On 2014-11-17 11:25:40 -0500, Steve Singer wrote:
>> On 11/17/2014 10:37 AM, Andres Freund wrote:
>>> On 2014-11-13 22:23:02 -0500, Steve Singer wrote:
>>>
>>>
>>> Also since updating (to 2c267e47afa4f9a7c) I've seen a assertion failure in
>>> a normal client connection, not the walsender
>>>
>>> #3  0x00000000006b4978 in GetSerializableTransactionSnapshotInt (
>>>      snapshot=snapshot@entry=0xbfa8a0 <CurrentSnapshotData>,
>>>      sourcexid=sourcexid@entry=0) at predicate.c:1738
>>> #4  0x00000000006b66c3 in GetSafeSnapshot (origSnapshot=<optimized out>)
>>>      at predicate.c:1517
>>> #5  GetSerializableTransactionSnapshot (
>>>      snapshot=0xbfa8a0 <CurrentSnapshotData>) at predicate.c:1598
>>> #6  0x00000000007d16dd in GetTransactionSnapshot () at snapmgr.c:200
>>> #7  0x00000000006c0e35 in exec_simple_query (
>>>      query_string=0x1fd01b8 "select ev_origin, ev_seqno, ev_timestamp,
>>> ev_snapshot, \"pg_catalog\".txid_snapshot_xmin(ev_snapshot),
>>> \"pg_catalog\".txid_snapshot_xmax(ev_snapshot),
>>> coalesce(ev_provider_xid,\""...)
>>>      at postgres.c:959
>>> #8  PostgresMain (argc=<optimized out>, argv=argv@entry=0x1f5ab50,
>>>
>>>
>>> I have no idea if this has anything to do with your recent changes or some
>>> other change. I haven't so far been able to replicate that since the first
>>> time I saw it.
>>> That crash is decidedly odd. Any chance you still have the full
>>> backtrace around?
>> Yes I still have the core file
> Cool, could you show the full thing? Or did you just snip it because
> it's just the Assert/ExceptionalCondition thing?

I just snipped the exception stuff. Here is the full thing

(gdb) backtrace
#0  0x00007f6fb22e8295 in __GI_raise (sig=sig@entry=6)    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f6fb22eb438 in __GI_abort () at abort.c:90
#2  0x00000000007a08e7 in ExceptionalCondition (    conditionName=conditionName@entry=0x918e88 
"!(TransactionIdFollows(snapshot->xmin, PredXact->SxactGlobalXmin))",    errorType=errorType@entry=0x7da390
"FailedAssertion",   fileName=fileName@entry=0x9182c3 "predicate.c",    lineNumber=lineNumber@entry=1738) at
assert.c:54
#3  0x00000000006b4978 in GetSerializableTransactionSnapshotInt (    snapshot=snapshot@entry=0xbfa8a0
<CurrentSnapshotData>,   sourcexid=sourcexid@entry=0) at predicate.c:1738
 
#4  0x00000000006b66c3 in GetSafeSnapshot (origSnapshot=<optimized out>)    at predicate.c:1517
#5  GetSerializableTransactionSnapshot (    snapshot=0xbfa8a0 <CurrentSnapshotData>) at predicate.c:1598
#6  0x00000000007d16dd in GetTransactionSnapshot () at snapmgr.c:200
#7  0x00000000006c0e35 in exec_simple_query (    query_string=0x1fd01b8 "select ev_origin, ev_seqno, 
ev_timestamp,        ev_snapshot, 
\"pg_catalog\".txid_snapshot_xmin(ev_snapshot), 
\"pg_catalog\".txid_snapshot_xmax(ev_snapshot), 
coalesce(ev_provider_xid,\""...)    at postgres.c:959
#8  PostgresMain (argc=<optimized out>, argv=argv@entry=0x1f5ab50,
---Type <return> to continue, or q <return> to quit---    dbname=0x1f5ab30 "test2", username=<optimized out>) at
postgres.c:4016
#9  0x000000000046a08e in BackendRun (port=0x1f83010) at postmaster.c:4123
#10 BackendStartup (port=0x1f83010) at postmaster.c:3797
#11 ServerLoop () at postmaster.c:1576
#12 0x0000000000665eae in PostmasterMain (argc=argc@entry=3,    argv=argv@entry=0x1f59d00) at postmaster.c:1223
#13 0x000000000046ab58 in main (argc=3, argv=0x1f59d00) at main.c:227


>
> Could you print *snapshot in frame #3?

(gdb) p *snapshot
$1 = {satisfies = 0x7d0330 <HeapTupleSatisfiesMVCC>, xmin = 412635,  xmax = 412637, xip = 0x1f86e40, xcnt = 1, subxcnt
=0, subxip = 
 
0x1fd2190,  suboverflowed = 0 '\000', takenDuringRecovery = 0 '\000', copied = 0 
'\000',  curcid = 0, active_count = 0, regd_count = 0}
(gdb)


>>> This is in the SSI code... I'm not immediately seeing how this could be
>>> related to logical decoding. It can't even be a imported snapshot,
>>> because the exported snapshot is marked repeatable read.
>>>
>>> Are you actually using serializable transactions? If so, how and why?
>> Yes, the test client that performs the 'simulated workload' does some
>> serializable transactions.  It connects as a normal client via JDBC and does
>> a prepareStatement("SET TRANSACTION ISOLATION LEVEL SERIALIZABLE") and then
>> does some DML. Why? because it seemed like a good thing to include in the
>> test suite.
> Yes, it's a good reason as the above backtrace proves ;). I'm just
> trying to understand uner which circumstances it happens.
>
> The above backtrace looks like it can only be triggered if you do a
> BEGIN TRANSACTION SERIALIZABLE DEFERRABLE READ ONLY; Is that something
> you do?

The slony remote listener connection does this when it selects from 
sl_event.  We switched to this shortly after 9.1 came out.