On Tue, 2005-12-20 at 16:37, Tom Lane wrote:
> Jonathan Parkin <jonathan.parkin@xxxxxxxxxxxxx> writes:
> > I have a reasonably large, live, system-critical database. A perl
> > script on another machine connects and issues a sequence of commands in
> > a transaction, the last of which is a delete. The delete never returns
> > a response, and the connection never times out. The postgres process
> > handling the delete is in a scheduled state, but stracing it produces no
> > output at all.
>
> Sounds like it's stuck in a tight loop. Can you attach to the postgres
> process with gdb and get a stack trace to find out where the loop is?
I've attached two back traces. The first (process 23755) is unique
across the ten or so current hangign processes. All the rest follow the
same trace as the second (process 25376). I notice that first (process
23755) has the lowest-numbered PID of the hanging processes, suggesting
it began before the rest.
The "ignoring modified tuple in DELETE trigger" is reaching syslog and
being logged in /var/log/messages. This normally occurs during
processing. Syslog apears to be operating correctly, and HUPing it has
had no effect.
I should note that, other than the upgrade mentioned previously, no
changes have been made recently that I know of, and that the system has
previously appeared to be working correctly. It is not clear when this
issue began.
> If this is a specific row causing the issue, then I'd wonder about
> data corruption of some sort. It might be worth looking at the
> table with pg_filedump (from http://sources.redhat.com/rhdb/).
Thanks, I hadn't heard of that. I'll see what I can turn up with it.
Anything in particular I should be looking for?
Our current plan is to do a rebuild of the database tonight (UK time).
This would hopefully eliminate any such data corruption.
--
Best Regards
Jonathan Parkin
Developer
Legend Communications plc
T: 0844 390 2049
F: 0844 390 2001
E: jonathan.parkin@xxxxxxxxxxxxx
W: http://www.legend.co.uk/
The information in this message is confidential and may be legally
privileged. Unauthorised disclosure, copying or distribution, either
whole or in part; or action taken in reliance on its content is
prohibited. If you are not the intended recipient, please notify Legend
Communications immediately.
### Start of trace one (Process 23755)
#0 0x485ec845 in __pthread_sigsuspend () from /lib/i686/libpthread.so.0
#1 0x485ec318 in __pthread_wait_for_restart_signal () from /lib/i686/libpthread.so.0
#2 0x485edd30 in __pthread_alt_lock () from /lib/i686/libpthread.so.0
#3 0x485ead37 in pthread_mutex_lock () from /lib/i686/libpthread.so.0
#4 0x402e22fc in vsyslog () from /lib/i686/libc.so.6
#5 0x402e1e6f in syslog () from /lib/i686/libc.so.6
#6 0x081e4a52 in write_syslog (level=5, line=0x4033afac "") at elog.c:1013
#7 0x081e4d7f in send_message_to_server_log (edata=0x82aad80) at elog.c:1146
#8 0x081e3b0c in errfinish (dummy=0) at elog.c:341
#9 0x081e46a6 in elog_finish (elevel=-4, fmt=0x485ac920 "ignoring modified tuple in DELETE trigger")
at elog.c:849
#10 0x485247d2 in PLy_trigger_handler (fcinfo=0xbfffddf0, proc=0x83b8860) at plpython.c:455
#11 0x485244d0 in plpython_call_handler (fcinfo=0xbfffddf0) at plpython.c:370
#12 0x080f253e in ExecCallTriggerFunc (trigdata=0xbfffdcbc, finfo=0x485df998, per_tuple_context=0xfffffffc)
at trigger.c:1150
#13 0x080f2b7a in ExecBRDeleteTriggers (estate=0x83ad828, relinfo=0x83ad960, tupleid=0xfffffffc,
cid=4294967292) at trigger.c:1377
#14 0x08105b7c in ExecDelete (slot=0x83adee0, tupleid=0xbfffe000, estate=0x83ad828) at execMain.c:1474
#15 0x08105545 in ExecutePlan (estate=0x83ad828, planstate=0x83adf00, operation=CMD_DELETE, numberTuples=0,
direction=-4, dest=0x82768d4) at execMain.c:1262
#16 0x081046c8 in ExecutorRun (queryDesc=0x83ba1a8, direction=ForwardScanDirection, count=-4)
at execMain.c:249
#17 0x08118464 in _SPI_pquery (queryDesc=0x83ad828, runit=0 '\0', useCurrentSnapshot=8 '\b', tcount=-4)
at spi.c:1254
#18 0x08118356 in _SPI_execute_plan (plan=0xfffffffc, Values=0x83a5328, Nulls=0x83a9b48 " ",
useCurrentSnapshot=0 '\0', tcount=0) at spi.c:1201
#19 0x08116832 in SPI_execp (plan=0x83ad828, Values=0x83a5328,
Nulls=0xfffffffc <Address 0xfffffffc out of bounds>, tcount=0) at spi.c:241
#20 0x485281e9 in PLy_spi_execute_plan (ob=0x834d418, list=0x834c82c, limit=0) at plpython.c:2205
#21 0x4852802d in PLy_spi_execute (self=0x0, args=0x83bdd54) at plpython.c:2082
#22 0x48542624 in PyCFunction_Call () from /usr/lib/pgsql/plpython.so
#23 0x4856841e in eval_frame () from /usr/lib/pgsql/plpython.so
#24 0x48568e8e in PyEval_EvalCodeEx () from /usr/lib/pgsql/plpython.so
#25 0x4856a3eb in fast_function () from /usr/lib/pgsql/plpython.so
#26 0x48568363 in eval_frame () from /usr/lib/pgsql/plpython.so
#27 0x48568e8e in PyEval_EvalCodeEx () from /usr/lib/pgsql/plpython.so
#28 0x48565d85 in PyEval_EvalCode () from /usr/lib/pgsql/plpython.so
#29 0x48525bd7 in PLy_procedure_call (proc=0x83b8860, kargs=0xfffffffc <Address 0xfffffffc out of bounds>,
vargs=0xfffffffc) at plpython.c:881
#30 0x48524621 in PLy_trigger_handler (fcinfo=0xbfffe7c0, proc=0x83b8860) at plpython.c:420
#31 0x485244d0 in plpython_call_handler (fcinfo=0xbfffe7c0) at plpython.c:370
#32 0x080f253e in ExecCallTriggerFunc (trigdata=0xbfffe68c, finfo=0x485df998, per_tuple_context=0xfffffffc)
at trigger.c:1150
#33 0x080f2b7a in ExecBRDeleteTriggers (estate=0x8336d78, relinfo=0x8336eb0, tupleid=0xfffffffc,
cid=4294967292) at trigger.c:1377
#34 0x08105b7c in ExecDelete (slot=0x8337430, tupleid=0xbfffe9d0, estate=0x8336d78) at execMain.c:1474
#35 0x08105545 in ExecutePlan (estate=0x8336d78, planstate=0x8337450, operation=CMD_DELETE, numberTuples=0,
direction=-4, dest=0x83282d0) at execMain.c:1262
#36 0x081046c8 in ExecutorRun (queryDesc=0x8344da0, direction=ForwardScanDirection, count=-4)
at execMain.c:249
#37 0x0817b782 in ProcessQuery (parsetree=0xfffffffc, plan=0x8336d78, params=0x8, dest=0x0,
completionTag=0x8344da0 "\004") at pquery.c:139
#38 0x0817c2f4 in PortalRunMulti (portal=0x832ba10, dest=0x83282d0, altdest=0x83282d0,
completionTag=0xbfffeb30 "") at pquery.c:860
#39 0x0817bc63 in PortalRun (portal=0x832ba10, count=2147483647, dest=0x83282d0, altdest=0xfffffffc,
completionTag=0xbfffeb30 "") at pquery.c:494
#40 0x08178543 in exec_simple_query (
query_string=0x8326358 ' ' <repeats 45 times>, "DELETE FROM dbbq1 WHERE id = 53831") at postgres.c:914
#41 0x0817ad31 in PostgresMain (argc=4, argv=0x82b8168, username=0x82b8138 "admin") at postgres.c:2918
#42 0x08154880 in BackendFork (port=0x82d2358) at postmaster.c:2564
#43 0x08154273 in BackendStartup (port=0x82d2358) at postmaster.c:2207
#44 0x081527d8 in ServerLoop () at postmaster.c:1119
#45 0x08151e9e in PostmasterMain (argc=5, argv=0x82b72a0) at postmaster.c:897
#46 0x08121bd3 in main (argc=5, argv=0xbffffb74) at main.c:214
#47 0x4021aa07 in __libc_start_main () from /lib/i686/libc.so.6
### End of trace one (Process 23755)
### Start of trace two (Process 25376)
#0 0x485ec845 in __pthread_sigsuspend () from /lib/i686/libpthread.so.0
#1 0x485ec318 in __pthread_wait_for_restart_signal () from /lib/i686/libpthread.so.0
#2 0x485edd30 in __pthread_alt_lock () from /lib/i686/libpthread.so.0
#3 0x485ead37 in pthread_mutex_lock () from /lib/i686/libpthread.so.0
#4 0x402e22fc in vsyslog () from /lib/i686/libc.so.6
#5 0x402e1e6f in syslog () from /lib/i686/libc.so.6
#6 0x081e4a52 in write_syslog (level=5, line=0x4033afac "") at elog.c:1013
#7 0x081e4d7f in send_message_to_server_log (edata=0x82aad80) at elog.c:1146
#8 0x081e3b0c in errfinish (dummy=0) at elog.c:341
#9 0x081e46a6 in elog_finish (elevel=-4, fmt=0x485ac920 "ignoring modified tuple in DELETE trigger")
at elog.c:849
#10 0x485247d2 in PLy_trigger_handler (fcinfo=0xbfffe7c0, proc=0x83428b8) at plpython.c:455
#11 0x485244d0 in plpython_call_handler (fcinfo=0xbfffe7c0) at plpython.c:370
#12 0x080f253e in ExecCallTriggerFunc (trigdata=0xbfffe68c, finfo=0x485df998, per_tuple_context=0xfffffffc)
at trigger.c:1150
#13 0x080f2b7a in ExecBRDeleteTriggers (estate=0x83adbe8, relinfo=0x83adda0, tupleid=0xfffffffc,
cid=4294967292) at trigger.c:1377
#14 0x08105b7c in ExecDelete (slot=0x83ae320, tupleid=0xbfffe9d0, estate=0x83adbe8) at execMain.c:1474
#15 0x08105545 in ExecutePlan (estate=0x83adbe8, planstate=0x83ae340, operation=CMD_DELETE, numberTuples=0,
direction=-4, dest=0x8328698) at execMain.c:1262
#16 0x081046c8 in ExecutorRun (queryDesc=0x8341c20, direction=ForwardScanDirection, count=-4)
at execMain.c:249
#17 0x0817b782 in ProcessQuery (parsetree=0xfffffffc, plan=0x83adbe8, params=0x8, dest=0x0,
completionTag=0x8341c20 "\004") at pquery.c:139
#18 0x0817c2f4 in PortalRunMulti (portal=0x832bdd8, dest=0x8328698, altdest=0x8328698,
completionTag=0xbfffeb30 "") at pquery.c:860
#19 0x0817bc63 in PortalRun (portal=0x832bdd8, count=2147483647, dest=0x8328698, altdest=0xfffffffc,
completionTag=0xbfffeb30 "") at pquery.c:494
#20 0x08178543 in exec_simple_query (
query_string=0x8326720 ' ' <repeats 45 times>, "DELETE FROM dbbq1 WHERE id = 54114") at postgres.c:914
#21 0x0817ad31 in PostgresMain (argc=4, argv=0x82b8168, username=0x82b8138 "admin") at postgres.c:2918
#22 0x08154880 in BackendFork (port=0x82d3008) at postmaster.c:2564
#23 0x08154273 in BackendStartup (port=0x82d3008) at postmaster.c:2207
#24 0x081527d8 in ServerLoop () at postmaster.c:1119
#25 0x08151e9e in PostmasterMain (argc=5, argv=0x82b72a0) at postmaster.c:897
#26 0x08121bd3 in main (argc=5, argv=0xbffffb74) at main.c:214
#27 0x4021aa07 in __libc_start_main () from /lib/i686/libc.so.6
### End of trace two (Process 25376)
