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
0x000000361ba37b9bin __GI_abort () at abort.c:91   #2  0x000000000075c157 in ExceptionalCondition
(conditionName=<optimizedout>, 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=<optimizedout>) at   /home/andrew/pgl/pg_9_3/src/backend/access/heap/heapam.c:1459   #8  0x00000000005becab
inSeqNext (node=<optimized out>) at   /home/andrew/pgl/pg_9_3/src/backend/executor/nodeSeqscan.c:66   #9
0x00000000005ac66ein 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
0x00000000005a5338in 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
0x0000000000722635in 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=<optimizedout>)   at /home/andrew/pgl/pg_9_3/src/backend/utils/adt/ri_triggers.c:440   #23 0x0000000000588add
inExecCallTriggerFunc   (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
#260x000000000058e873 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
#290x00007feb5cd2a163 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
0x00007feb3908ee9ein 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
0x00007feb390921ddin 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
#51PostgresMain (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=<optimizedout>) 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