Re: assertion failure 9.3.4

On 04/14/2014 09:28 PM, Andrew Dunstan wrote:
>
> With a client's code I have just managed to produce the following
> assertion failure on 9.3.4:
>
> 2014-04-15 01:02:46 GMT [19854] 76299: LOG: execute <unnamed>:
> select * from "asp_ins_event_task_log"( job_id:=1, event_id:=3164,
> task_name:='EventUtcComputeTask', task_status_code:='VALID'
> , task_start_utc:='04/15/2014 01:02:44.563',
> task_end_utc:='04/15/2014 01:02:44.563')
> TRAP: FailedAssertion("!(update_xact == ((TransactionId) 0))", File:
> "/home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c", Line:
> 5873)
> 2014-04-15 01:02:46 GMT [11959] 11: LOG: server process (PID 19854)
> was terminated by signal 6: Aborted
> 2014-04-15 01:02:46 GMT [11959] 12: DETAIL: Failed process was
> running: select * from "asp_ins_event_task_log"( job_id:=1,
> event_id:=3164, task_name:='EventUtcComputeTask', task_status_code
> :='VALID', task_start_utc:='04/15/2014 01:02:44.563',
> task_end_utc:='04/15/2014 01:02:44.563')
> 2014-04-15 01:02:46 GMT [11959] 13: LOG: terminating any other
> active server processes
>
>
> When running without assertions, the client reports experiencing
> tables with duplicate primary keys among other things. It's apparently
> quite reproducible.
>
> I'm digging into this, but it's a nasty bug and any useful thoughts
> would be appreciated.

and here the stack trace:

