Date: Thu, 29 Sep 2022 02:55:40 -0500
From: Jaime Casanova <jcasanov@systemguards.com.ec>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-committers@lists.postgresql.org
Subject: Re: pgsql: Avoid improbable PANIC during heap_update.
Message-ID: <YzVPfCKNrmi0aLEh@ahch-to>
References: <E1lWLjP-00006Y-Ml@gemulon.postgresql.org>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="ayuiFyMFwhYfonXf"
Content-Disposition: inline
In-Reply-To: <E1lWLjP-00006Y-Ml@gemulon.postgresql.org>
Archived-At: 
 <https://www.postgresql.org/message-id/YzVPfCKNrmi0aLEh%40ahch-to>
Precedence: bulk


--ayuiFyMFwhYfonXf
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Tue, Apr 13, 2021 at 04:17:39PM +0000, Tom Lane wrote:
> Avoid improbable PANIC during heap_update.
> 
> heap_update needs to clear any existing "all visible" flag on
> the old tuple's page (and on the new page too, if different).
> Per coding rules, to do this it must acquire pin on the appropriate
> visibility-map page while not holding exclusive buffer lock;
> which creates a race condition since someone else could set the
> flag whenever we're not holding the buffer lock.  The code is
> supposed to handle that by re-checking the flag after acquiring
> buffer lock and retrying if it became set.  However, one code
> path through heap_update itself, as well as one in its subroutine
> RelationGetBufferForTuple, failed to do this.  The end result,
> in the unlikely event that a concurrent VACUUM did set the flag
> while we're transiently not holding lock, is a non-recurring
> "PANIC: wrong buffer passed to visibilitymap_clear" failure.
> 

Hi,

This doesn't look as improbable because I saw it at least 3 times with
v15beta4.

The first time I thought it was my fault, then I tried with a commit on
september 25 (didn't remember which exactly but that doesn't seems too
relevant).
Finally I saw it again in a build with TRACE_VISIBILITYMAP defined (the
same commit).

But I haven't see it anymore on rc1. Anyway I'm attaching the backtrace
(this is from the build with TRACE_VISIBILITYMAP), the query that was 
running at the time was (no changes were made to quad_poly_tbl table 
nor any indexes were added to this table):

"""
update public.quad_poly_tbl set
  id = public.quad_poly_tbl.id
returning
  public.quad_poly_tbl.id as c0
"""

-- 
Jaime Casanova
Director de Servicios Profesionales
SystemGuards - Consultores de PostgreSQL

--ayuiFyMFwhYfonXf
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="wrong_buffer_panic_beta4.txt"

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {4194304, 139906277533872, 139906277529216, 139906277533872, 139906275702592, 0, 895, 94675498488722, 140729237540432, 
            281470681751485, 0, 0, 0, 0, 0, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007f3e77dfc535 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x3ff0000000000000, sa_sigaction = 0x3ff0000000000000}, sa_mask = {__val = {0, 
              4609753056924675352, 0, 4728779608772575232, 0, 140729237540784, 94675496496005, 94675512751464, 94675512749920, 12884901888, 
              94675512751464, 94675512751440, 94675512749920, 140729237540832, 139906277529216, 139906277511840}}, sa_flags = 2011471149, 
          sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x0000561b5b5335c7 in errfinish (filename=0x561b5b5c7180 "visibilitymap.c", lineno=156, 
    funcname=0x561b5b5c74a0 <__func__.12294> "visibilitymap_clear") at elog.c:675
        edata = 0x561b5b8a8960 <errordata>
        elevel = 23
        oldcontext = 0x561b5d786c00
        econtext = 0x0
        __func__ = "errfinish"
#3  0x0000561b5af09ef7 in visibilitymap_clear (rel=0x561b5da3eb48, heapBlk=49, buf=0, flags=3 '\003') at visibilitymap.c:156
        __errno_location = <optimized out>
        mapBlock = 0
        mapByte = 12
        mapOffset = 2
        mask = 12 '\f'
        map = 0x7f3e70fc7af8 "\200\326\r"
        cleared = false
        __func__ = "visibilitymap_clear"
