On 24/08/16 16:33, Amit Kapila wrote:
On Wed, Aug 24, 2016 at 9:53 AM, Mark Kirkwood
<mark.kirkw...@catalyst.net.nz> wrote:
On 24/08/16 15:36, Amit Kapila wrote:
On Wed, Aug 24, 2016 at 8:54 AM, Mark Kirkwood
<mark.kirkw...@catalyst.net.nz> wrote:
Can you get the call stacks?
For every stuck backend? (just double checking)...
Yeah.
Cool,
I managed to reproduce with a reduced workload of 4 backends, then
noticed that the traces for 3 of 'em were all the same. So I've attached
the 2 unique ones, plus noted what pg_stat_activity thought the wait
event was, in case that is useful.
Cheers
Mark
$ pgbench -c 4 -T600 bench
postgres=# SELECT pid, state,now()-xact_start AS
wait,wait_event_type,wait_event,query FROM pg_stat_activity WHERE
datname='bench' ORDER BY wait DESC; pid | state | wait |
wait_event_type | wait_event |
query
-------+--------+-----------------+-----------------+----------------+---------------------------------------------------------------------------------------------
-------------------
16549 | active | 00:06:00.252146 | LWLockTranche | buffer_content | INSERT
INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (190, 24, 9513890,
-2566, C
URRENT_TIMESTAMP);
16548 | active | 00:06:00.235003 | LWLockTranche | buffer_content | INSERT
INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (445, 3, 5688076,
1021, CUR
RENT_TIMESTAMP);
16547 | active | 00:06:00.218032 | LWLockTranche | buffer_content | INSERT
INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (803, 97, 6871273,
-35, CUR
RENT_TIMESTAMP);
16546 | active | 00:06:00.192543 | Lock | transactionid | UPDATE
pgbench_branches SET bbalance = bbalance + -2823 WHERE bid = 3;
(4 rows)
postgres@zmori:~$ gdb -p 16546
0x00007f51daa3a133 in __epoll_wait_nocancel ()
at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0x00007f51daa3a133 in __epoll_wait_nocancel ()
at ../sysdeps/unix/syscall-template.S:84
#1 0x00000000006abdb6 in WaitEventSetWaitBlock (nevents=1,
occurred_events=0x7fffd197d3a0, cur_timeout=-1, set=0xdc9288)
at latch.c:987
#2 WaitEventSetWait (set=set@entry=0xdc9288, timeout=timeout@entry=-1,
occurred_events=occurred_events@entry=0x7fffd197d3a0,
nevents=nevents@entry=1) at latch.c:941
#3 0x00000000006ac1ca in WaitLatchOrSocket (latch=0x7f51d9fd969c,
wakeEvents=wakeEvents@entry=1, sock=sock@entry=-1, timeout=-1,
timeout@entry=0) at latch.c:347
#4 0x00000000006ac27d in WaitLatch (latch=<optimized out>,
wakeEvents=wakeEvents@entry=1, timeout=timeout@entry=0) at latch.c:302
#5 0x00000000006bb5e3 in ProcSleep (locallock=locallock@entry=0xd3d690,
lockMethodTable=lockMethodTable@entry=0x9149a0 <default_lockmethod>)
at proc.c:1219
#6 0x00000000006b639d in WaitOnLock (locallock=locallock@entry=0xd3d690,
owner=owner@entry=0xdc4cb0) at lock.c:1703
#7 0x00000000006b7a77 in LockAcquireExtended (
locktag=locktag@entry=0x7fffd197d700, lockmode=lockmode@entry=5,
sessionLock=sessionLock@entry=0 '\000', dontWait=dontWait@entry=0 '\000',
reportMemoryError=reportMemoryError@entry=1 '\001') at lock.c:998
#8 0x00000000006b7d51 in LockAcquire (locktag=locktag@entry=0x7fffd197d700,
lockmode=lockmode@entry=5, sessionLock=sessionLock@entry=0 '\000',
dontWait=dontWait@entry=0 '\000') at lock.c:688
#9 0x00000000006b58fe in XactLockTableWait (xid=xid@entry=7667,
rel=rel@entry=0x7f51db5c6398, ctid=ctid@entry=0x7fffd197d844,
oper=oper@entry=XLTW_Update) at lmgr.c:587
#10 0x00000000004a5d29 in heap_update (relation=relation@entry=0x7f51db5c6398,
otid=otid@entry=0x7fffd197d9e0, newtup=newtup@entry=0xd4b3d0, cid=2,
crosscheck=0x0, wait=wait@entry=1 '\001', hufd=0x7fffd197d8f0,
lockmode=0x7fffd197d8ec) at heapam.c:3755
#11 0x00000000005dbeaa in ExecUpdate (tupleid=tupleid@entry=0x7fffd197d9e0,
oldtuple=oldtuple@entry=0x0, slot=slot@entry=0xd4adb0,
planSlot=planSlot@entry=0xdc8ea0, epqstate=epqstate@entry=0xdc76c8,
estate=estate@entry=0xdc73d0, canSetTag=1 '\001') at nodeModifyTable.c:922
#12 0x00000000005dc633 in ExecModifyTable (node=node@entry=0xdc7620)
at nodeModifyTable.c:1501
#13 0x00000000005c3948 in ExecProcNode (node=node@entry=0xdc7620)
at execProcnode.c:396
#14 0x00000000005bfdbf in ExecutePlan (dest=0xdc9e60,
direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>,
operation=CMD_UPDATE, use_parallel_mode=<optimized out>,
planstate=0xdc7620, estate=0xdc73d0) at execMain.c:1567
#15 standard_ExecutorRun (queryDesc=0xdc6fc0, direction=<optimized out>,
count=0) at execMain.c:338
#16 0x00000000006ce669 in ProcessQuery (plan=<optimized out>,
sourceText=0xd8ff70 "UPDATE pgbench_branches SET bbalance = bbalance +
-2823 WHERE bid = 3;", params=0x0, dest=0xdc9e60, completionTag=0x7fffd197dfc0
"")
---Type <return> to continue, or q <return> to quit---
at pquery.c:187
#17 0x00000000006ce89c in PortalRunMulti (portal=portal@entry=0xd35000,
isTopLevel=isTopLevel@entry=1 '\001',
setHoldSnapshot=setHoldSnapshot@entry=0 '\000', dest=dest@entry=0xdc9e60,
altdest=altdest@entry=0xdc9e60,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:1303
#18 0x00000000006cf34e in PortalRun (portal=portal@entry=0xd35000,
count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1 '\001', dest=dest@entry=0xdc9e60,
altdest=altdest@entry=0xdc9e60,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:815
#19 0x00000000006cc45b in exec_simple_query (
query_string=0xd8ff70 "UPDATE pgbench_branches SET bbalance = bbalance +
-2823 WHERE bid = 3;") at postgres.c:1094
#20 PostgresMain (argc=<optimized out>, argv=argv@entry=0xd16a20,
dbname=0xd16950 "bench", username=<optimized out>) at postgres.c:4074
#21 0x000000000046d509 in BackendRun (port=0xd396e0) at postmaster.c:4262
#22 BackendStartup (port=0xd396e0) at postmaster.c:3936
#23 ServerLoop () at postmaster.c:1693
#24 0x000000000066fb91 in PostmasterMain (argc=argc@entry=1,
argv=argv@entry=0xd15b50) at postmaster.c:1301
#25 0x000000000046e2b0 in main (argc=1, argv=0xd15b50) at main.c:228
(gdb)
postgres@zmori:~$ gdb -p 16548
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.04) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 16548
Reading symbols from /usr/local/pgsql/10/bin/postgres...done.
Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols from
/usr/lib/debug//lib/x86_64-linux-gnu/librt-2.23.so...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols from
/usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.23.so...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols from
/usr/lib/debug//lib/x86_64-linux-gnu/libm-2.23.so...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols from
/usr/lib/debug//lib/x86_64-linux-gnu/libc-2.23.so...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading symbols
from
/usr/lib/debug/.build-id/b7/7847cc9cacbca3b5753d0d25a32e5795afe75b.debug...done.
done.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from
/usr/lib/debug//lib/x86_64-linux-gnu/ld-2.23.so...done.
done.
Reading symbols from /lib/x86_64-linux-gnu/libnss_files.so.2...Reading symbols
from /usr/lib/debug//lib/x86_64-linux-gnu/libnss_files-2.23.so...done.
done.
0x00007f51daa3b387 in semop () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0x00007f51daa3b387 in semop () at ../sysdeps/unix/syscall-template.S:84
#1 0x0000000000660331 in PGSemaphoreLock (sema=sema@entry=0x7f51d9fd9040) at
pg_sema.c:387
#2 0x00000000006bde9b in LWLockAcquire (lock=0x7f51d1a29da4,
mode=LW_EXCLUSIVE) at lwlock.c:1288
#3 0x00000000004978a4 in _hash_doinsert (rel=rel@entry=0x7f51db5c9308,
itup=itup@entry=0xdc90d8) at hashinsert.c:104
#4 0x000000000049617f in hashinsert (rel=0x7f51db5c9308, values=<optimized
out>, isnull=<optimized out>, ht_ctid=0xdc8f9c, heapRel=<optimized out>,
checkUnique=<optimized out>) at hash.c:247
#5 0x00000000005bf060 in ExecInsertIndexTuples (slot=slot@entry=0xdc7a90,
tupleid=tupleid@entry=0xdc8f9c, estate=estate@entry=0xdc73d0,
noDupErr=noDupErr@entry=0 '\000', specConflict=specConflict@entry=0x0,
arbiterIndexes=arbiterIndexes@entry=0x0) at execIndexing.c:388
#6 0x00000000005dd011 in ExecInsert (canSetTag=1 '\001', estate=0xdc73d0,
onconflict=<optimized out>, arbiterIndexes=0x0, planSlot=0xdc7a90,
slot=0xdc7a90,
mtstate=0xdc7620) at nodeModifyTable.c:481
#7 ExecModifyTable (node=node@entry=0xdc7620) at nodeModifyTable.c:1496
#8 0x00000000005c3948 in ExecProcNode (node=node@entry=0xdc7620) at
execProcnode.c:396
#9 0x00000000005bfdbf in ExecutePlan (dest=0xdb7bf8, direction=<optimized
out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_INSERT,
use_parallel_mode=<optimized out>, planstate=0xdc7620, estate=0xdc73d0) at
execMain.c:1567
#10 standard_ExecutorRun (queryDesc=0xdc6fc0, direction=<optimized out>,
count=0) at execMain.c:338
#11 0x00000000006ce669 in ProcessQuery (plan=<optimized out>,
sourceText=0xd8ff70 "INSERT INTO pgbench_history (tid, bid, aid, delta,
mtime) VALUES (445, 3, 5688076, 1021, CURRENT_TIMESTAMP);", params=0x0,
dest=0xdb7bf8, completionTag=0x7fffd197dfc0 "") at pquery.c:187
#12 0x00000000006ce89c in PortalRunMulti (portal=portal@entry=0xd35000,
isTopLevel=isTopLevel@entry=1 '\001', setHoldSnapshot=setHoldSnapshot@entry=0
'\000',
dest=dest@entry=0xdb7bf8, altdest=altdest@entry=0xdb7bf8,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:1303
#13 0x00000000006cf34e in PortalRun (portal=portal@entry=0xd35000,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=1 '\001',
dest=dest@entry=0xdb7bf8, altdest=altdest@entry=0xdb7bf8,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:815
#14 0x00000000006cc45b in exec_simple_query (
query_string=0xd8ff70 "INSERT INTO pgbench_history (tid, bid, aid, delta,
mtime) VALUES (445, 3, 5688076, 1021, CURRENT_TIMESTAMP);") at postgres.c:1094
#15 PostgresMain (argc=<optimized out>, argv=argv@entry=0xd16a20,
dbname=0xd16950 "bench", username=<optimized out>) at postgres.c:4074
#16 0x000000000046d509 in BackendRun (port=0xd396e0) at postmaster.c:4262
#17 BackendStartup (port=0xd396e0) at postmaster.c:3936
#18 ServerLoop () at postmaster.c:1693
#19 0x000000000066fb91 in PostmasterMain (argc=argc@entry=1,
argv=argv@entry=0xd15b50) at postmaster.c:1301
#20 0x000000000046e2b0 in main (argc=1, argv=0xd15b50) at main.c:228
(gdb)
postgres@zmori:~$ gdb -p 16548
0x00007f51daa3b387 in semop () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0x00007f51daa3b387 in semop () at ../sysdeps/unix/syscall-template.S:84
#1 0x0000000000660331 in PGSemaphoreLock (sema=sema@entry=0x7f51d9fd9040) at
pg_sema.c:387
#2 0x00000000006bde9b in LWLockAcquire (lock=0x7f51d1a29da4,
mode=LW_EXCLUSIVE) at lwlock.c:1288
#3 0x00000000004978a4 in _hash_doinsert (rel=rel@entry=0x7f51db5c9308,
itup=itup@entry=0xdc90d8) at hashinsert.c:104
#4 0x000000000049617f in hashinsert (rel=0x7f51db5c9308, values=<optimized
out>, isnull=<optimized out>, ht_ctid=0xdc8f9c, heapRel=<optimized out>,
checkUnique=<optimized out>) at hash.c:247
#5 0x00000000005bf060 in ExecInsertIndexTuples (slot=slot@entry=0xdc7a90,
tupleid=tupleid@entry=0xdc8f9c, estate=estate@entry=0xdc73d0,
noDupErr=noDupErr@entry=0 '\000', specConflict=specConflict@entry=0x0,
arbiterIndexes=arbiterIndexes@entry=0x0) at execIndexing.c:388
#6 0x00000000005dd011 in ExecInsert (canSetTag=1 '\001', estate=0xdc73d0,
onconflict=<optimized out>, arbiterIndexes=0x0, planSlot=0xdc7a90,
slot=0xdc7a90,
mtstate=0xdc7620) at nodeModifyTable.c:481
#7 ExecModifyTable (node=node@entry=0xdc7620) at nodeModifyTable.c:1496
#8 0x00000000005c3948 in ExecProcNode (node=node@entry=0xdc7620) at
execProcnode.c:396
#9 0x00000000005bfdbf in ExecutePlan (dest=0xdb7bf8, direction=<optimized
out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_INSERT,
use_parallel_mode=<optimized out>, planstate=0xdc7620, estate=0xdc73d0) at
execMain.c:1567
#10 standard_ExecutorRun (queryDesc=0xdc6fc0, direction=<optimized out>,
count=0) at execMain.c:338
#11 0x00000000006ce669 in ProcessQuery (plan=<optimized out>,
sourceText=0xd8ff70 "INSERT INTO pgbench_history (tid, bid, aid, delta,
mtime) VALUES (445, 3, 5688076, 1021, CURRENT_TIMESTAMP);", params=0x0,
dest=0xdb7bf8, completionTag=0x7fffd197dfc0 "") at pquery.c:187
#12 0x00000000006ce89c in PortalRunMulti (portal=portal@entry=0xd35000,
isTopLevel=isTopLevel@entry=1 '\001', setHoldSnapshot=setHoldSnapshot@entry=0
'\000',
dest=dest@entry=0xdb7bf8, altdest=altdest@entry=0xdb7bf8,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:1303
#13 0x00000000006cf34e in PortalRun (portal=portal@entry=0xd35000,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=1 '\001',
dest=dest@entry=0xdb7bf8, altdest=altdest@entry=0xdb7bf8,
completionTag=completionTag@entry=0x7fffd197dfc0 "") at pquery.c:815
#14 0x00000000006cc45b in exec_simple_query (
query_string=0xd8ff70 "INSERT INTO pgbench_history (tid, bid, aid, delta,
mtime) VALUES (445, 3, 5688076, 1021, CURRENT_TIMESTAMP);") at postgres.c:1094
#15 PostgresMain (argc=<optimized out>, argv=argv@entry=0xd16a20,
dbname=0xd16950 "bench", username=<optimized out>) at postgres.c:4074
#16 0x000000000046d509 in BackendRun (port=0xd396e0) at postmaster.c:4262
#17 BackendStartup (port=0xd396e0) at postmaster.c:3936
#18 ServerLoop () at postmaster.c:1693
#19 0x000000000066fb91 in PostmasterMain (argc=argc@entry=1,
argv=argv@entry=0xd15b50) at postmaster.c:1301
#20 0x000000000046e2b0 in main (argc=1, argv=0xd15b50) at main.c:228
(gdb)
(16547, 16548, 16549 all look the same)
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
