Bus error in pg_logical_slot_get_changes (9.4.7, sparc)

Поиск
Список
Период
Сортировка
От Christoph Berg
Тема Bus error in pg_logical_slot_get_changes (9.4.7, sparc)
Дата
Msg-id 20160413094117.GC21485@msg.credativ.de
обсуждение исходный текст
Ответы Re: Bus error in pg_logical_slot_get_changes (9.4.7, sparc)  (Andres Freund <andres@anarazel.de>)
Список 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

В списке pgsql-bugs по дате отправления:

Предыдущее
От: Tom Lane
Дата:
Сообщение: Re: BUG #14078: Excessive memory growth during nested loop in select
Следующее
От: Andres Freund
Дата:
Сообщение: Re: Bus error in pg_logical_slot_get_changes (9.4.7, sparc)