#4  0x0000561b5aee6ea7 in heap_update (relation=0x561b5da3eb48, otid=0x7ffe1436942a, newtup=0x561b5cdcf350, cid=0, crosscheck=0x0, wait=true, 
    tmfd=0x7ffe14369460, lockmode=0x7ffe14369394) at heapam.c:3913
        result = TM_Ok
        xid = 906880
        hot_attrs = 0x561b5cdcf740
        key_attrs = 0x0
        id_attrs = 0x0
        interesting_attrs = 0x561b5cdcf718
        modified_attrs = 0x0
        lp = 0x7f3e74a0fc18
        oldtup = {t_len = 264, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 49}, ip_posid = 1}, t_tableOid = 17323, t_data = 0x7f3e74a11af8}
        heaptup = 0x561b5cdcf350
        old_key_tuple = 0x0
        old_key_copied = false
        page = 0x7f3e74a0fc00 "\215"
        block = 49
        mxact_status = MultiXactStatusNoKeyUpdate
        buffer = 11159
        newbuf = 3698
        vmbuffer = 0
        vmbuffer_new = 0
        need_toast = false
        newtupsize = 264
        pagefree = 112
        have_tuple_lock = false
        iscombo = false
        use_hot_update = false
        key_intact = true
        all_visible_cleared = true
        all_visible_cleared_new = false
        checked_lockers = false
        locker_remains = false
        id_has_external = false
        xmax_new_tuple = 0
        xmax_old_tuple = 906880
        infomask_old_tuple = 0
        infomask2_old_tuple = 0
        infomask_new_tuple = 2048
        infomask2_new_tuple = 0
        __func__ = "heap_update"
#5  0x0000561b5aef562b in heapam_tuple_update (relation=0x561b5da3eb48, otid=0x7ffe1436942a, slot=0x561b5d788a58, cid=0, snapshot=0x561b5c51be80, 
    crosscheck=0x0, wait=true, tmfd=0x7ffe14369460, lockmode=0x7ffe14369394, update_indexes=0x7ffe14369391) at heapam_handler.c:327
        shouldFree = false
        tuple = 0x561b5cdcf350
        result = 32766
#6  0x0000561b5b186b50 in table_tuple_update (rel=0x561b5da3eb48, otid=0x7ffe1436942a, slot=0x561b5d788a58, cid=0, snapshot=0x561b5c51be80, 
    crosscheck=0x0, wait=true, tmfd=0x7ffe14369460, lockmode=0x7ffe14369394, update_indexes=0x7ffe14369391)
    at ../../../src/include/access/tableam.h:1511
No locals.
#7  0x0000561b5b18996d in ExecUpdateAct (context=0x7ffe14369430, resultRelInfo=0x561b5d7871a8, tupleid=0x7ffe1436942a, oldtuple=0x0, 
    slot=0x561b5d788a58, canSetTag=true, updateCxt=0x7ffe14369390) at nodeModifyTable.c:1971
        estate = 0x561b5d786d20
        resultRelationDesc = 0x561b5da3eb48
        partition_constraint_failed = false
        result = 1568173344
#8  0x0000561b5b189e96 in ExecUpdate (context=0x7ffe14369430, resultRelInfo=0x561b5d7871a8, tupleid=0x7ffe1436942a, oldtuple=0x0, 
    slot=0x561b5d788a58, canSetTag=true) at nodeModifyTable.c:2185
        estate = 0x561b5d786d20
        resultRelationDesc = 0x561b5da3eb48
        updateCxt = {updated = false, updateIndexes = false, crossPartUpdate = false, lockmode = LockTupleNoKeyExclusive}
        recheckIndexes = 0x0
        result = 22043
        __func__ = "ExecUpdate"
