Assertion failure in HEAD and 13 after calling COMMIT in a stored proc

From: Jim Nasby <nasbyj(at)amazon(dot)com>
To: "pgsql-hackers(at)lists(dot)postgresql(dot)org" <pgsql-hackers(at)lists(dot)postgresql(dot)org>
Subject: Assertion failure in HEAD and 13 after calling COMMIT in a stored proc
Date: 2021-06-21 23:19:27
Message-ID: 378885e4-f85f-fc28-6c91-c4d1c080bf26@amazon.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

The following generates an assertion failure. Quick testing with start
and stop as well as the core dump shows it’s failing on the execution of
`schema_name := schema_name(i)` immediately after COMMIT, because
there’s no active snapshot. On a build without asserts I get a failure
in GetActiveSnapshot() (second stack trace). This works fine on
12_STABLE, but fails on 13_STABLE and HEAD.

CREATE OR REPLACE FUNCTION public.schema_name(i integer)
 RETURNS text
 LANGUAGE sql
 IMMUTABLE
AS $function$
SELECT 'test_' || trim(to_char(i, '000000'))
$function$;

CREATE OR REPLACE PROCEDURE public.build_schema(start integer, stop
integer, commit_interval integer DEFAULT 10, do_insert boolean DEFAULT true)
 LANGUAGE plpgsql
AS $procedure$
DECLARE
    schema_name text;
BEGIN
FOR i IN start .. stop LOOP
    schema_name := schema_name(i);
    IF i % commit_interval = 0 THEN
        --RAISE NOTICE 'COMMIT CREATE step %', i;
        COMMIT;
    END IF;
END LOOP;
END$procedure$;

CALL build_schema(1,11);

<assert failure>

Core file '/cores/core.1912' (x86_64) was loaded.

(lldb) bt
* thread #1, stop reason = signal SIGSTOP
  * frame #0: 0x00007fff6c3ae33a libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff6c46ae60 libsystem_pthread.dylib`pthread_kill + 430
    frame #2: 0x00007fff6c335808 libsystem_c.dylib`abort + 120
    frame #3: 0x000000010af1af6d
postgres`ExceptionalCondition(conditionName="ActiveSnapshotSet()",
errorType="FailedAssertion", fileName="postgres.c", lineNumber=867) at
assert.c:67:2
    frame #4: 0x000000010ad3aeb3
postgres`pg_plan_query(querytree=0x00007ff663023848,
query_string="\nSELECT 'test_' || trim(to_char(i, '000000'))\n",
cursorOptions=256, boundParams=0x0000000000000000) at postgres.c:867:2
    frame #5: 0x000000010aad9059
postgres`init_execution_state(queryTree_list=0x00007ff663024208,
fcache=0x00007ff663022720, lazyEvalOK=true) at functions.c:513:12
    frame #6: 0x000000010aad6dec
postgres`init_sql_fcache(fcinfo=0x00007ff663035918, collation=0,
lazyEvalOK=true) at functions.c:787:23
    frame #7: 0x000000010aad5ffa
postgres`fmgr_sql(fcinfo=0x00007ff663035918) at functions.c:1070:3
    frame #8: 0x000000010aaaf660
postgres`ExecInterpExpr(state=0x00007ff663035828,
econtext=0x00007ff663035738, isnull=0x00007ffee5459bbf) at
execExprInterp.c:680:8
    frame #9: 0x000000010aaae9b7
postgres`ExecInterpExprStillValid(state=0x00007ff663035828,
econtext=0x00007ff663035738, isNull=0x00007ffee5459bbf) at
execExprInterp.c:1807:9
    frame #10: 0x00000001163e5b5a
plpgsql.so`ExecEvalExpr(state=0x00007ff663035828,
econtext=0x00007ff663035738, isNull=0x00007ffee5459bbf) at executor.h:303:9
    frame #11: 0x00000001163e4fe0
plpgsql.so`exec_eval_simple_expr(estate=0x00007ffee545a080,
expr=0x00007ff662032db0, result=0x00007ffee5459b68,
isNull=0x00007ffee5459bbf, rettype=0x00007ffee5459bb8,
rettypmod=0x00007ffee5459bb4) at pl_exec.c:6328:12
    frame #12: 0x00000001163e4887
plpgsql.so`exec_eval_expr(estate=0x00007ffee545a080,
expr=0x00007ff662032db0, isNull=0x00007ffee5459bbf,
rettype=0x00007ffee5459bb8, rettypmod=0x00007ffee5459bb4) at
pl_exec.c:5833:6
    frame #13: 0x00000001163e30c2
