Re: Re: Monitoring activities of PostgreSQL ("Everlasting" function execution)

On Wed, Jun 16, 2010 at 1:15 PM, Craig Ringer
<craig@postnewspapers.com.au> wrote:
> On 16/06/10 16:56, Allan Kamau wrote:
>
>> The function I have mentioned above seems to "hang" indefinitely (now
>> 12hours and counting) while it took only 2secs for the many times it
>> was previously invoked from the client application (with slightly
>> different parameter value at each such time).
>
> Is there anything in pg_catalog.pg_locks that relates to that query?
>
> If you attach a debugger to the stalled backend and get a backtrace,
> what's the output? See:
>
> http://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD
>
> If you strace the problem backend, does it appear to be doing anything?
>
> --
> Craig Ringer
>
> Tech-related writing: http://soapyfrogs.blogspot.com/
>


The pg_catalog.pg_locks table does indeed have 20 records pertaining
to the "everlasting" function
(mining.perform_itemset_fragment_mining()) execution. Please have a
look at the query output below.


po12=> SELECT a.* FROM pg_stat_activity a;
  datid  | datname | procpid | usesysid | usename |
         current_query                              | waiting |
  xact_start           |
      query_start          |         backend_start         |
client_addr | client_port

---------+---------+---------+----------+---------+------------------------------------------------------------------------+---------+-------------------------------+----
---------------------------+-------------------------------+-------------+-------------
 1936449 | po12    |   14277 |    16392 | test    | SELECT a.* FROM
pg_stat_activity a;                                    | f       |
2010-06-17 13:56:50.129498+03 | 201
0-06-17 13:56:50.129498+03 | 2010-06-17 13:15:23.018817+03 |
  |          -1
 1936449 | po12    |   14657 |    16392 | test    | SELECT
mining.perform_itemset_fragment_mining($1,$2,$3,$4,$5,$6,$7,$8) | f
   | 2010-06-17 13:33:13.315609+03 | 201
0-06-17 13:33:13.319398+03 | 2010-06-17 13:22:33.606603+03 | 127.0.0.1
  |       36211
(2 rows)

po12=> SELECT a.* FROM pg_catalog.pg_locks a;
   locktype    | database | relation | page | tuple | virtualxid |
transactionid | classid |  objid  | objsubid | virtualtransaction |
pid  |        mode         | grant
ed

---------------+----------+----------+------+-------+------------+---------------+---------+---------+----------+--------------------+-------+---------------------+------
---
 object        |  1936449 |          |      |       |            |
          |    1247 | 3546410 |        0 | 1/6500             | 14657
| AccessExclusiveLock | t
 virtualxid    |          |          |      |       | 1/6500     |
          |         |         |          | 1/6500             | 14657
| ExclusiveLock       | t
 object        |        0 |          |      |       |            |
          |    1260 |   16392 |        0 | 1/6500             | 14657
| AccessShareLock     | t
 relation      |  1936449 |  3529708 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessShareLock     | t
 relation      |  1936449 |  3546485 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessExclusiveLock | t
 transactionid |          |          |      |       |            |
  1548543 |         |         |          | 1/6500             | 14657
| ExclusiveLock       | t
 relation      |  1936449 |  3546409 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessExclusiveLock | t
 relation      |  1936449 |  3529699 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessShareLock     | t
 relation      |  1936449 |  3546477 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessExclusiveLock | t
 relation      |  1936449 |  3529709 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessShareLock     | t
 virtualxid    |          |          |      |       | 2/271      |
          |         |         |          | 2/271              | 14277
| ExclusiveLock       | t
 relation      |  1936449 |  3546483 |      |       |            |
          |         |         |          | 1/6500             | 14657
| ShareLock           | t
 relation      |  1936449 |    10969 |      |       |            |
          |         |         |          | 2/271              | 14277