#9  0x0000561b5b18c865 in ExecModifyTable (pstate=0x561b5d786f90) at nodeModifyTable.c:3737
        node = 0x561b5d786f90
        context = {mtstate = 0x561b5d786f90, epqstate = 0x561b5d787078, estate = 0x561b5d786d20, planSlot = 0x561b5d7878e8, 
          GetUpdateNewTuple = 0x561b5b187d1d <internalGetUpdateNewTuple>, relaction = 0x0, tmfd = {ctid = {ip_blkid = {bi_hi = 49287, 
                bi_lo = 23320}, ip_posid = 22043}, xmax = 1561021592, cmax = 22043, traversed = 4}, cpUpdateRetrySlot = 0x100000010, 
          cpUpdateReturningSlot = 0x561b5d0b4c98}
        estate = 0x561b5d786d20
        operation = CMD_UPDATE
        resultRelInfo = 0x561b5d7871a8
        subplanstate = 0x561b5d787458
        slot = 0x561b5d788a58
        oldSlot = 0x561b5d788940
        tuple_ctid = {ip_blkid = {bi_hi = 0, bi_lo = 49}, ip_posid = 1}
        oldtupdata = {t_len = 1561021608, t_self = {ip_blkid = {bi_hi = 22043, bi_lo = 0}, ip_posid = 1}, t_tableOid = 1, t_data = 0x7ffe14369490}
        oldtuple = 0x0
        tupleid = 0x7ffe1436942a
        proute = 0x0
        relinfos = 0x0
        lc = 0x561b5d787f48
        __func__ = "ExecModifyTable"
#10 0x0000561b5b140cd3 in ExecProcNode (node=0x561b5d786f90) at ../../../src/include/executor/executor.h:259
No locals.
#11 0x0000561b5b143992 in ExecutePlan (estate=0x561b5d786d20, planstate=0x561b5d786f90, use_parallel_mode=false, operation=CMD_UPDATE, 
    sendTuples=true, numberTuples=0, direction=ForwardScanDirection, dest=0x561b5c535b28, execute_once=true) at execMain.c:1636
        slot = 0x561b5d787f48
        current_tuple_count = 1471
#12 0x0000561b5b141379 in standard_ExecutorRun (queryDesc=0x561b5c535bc0, direction=ForwardScanDirection, count=0, execute_once=true)
    at execMain.c:363
        estate = 0x561b5d786d20
        operation = CMD_UPDATE
        dest = 0x561b5c535b28
        sendTuples = true
        oldcontext = 0x561b5c5358d0
        __func__ = "standard_ExecutorRun"
#13 0x0000561b5b14118f in ExecutorRun (queryDesc=0x561b5c535bc0, direction=ForwardScanDirection, count=0, execute_once=true) at execMain.c:307
No locals.
#14 0x0000561b5b391d88 in ProcessQuery (plan=0x561b6046f6a0, 
    sourceText=0x561b5c4eb8a0 "update public.quad_poly_tbl set \n  id = public.quad_poly_tbl.id\nreturning \n  public.quad_poly_tbl.id as c0", 
    params=0x0, queryEnv=0x0, dest=0x561b5c535b28, qc=0x7ffe14369710) at pquery.c:160
        queryDesc = 0x561b5c535bc0
#15 0x0000561b5b393761 in PortalRunMulti (portal=0x561b5f832120, isTopLevel=true, setHoldSnapshot=true, dest=0x561b5c535b28, 
    altdest=0x561b5b86da00 <donothingDR>, qc=0x7ffe14369710) at pquery.c:1277
        pstmt = 0x561b6046f6a0
        stmtlist_item__state = {l = 0x561b5cfce990, i = 0}
        active_snapshot_set = true
        stmtlist_item = 0x561b5cfce9a8
#16 0x0000561b5b3932a5 in FillPortalStore (portal=0x561b5f832120, isTopLevel=true) at pquery.c:1026
        treceiver = 0x561b5c535b28
        qc = {commandTag = CMDTAG_UNKNOWN, nprocessed = 0}
        __func__ = "FillPortalStore"
#17 0x0000561b5b392c4b in PortalRun (portal=0x561b5f832120, count=9223372036854775807, isTopLevel=true, run_once=true, dest=0x561b5cfce9e8, 
    altdest=0x561b5cfce9e8, qc=0x7ffe143698e0) at pquery.c:763
        _save_exception_stack = 0x7ffe143699e0
        _save_context_stack = 0x0
        _local_sigjmp_buf = {{__jmpbuf = {0, 2860372577420250015, 94675489186000, 140729237544704, 0, 0, 2860372577606896543, 8392611472902654879}, 
            __mask_was_saved = 0, __saved_mask = {__val = {18728835850, 94675524184528, 128, 94675512768384, 94675513071824, 140729237542976, 
                16256, 94675513072368, 94675524184400, 140729237543008, 94675496542566, 109, 112, 94675524184664, 112, 339122288}}}}
        _do_rethrow = false
        result = false
        nprocessed = 94675524184552
        saveTopTransactionResourceOwner = 0x561b5c573850
        saveTopTransactionContext = 0x561b5c51bc90
        saveActivePortal = 0x0
        saveResourceOwner = 0x561b5c573850
        savePortalContext = 0x0
        saveMemoryContext = 0x561b5c51bc90
        __func__ = "PortalRun"