#0 0x000000361ba36285 in __GI_raise (sig=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1 0x000000361ba37b9b in __GI_abort () at abort.c:91
#2 0x000000000075c157 in ExceptionalCondition
(conditionName=<optimized out>, errorType=<optimized out>,
fileName=<optimized out>, lineNumber=<optimized out>)
at /home/andrew/pgl/pg_9_3/src/backend/utils/error/assert.c:54
#3 0x000000000048c2af in MultiXactIdGetUpdateXid (xmax=<optimized
out>, t_infomask=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c:5873
#4 0x000000000078ad50 in HeapTupleSatisfiesMVCC
(tuple=0x7feb3be8a790, snapshot=0x1025d70, buffer=2172) at
/home/andrew/pgl/pg_9_3/src/backend/utils/time/tqual.c:1221
#5 0x000000000048aad2 in heapgetpage (scan=0x11522f0, page=6) at
/home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c:397
#6 0x000000000048aee9 in heapgettup_pagemode (scan=0x11522f0,
dir=<optimized out>, nkeys=0, key=0x0) at
/home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c:939
#7 0x000000000048d646 in heap_getnext (scan=0x11522f0,
direction=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c:1459
#8 0x00000000005becab in SeqNext (node=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/executor/nodeSeqscan.c:66
#9 0x00000000005ac66e in ExecScanFetch (recheckMtd=0x5bec70
<SeqRecheck>, accessMtd=0x5bec80 <SeqNext>, node=0x1151488) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execScan.c:82
#10 ExecScan (node=0x1151488, accessMtd=0x5bec80 <SeqNext>,
recheckMtd=0x5bec70 <SeqRecheck>) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execScan.c:167
#11 0x00000000005a5338 in ExecProcNode (node=0x1151488) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execProcnode.c:400
#12 0x00000000005b9bcf in ExecLockRows (node=0x1151278) at
/home/andrew/pgl/pg_9_3/src/backend/executor/nodeLockRows.c:56
#13 0x00000000005a51d0 in ExecProcNode (node=0x1151278) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execProcnode.c:496
#14 0x00000000005a250a in ExecutePlan (dest=0xb952e0,
direction=<optimized out>, numberTuples=1, sendTuples=1 '\001',
operation=CMD_SELECT, planstate=0x1151278, estate=0x1151038)
at /home/andrew/pgl/pg_9_3/src/backend/executor/execMain.c:1473
#15 standard_ExecutorRun (queryDesc=0x114f230, direction=<optimized
out>, count=1) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execMain.c:307
#16 0x00007feb5cf2f27d in explain_ExecutorRun (queryDesc=0x114f230,
direction=ForwardScanDirection, count=1) at
/home/andrew/pgl/pg_9_3/contrib/auto_explain/auto_explain.c:233
#17 0x00007feb5cd2a235 in pgss_ExecutorRun (queryDesc=0x114f230,
direction=ForwardScanDirection, count=1) at
/home/andrew/pgl/pg_9_3/contrib/pg_stat_statements/pg_stat_statements.c:717
#18 0x00000000005c8b97 in _SPI_pquery (tcount=1, fire_triggers=0
'\000', queryDesc=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:2369
#19 _SPI_execute_plan (plan=0x10afac8, paramLI=0x114f028,
snapshot=0x0, crosscheck_snapshot=0x0, read_only=0 '\000',
fire_triggers=0 '\000', tcount=1)
at /home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:2157
#20 0x00000000005c8fd1 in SPI_execute_snapshot (plan=0x10afac8,
Values=0x7fff147d8500, Nulls=0x7fff147d8700 " ", snapshot=0x0,
crosscheck_snapshot=0x0, read_only=0 '\000',
fire_triggers=0 '\000', tcount=1) at
/home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:488
#21 0x0000000000722635 in ri_PerformCheck (riinfo=0xf98168,
qkey=0x7fff147d8a20, qplan=0x10afac8, fk_rel=0x7feb39048048,
pk_rel=0x7feb38ff9b40, old_tuple=0x0, new_tuple=0x7fff147d9010,
detectNewRows=0 '\000', expect_OK=5) at
/home/andrew/pgl/pg_9_3/src/backend/utils/adt/ri_triggers.c:3094
#22 0x0000000000722cfc in RI_FKey_check (trigdata=<optimized out>)
at /home/andrew/pgl/pg_9_3/src/backend/utils/adt/ri_triggers.c:440
#23 0x0000000000588add in ExecCallTriggerFunc
(trigdata=0x7fff147d8fe0, tgindx=4, finfo=0x11409a8, instr=0x0,
per_tuple_context=0x1198d28)
at /home/andrew/pgl/pg_9_3/src/backend/commands/trigger.c:1871
#24 0x0000000000588f6b in AfterTriggerExecute
(per_tuple_context=0x1198d28, instr=0x0, finfo=0x11408e8,
trigdesc=0x11401f8, rel=0x7feb39048048, event=0x114d038)
at /home/andrew/pgl/pg_9_3/src/backend/commands/trigger.c:3454
#25 afterTriggerInvokeEvents (events=0x1025620, firing_id=1,
estate=0x113ffb8, delete_ok=1 '\001') at
/home/andrew/pgl/pg_9_3/src/backend/commands/trigger.c:3633
#26 0x000000000058e873 in AfterTriggerEndQuery (estate=0x113ffb8) at
/home/andrew/pgl/pg_9_3/src/backend/commands/trigger.c:3823
#27 0x00000000005a26f4 in standard_ExecutorFinish
(queryDesc=0x1076d08) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execMain.c:379
#28 0x00007feb5cf2f1a5 in explain_ExecutorFinish
(queryDesc=0x1076d08) at
/home/andrew/pgl/pg_9_3/contrib/auto_explain/auto_explain.c:256
#29 0x00007feb5cd2a163 in pgss_ExecutorFinish (queryDesc=0x1076d08)
at
/home/andrew/pgl/pg_9_3/contrib/pg_stat_statements/pg_stat_statements.c:740
#30 0x00000000005c8be4 in _SPI_pquery (tcount=2, fire_triggers=1
'\001', queryDesc=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:2381
#31 _SPI_execute_plan (plan=0x10905a8, paramLI=0x112ab10,
snapshot=0x0, crosscheck_snapshot=0x0, read_only=0 '\000',
fire_triggers=1 '\001', tcount=2)
at /home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:2157
#32 0x00000000005c909f in SPI_execute_plan_with_paramlist
(plan=0x10905a8, params=0x112ab10, read_only=0 '\000', tcount=2) at
/home/andrew/pgl/pg_9_3/src/backend/executor/spi.c:449
#33 0x00007feb3908d877 in exec_stmt_execsql (estate=0x7fff147d9700,
stmt=0x10630f0) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_exec.c:3293
#34 0x00007feb3908ee9e in exec_stmt (stmt=0x10630f0,
estate=0x7fff147d9700) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_exec.c:1446
#35 exec_stmts (estate=0x7fff147d9700, stmts=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_exec.c:1345
#36 0x00007feb3909157b in exec_stmt_block (estate=0x7fff147d9700,
block=0x1063c68) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_exec.c:1283
#37 0x00007feb390921dd in plpgsql_exec_function (func=0x106bbe8,
fcinfo=0x7fff147d9940) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_exec.c:321
#38 0x00007feb39086ff4 in plpgsql_call_handler
(fcinfo=0x7fff147d9940) at
/home/andrew/pgl/pg_9_3/src/pl/plpgsql/src/pl_handler.c:129
#39 0x00000000005aa632 in ExecMakeTableFunctionResult
(funcexpr=0x1122070, econtext=0x1121b98, expectedDesc=0x1121f18,
randomAccess=0 '\000')
at /home/andrew/pgl/pg_9_3/src/backend/executor/execQual.c:2164
#40 0x00000000005be0c1 in FunctionNext (node=0x1121a80) at
/home/andrew/pgl/pg_9_3/src/backend/executor/nodeFunctionscan.c:64
#41 0x00000000005ac74e in ExecScanFetch (recheckMtd=0x5be040
<FunctionRecheck>, accessMtd=0x5be050 <FunctionNext>, node=0x1121a80)
at /home/andrew/pgl/pg_9_3/src/backend/executor/execScan.c:82
#42 ExecScan (node=0x1121a80, accessMtd=0x5be050 <FunctionNext>,
recheckMtd=0x5be040 <FunctionRecheck>) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execScan.c:132
#43 0x00000000005a52d8 in ExecProcNode (node=0x1121a80) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execProcnode.c:426
#44 0x00000000005a250a in ExecutePlan (dest=0xeeaa40,
direction=<optimized out>, numberTuples=0, sendTuples=1 '\001',
operation=CMD_SELECT, planstate=0x1121a80, estate=0x1121968)
at /home/andrew/pgl/pg_9_3/src/backend/executor/execMain.c:1473
#45 standard_ExecutorRun (queryDesc=0x1029e60, direction=<optimized
out>, count=0) at
/home/andrew/pgl/pg_9_3/src/backend/executor/execMain.c:307
#46 0x00007feb5cf2f27d in explain_ExecutorRun (queryDesc=0x1029e60,
direction=ForwardScanDirection, count=0) at
/home/andrew/pgl/pg_9_3/contrib/auto_explain/auto_explain.c:233
#47 0x00007feb5cd2a235 in pgss_ExecutorRun (queryDesc=0x1029e60,
direction=ForwardScanDirection, count=0) at
/home/andrew/pgl/pg_9_3/contrib/pg_stat_statements/pg_stat_statements.c:717
#48 0x000000000068fe77 in PortalRunSelect (portal=0xf2d598,
forward=<optimized out>, count=0, dest=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/tcop/pquery.c:946
#49 0x00000000006913c1 in PortalRun (portal=0xf2d598,
count=9223372036854775807, isTopLevel=1 '\001', dest=0xeeaa40,
altdest=0xeeaa40, completionTag=0x7fff147da470 "")
at /home/andrew/pgl/pg_9_3/src/backend/tcop/pquery.c:790
#50 0x000000000068ec50 in exec_execute_message (max_rows=<optimized
out>, portal_name=0xeea628 "") at
/home/andrew/pgl/pg_9_3/src/backend/tcop/postgres.c:1931
#51 PostgresMain (argc=<optimized out>, argv=<optimized out>,
dbname=0xe3e0c8 "eventjobs", username=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/tcop/postgres.c:4060
#52 0x000000000064465c in BackendRun (port=0xe63490) at
/home/andrew/pgl/pg_9_3/src/backend/postmaster/postmaster.c:4011
#53 BackendStartup (port=0xe63490) at
/home/andrew/pgl/pg_9_3/src/backend/postmaster/postmaster.c:3685
#54 ServerLoop () at
/home/andrew/pgl/pg_9_3/src/backend/postmaster/postmaster.c:1586
#55 PostmasterMain (argc=<optimized out>, argv=<optimized out>) at
/home/andrew/pgl/pg_9_3/src/backend/postmaster/postmaster.c:1253
#56 0x000000000045c897 in main (argc=3, argv=0xe3d270) at
/home/andrew/pgl/pg_9_3/src/backend/main/main.c:226

cheers

andrew