| AccessShareLock     | t
 relation      |  1936449 |  3529706 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessShareLock     | t
 relation      |  1936449 |  3546486 |      |       |            |
          |         |         |          | 1/6500             | 14657
| RowExclusiveLock    | t
 relation      |  1936449 |  3546486 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessExclusiveLock | t
 relation      |  1936449 |  3546479 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessShareLock     | t
 relation      |  1936449 |  3546479 |      |       |            |
          |         |         |          | 1/6500             | 14657
| RowExclusiveLock    | t
 relation      |  1936449 |  3546479 |      |       |            |
          |         |         |          | 1/6500             | 14657
| ShareLock           | t
 relation      |  1936449 |  3546479 |      |       |            |
          |         |         |          | 1/6500             | 14657
| AccessExclusiveLock | t
(20 rows)





I did try collecting the trace of the process 14657 using gdb (as
advised in the suggested resource
"http://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD")
and this is how it looks like.

Continuing.

Program received signal SIGINT, Interrupt.
0x0000000000a1a8cd in pg_detoast_datum (datum=0xe52318c) at fmgr.c:2217
2217        if (VARATT_IS_EXTENDED(datum))
#0  0x0000000000a1a8cd in pg_detoast_datum (datum=0xe52318c) at fmgr.c:2217
#1  0x00000000009771b3 in bitcmp (fcinfo=0x7fff4ebd2170) at varbit.c:857
#2  0x0000000000a5c9d0 in myFunctionCall2 (flinfo=0x341c0b0,
arg1=240267660, arg2=162198044) at tuplesort.c:2511
#3  0x0000000000a5cb65 in inlineApplySortFunction
(sortFunction=0x341c0b0, sk_flags=0, datum1=240267660, isNull1=0
'\000', datum2=162198044, isNull2=0 '\000') at tuplesort.c:2551
#4  0x0000000000a5cce8 in comparetup_heap (a=0x7fc84c82fe70,
b=0x7fc84c82fe88, state=0x341be88) at tuplesort.c:2594
#5  0x0000000000a5c4ba in tuplesort_heap_siftup (state=0x341be88,
checkIndex=1 '\001') at tuplesort.c:2435
#6  0x0000000000a5af75 in dumptuples (state=0x341be88, alltuples=0
'\000') at tuplesort.c:2070
#7  0x0000000000a57d1c in puttuple_common (state=0x341be88,
tuple=0x7fff4ebd2700) at tuplesort.c:1097
#8  0x0000000000a5754d in tuplesort_puttupleslot (state=0x341be88,
slot=0x342d7b8) at tuplesort.c:921
#9  0x00000000006eee50 in ExecSort (node=0x347ac98) at nodeSort.c:107
#10 0x00000000006ba46b in ExecProcNode (node=0x347ac98) at execProcnode.c:423
#11 0x00000000006ef4f4 in ExecUnique (node=0x347ab80) at nodeUnique.c:69
#12 0x00000000006ba54f in ExecProcNode (node=0x347ab80) at execProcnode.c:439
#13 0x00000000006f75be in SubqueryNext (node=0x347a8d8) at nodeSubqueryscan.c:58
#14 0x00000000006cc9ee in ExecScan (node=0x347a8d8, accessMtd=0x6f7588
<SubqueryNext>) at execScan.c:103
#15 0x00000000006f7620 in ExecSubqueryScan (node=0x347a8d8) at
nodeSubqueryscan.c:85
#16 0x00000000006ba26a in ExecProcNode (node=0x347a8d8) at execProcnode.c:381
#17 0x00000000006ef4f4 in ExecUnique (node=0x347a7c0) at nodeUnique.c:69
#18 0x00000000006ba54f in ExecProcNode (node=0x347a7c0) at execProcnode.c:439
#19 0x00000000006f75be in SubqueryNext (node=0x342df00) at nodeSubqueryscan.c:58
#20 0x00000000006cc9ee in ExecScan (node=0x342df00, accessMtd=0x6f7588
<SubqueryNext>) at execScan.c:103
#21 0x00000000006f7620 in ExecSubqueryScan (node=0x342df00) at
nodeSubqueryscan.c:85
#22 0x00000000006ba26a in ExecProcNode (node=0x342df00) at execProcnode.c:381
#23 0x00000000006b4faa in ExecutePlan (estate=0x342c038,
planstate=0x342df00, operation=CMD_INSERT, numberTuples=0,
direction=ForwardScanDirection, dest=0xe7bf40) at execMain.c:1504
#24 0x00000000006b1496 in standard_ExecutorRun (queryDesc=0x36fb6d8,
direction=ForwardScanDirection, count=0) at execMain.c:309
#25 0x00000000006b122d in ExecutorRun (queryDesc=0x36fb6d8,
direction=ForwardScanDirection, count=0) at execMain.c:258
#26 0x00000000007062cb in _SPI_pquery (queryDesc=0x36fb6d8,
fire_triggers=1 '\001', tcount=0) at spi.c:2009
#27 0x0000000000705b9c in _SPI_execute_plan (plan=0x7fff4ebd2dd0,
paramLI=0x339b578, snapshot=0x0, crosscheck_snapshot=0x0, read_only=0
'\000', fire_triggers=1 '\001', tcount=0) at spi.c:1831
#28 0x0000000000700d2b in SPI_execute_with_args (src=0x27ae950 "
INSERT INTO _itemset_fragment_major ( itemset_fragment_item_bit_code
,itemset_fragment_item_bit_code_overhang ) SELECT DISTINCT
itemset_fragment_item_bit_code
,itemset_fragment_item_bit_code_overhang"..., nargs=6,
argtypes=0x27aedc0, Values=0x27aedf8, Nulls=0x27ae518 "
~\177\330XG\003", read_only=0 '\000', tcount=0) at spi.c:495
#29 0x00007fc851dae0f7 in exec_stmt_dynexecute (estate=0x7fff4ebd31b0,
stmt=0x2864d80) at pl_exec.c:2945
#30 0x00007fc851da8505 in exec_stmt (estate=0x7fff4ebd31b0,
stmt=0x2864d80) at pl_exec.c:1301
#31 0x00007fc851da7f2f in exec_stmts (estate=0x7fff4ebd31b0,
stmts=0x28640c0) at pl_exec.c:1200
#32 0x00007fc851da8b88 in exec_stmt_if (estate=0x7fff4ebd31b0,
stmt=0x2873290) at pl_exec.c:1435
#33 0x00007fc851da81d2 in exec_stmt (estate=0x7fff4ebd31b0,
stmt=0x2873290) at pl_exec.c:1249
#34 0x00007fc851da7f2f in exec_stmts (estate=0x7fff4ebd31b0,
stmts=0x2863418) at pl_exec.c:1200
#35 0x00007fc851da7cd2 in exec_stmt_block (estate=0x7fff4ebd31b0,
block=0x2886810) at pl_exec.c:1137
#36 0x00007fc851da5301 in plpgsql_exec_function (func=0x2855050,
fcinfo=0x7fff4ebd3480) at pl_exec.c:315
#37 0x00007fc851d9da08 in plpgsql_call_handler (fcinfo=0x7fff4ebd3480)
at pl_handler.c:95
#38 0x00000000006c06ba in ExecMakeFunctionResult (fcache=0x28b5550,
econtext=0x28b5420, isNull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", isDone=0x28b6378) at
execQual.c:1789
#39 0x00000000006c1750 in ExecEvalFunc (fcache=0x28b5550,
econtext=0x28b5420, isNull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", isDone=0x28b6378) at
execQual.c:2215
#40 0x00000000006cbe44 in ExecTargetList (targetlist=0x28b6340,
econtext=0x28b5420, values=0x28b6218, isnull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", itemIsDone=0x28b6378,
isDone=0x7fff4ebd3a34) at execQual.c:5108
#41 0x00000000006cc743 in ExecProject (projInfo=0x28b6258,
isDone=0x7fff4ebd3a34) at execQual.c:5323
#42 0x00000000006ec5b0 in ExecResult (node=0x28b5308) at nodeResult.c:155
#43 0x00000000006ba0db in ExecProcNode (node=0x28b5308) at execProcnode.c:344
#44 0x00000000006b4faa in ExecutePlan (estate=0x28b50d8,
planstate=0x28b5308, operation=CMD_SELECT, numberTuples=0,
direction=ForwardScanDirection, dest=0x2723890) at execMain.c:1504
#45 0x00000000006b1496 in standard_ExecutorRun (queryDesc=0x2777a38,
direction=ForwardScanDirection, count=0) at execMain.c:309
#46 0x00000000006b122d in ExecutorRun (queryDesc=0x2777a38,
direction=ForwardScanDirection, count=0) at execMain.c:258
#47 0x000000000087d517 in PortalRunSelect (portal=0x2787398, forward=1
'\001', count=0, dest=0x2723890) at pquery.c:953
#48 0x000000000087ce98 in PortalRun (portal=0x2787398,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x2723890,
altdest=0x2723890, completionTag=0x7fff4ebd3e60 "") at pquery.c:779
#49 0x0000000000874ad3 in exec_execute_message (portal_name=0x2723478
"", max_rows=9223372036854775807) at postgres.c:1928
#50 0x0000000000879efd in PostgresMain (argc=4, argv=0x2678b50,
username=0x2678900 "test") at postgres.c:3671
#51 0x0000000000809631 in BackendRun (port=0x2699140) at postmaster.c:3449
#52 0x0000000000808352 in BackendStartup (port=0x2699140) at postmaster.c:3063
#53 0x0000000000802cd0 in ServerLoop () at postmaster.c:1387
#54 0x0000000000801b19 in PostmasterMain (argc=6, argv=0x26746e0) at
postmaster.c:1040
#55 0x0000000000720646 in main (argc=6, argv=0x26746e0) at main.c:188
Continuing.