#18 0x0000561b5b38c548 in exec_simple_query (
    query_string=0x561b5c4eb8a0 "update public.quad_poly_tbl set \n  id = public.quad_poly_tbl.id\nreturning \n  public.quad_poly_tbl.id as c0")
    at postgres.c:1250
        snapshot_set = true
        per_parsetree_context = 0x0
        plantree_list = 0x561b5cfce990
        parsetree = 0x561b5c4ec8f0
        commandTag = CMDTAG_UPDATE
        qc = {commandTag = CMDTAG_UNKNOWN, nprocessed = 0}
        querytree_list = 0x561b5c4ed358
        portal = 0x561b5f832120
        receiver = 0x561b5cfce9e8
        format = 0
        parsetree_item__state = {l = 0x561b5c4ec928, i = 0}
        dest = DestRemote
        oldcontext = 0x561b5c51bc90
        parsetree_list = 0x561b5c4ec928
        parsetree_item = 0x561b5c4ec940
        save_log_statement_stats = false
        was_logged = true
        use_implicit_block = false
        msec_str = "\240\270N\\\033V\000\000j\000\000\000\006\000\000\000\060\231\066\024\376\177\000\000\062\001\034[j\000\000"
        __func__ = "exec_simple_query"
#19 0x0000561b5b390d39 in PostgresMain (dbname=0x561b5c5163e0 "regression", username=0x561b5c5163b8 "jcasanov") at postgres.c:4581
        query_string = 0x561b5c4eb8a0 "update public.quad_poly_tbl set \n  id = public.quad_poly_tbl.id\nreturning \n  public.quad_poly_tbl.id as c0"
        firstchar = 81
        input_message = {
          data = 0x561b5c4eb8a0 "update public.quad_poly_tbl set \n  id = public.quad_poly_tbl.id\nreturning \n  public.quad_poly_tbl.id as c0", 
          len = 107, maxlen = 1024, cursor = 107}
        local_sigjmp_buf = {{__jmpbuf = {0, 2860372577472678815, 94675489186000, 140729237544704, 0, 0, 2860372577384598431, 8392611473924361119}, 
            __mask_was_saved = 1, __saved_mask = {__val = {4194304, 1, 15679, 15680, 979, 18446744073709551536, 0, 0, 139906276254835, 3904, 0, 
                140729237543680, 94675489186000, 140729237544704, 94675496494014, 15616}}}}
        send_ready_for_query = false
        idle_in_transaction_timeout_enabled = false
        idle_session_timeout_enabled = false
        __func__ = "PostgresMain"
#20 0x0000561b5b2c8a02 in BackendRun (port=0x561b5c51a640) at postmaster.c:4504
No locals.
#21 0x0000561b5b2c834e in BackendStartup (port=0x561b5c51a640) at postmaster.c:4232
        bn = 0x561b5c50d830
        pid = 0
        __func__ = "BackendStartup"
#22 0x0000561b5b2c4793 in ServerLoop () at postmaster.c:1806
        port = 0x561b5c51a640
        i = 2
        rmask = {fds_bits = {256, 0 <repeats 15 times>}}
        selres = 1
        now = 1664163286
        readmask = {fds_bits = {448, 0 <repeats 15 times>}}
        nSockets = 9
        last_lockfile_recheck_time = 1664163252
        last_touch_time = 1664163132
        __func__ = "ServerLoop"
#23 0x0000561b5b2c3fe2 in PostmasterMain (argc=3, argv=0x561b5c4e4eb0) at postmaster.c:1478
        opt = -1
        status = 0
        userDoption = 0x561b5c5088a0 "data1"
        listen_addr_saved = true
        i = 64
        output_config_variable = 0x0
        __func__ = "PostmasterMain"
#24 0x0000561b5b1c33da in main (argc=3, argv=0x561b5c4e4eb0) at main.c:202
        do_check_root = true

--ayuiFyMFwhYfonXf--