plpgsql.so`exec_assign_expr(estate=0x00007ffee545a080,
target=0x00007ff66300e4d0, expr=0x00007ff662032db0) at pl_exec.c:4973:10
    frame #14: 0x00000001163dc407
plpgsql.so`exec_stmt_assign(estate=0x00007ffee545a080,
stmt=0x00007ff662032e80) at pl_exec.c:2112:2
    frame #15: 0x00000001163d9de2
plpgsql.so`exec_stmt(estate=0x00007ffee545a080, stmt=0x00007ff662032e80)
at pl_exec.c:1980:9
    frame #16: 0x00000001163e3387
plpgsql.so`exec_stmts(estate=0x00007ffee545a080,
stmts=0x00007ff662032eb8) at pl_exec.c:1943:14
    frame #17: 0x00000001163ddd7c
plpgsql.so`exec_stmt_fori(estate=0x00007ffee545a080,
stmt=0x00007ff662032ca8) at pl_exec.c:2783:8
    frame #18: 0x00000001163d9ea2
plpgsql.so`exec_stmt(estate=0x00007ffee545a080, stmt=0x00007ff662032ca8)
at pl_exec.c:2012:9
    frame #19: 0x00000001163e3387
plpgsql.so`exec_stmts(estate=0x00007ffee545a080,
stmts=0x00007ff6620328d0) at pl_exec.c:1943:14
    frame #20: 0x00000001163dc20d
plpgsql.so`exec_stmt_block(estate=0x00007ffee545a080,
block=0x00007ff6620231c8) at pl_exec.c:1884:8
    frame #21: 0x00000001163d9dca
plpgsql.so`exec_stmt(estate=0x00007ffee545a080, stmt=0x00007ff6620231c8)
at pl_exec.c:1976:9
    frame #22: 0x00000001163d8393
plpgsql.so`plpgsql_exec_function(func=0x00007ff666055738,
fcinfo=0x00007ffee545a478, simple_eval_estate=0x0000000000000000,
simple_eval_resowner=0x0000000000000000, atomic=false) at pl_exec.c:610:7
    frame #23: 0x00000001163f6c4a
plpgsql.so`plpgsql_call_handler(fcinfo=0x00007ffee545a478) at
pl_handler.c:265:13
    frame #24: 0x000000010aa22232
postgres`ExecuteCallStmt(stmt=0x00007ff662010320,
params=0x0000000000000000, atomic=false, dest=0x00007ff662010ba0) at
functioncmds.c:2232:11
    frame #25: 0x000000010ad454af
postgres`standard_ProcessUtility(pstmt=0x00007ff6620103e8,
queryString="call build_schema (1,11);",
context=PROCESS_UTILITY_TOPLEVEL, params=0x0000000000000000,
queryEnv=0x0000000000000000, dest=0x00007ff662010ba0,
qc=0x00007ffee545b070) at utility.c:817:4
    frame #26: 0x000000010ad44c82
postgres`ProcessUtility(pstmt=0x00007ff6620103e8, queryString="call
build_schema (1,11);", context=PROCESS_UTILITY_TOPLEVEL,
params=0x0000000000000000, queryEnv=0x0000000000000000,
dest=0x00007ff662010ba0, qc=0x00007ffee545b070) at utility.c:524:3
    frame #27: 0x000000010ad4443e
postgres`PortalRunUtility(portal=0x00007ff66282f320,
pstmt=0x00007ff6620103e8, isTopLevel=true, setHoldSnapshot=false,
dest=0x00007ff662010ba0, qc=0x00007ffee545b070) at pquery.c:1145:2
    frame #28: 0x000000010ad4359d
postgres`PortalRunMulti(portal=0x00007ff66282f320, isTopLevel=true,
setHoldSnapshot=false, dest=0x00007ff662010ba0,
altdest=0x00007ff662010ba0, qc=0x00007ffee545b070) at pquery.c:1301:5
    frame #29: 0x000000010ad42b2e
postgres`PortalRun(portal=0x00007ff66282f320, count=9223372036854775807,
isTopLevel=true, run_once=true, dest=0x00007ff662010ba0,
altdest=0x00007ff662010ba0, qc=0x00007ffee545b070) at pquery.c:786:5
    frame #30: 0x000000010ad3e0c5
postgres`exec_simple_query(query_string="call build_schema (1,11);") at
postgres.c:1239:10
    frame #31: 0x000000010ad3d26d postgres`PostgresMain(argc=1,
argv=0x00007ff66280f670, dbname="nasbyj", username="nasbyj") at
postgres.c:4339:7
    frame #32: 0x000000010ac6752a
