Re: logical decoding - reading a user catalog table

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(at)entry=0xbfa8a0 <CurrentSnapshotData>,
>>> sourcexid=sourcexid(at)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(at)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(at)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(at)entry=0x918e88
"!(TransactionIdFollows(snapshot->xmin, PredXact->SxactGlobalXmin))",
errorType=errorType(at)entry=0x7da390 "FailedAssertion",
fileName=fileName(at)entry=0x9182c3 "predicate.c",
lineNumber=lineNumber(at)entry=1738) at assert.c:54
#3 0x00000000006b4978 in GetSerializableTransactionSnapshotInt (
snapshot=snapshot(at)entry=0xbfa8a0 <CurrentSnapshotData>,
sourcexid=sourcexid(at)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(at)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(at)entry=3,
argv=argv(at)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.