Program received signal SIGINT, Interrupt.
0x0000003775ce0fcb in __mcount_internal () from /lib64/libc.so.6
#0  0x0000003775ce0fcb in __mcount_internal () from /lib64/libc.so.6
#1  0x0000003775ce1c74 in mcount () from /lib64/libc.so.6
#2  0x00007fff4ebd1990 in ?? ()
#3  0x0000000000000003 in ?? ()
#4  0x00000000009781b2 in bitxor (fcinfo=0x7fff4ebd1950) at varbit.c:1167
#5  0x00007fff4ebd1950 in ?? ()
#6  0x00007fff4ebd1990 in ?? ()
#7  0x00000000006bcf45 in ExecEvalVar (exprstate=0x7fff4ebd1990,
econtext=0x7fff4ebd1950, isNull=0x7fff4ebd1950 "", isDone=0x3) at
execQual.c:748
#8  0x0000000000600000 in check_index_is_clusterable
(OldHeap=0xc78948de89488845, indexOid=2336784477, recheck=-1 '\377')
at cluster.c:446
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
Continuing.

Program received signal SIGINT, Interrupt.
0x0000000000a5cd99 in comparetup_heap (a=0x7fc84c99f880,
b=0x7fc84c99f898, state=0x341be88) at tuplesort.c:2615
2615            datum1 = heap_getattr(<up, attno, tupDesc, &isnull1);
#0  0x0000000000a5cd99 in comparetup_heap (a=0x7fc84c99f880,
b=0x7fc84c99f898, state=0x341be88) at tuplesort.c:2615
#1  0x0000000000a5c4ba in tuplesort_heap_siftup (state=0x341be88,
checkIndex=1 '\001') at tuplesort.c:2435
#2  0x0000000000a5af75 in dumptuples (state=0x341be88, alltuples=0
'\000') at tuplesort.c:2070
#3  0x0000000000a57d1c in puttuple_common (state=0x341be88,
tuple=0x7fff4ebd2700) at tuplesort.c:1097
#4  0x0000000000a5754d in tuplesort_puttupleslot (state=0x341be88,
slot=0x342d7b8) at tuplesort.c:921
#5  0x00000000006eee50 in ExecSort (node=0x347ac98) at nodeSort.c:107
#6  0x00000000006ba46b in ExecProcNode (node=0x347ac98) at execProcnode.c:423
#7  0x00000000006ef4f4 in ExecUnique (node=0x347ab80) at nodeUnique.c:69
#8  0x00000000006ba54f in ExecProcNode (node=0x347ab80) at execProcnode.c:439
#9  0x00000000006f75be in SubqueryNext (node=0x347a8d8) at nodeSubqueryscan.c:58
#10 0x00000000006cc9ee in ExecScan (node=0x347a8d8, accessMtd=0x6f7588
<SubqueryNext>) at execScan.c:103
#11 0x00000000006f7620 in ExecSubqueryScan (node=0x347a8d8) at
nodeSubqueryscan.c:85
#12 0x00000000006ba26a in ExecProcNode (node=0x347a8d8) at execProcnode.c:381
#13 0x00000000006ef4f4 in ExecUnique (node=0x347a7c0) at nodeUnique.c:69
#14 0x00000000006ba54f in ExecProcNode (node=0x347a7c0) at execProcnode.c:439
#15 0x00000000006f75be in SubqueryNext (node=0x342df00) at nodeSubqueryscan.c:58
#16 0x00000000006cc9ee in ExecScan (node=0x342df00, accessMtd=0x6f7588
<SubqueryNext>) at execScan.c:103
#17 0x00000000006f7620 in ExecSubqueryScan (node=0x342df00) at
nodeSubqueryscan.c:85
#18 0x00000000006ba26a in ExecProcNode (node=0x342df00) at execProcnode.c:381
#19 0x00000000006b4faa in ExecutePlan (estate=0x342c038,
planstate=0x342df00, operation=CMD_INSERT, numberTuples=0,
direction=ForwardScanDirection, dest=0xe7bf40) at execMain.c:1504
#20 0x00000000006b1496 in standard_ExecutorRun (queryDesc=0x36fb6d8,
direction=ForwardScanDirection, count=0) at execMain.c:309
#21 0x00000000006b122d in ExecutorRun (queryDesc=0x36fb6d8,
direction=ForwardScanDirection, count=0) at execMain.c:258
#22 0x00000000007062cb in _SPI_pquery (queryDesc=0x36fb6d8,
fire_triggers=1 '\001', tcount=0) at spi.c:2009
#23 0x0000000000705b9c in _SPI_execute_plan (plan=0x7fff4ebd2dd0,
paramLI=0x339b578, snapshot=0x0, crosscheck_snapshot=0x0, read_only=0
'\000', fire_triggers=1 '\001', tcount=0) at spi.c:1831
#24 0x0000000000700d2b in SPI_execute_with_args (src=0x27ae950 "
INSERT INTO _itemset_fragment_major ( itemset_fragment_item_bit_code
,itemset_fragment_item_bit_code_overhang ) SELECT DISTINCT
itemset_fragment_item_bit_code
,itemset_fragment_item_bit_code_overhang"..., nargs=6,
argtypes=0x27aedc0, Values=0x27aedf8, Nulls=0x27ae518 "
~\177\330XG\003", read_only=0 '\000', tcount=0) at spi.c:495
#25 0x00007fc851dae0f7 in exec_stmt_dynexecute (estate=0x7fff4ebd31b0,
stmt=0x2864d80) at pl_exec.c:2945
#26 0x00007fc851da8505 in exec_stmt (estate=0x7fff4ebd31b0,
stmt=0x2864d80) at pl_exec.c:1301
#27 0x00007fc851da7f2f in exec_stmts (estate=0x7fff4ebd31b0,
stmts=0x28640c0) at pl_exec.c:1200
#28 0x00007fc851da8b88 in exec_stmt_if (estate=0x7fff4ebd31b0,
stmt=0x2873290) at pl_exec.c:1435
#29 0x00007fc851da81d2 in exec_stmt (estate=0x7fff4ebd31b0,
stmt=0x2873290) at pl_exec.c:1249
#30 0x00007fc851da7f2f in exec_stmts (estate=0x7fff4ebd31b0,
stmts=0x2863418) at pl_exec.c:1200
#31 0x00007fc851da7cd2 in exec_stmt_block (estate=0x7fff4ebd31b0,
block=0x2886810) at pl_exec.c:1137
#32 0x00007fc851da5301 in plpgsql_exec_function (func=0x2855050,
fcinfo=0x7fff4ebd3480) at pl_exec.c:315
#33 0x00007fc851d9da08 in plpgsql_call_handler (fcinfo=0x7fff4ebd3480)
at pl_handler.c:95
#34 0x00000000006c06ba in ExecMakeFunctionResult (fcache=0x28b5550,
econtext=0x28b5420, isNull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", isDone=0x28b6378) at
execQual.c:1789
#35 0x00000000006c1750 in ExecEvalFunc (fcache=0x28b5550,
econtext=0x28b5420, isNull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", isDone=0x28b6378) at
execQual.c:2215
#36 0x00000000006cbe44 in ExecTargetList (targetlist=0x28b6340,
econtext=0x28b5420, values=0x28b6218, isnull=0x28b6238
"\177~\177\177\177\177\177\177x\215B\003", itemIsDone=0x28b6378,
isDone=0x7fff4ebd3a34) at execQual.c:5108
#37 0x00000000006cc743 in ExecProject (projInfo=0x28b6258,
isDone=0x7fff4ebd3a34) at execQual.c:5323
#38 0x00000000006ec5b0 in ExecResult (node=0x28b5308) at nodeResult.c:155
#39 0x00000000006ba0db in ExecProcNode (node=0x28b5308) at execProcnode.c:344
#40 0x00000000006b4faa in ExecutePlan (estate=0x28b50d8,
planstate=0x28b5308, operation=CMD_SELECT, numberTuples=0,
direction=ForwardScanDirection, dest=0x2723890) at execMain.c:1504
#41 0x00000000006b1496 in standard_ExecutorRun (queryDesc=0x2777a38,
direction=ForwardScanDirection, count=0) at execMain.c:309
#42 0x00000000006b122d in ExecutorRun (queryDesc=0x2777a38,
direction=ForwardScanDirection, count=0) at execMain.c:258
#43 0x000000000087d517 in PortalRunSelect (portal=0x2787398, forward=1
'\001', count=0, dest=0x2723890) at pquery.c:953
#44 0x000000000087ce98 in PortalRun (portal=0x2787398,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x2723890,
altdest=0x2723890, completionTag=0x7fff4ebd3e60 "") at pquery.c:779
#45 0x0000000000874ad3 in exec_execute_message (portal_name=0x2723478
"", max_rows=9223372036854775807) at postgres.c:1928
#46 0x0000000000879efd in PostgresMain (argc=4, argv=0x2678b50,
username=0x2678900 "test") at postgres.c:3671
#47 0x0000000000809631 in BackendRun (port=0x2699140) at postmaster.c:3449
#48 0x0000000000808352 in BackendStartup (port=0x2699140) at postmaster.c:3063
#49 0x0000000000802cd0 in ServerLoop () at postmaster.c:1387
#50 0x0000000000801b19 in PostmasterMain (argc=6, argv=0x26746e0) at
postmaster.c:1040
#51 0x0000000000720646 in main (argc=6, argv=0x26746e0) at main.c:188