postgres`BackendRun(port=0x00007ff664404080) at postmaster.c:4526:2
    frame #33: 0x000000010ac66979
postgres`BackendStartup(port=0x00007ff664404080) at postmaster.c:4210:3
    frame #34: 0x000000010ac658fd postgres`ServerLoop at
postmaster.c:1739:7
    frame #35: 0x000000010ac633e4 postgres`PostmasterMain(argc=1,
argv=0x00007ff661c06cc0) at postmaster.c:1412:11
    frame #36: 0x000000010ab45679 postgres`main(argc=1,
argv=0x00007ff661c06cc0) at main.c:210:3
    frame #37: 0x00007fff6c266cc9 libdyld.dylib`start + 1
    frame #38: 0x00007fff6c266cc9 libdyld.dylib`start + 1
(lldb) fr 4
invalid command 'frame 4'.
(lldb) fr s 4
frame #4: 0x000000010ad3aeb3
postgres`pg_plan_query(querytree=0x00007ff663023848,
query_string="\nSELECT 'test_' || trim(to_char(i, '000000'))\n",
cursorOptions=256, boundParams=0x0000000000000000) at postgres.c:867:2
   864             return NULL;
   865
   866         /* Planner must have a snapshot in case it calls
user-defined functions. */
-> 867         Assert(ActiveSnapshotSet());
   868
   869         TRACE_POSTGRESQL_QUERY_PLAN_START();
   870
(lldb)

... non-assert build ...

(lldb) bt
postgres was compiled with optimization - stepping may behave oddly;
variables may not be available.
* thread #1, stop reason = signal SIGSTOP
  * frame #0: 0x0000000101d207db postgres`GetActiveSnapshot at
snapmgr.c:845:25 [opt]
    frame #1: 0x0000000101a83f25 postgres`fmgr_sql [inlined]
postquel_start(es=0x00007fd19789c5a8, fcache=<unavailable>) at
functions.c:832:9 [opt]
    frame #2: 0x0000000101a83ec6
postgres`fmgr_sql(fcinfo=<unavailable>) at functions.c:1161 [opt]
    frame #3: 0x0000000101a6fae1
postgres`ExecInterpExpr(state=<unavailable>, econtext=<unavailable>,
isnull=0x00007ffeee304a57) at execExprInterp.c:680:8 [opt]
    frame #4: 0x00000001028ddc10 plpgsql.so`exec_eval_expr [inlined]
ExecEvalExpr(state=<unavailable>, econtext=0x00007fd19a818128,
isNull=0x00007ffeee304a57) at executor.h:303:9 [opt]
    frame #5: 0x00000001028ddc06 plpgsql.so`exec_eval_expr [inlined]
exec_eval_simple_expr(estate=0x00007ffeee304f18,
expr=0x00007fd1980268c0, isNull=<unavailable>, rettype=<unavailable>,
rettypmod=0x00007fd19a80fe00) at pl_exec.c:6328 [opt]
    frame #6: 0x00000001028ddb2a
plpgsql.so`exec_eval_expr(estate=0x00007ffeee304f18,
expr=0x00007fd1980268c0, isNull=<unavailable>, rettype=<unavailable>,
rettypmod=0x00007fd19a80fe00) at pl_exec.c:5833 [opt]
    frame #7: 0x00000001028dd258
plpgsql.so`exec_assign_expr(estate=0x00007ffeee304f18,
target=0x00007fd19a810120, expr=0x00007fd1980268c0) at pl_exec.c:4973:10
[opt]
    frame #8: 0x00000001028d86a2 plpgsql.so`exec_stmt [inlined]
exec_stmt_assign(estate=0x00007ffeee304f18, stmt=0x00007fd198026980) at
pl_exec.c:2112:2 [opt]
    frame #9: 0x00000001028d868a
plpgsql.so`exec_stmt(estate=0x00007ffeee304f18, stmt=0x00007fd198026980)
at pl_exec.c:1980 [opt]
    frame #10: 0x00000001028d9941 plpgsql.so`exec_stmt at
pl_exec.c:1943:14 [opt]
    frame #11: 0x00000001028d9914 plpgsql.so`exec_stmt [inlined]
exec_stmt_fori(estate=0x00007ffeee304f18, stmt=0x00007fd1980267d8) at
pl_exec.c:2783 [opt]
    frame #12: 0x00000001028d98a9
plpgsql.so`exec_stmt(estate=<unavailable>, stmt=<unavailable>) at
pl_exec.c:2012 [opt]
    frame #13: 0x00000001028dbf20 plpgsql.so`exec_stmt_block at
