Bus error in pg_logical_slot_get_changes (9.4.7, sparc)

From: Christoph Berg <christoph(dot)berg(at)credativ(dot)de>
To: PostgreSQL Bugs <pgsql-bugs(at)postgresql(dot)org>, Andres Freund <andres(at)anarazel(dot)de>
Subject: Bus error in pg_logical_slot_get_changes (9.4.7, sparc)
Date: 2016-04-13 09:41:17
Message-ID: 20160413094117.GC21485@msg.credativ.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

Hi,

I've just uploaded 9.4.7 for Debian's wheezy-backports suite.
Unfortunately it's now crashing twice in the contrib/test_decoding
regression tests on sparc. I could reproduce the error on the porter
box:

LOG: server process (PID 22534) was terminated by signal 10: Bus error
DETAIL: Failed process was running: SELECT data
FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1')
WHERE data ~ 'UPDATE';

LOG: server process (PID 22558) was terminated by signal 10: Bus error
DETAIL: Failed process was running: SELECT substr(data, 1, 200) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');

Reading symbols from /home/myon/postgresql-9.4-9.4.7/build/src/backend/postgres...done.
[New LWP 22558]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/sparc-linux-gnu/libthread_db.so.1".
Core was generated by `postgres: myon regression [local] SELECT '.
Program terminated with signal 10, Bus error.
#0 ReorderBufferRestoreChange (data=0x5de0f7 "", txn=0x622660, rb=0x6225d8)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/reorderbuffer.c:2327
2327 Size tuplelen = ((HeapTuple) data)->t_len;
(gdb) l
2322 data += tuplelen;
2323 }
2324
2325 if (change->data.tp.newtuple)
2326 {
2327 Size tuplelen = ((HeapTuple) data)->t_len;
2328
2329 change->data.tp.newtuple =
2330 ReorderBufferGetTupleBuf(rb, tuplelen - offsetof(HeapTupleHeaderData, t_bits));
2331
(gdb) bt full
#0 ReorderBufferRestoreChange (data=0x5de0f7 "", txn=0x622660, rb=0x6225d8)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/reorderbuffer.c:2327
tuplelen = <optimized out>
ondisk = <optimized out>
change = 0x11ea888
#1 ReorderBufferRestoreChanges (rb=0x6225d8, txn=0x622660, fd=0x79860910, segno=0x79860918)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/reorderbuffer.c:2269
ondisk = <optimized out>
restored = <optimized out>
last_segno = 1
cleanup_iter = {cur = <optimized out>, next = <optimized out>, end = 0x6226b0}
__func__ = "ReorderBufferRestoreChanges"
#2 0x00261790 in ReorderBufferIterTXNNext (state=0x798608f0, rb=0x6225d8)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/reorderbuffer.c:981
change = 0x7985f858
entry = 0x79860900
off = 0
#3 ReorderBufferCommit (rb=0x6225d8, xid=<optimized out>, commit_lsn=27808752, end_lsn=<optimized out>,
commit_time=513854161898478)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/reorderbuffer.c:1355
change = 0x7985f858
save_exception_stack = 0xffbc6538
save_context_stack = 0x0
local_sigjmp_buf = {{__jmpbuf = {-1279391982, -1279392038, 1277457654}, __mask_was_saved = 0,
__saved_mask = {__val = {0, 4290536232, 2500668, 1296, 6195616, 4290536240, 3926116, 4290536336, 1,
5595136, 5598208, 0, 0, 1, 26206208, 0, 0, 0, 0, 0, 0, 1296, 1295, 1, 15213480, 0, 1, 1296, 0, 0,
1296, 0}}}}
txn = 0x622660
snapshot_now = 0x5ddfa0
command_id = 1
iterstate = 0x798608f0
__func__ = "ReorderBufferCommit"
#4 0x0025c9bc in DecodeXactOp (buf=0xffbc6460, ctx=0x6145c0)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/decode.c:226
xlrec = <optimized out>
subxacts = <optimized out>
invals = <optimized out>
builder = <optimized out>
reorder = <optimized out>
info = <optimized out>
r = 0xffbc6470
#5 LogicalDecodingProcessRecord (ctx=0x6145c0, record=0x6179a0)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/decode.c:111
buf = {origptr = 27808752, endptr = 27809568, record = {xl_tot_len = 812, xl_xid = 1296, xl_len = 780,
xl_info = 0 '\000', xl_rmid = 1 '\001', xl_prev = 27808688, xl_crc = 1979174325},
record_data = 0x6179c0 ""}
__func__ = "LogicalDecodingProcessRecord"
#6 0x0025e69c in pg_logical_slot_get_changes_guts (fcinfo=0xffbc6694, confirm=<optimized out>,
binary=<optimized out>)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/replication/logical/logicalfuncs.c:440
record = <optimized out>
errm = 0x0
save_exception_stack = 0xffbc6b28
save_context_stack = 0x0
local_sigjmp_buf = {{__jmpbuf = {-1279393398, -1279393542, 1277657190}, __mask_was_saved = 0,
__saved_mask = {__val = {4290536824, 1264536, 1314, 5446656, 5447680, 0, 5447680, 0, 0, 0, 0, 1, 25, 0,
0, 0, 0, 1, 3782, 1, 4290537052, 1, 0, 4294967295, 1, 0, 4290536944, 2309772, 0, 0, 0, 4290537540}}}}
name = 0x0
upto_lsn = 0
upto_nchanges = 0
rsinfo = <optimized out>
per_query_ctx = <optimized out>
oldcontext = 0x5e8320
end_of_wal = 28052656
startptr = 0
ctx = 0x6145c0
old_resowner = 0x5e7df8
arr = <optimized out>
ndim = <optimized out>
options = 0x60dfd0
p = 0x60e598
__func__ = "pg_logical_slot_get_changes_guts"
#7 0x001ab830 in ExecMakeTableFunctionResult (funcexpr=0x60ccd8, econtext=0x60c6a0, argContext=<optimized out>,
expectedDesc=0x60d548, randomAccess=0 '\000')
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execQual.c:2196
result = 4290537288
tupstore = 0x0
tupdesc = 0x0
funcrettype = 2249
returnsTuple = <optimized out>
returnsSet = 1 '\001'
fcinfo = {flinfo = 0x60cce8, context = 0x0, resultinfo = 0xffbc6640, fncollation = 100, isnull = 0 '\000',
nargs = 4, arg = {5960656, 0, 0, 5959720, 2, 5734184, 31808, 15213480, 4290537200, 2212260, 5732864,
5595136, 0, 0, 1072693248, 0, 5959856, 5598208, 0, 5959856, 5961824, 2, 700, 1884286976, 5732864,
5732032, 5733440, 0, 4294836227, 0, 0, 15213480, 184, 131328, 33554432, 0, 5638448, 0, 25, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 15213480, 0, 0, 0, 0, 0, 0, 0, 0, 4294836227, 0, 0, 3314144, 184, 131328, 33554432, 0,
5638448, 0, 25, 0, 0, 0, 0, 15213480, 0 <repeats 26 times>},
argnull = "\000\001\001\000\000\000\000\000\000\000\000\000\000\062\221\340\000\000\000\270\000\002\001\000\002\000\000\000\000\000\000\000\000V\t0\000\000\000\000\000\000\000\031", '\000' <repeats 55 times>}
fcusage = {fs = 0x0, save_f_total_time = {tv_sec = 5891064, tv_usec = 1}, save_total = {tv_sec = 4039680,
tv_usec = 1}, f_start = {tv_sec = 0, tv_usec = 1072693248}}
rsinfo = {type = T_ReturnSetInfo, econtext = 0x60c6a0, expectedDesc = 0x60d548, allowedModes = 11,
returnMode = SFRM_Materialize, isDone = ExprSingleResult, setResult = 0x60e068, setDesc = 0x60e768}
tmptup = {t_len = 0, t_self = {ip_blkid = {bi_hi = 61, bi_lo = 47104}, ip_posid = 89}, t_tableOid = 0,
t_data = 0x79820c1c}
callerContext = 0x5e8298
direct_function_call = <optimized out>
first_time = 1 '\001'
__func__ = "ExecMakeTableFunctionResult"
#8 0x001bdf90 in FunctionNext (node=0x60c618)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/nodeFunctionscan.c:94
tstore = 0x0
estate = <optimized out>
direction = ForwardScanDirection
scanslot = 0x60c780
alldone = <optimized out>
oldpos = <optimized out>
funcno = <optimized out>
att = <optimized out>
#9 0x001ad7f0 in ExecScanFetch (recheckMtd=0x1bdca0 <FunctionRecheck>, accessMtd=0x1bdcc0 <FunctionNext>,
node=0x60c618) at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execScan.c:82
estate = <optimized out>
#10 ExecScan (node=0x60c618, accessMtd=0x1bdcc0 <FunctionNext>, recheckMtd=0x1bdca0 <FunctionRecheck>)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execScan.c:167
slot = 0x60c618
econtext = 0x60c6a0
qual = 0x0
projInfo = 0x60daa8
isDone = 5732760
resultSlot = <optimized out>
#11 0x001a6790 in ExecProcNode (node=0x60c618)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execProcnode.c:426
result = <optimized out>
__func__ = "ExecProcNode"
#12 0x001a35dc in ExecutePlan (dest=0x578840, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>,
operation=CMD_SELECT, planstate=0x60c618, estate=0x60c590)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execMain.c:1490
slot = <optimized out>
current_tuple_count = 0
#13 standard_ExecutorRun (queryDesc=0x5face0, direction=<optimized out>, count=0)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/executor/execMain.c:319
estate = 0x60c590
operation = CMD_SELECT
dest = 0x578840
sendTuples = <optimized out>
oldcontext = 0x5e8ad8
#14 0x002ab0d4 in PortalRunSelect (portal=0x5ebb60, forward=1 '\001', count=0, dest=0x578840)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/tcop/pquery.c:942
queryDesc = 0x5face0
direction = ForwardScanDirection
nprocessed = <optimized out>
__func__ = "PortalRunSelect"
#15 0x002ac45c in PortalRun (portal=0x5ebb60, count=2147483647, isTopLevel=1 '\001', dest=0x578840,
altdest=0x578840, completionTag=0xffbc6d20 "")
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/tcop/pquery.c:786
save_exception_stack = 0xffbc6c64
save_context_stack = 0x0
local_sigjmp_buf = {{__jmpbuf = {-1279389822, -1279390062, 1277732494}, __mask_was_saved = 0,
__saved_mask = {__val = {4290538424, 5639264, 16777218, 0, 2, 1314, 0, 1276, 5595424, 5598208, 5444608,
5595136, 5381120, 161, 5640592, 0, 5732840, 0, 0, 0, 0, 5732824, 4290538424, 2786944, 102, 6192632,
2, 1, 0, 1, 1024, 0}}}}
result = <optimized out>
nprocessed = <optimized out>
saveTopTransactionResourceOwner = 0x560c60
saveTopTransactionContext = 0x560bd8
saveActivePortal = 0x0
saveResourceOwner = 0x560c60
savePortalContext = 0x0
saveMemoryContext = 0x560bd8
__func__ = "PortalRun"
#16 0x002a8558 in exec_simple_query (
query_string=0x5ae0d0 "SELECT substr(data, 1, 200) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');")
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/tcop/postgres.c:1072
parsetree = 0x5aef78
portal = 0x5ebb60
snapshot_set = <optimized out>
commandTag = <optimized out>
completionTag = "\000OPY 203\000LE\000\000CE", '\000' <repeats 32 times>, "\024\000\000\000\024\377\377\377\377\000S\024\204\000S\023\204"
plantree_list = 0x578828
receiver = 0x578840
format = 0
dest = DestRemote
parsetree_list = 0x5af010
save_log_statement_stats = 0 '\000'
was_logged = 0 '\000'
msec_str = "\000\274m\210\000\005\365D\000\000\000\000\000W\335\f0\n\000\034\000\000\000 \000\000\000\000\000\000\000\002"
parsetree_item = 0x5af000
isTopLevel = <optimized out>
#17 PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=0x55fb00 "regression", username=<optimized out>)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/tcop/postgres.c:4079
query_string = 0x5ae0d0 "SELECT substr(data, 1, 200) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');"
firstchar = 5959544
input_message = {
data = 0x5ae0d0 "SELECT substr(data, 1, 200) FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');", len = 139, maxlen = 1024, cursor = 139}
local_sigjmp_buf = {{__jmpbuf = {-1279390062, -1279391582, 1277696902}, __mask_was_saved = 1,
__saved_mask = {__val = {0, 0, 0, 0, 1882843284, 1879202304, 1881990312, 0, 1, 0, 0, 0, 1881277836, 4,
0, 0, 0, 0, 0, 0, 1886277632, 1886289096, 1886289096, 5758488, 0, 0, 0, 4290538792, 1885242328,
4290538768, 2359384, 0}}}}
send_ready_for_query = 0 '\000'
__func__ = "PostgresMain"
#18 0x0005f724 in BackendRun (port=0x57dc80)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/postmaster/postmaster.c:4285
ac = 1
secs = 513854165
usecs = 348281
i = 1
av = 0x55fc70
maxac = <optimized out>
#19 BackendStartup (port=0x57dc80)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/postmaster/postmaster.c:3948
bn = 0x10b3
pid = 0
#20 ServerLoop () at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/postmaster/postmaster.c:1679
port = 0x57dc80
rmask = {fds_bits = {16, 0 <repeats 31 times>}}
selres = <optimized out>
now = <optimized out>
readmask = {fds_bits = {16, 0 <repeats 31 times>}}
nSockets = 5
last_lockfile_recheck_time = 1460538957
last_touch_time = 1460538957
__func__ = "ServerLoop"
#21 0x0024c04c in PostmasterMain (argc=8, argv=<optimized out>)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/postmaster/postmaster.c:1287
opt = <optimized out>
status = <optimized out>
userDoption = <optimized out>
listen_addr_saved = <optimized out>
i = <optimized out>
output_config_variable = <optimized out>
__func__ = "PostmasterMain"
#22 0x00060750 in main (argc=8, argv=0x55ef80)
at /home/myon/postgresql-9.4-9.4.7/build/../src/backend/main/main.c:233
No locals.

Original build log (but doesn't have much useful content):
https://buildd.debian.org/status/fetch.php?pkg=postgresql-9.4&arch=sparc&ver=9.4.7-0%2Bdeb8u1~bpo70%2B1&stamp=1460482241

Mit freundlichen Grüßen,
Christoph Berg
--
Senior Berater, Tel.: +49 (0)21 61 / 46 43-187
credativ GmbH, HRB Mönchengladbach 12080, USt-ID-Nummer: DE204566209
Hohenzollernstr. 133, 41061 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer
pgp fingerprint: 5C48 FE61 57F4 9179 5970 87C6 4C5A 6BAB 12D2 A7AE

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message Andres Freund 2016-04-13 16:19:06 Re: Bus error in pg_logical_slot_get_changes (9.4.7, sparc)
Previous Message Tom Lane 2016-04-12 21:15:39 Re: BUG #14078: Excessive memory growth during nested loop in select