Hi all
It appears that logical decoding may be broken in 9.5 at the moment.
With HEAD at f6caf5a:
./configure --enable-debug --enable-cassert --prefix=/home/craig/pg/95
CFLAGS="-Og -ggdb -fno-omit-frame-pointer"
make clean install
make -C contrib/test_decoding clean install
PGPORT=5142 PATH=/home/craig/pg/95/bin:$PATH initdb -D ~/tmp/slottest95
PGPORT=5142 PATH=/home/craig/pg/95/bin:$PATH postgres -D ~/tmp/slottest95
and in another session:
psql -p 5142 -c 'SELECT pg_create_logical_replication_slot('test',
'test_decoding');'
in yet another:
PGPORT=5142 PATH=$HOME/pg/95/bin:$PATH pg_recvlogical -d postgres -S test
--start -f -
and back in the psql session do some work:
psql -p 5142 -c 'CREATE TABLE x AS SELECT xx FROM generate_series(1,10000)
xx;'
This works fine in REL9_4_STABLE at a44e54c.
Decoding over the SQL protocol works fine, and "make check" in
contrib/test_decoding passes without errors. This issue only arises in
decoding in a walsender.
I haven't bisected it back to a specific change yet, I just wanted to give
early heads-up. Also, our testing clearly needs to cover logical decoding
over walsenders.
See attachment for the bt.
--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
Core was generated by `postgres: wal sender pr'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007f4005aa28d7 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
55 return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt
#0 0x00007f4005aa28d7 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
#1 0x00007f4005aa453a in __GI_abort () at abort.c:89
#2 0x00000000008e3a00 in ExceptionalCondition (conditionName=0xae3528
"!(!((&RegisteredSnapshots)->ph_root == ((void *)0)))", errorType=0xae323a
"FailedAssertion", fileName=0xae3230 "snapmgr.c", lineNumber=677) at assert.c:54
#3 0x0000000000929082 in UnregisterSnapshotFromOwner (snapshot=0x7f3ff5232f58,
owner=0x1cd4698) at snapmgr.c:677
#4 0x000000000092901b in UnregisterSnapshot (snapshot=0x7f3ff5232f58) at
snapmgr.c:663
#5 0x00000000004c4b76 in systable_endscan (sysscan=0x1d1b210) at genam.c:504
#6 0x00000000008cf3d7 in RelationBuildTupleDesc (relation=0x7f40066ffe78) at
relcache.c:569
#7 0x00000000008d055c in RelationBuildDesc (targetRelId=3455, insertIt=1
'\001') at relcache.c:1036
#8 0x00000000008d221c in RelationIdGetRelation (relationId=3455) at
relcache.c:1778
#9 0x00000000004aad94 in relation_open (relationId=3455, lockmode=1) at
heapam.c:1047
#10 0x00000000004c4efb in index_open (relationId=3455, lockmode=1) at
indexam.c:167
#11 0x00000000004c45ff in systable_beginscan (heapRelation=0x7f40067584e0,
indexId=3455, indexOK=1 '\001', snapshot=0x0, nkeys=2, key=0x7ffcde1e7900) at
genam.c:334
#12 0x00000000008da269 in RelidByRelfilenode (reltablespace=0,
relfilenode=1247) at relfilenodemap.c:204
#13 0x0000000000750dd7 in ReorderBufferCommit (rb=0x1c62788, xid=1865,
commit_lsn=25360464, end_lsn=25360872, commit_time=481271227439738) at
reorderbuffer.c:1338
#14 0x000000000074bac7 in DecodeCommit (ctx=0x1c60778, buf=0x7ffcde1e7c80,
parsed=0x7ffcde1e7bc0, xid=1865) at decode.c:494
#15 0x000000000074b43a in DecodeXactOp (ctx=0x1c60778, buf=0x7ffcde1e7c80) at
decode.c:211
#16 0x000000000074b1a7 in LogicalDecodingProcessRecord (ctx=0x1c60778,
record=0x1c60a38) at decode.c:100
#17 0x000000000075ad78 in XLogSendLogical () at walsender.c:2425
#18 0x000000000075a078 in WalSndLoop (send_data=0x75acd7 <XLogSendLogical>) at
walsender.c:1834
#19 0x00000000007590f0 in StartLogicalReplication (cmd=0x1c59eb8) at
walsender.c:997
#20 0x0000000000759713 in exec_replication_command (cmd_string=0x1cb3108
"START_REPLICATION SLOT \"test\" LOGICAL 0/0") at walsender.c:1326
#21 0x00000000007aea57 in PostgresMain (argc=1, argv=0x1c40350,
dbname=0x1c40240 "postgres", username=0x1c40220 "craig") at postgres.c:4021
#22 0x00000000007354e3 in BackendRun (port=0x1c64900) at postmaster.c:4141
#23 0x0000000000734c4b in BackendStartup (port=0x1c64900) at postmaster.c:3826
#24 0x000000000073150a in ServerLoop () at postmaster.c:1594
#25 0x0000000000730b95 in PostmasterMain (argc=3, argv=0x1c3f410) at
postmaster.c:1241
#26 0x0000000000690e64 in main (argc=3, argv=0x1c3f410) at main.c:221
(gdb) bt full
#0 0x00007f4005aa28d7 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
resultvar = 0
pid = 22806
selftid = 22806
#1 0x00007f4005aa453a in __GI_abort () at abort.c:89
save_stage = 2
act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0},
sa_mask = {__val = {140724035024416, 4590256, 139912960889648, 11420318053453,
72057594037927936, 1, 30519912, 140724035024352, 9497950, 72057594068447848,
29999520, 0, 139912950442304, 0, 139912953362992, 139912953358080}}, sa_flags =
98728496, sa_restorer = 0x7f4006734700}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00000000008e3a00 in ExceptionalCondition (conditionName=0xae3528
"!(!((&RegisteredSnapshots)->ph_root == ((void *)0)))", errorType=0xae323a
"FailedAssertion", fileName=0xae3230 "snapmgr.c", lineNumber=677) at assert.c:54
No locals.
#3 0x0000000000929082 in UnregisterSnapshotFromOwner (snapshot=0x7f3ff5232f58,
owner=0x1cd4698) at snapmgr.c:677
No locals.
#4 0x000000000092901b in UnregisterSnapshot (snapshot=0x7f3ff5232f58) at
snapmgr.c:663
No locals.
#5 0x00000000004c4b76 in systable_endscan (sysscan=0x1d1b210) at genam.c:504
No locals.
#6 0x00000000008cf3d7 in RelationBuildTupleDesc (relation=0x7f40066ffe78) at
relcache.c:569
pg_attribute_tuple = 0x1d1b2b8
pg_attribute_desc = 0x7f40066f4a00
pg_attribute_scan = 0x1d1b210
skey = {{sk_flags = 0, sk_attno = 1, sk_strategy = 3, sk_subtype = 0,
sk_collation = 100, sk_func = {fn_addr = 0x84ee95 <oideq>, fn_oid = 184,
fn_nargs = 2, fn_strict = 1 '\001', fn_retset = 0 '\000', fn_stats = 2 '\002',
fn_extra = 0x0, fn_mcxt = 0x1d191a8, fn_expr = 0x0}, sk_argument = 3455},
{sk_flags = 0, sk_attno = 2, sk_strategy = 5, sk_subtype = 0, sk_collation =
100, sk_func = {fn_addr = 0x81bc4c <int2gt>, fn_oid = 146, fn_nargs = 2,
fn_strict = 1 '\001', fn_retset = 0 '\000', fn_stats = 2 '\002', fn_extra =
0x0, fn_mcxt = 0x1d191a8, fn_expr = 0x0}, sk_argument = 0}}
need = 0
constr = 0x7f40067003c0
attrdef = 0x0
ndef = 0
__func__ = "RelationBuildTupleDesc"
#7 0x00000000008d055c in RelationBuildDesc (targetRelId=3455, insertIt=1
'\001') at relcache.c:1036
relation = 0x7f40066ffe78
relid = 3455
pg_class_tuple = 0x1d1b430
relp = 0x1d1b468
__func__ = "RelationBuildDesc"
#8 0x00000000008d221c in RelationIdGetRelation (relationId=3455) at
relcache.c:1778
rd = 0x0
#9 0x00000000004aad94 in relation_open (relationId=3455, lockmode=1) at
heapam.c:1047
r = 0x69909e <list_member_oid+84>
__func__ = "relation_open"
#10 0x00000000004c4efb in index_open (relationId=3455, lockmode=1) at
indexam.c:167
r = 0x531752 <ReindexIsProcessingIndex+42>
__func__ = "index_open"
#11 0x00000000004c45ff in systable_beginscan (heapRelation=0x7f40067584e0,
indexId=3455, indexOK=1 '\001', snapshot=0x0, nkeys=2, key=0x7ffcde1e7900) at
genam.c:334
sysscan = 0x7f40067584e0
irel = 0x0
__func__ = "systable_beginscan"
#12 0x00000000008da269 in RelidByRelfilenode (reltablespace=0,
relfilenode=1247) at relfilenodemap.c:204
key = {reltablespace = 0, relfilenode = 1247}
entry = 0x0
found = 0 '\000'
scandesc = 0x750168 <ReorderBufferIterTXNNext+407>
relation = 0x7f40067584e0
ntp = 0x7ffcde1e7a00
skey = {{sk_flags = 0, sk_attno = 8, sk_strategy = 3, sk_subtype = 0,
sk_collation = 0, sk_func = {fn_addr = 0x84ee95 <oideq>, fn_oid = 184, fn_nargs
= 2, fn_strict = 1 '\001', fn_retset = 0 '\000', fn_stats = 2 '\002', fn_extra
= 0x0, fn_mcxt = 0x1c41208, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0,
sk_attno = 7, sk_strategy = 3, sk_subtype = 0, sk_collation = 0, sk_func =
{fn_addr = 0x84ee95 <oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = 1 '\001',
fn_retset = 0 '\000', fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x1c41208,
fn_expr = 0x0}, sk_argument = 1247}}
relid = 0
__func__ = "RelidByRelfilenode"
#13 0x0000000000750dd7 in ReorderBufferCommit (rb=0x1c62788, xid=1865,
commit_lsn=25360464, end_lsn=25360872, commit_time=481271227439738) at
reorderbuffer.c:1338
relation = 0x0
reloid = 0
change = 0x7f3ff5891fb0
save_exception_stack = 0x7ffcde1e7e10
save_context_stack = 0x0
local_sigjmp_buf = {{__jmpbuf = {0, 1099707688608628154, 4590256,
140724035027776, 0, 0, 1099707688648474042, -1100199346182783558},
__mask_was_saved = 0, __saved_mask = {__val = {29763464, 140724035025648,
29763744, 140724035025632, 7673316, 30381528, 25360464, 8010144388608,
29763464, 0, 139912679079968, 140724035025696, 7690349, 25360464, 30380376,
29763472}}}}
txn = 0x1c628a0
snapshot_now = 0x7f3ff5232f58
command_id = 1
using_subtxn = 0 '\000'
iterstate = 0x7f3ff4a31f58
__func__ = "ReorderBufferCommit"
#14 0x000000000074bac7 in DecodeCommit (ctx=0x1c60778, buf=0x7ffcde1e7c80,
parsed=0x7ffcde1e7bc0, xid=1865) at decode.c:494
i = 0
#15 0x000000000074b43a in DecodeXactOp (ctx=0x1c60778, buf=0x7ffcde1e7c80) at
decode.c:211
xlrec = 0x1c5ad20
parsed = {xact_time = 481271227439738, xinfo = 9, dbId = 13389, tsId =
1663, nsubxacts = 0, subxacts = 0x0, nrels = 0, xnodes = 0x0, nmsgs = 22, msgs
= 0x1c5ad38, twophase_xid = 0}
xid = 1865
builder = 0x1cf9158
reorder = 0x1c62788
r = 0x1c60a38
info = 0 '\000'
__func__ = "DecodeXactOp"
#16 0x000000000074b1a7 in LogicalDecodingProcessRecord (ctx=0x1c60778,
record=0x1c60a38) at decode.c:100
buf = {origptr = 25360464, endptr = 25360872, record = 0x1c60a38}
__func__ = "LogicalDecodingProcessRecord"
#17 0x000000000075ad78 in XLogSendLogical () at walsender.c:2425
record = 0x1ce6938
errm = 0x0
__func__ = "XLogSendLogical"
#18 0x000000000075a078 in WalSndLoop (send_data=0x75acd7 <XLogSendLogical>) at
walsender.c:1834
now = 481271227525975
__func__ = "WalSndLoop"
#19 0x00000000007590f0 in StartLogicalReplication (cmd=0x1c59eb8) at
walsender.c:997
buf = {data = 0x0, len = 3, maxlen = 1024, cursor = 87}
__func__ = "StartLogicalReplication"
#20 0x0000000000759713 in exec_replication_command (cmd_string=0x1cb3108
"START_REPLICATION SLOT \"test\" LOGICAL 0/0") at walsender.c:1326
cmd = 0x1c59eb8
parse_rc = 0
cmd_node = 0x1c59eb8
cmd_context = 0x1c9bd40
old_context = 0x1c3f6d0
__func__ = "exec_replication_command"
#21 0x00000000007aea57 in PostgresMain (argc=1, argv=0x1c40350,
dbname=0x1c40240 "postgres", username=0x1c40220 "craig") at postgres.c:4021
query_string = 0x1cb3108 "START_REPLICATION SLOT \"test\" LOGICAL 0/0"
firstchar = 81
input_message = {data = 0x1cb3108 "START_REPLICATION SLOT \"test\"
LOGICAL 0/0", len = 42, maxlen = 1024, cursor = 42}
local_sigjmp_buf = {{__jmpbuf = {0, 1099707688476507578, 4590256,
140724035027776, 0, 0, 1099707688556199354, -1100199261698097734},
__mask_was_saved = 1, __saved_mask = {__val = {0, 29733480, 0, 29619920, 0, 0,
0, 0, 0, 140724035026656, 9504764, 0, 1024, 140724035026736, 29733504, 0}}}}
send_ready_for_query = 0 '\000'
__func__ = "PostgresMain"
#22 0x00000000007354e3 in BackendRun (port=0x1c64900) at postmaster.c:4141
av = 0x1c40350
maxac = 2
ac = 1
secs = 481271186
usecs = 140369
i = 1
__func__ = "BackendRun"
#23 0x0000000000734c4b in BackendStartup (port=0x1c64900) at postmaster.c:3826
bn = 0x1c5d9a0
pid = 0
__func__ = "BackendStartup"
#24 0x000000000073150a in ServerLoop () at postmaster.c:1594
port = 0x1c64900
i = 1
rmask = {fds_bits = {16, 0 <repeats 15 times>}}
selres = 1
readmask = {fds_bits = {24, 0 <repeats 15 times>}}
nSockets = 5
now = 1427955985
last_touch_time = 1427955965
__func__ = "ServerLoop"
#25 0x0000000000730b95 in PostmasterMain (argc=3, argv=0x1c3f410) at
postmaster.c:1241
opt = -1
status = 0
userDoption = 0x1c5bee0 "slottest95"
listen_addr_saved = 1 '\001'
i = 64
output_config_variable = 0x0
__func__ = "PostmasterMain"
#26 0x0000000000690e64 in main (argc=3, argv=0x1c3f410) at main.c:221
do_check_root = 1 '\001'
--
Sent via pgsql-hackers mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