pl_exec.c:1943:14 [opt]
    frame #14: 0x00000001028dbefb
plpgsql.so`exec_stmt_block(estate=0x00007ffeee304f18,
block=0x00007fd198026c20) at pl_exec.c:1884 [opt]
    frame #15: 0x00000001028d7ec3
plpgsql.so`exec_stmt(estate=0x00007ffeee304f18, stmt=0x00007fd198026c20)
at pl_exec.c:1976:9 [opt]
    frame #16: 0x00000001028d6f45
plpgsql.so`plpgsql_exec_function(func=0x00007fd19785cc60,
fcinfo=0x00007ffeee3051f0, simple_eval_estate=<unavailable>,
simple_eval_resowner=<unavailable>, atomic=<unavailable>) at
pl_exec.c:610:7 [opt]
    frame #17: 0x00000001028e9122
plpgsql.so`plpgsql_call_handler(fcinfo=0x00007ffeee3051f0) at
pl_handler.c:265:13 [opt]
    frame #18: 0x0000000101a2b5e4
postgres`ExecuteCallStmt(stmt=0x00007fd1978102b0,
params=0x00007fd19a80f4e8, atomic=<unavailable>,
dest=0x00007fd1978108d0) at functioncmds.c:2232:11 [opt]
    frame #19: 0x0000000101bd31f5
postgres`standard_ProcessUtility(pstmt=0x00007fd197810360,
queryString="CALL build_schema(1,11);",
context=PROCESS_UTILITY_TOPLEVEL, params=0x0000000000000000,
queryEnv=0x0000000000000000, dest=0x00007fd1978108d0,
qc=0x00007ffeee305b80) at utility.c:817:4 [opt]
    frame #20: 0x0000000101bd2c58
postgres`ProcessUtility(pstmt=0x00007fd197810360,
queryString=<unavailable>, context=<unavailable>, params=<unavailable>,
queryEnv=<unavailable>, dest=<unavailable>, qc=0x00007ffeee305b80) at
utility.c:524:3 [opt]
    frame #21: 0x0000000101bd29b1
postgres`PortalRunUtility(portal=0x00007fd197838118,
pstmt=0x00007fd197810360, isTopLevel=<unavailable>,
setHoldSnapshot=<unavailable>, dest=<unavailable>,
qc=0x00007ffeee305b80) at pquery.c:1145:2 [opt]
    frame #22: 0x0000000101bd2028
postgres`PortalRunMulti(portal=0x00007fd197838118, isTopLevel=true,
setHoldSnapshot=false, dest=0x00007fd1978108d0,
altdest=0x00007fd1978108d0, qc=<unavailable>) at pquery.c:0 [opt]
    frame #23: 0x0000000101bd1afd
postgres`PortalRun(portal=0x00007fd197838118, count=9223372036854775807,
isTopLevel=true, run_once=<unavailable>, dest=0x00007fd1978108d0,
altdest=0x00007fd1978108d0, qc=0x00007ffeee305b80) at pquery.c:786:5 [opt]
    frame #24: 0x0000000101bd0d5a
postgres`exec_simple_query(query_string="CALL build_schema(1,11);") at
postgres.c:1239:10 [opt]
    frame #25: 0x0000000101bce608
postgres`PostgresMain(argc=<unavailable>, argv=<unavailable>,
dbname=<unavailable>, username=<unavailable>) at postgres.c:0 [opt]
    frame #26: 0x0000000101b57e11
postgres`BackendRun(port=<unavailable>) at postmaster.c:4526:2 [opt]
    frame #27: 0x0000000101b57590 postgres`ServerLoop [inlined]
BackendStartup(port=<unavailable>) at postmaster.c:4210:3 [opt]
    frame #28: 0x0000000101b5756f postgres`ServerLoop at
postmaster.c:1739 [opt]
    frame #29: 0x0000000101b5474a
postgres`PostmasterMain(argc=<unavailable>, argv=0x00007fd197406cc0) at
postmaster.c:1412:11 [opt]
    frame #30: 0x0000000101abf3ef postgres`main(argc=<unavailable>,
argv=<unavailable>) at main.c:210:3 [opt]
    frame #31: 0x00007fff6c266cc9 libdyld.dylib`start + 1
    frame #32: 0x00007fff6c266cc9 libdyld.dylib`start + 1
(lldb)

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Peter Geoghegan 2021-06-21 23:47:09 Re: Maintaining a list of pgindent commits for "git blame" to ignore
Previous Message Justin Pryzby 2021-06-21 22:54:51 Re: Doc chapter for Hash Indexes