pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedBUG #15290: Stuck Parallel Index Scan query
16+ messages / 5 participants
[nested] [flat]
Commits from this thread:
2018-07-27 8ce29bb4f0 09a5be587b ff8ce0b790 Fix the buffer release order for parallel index scans.
* BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-22 18:30 PG Bug reporting form <noreply@postgresql.org>
0 siblings, 2 replies; 16+ messages in thread
From: PG Bug reporting form @ 2018-07-22 18:30 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org; +Cc: vyegorov@gmail.com
The following bug has been logged on the website:
Bug reference: 15290
Logged by: Victor Yegorov
Email address: vyegorov@gmail.com
PostgreSQL version: 10.4
Operating system: Debian GNU/Linux 8.7 (jessie)
Description:
We've just encountered an issue on the streaming replica of the client.
In short — query is active for 8 hours and we're not able to terminate it:
all processes (leader and workers) are ignoring all signals.
Symptoms are similar to the ones described in #15036. As a result, we had to
perform immediate shutdown f the instance.
After restart we've got another such stuck query within minutes, so it's not
a single occurrence..
Query in subject
----------------
-[ RECORD 1
]-----------------------------------------------------------------------------------------------------
ts_age | 08:32:17.286343
state | active
query_age | 08:32:17.286345
change_age | 08:32:17.286344
datname | coub
pid | 2877
usename | app
waiting | f
client_addr |
client_port | -1
query | select count(*) as value from coubs where type='Coub::Simple'
and is_done=false and in_process=false
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=666001.67..666001.72 rows=1 width=8)
-> Gather (cost=666001.20..666001.65 rows=8 width=8)
Workers Planned: 8
-> Partial Aggregate (cost=665901.20..665901.25 rows=1 width=8)
-> Parallel Index Scan using
coubs_type_is_done_partial_simple on coubs (cost=0.56..663016.01
rows=1154077 width=0)
Index Cond: (is_done = false)
Filter: ((NOT is_done) AND (NOT in_process))
(7 rows)
In reality this query worked with just 4 workers:
2877 ? ts 0:08 \_ postgres: 10/main: app coub [local] SELECT
3416 ? Ss 0:00 \_ postgres: 10/main: bgworker: parallel worker
for PID 2877
3417 ? Ss 0:00 \_ postgres: 10/main: bgworker: parallel worker
for PID 2877
3418 ? Ss 0:00 \_ postgres: 10/main: bgworker: parallel worker
for PID 2877
3419 ? Ss 0:00 \_ postgres: 10/main: bgworker: parallel worker
for PID 2877
We have backtraces of the main process and all workers, and also
`pg_stat_activity` snapshot — I will attach them to the new e-mail.
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-22 18:33 Victor Yegorov <vyegorov@gmail.com>
parent: PG Bug reporting form <noreply@postgresql.org>
1 sibling, 0 replies; 16+ messages in thread
From: Victor Yegorov @ 2018-07-22 18:33 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org
вс, 22 июл. 2018 г. в 21:31, PG Bug reporting form <noreply@postgresql.org>:
> The following bug has been logged on the website:
>
> Bug reference: 15290
> Logged by: Victor Yegorov
> Email address: vyegorov@gmail.com
> PostgreSQL version: 10.4
> Operating system: Debian GNU/Linux 8.7 (jessie)
>
And here're backtraces and pg_stat_activity snapshot.
--
Victor Yegorov
Attachments:
20180722-15290-pg_stat_activity.txt (text/plain, 3.9K) download
-[ RECORD 2 ]----+-----------------------------------------------------------------------------------------------------
datid | 16401
datname | coub
pid | 3416
usesysid | 16384
usename | app
application_name |
client_addr |
client_hostname |
client_port |
backend_start | 2018-07-22 12:01:15.035754+03
xact_start | 2018-07-22 12:01:15.035121+03
query_start | 2018-07-22 12:01:15.035121+03
state_change | 2018-07-22 12:01:15.036292+03
wait_event_type | IPC
wait_event | BtreePage
state | active
backend_xid |
backend_xmin | 1172840663
query | select count(*) as value from coubs where type='Coub::Simple' and is_done=false and in_process=false
backend_type | background worker
-[ RECORD 3 ]----+-----------------------------------------------------------------------------------------------------
datid | 16401
datname | coub
pid | 3417
usesysid | 16384
usename | app
application_name |
client_addr |
client_hostname |
client_port |
backend_start | 2018-07-22 12:01:15.037382+03
xact_start | 2018-07-22 12:01:15.036679+03
query_start | 2018-07-22 12:01:15.036679+03
state_change | 2018-07-22 12:01:15.037955+03
wait_event_type | IPC
wait_event | BtreePage
state | active
backend_xid |
backend_xmin | 1172840663
query | select count(*) as value from coubs where type='Coub::Simple' and is_done=false and in_process=false
backend_type | background worker
-[ RECORD 4 ]----+-----------------------------------------------------------------------------------------------------
datid | 16401
datname | coub
pid | 2877
usesysid | 16384
usename | app
application_name |
client_addr |
client_hostname |
client_port | -1
backend_start | 2018-07-22 11:59:15.039972+03
xact_start | 2018-07-22 12:01:15.032002+03
query_start | 2018-07-22 12:01:15.032002+03
state_change | 2018-07-22 12:01:15.032003+03
wait_event_type | IPC
wait_event | BgWorkerShutdown
state | active
backend_xid |
backend_xmin | 1172840663
query | select count(*) as value from coubs where type='Coub::Simple' and is_done=false and in_process=false
backend_type | client backend
-[ RECORD 5 ]----+-----------------------------------------------------------------------------------------------------
datid | 16401
datname | coub
pid | 3418
usesysid | 16384
usename | app
application_name |
client_addr |
client_hostname |
client_port |
backend_start | 2018-07-22 12:01:15.038647+03
xact_start | 2018-07-22 12:01:15.038105+03
query_start | 2018-07-22 12:01:15.038105+03
state_change | 2018-07-22 12:01:15.039151+03
wait_event_type | IPC
wait_event | BtreePage
state | active
backend_xid |
backend_xmin | 1172840663
query | select count(*) as value from coubs where type='Coub::Simple' and is_done=false and in_process=false
backend_type | background worker
-[ RECORD 6 ]----+-----------------------------------------------------------------------------------------------------
datid | 16401
datname | coub
pid | 3419
usesysid | 16384
usename | app
application_name |
client_addr |
client_hostname |
client_port |
backend_start | 2018-07-22 12:01:15.040754+03
xact_start | 2018-07-22 12:01:15.039853+03
query_start | 2018-07-22 12:01:15.039853+03
state_change | 2018-07-22 12:01:15.041481+03
wait_event_type | IPC
wait_event | BtreePage
state | active
backend_xid |
backend_xmin | 1172840663
query | select count(*) as value from coubs where type='Coub::Simple' and is_done=false and in_process=false
backend_type | background worker
20180722-15290-gdb.txt (text/plain, 26.9K) download
gdb -p 2877
-----------
#0 0x00007f5393dcbbe3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f5396957f51 in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffdf412c3f0, cur_timeout=-1, set=0x7f5398d62838) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1048
#2 WaitEventSetWait (set=set@entry=0x7f5398d62838, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffdf412c3f0, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217728) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1000
#3 0x00007f53969583d4 in WaitLatchOrSocket (latch=0x7f536ba54d84, wakeEvents=wakeEvents@entry=17, sock=sock@entry=-1, timeout=-1, timeout@entry=0, wait_event_info=wait_event_info@entry=134217728) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:385
#4 0x00007f5396958485 in WaitLatch (latch=<optimized out>, wakeEvents=wakeEvents@entry=17, timeout=timeout@entry=0, wait_event_info=wait_event_info@entry=134217728) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:339
#5 0x00007f53968fc6fb in WaitForBackgroundWorkerShutdown (handle=0x7f5398d092c0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/bgworker.c:1154
#6 0x00007f5396722cbd in WaitForParallelWorkersToExit (pcxt=0x7f5398d08ba8, pcxt=0x7f5398d08ba8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:655
#7 0x00007f53967239d7 in DestroyParallelContext (pcxt=0x7f5398d08ba8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:737
#8 0x00007f539672401d in AtEOXact_Parallel (isCommit=isCommit@entry=0 '\000') at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:1006
#9 0x00007f539672f477 in AbortTransaction () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/xact.c:2538
#10 0x00007f539672fb65 in AbortCurrentTransaction () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/xact.c:3097
#11 0x00007f539697ba5e in PostgresMain (argc=1, argv=argv@entry=0x7f5398d1bbc8, dbname=0x7f5398d1bb98 "coub", username=0x7f5398d1bbb0 "app") at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/tcop/postgres.c:3879
#12 0x00007f53966b41a7 in BackendRun (port=0x7f5398d0c070) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:4405
#13 BackendStartup (port=0x7f5398d0c070) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:4077
#14 ServerLoop () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1755
#15 0x00007f539690ae2d in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1363
#16 0x00007f53966b558b in main (argc=5, argv=0x7f5398ce95f0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/main/main.c:228
gdb -p 3416
-----------
#0 0x00007f5393dcbbe3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f5396957f51 in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffdf412a460, cur_timeout=-1, set=0x7f5398d23378)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1048
#2 WaitEventSetWait (set=0x7f5398d23378, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffdf412a460, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1000
#3 0x00007f539697196b in ConditionVariableSleep (cv=cv@entry=0x7f5396e17178, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/lmgr/condition_variable.c:149
#4 0x00007f5396707057 in _bt_parallel_seize (scan=scan@entry=0x7f5398db1bb0, pageno=pageno@entry=0x7ffdf412a54c)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:811
#5 0x00007f5396707f7a in _bt_readnextpage (scan=scan@entry=0x7f5398db1bb0, blkno=0, dir=dir@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1498
#6 0x00007f5396708de7 in _bt_parallel_readpage (dir=ForwardScanDirection, blkno=<optimized out>, scan=0x7f5398db1bb0)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1631
#7 _bt_first (scan=scan@entry=0x7f5398db1bb0, dir=dir@entry=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:591
#8 0x00007f5396705e99 in btgettuple (scan=0x7f5398db1bb0, dir=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:372
#9 0x00007f53966fff82 in index_getnext_tid (scan=0x7f5398db1bb0, direction=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:541
#10 0x00007f5396700174 in index_getnext (scan=scan@entry=0x7f5398db1bb0, direction=direction@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:679
#11 0x00007f539685795c in IndexNext (node=node@entry=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeIndexscan.c:134
#12 0x00007f5396846fe5 in ExecScanFetch (recheckMtd=0x7f53968577b0 <IndexRecheck>, accessMtd=0x7f53968578f0 <IndexNext>, node=0x7f5398db6c50)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:97
#13 ExecScan (node=0x7f5398db6c50, accessMtd=0x7f53968578f0 <IndexNext>, recheckMtd=0x7f53968577b0 <IndexRecheck>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:164
#14 0x00007f539684cf8c in ExecProcNode (node=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#15 fetch_input_tuple (aggstate=aggstate@entry=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:695
#16 0x00007f539684f26f in agg_retrieve_direct (aggstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2347
#17 ExecAgg (pstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2158
#18 0x00007f5396840e03 in ExecProcNode (node=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#19 ExecutePlan (execute_once=<optimized out>, dest=0x7f5398d87e38, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x7f5398db66f8, estate=0x7f5398db5ce8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:1722
#20 standard_ExecutorRun (queryDesc=0x7f5398db1a90, direction=<optimized out>, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:363
#21 0x00007f538ed03185 in pgss_ExecutorRun (queryDesc=0x7f5398db1a90, direction=ForwardScanDirection, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../contrib/pg_stat_statements/pg_stat_statements.c:889
#22 0x00007f539684572d in ParallelQueryMain (seg=<optimized out>, toc=0x7f5396e17000) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execParallel.c:997
#23 0x00007f53967243c3 in ParallelWorkerMain (main_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:1203
#24 0x00007f53968fc06c in StartBackgroundWorker () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/bgworker.c:835
#25 0x00007f5396908f43 in do_start_bgworker (rw=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5728
#26 maybe_start_bgworkers () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5941
#27 0x00007f5396909bb5 in sigusr1_handler (postgres_signal_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5121
#28 <signal handler called>
#29 0x00007f5393dc4873 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
#30 0x00007f53966b3757 in ServerLoop () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1719
#31 0x00007f539690ae2d in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1363
#32 0x00007f53966b558b in main (argc=5, argv=0x7f5398ce95f0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/main/main.c:228
gdb -p 3417
-----------
#0 0x00007f5393dcbbe3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f5396957f51 in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffdf412a460, cur_timeout=-1, set=0x7f5398d23378)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1048
#2 WaitEventSetWait (set=0x7f5398d23378, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffdf412a460, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1000
#3 0x00007f539697196b in ConditionVariableSleep (cv=cv@entry=0x7f5396e17178, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/lmgr/condition_variable.c:149
#4 0x00007f5396707057 in _bt_parallel_seize (scan=scan@entry=0x7f5398db1bb0, pageno=pageno@entry=0x7ffdf412a54c)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:811
#5 0x00007f5396707f7a in _bt_readnextpage (scan=scan@entry=0x7f5398db1bb0, blkno=0, dir=dir@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1498
#6 0x00007f5396708de7 in _bt_parallel_readpage (dir=ForwardScanDirection, blkno=<optimized out>, scan=0x7f5398db1bb0)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1631
#7 _bt_first (scan=scan@entry=0x7f5398db1bb0, dir=dir@entry=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:591
#8 0x00007f5396705e99 in btgettuple (scan=0x7f5398db1bb0, dir=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:372
#9 0x00007f53966fff82 in index_getnext_tid (scan=0x7f5398db1bb0, direction=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:541
#10 0x00007f5396700174 in index_getnext (scan=scan@entry=0x7f5398db1bb0, direction=direction@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:679
#11 0x00007f539685795c in IndexNext (node=node@entry=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeIndexscan.c:134
#12 0x00007f5396846fe5 in ExecScanFetch (recheckMtd=0x7f53968577b0 <IndexRecheck>, accessMtd=0x7f53968578f0 <IndexNext>, node=0x7f5398db6c50)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:97
#13 ExecScan (node=0x7f5398db6c50, accessMtd=0x7f53968578f0 <IndexNext>, recheckMtd=0x7f53968577b0 <IndexRecheck>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:164
#14 0x00007f539684cf8c in ExecProcNode (node=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#15 fetch_input_tuple (aggstate=aggstate@entry=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:695
#16 0x00007f539684f26f in agg_retrieve_direct (aggstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2347
#17 ExecAgg (pstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2158
#18 0x00007f5396840e03 in ExecProcNode (node=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#19 ExecutePlan (execute_once=<optimized out>, dest=0x7f5398d87e38, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x7f5398db66f8, estate=0x7f5398db5ce8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:1722
#20 standard_ExecutorRun (queryDesc=0x7f5398db1a90, direction=<optimized out>, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:363
#21 0x00007f538ed03185 in pgss_ExecutorRun (queryDesc=0x7f5398db1a90, direction=ForwardScanDirection, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../contrib/pg_stat_statements/pg_stat_statements.c:889
#22 0x00007f539684572d in ParallelQueryMain (seg=<optimized out>, toc=0x7f5396e17000) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execParallel.c:997
#23 0x00007f53967243c3 in ParallelWorkerMain (main_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:1203
#24 0x00007f53968fc06c in StartBackgroundWorker () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/bgworker.c:835
#25 0x00007f5396908f43 in do_start_bgworker (rw=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5728
#26 maybe_start_bgworkers () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5941
#27 0x00007f5396909bb5 in sigusr1_handler (postgres_signal_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5121
#28 <signal handler called>
#29 0x00007f5393dc4873 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
#30 0x00007f53966b3757 in ServerLoop () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1719
#31 0x00007f539690ae2d in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1363
#32 0x00007f53966b558b in main (argc=5, argv=0x7f5398ce95f0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/main/main.c:228
gdb -p 3418
-----------
#0 0x00007f5393dcbbe3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f5396957f51 in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffdf412a460, cur_timeout=-1, set=0x7f5398d23378)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1048
#2 WaitEventSetWait (set=0x7f5398d23378, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffdf412a460, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1000
#3 0x00007f539697196b in ConditionVariableSleep (cv=cv@entry=0x7f5396e17178, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/lmgr/condition_variable.c:149
#4 0x00007f5396707057 in _bt_parallel_seize (scan=scan@entry=0x7f5398db1bb0, pageno=pageno@entry=0x7ffdf412a54c)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:811
#5 0x00007f5396707f7a in _bt_readnextpage (scan=scan@entry=0x7f5398db1bb0, blkno=0, dir=dir@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1498
#6 0x00007f5396708de7 in _bt_parallel_readpage (dir=ForwardScanDirection, blkno=<optimized out>, scan=0x7f5398db1bb0)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1631
#7 _bt_first (scan=scan@entry=0x7f5398db1bb0, dir=dir@entry=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:591
#8 0x00007f5396705e99 in btgettuple (scan=0x7f5398db1bb0, dir=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:372
#9 0x00007f53966fff82 in index_getnext_tid (scan=0x7f5398db1bb0, direction=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:541
#10 0x00007f5396700174 in index_getnext (scan=scan@entry=0x7f5398db1bb0, direction=direction@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:679
#11 0x00007f539685795c in IndexNext (node=node@entry=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeIndexscan.c:134
#12 0x00007f5396846fe5 in ExecScanFetch (recheckMtd=0x7f53968577b0 <IndexRecheck>, accessMtd=0x7f53968578f0 <IndexNext>, node=0x7f5398db6c50)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:97
#13 ExecScan (node=0x7f5398db6c50, accessMtd=0x7f53968578f0 <IndexNext>, recheckMtd=0x7f53968577b0 <IndexRecheck>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:164
#14 0x00007f539684cf8c in ExecProcNode (node=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#15 fetch_input_tuple (aggstate=aggstate@entry=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:695
#16 0x00007f539684f26f in agg_retrieve_direct (aggstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2347
#17 ExecAgg (pstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2158
#18 0x00007f5396840e03 in ExecProcNode (node=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#19 ExecutePlan (execute_once=<optimized out>, dest=0x7f5398d87e38, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x7f5398db66f8, estate=0x7f5398db5ce8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:1722
#20 standard_ExecutorRun (queryDesc=0x7f5398db1a90, direction=<optimized out>, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:363
#21 0x00007f538ed03185 in pgss_ExecutorRun (queryDesc=0x7f5398db1a90, direction=ForwardScanDirection, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../contrib/pg_stat_statements/pg_stat_statements.c:889
#22 0x00007f539684572d in ParallelQueryMain (seg=<optimized out>, toc=0x7f5396e17000) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execParallel.c:997
#23 0x00007f53967243c3 in ParallelWorkerMain (main_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:1203
#24 0x00007f53968fc06c in StartBackgroundWorker () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/bgworker.c:835
#25 0x00007f5396908f43 in do_start_bgworker (rw=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5728
#26 maybe_start_bgworkers () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5941
#27 0x00007f5396909bb5 in sigusr1_handler (postgres_signal_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5121
#28 <signal handler called>
#29 0x00007f5393dc4873 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
#30 0x00007f53966b3757 in ServerLoop () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1719
#31 0x00007f539690ae2d in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1363
#32 0x00007f53966b558b in main (argc=5, argv=0x7f5398ce95f0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/main/main.c:228
gdb -p 3419
-----------
#0 0x00007f5393dcbbe3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1 0x00007f5396957f51 in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffdf412a460, cur_timeout=-1, set=0x7f5398d23378)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1048
#2 WaitEventSetWait (set=0x7f5398d23378, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffdf412a460, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/ipc/latch.c:1000
#3 0x00007f539697196b in ConditionVariableSleep (cv=cv@entry=0x7f5396e17178, wait_event_info=wait_event_info@entry=134217730)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/storage/lmgr/condition_variable.c:149
#4 0x00007f5396707057 in _bt_parallel_seize (scan=scan@entry=0x7f5398db1bb0, pageno=pageno@entry=0x7ffdf412a54c)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:811
#5 0x00007f5396707f7a in _bt_readnextpage (scan=scan@entry=0x7f5398db1bb0, blkno=0, dir=dir@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1498
#6 0x00007f5396708de7 in _bt_parallel_readpage (dir=ForwardScanDirection, blkno=<optimized out>, scan=0x7f5398db1bb0)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:1631
#7 _bt_first (scan=scan@entry=0x7f5398db1bb0, dir=dir@entry=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtsearch.c:591
#8 0x00007f5396705e99 in btgettuple (scan=0x7f5398db1bb0, dir=ForwardScanDirection) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/nbtree/nbtree.c:372
#9 0x00007f53966fff82 in index_getnext_tid (scan=0x7f5398db1bb0, direction=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:541
#10 0x00007f5396700174 in index_getnext (scan=scan@entry=0x7f5398db1bb0, direction=direction@entry=ForwardScanDirection)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/index/indexam.c:679
#11 0x00007f539685795c in IndexNext (node=node@entry=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeIndexscan.c:134
#12 0x00007f5396846fe5 in ExecScanFetch (recheckMtd=0x7f53968577b0 <IndexRecheck>, accessMtd=0x7f53968578f0 <IndexNext>, node=0x7f5398db6c50)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:97
#13 ExecScan (node=0x7f5398db6c50, accessMtd=0x7f53968578f0 <IndexNext>, recheckMtd=0x7f53968577b0 <IndexRecheck>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execScan.c:164
#14 0x00007f539684cf8c in ExecProcNode (node=0x7f5398db6c50) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#15 fetch_input_tuple (aggstate=aggstate@entry=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:695
#16 0x00007f539684f26f in agg_retrieve_direct (aggstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2347
#17 ExecAgg (pstate=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/nodeAgg.c:2158
#18 0x00007f5396840e03 in ExecProcNode (node=0x7f5398db66f8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/include/executor/executor.h:250
#19 ExecutePlan (execute_once=<optimized out>, dest=0x7f5398d87e38, direction=<optimized out>, numberTuples=0, sendTuples=<optimized out>, operation=CMD_SELECT, use_parallel_mode=<optimized out>,
planstate=0x7f5398db66f8, estate=0x7f5398db5ce8) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:1722
#20 standard_ExecutorRun (queryDesc=0x7f5398db1a90, direction=<optimized out>, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execMain.c:363
#21 0x00007f538ed03185 in pgss_ExecutorRun (queryDesc=0x7f5398db1a90, direction=ForwardScanDirection, count=0, execute_once=<optimized out>)
at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../contrib/pg_stat_statements/pg_stat_statements.c:889
#22 0x00007f539684572d in ParallelQueryMain (seg=<optimized out>, toc=0x7f5396e17000) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/executor/execParallel.c:997
#23 0x00007f53967243c3 in ParallelWorkerMain (main_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/access/transam/parallel.c:1203
#24 0x00007f53968fc06c in StartBackgroundWorker () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/bgworker.c:835
#25 0x00007f5396908f43 in do_start_bgworker (rw=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5728
#26 maybe_start_bgworkers () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5941
#27 0x00007f5396909bb5 in sigusr1_handler (postgres_signal_arg=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:5121
#28 <signal handler called>
#29 0x00007f5393dc4873 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
#30 0x00007f53966b3757 in ServerLoop () at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1719
#31 0x00007f539690ae2d in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/postmaster/postmaster.c:1363
#32 0x00007f53966b558b in main (argc=5, argv=0x7f5398ce95f0) at /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/main/main.c:228
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-22 20:52 Victor Yegorov <vyegorov@gmail.com>
parent: PG Bug reporting form <noreply@postgresql.org>
1 sibling, 1 reply; 16+ messages in thread
From: Victor Yegorov @ 2018-07-22 20:52 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org
вс, 22 июл. 2018 г. в 21:31, PG Bug reporting form <noreply@postgresql.org>:
> The following bug has been logged on the website:
>
> Bug reference: 15290
> Logged by: Victor Yegorov
> Email address: vyegorov@gmail.com
> PostgreSQL version: 10.4
> Operating system: Debian GNU/Linux 8.7 (jessie)
>
Some more details.
Index that was chosen for Parallel Index Scan was a partial index. And it
is quite bloated:
"coubs_type_is_done_partial_simple" btree (type, is_done) WHERE type::text
= 'Coub::Simple'::text
6766MB
What we did — created another, ordinary index:
"index_coubs_on_is_done_and_in_process_and_type" btree (is_done,
in_process, type)
2141MB
So now planner prefers to use new index and issue is not re-appearing.
Query executes within 10-20ms.
Old bloated index is still around for analysis. `amcheck` showed no issues
with it, though.
--
Victor Yegorov
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-23 04:30 Thomas Munro <thomas.munro@enterprisedb.com>
parent: Victor Yegorov <vyegorov@gmail.com>
0 siblings, 2 replies; 16+ messages in thread
From: Thomas Munro @ 2018-07-23 04:30 UTC (permalink / raw)
To: Victor Yegorov <vyegorov@gmail.com>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Mon, Jul 23, 2018 at 8:52 AM, Victor Yegorov <vyegorov@gmail.com> wrote:
> вс, 22 июл. 2018 г. в 21:31, PG Bug reporting form <noreply@postgresql.org>:
>>
>> The following bug has been logged on the website:
>>
>> Bug reference: 15290
>> Logged by: Victor Yegorov
>> Email address: vyegorov@gmail.com
>> PostgreSQL version: 10.4
>> Operating system: Debian GNU/Linux 8.7 (jessie)
Thanks for the detailed report! To summarise your back traces, we have:
PID 2877 is the master process and has decided to abort and is waiting
for the workers to exit:
WaitLatch
WaitForBackgroundWorkerShutdown
WaitForParallelWorkersToExit
DestroyParallelContext
AtEOXact_Parallel
AbortTransaction
AbortCurrentTransaction
PostgresMain
PIDs 3416, 3417, 3418, 3419 meanwhile are waiting to seize the scan head:
WaitEventSetWaitBlock
ConditionVariableSleep
_bt_parallel_seize
_bt_readnextpage
Presumably 2877 has it (?), but aborted (do you have an error message
in the server log?), and the workers have somehow survived
TerminateBackgroundWorker() (called by DestroyParallelContext()).
Hmm.
TerminateBackgroundWorker() sets a shm flag and signals the
postmaster, the postmaster signals the worker with SIGTERM, the worker
handles SIGTERM in die() by setting ProcDiePending = true,
InterruptPending= true and then setting its own latch, and the
ConditionVarableSleep() loop should wake up, go around its loop again
and run CHECK_FOR_INTERRUPTS() which sees InterruptPending and runs
ProcessInterrupts(), which sees ProcDiePending and reports FATAL. So
which domino fell short here?
--
Thomas Munro
http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-23 04:35 Andres Freund <andres@anarazel.de>
parent: Thomas Munro <thomas.munro@enterprisedb.com>
1 sibling, 0 replies; 16+ messages in thread
From: Andres Freund @ 2018-07-23 04:35 UTC (permalink / raw)
To: Thomas Munro <thomas.munro@enterprisedb.com>; +Cc: Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On 2018-07-23 16:30:28 +1200, Thomas Munro wrote:
> TerminateBackgroundWorker() sets a shm flag and signals the
> postmaster, the postmaster signals the worker with SIGTERM, the worker
> handles SIGTERM in die() by setting ProcDiePending = true,
> InterruptPending= true and then setting its own latch, and the
> ConditionVarableSleep() loop should wake up, go around its loop again
> and run CHECK_FOR_INTERRUPTS() which sees InterruptPending and runs
> ProcessInterrupts(), which sees ProcDiePending and reports FATAL. So
> which domino fell short here?
I've not looked at this, but is it possible that interrupts aren't
accepted because they're held (e.g. because of an lwlock)?
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-23 07:57 Victor Yegorov <vyegorov@gmail.com>
parent: Thomas Munro <thomas.munro@enterprisedb.com>
1 sibling, 1 reply; 16+ messages in thread
From: Victor Yegorov @ 2018-07-23 07:57 UTC (permalink / raw)
To: thomas.munro@enterprisedb.com; +Cc: pgsql-bugs@lists.postgresql.org
пн, 23 июл. 2018 г. в 7:31, Thomas Munro <thomas.munro@enterprisedb.com>:
> PID 2877 is the master process and has decided to abort and is waiting
> for the workers to exit:
>
> WaitLatch
> WaitForBackgroundWorkerShutdown
> WaitForParallelWorkersToExit
> DestroyParallelContext
> AtEOXact_Parallel
> AbortTransaction
> AbortCurrentTransaction
> PostgresMain
>
> PIDs 3416, 3417, 3418, 3419 meanwhile are waiting to seize the scan head:
>
> WaitEventSetWaitBlock
> ConditionVariableSleep
> _bt_parallel_seize
> _bt_readnextpage
>
> Presumably 2877 has it (?), but aborted (do you have an error message
> in the server log?), and the workers have somehow survived
> TerminateBackgroundWorker() (called by DestroyParallelContext()).
>
Query was stuck for 8 hours when we tried to terminate it. Makes me think,
that master process was
still waiting for bgworkers to finish, as test run finished in 11ms for me.
As I mentioned, we've got this case re-appear while I was preparing
the report (had to restart the DB second time). I think I might make it
happen again, if necessary.
There is not so much in the logs:
- a bunch of `FATAL: connection to client lost`, but from another (web)
user (couple errors per hour)
- `ERROR: canceling statement due to conflict with recovery`, happened
right when our problematic query started, same user
- errors related to shutdown/startup of the DB.
--
Victor Yegorov
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-23 08:46 Thomas Munro <thomas.munro@enterprisedb.com>
parent: Victor Yegorov <vyegorov@gmail.com>
0 siblings, 1 reply; 16+ messages in thread
From: Thomas Munro @ 2018-07-23 08:46 UTC (permalink / raw)
To: Victor Yegorov <vyegorov@gmail.com>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Mon, Jul 23, 2018 at 7:57 PM, Victor Yegorov <vyegorov@gmail.com> wrote:
> - `ERROR: canceling statement due to conflict with recovery`, happened
> right when our problematic query started, same user
Ok, so that would explain how the master was cancelled. In 2877's
stack we see that it was aborting here:
#11 0x00007f539697ba5e in PostgresMain (argc=1,
argv=argv@entry=0x7f5398d1bbc8, dbname=0x7f5398d1bb98 "coub",
username=0x7f5398d1bbb0 "app") at
/build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/tcop/postgres.c:3879
That line calls AbortCurrentTransaction(), just after the call to
EmitErrorReport() that wrote something in your log. Andres's theory
(interrupts 'held') seems promising... perhaps there could be a bug
where parallel index scans leak a share-locked page or something like
that. I tried to reproduce this a bit, but no cigar so far. I wonder
if there could be something about your bloated index that reaches
buggy behaviour...
If you happen to have a core file for a worker that is waiting in
ConditionVariableSleep(), or it happens again, you'd be able to see if
an LWLock is causing this by printing num_held_lwlocks.
--
Thomas Munro
http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-23 11:42 Victor Yegorov <vyegorov@gmail.com>
parent: Thomas Munro <thomas.munro@enterprisedb.com>
0 siblings, 1 reply; 16+ messages in thread
From: Victor Yegorov @ 2018-07-23 11:42 UTC (permalink / raw)
To: thomas.munro@enterprisedb.com; +Cc: pgsql-bugs@lists.postgresql.org
пн, 23 июл. 2018 г. в 11:47, Thomas Munro <thomas.munro@enterprisedb.com>:
> On Mon, Jul 23, 2018 at 7:57 PM, Victor Yegorov <vyegorov@gmail.com>
> wrote:
> > - `ERROR: canceling statement due to conflict with recovery`, happened
> > right when our problematic query started, same user
>
> Ok, so that would explain how the master was cancelled. In 2877's
> stack we see that it was aborting here:
>
Right:
ERROR: canceling statement due to conflict with recovery
DETAIL: User was holding shared buffer pin for too long.
>
> #11 0x00007f539697ba5e in PostgresMain (argc=1,
> argv=argv@entry=0x7f5398d1bbc8, dbname=0x7f5398d1bb98 "coub",
> username=0x7f5398d1bbb0 "app") at
>
> /build/postgresql-10-U6N320/postgresql-10-10.4/build/../src/backend/tcop/postgres.c:3879
>
> That line calls AbortCurrentTransaction(), just after the call to
> EmitErrorReport() that wrote something in your log. Andres's theory
> (interrupts 'held') seems promising... perhaps there could be a bug
> where parallel index scans leak a share-locked page or something like
> that. I tried to reproduce this a bit, but no cigar so far. I wonder
> if there could be something about your bloated index that reaches
> buggy behaviour...
>
> If you happen to have a core file for a worker that is waiting in
> ConditionVariableSleep(), or it happens again, you'd be able to see if
> an LWLock is causing this by printing num_held_lwlocks.
>
No, we do not have core files around. And so far I was not able to
reproduce this situation.
I will keep monitoring. In case I'll hit it again — what else (except for
num_held_lwlocks)
should I check for?
--
Victor Yegorov
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 02:04 Thomas Munro <thomas.munro@enterprisedb.com>
parent: Victor Yegorov <vyegorov@gmail.com>
0 siblings, 1 reply; 16+ messages in thread
From: Thomas Munro @ 2018-07-25 02:04 UTC (permalink / raw)
To: Victor Yegorov <vyegorov@gmail.com>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
Ok, I see it:
/* check for interrupts while we're not
holding any buffer lock */
CHECK_FOR_INTERRUPTS();
/* step right one page */
so->currPos.buf = _bt_getbuf(rel, blkno, BT_READ);
...
/* nope, keep going */
if (scan->parallel_scan != NULL)
{
status = _bt_parallel_seize(scan, &blkno);
That leads to a condition variable wait, while we still hold that
buffer lock. That prevents interrupts. Oops.
--
Thomas Munro
http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 02:08 Andres Freund <andres@anarazel.de>
parent: Thomas Munro <thomas.munro@enterprisedb.com>
0 siblings, 1 reply; 16+ messages in thread
From: Andres Freund @ 2018-07-25 02:08 UTC (permalink / raw)
To: Thomas Munro <thomas.munro@enterprisedb.com>; +Cc: Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On 2018-07-25 14:04:11 +1200, Thomas Munro wrote:
> Ok, I see it:
>
> /* check for interrupts while we're not
> holding any buffer lock */
> CHECK_FOR_INTERRUPTS();
> /* step right one page */
> so->currPos.buf = _bt_getbuf(rel, blkno, BT_READ);
> ...
> /* nope, keep going */
> if (scan->parallel_scan != NULL)
> {
> status = _bt_parallel_seize(scan, &blkno);
>
> That leads to a condition variable wait, while we still hold that
> buffer lock. That prevents interrupts. Oops.
Heh, guessed right. I kinda wonder if we shouldn't add a
CHECK_FOR_INTERRUPTS_FOR_REALZ() that asserts if interrupts aren't
held. There are plenty places where we rely on that being the case, for
correctness.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 02:59 Thomas Munro <thomas.munro@enterprisedb.com>
parent: Andres Freund <andres@anarazel.de>
0 siblings, 1 reply; 16+ messages in thread
From: Thomas Munro @ 2018-07-25 02:59 UTC (permalink / raw)
To: Andres Freund <andres@anarazel.de>; +Cc: Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>; Amit Kapila <amit.kapila16@gmail.com>
On Wed, Jul 25, 2018 at 2:08 PM, Andres Freund <andres@anarazel.de> wrote:
> On 2018-07-25 14:04:11 +1200, Thomas Munro wrote:
>> Ok, I see it:
>>
>> /* check for interrupts while we're not
>> holding any buffer lock */
>> CHECK_FOR_INTERRUPTS();
>> /* step right one page */
>> so->currPos.buf = _bt_getbuf(rel, blkno, BT_READ);
>> ...
>> /* nope, keep going */
>> if (scan->parallel_scan != NULL)
>> {
>> status = _bt_parallel_seize(scan, &blkno);
>>
>> That leads to a condition variable wait, while we still hold that
>> buffer lock. That prevents interrupts. Oops.
>
> Heh, guessed right. I kinda wonder if we shouldn't add a
> CHECK_FOR_INTERRUPTS_FOR_REALZ() that asserts if interrupts aren't
> held. There are plenty places where we rely on that being the case, for
> correctness.
Yeah, I was wondering something similar: perhaps WaitEventSetWait()
should assert that interrupts are not held, unless you explicitly told
it somehow that it's OK? You couldn't do it unconditionally, because
we sometimes do that on purpose:
HOLD_INTERRUPTS();
WaitForParallelWorkersToExit(pcxt);
RESUME_INTERRUPTS();
Here's a reproducer (adjust timeout to suit your machine):
drop table if exists t;
create table t as select generate_series(1, 1000000)::int i;
create index on t(i);
alter table t set (autovacuum_enabled = false);
delete from t; -- 100% bloat please
set max_parallel_workers_per_gather = 2;
set min_parallel_index_scan_size = 0;
set enable_seqscan = false;
set enable_bitmapscan = false;
set parallel_tuple_cost = 0;
set parallel_setup_cost = 0;
set statement_timeout = '100ms'; -- enough to fork, not enough to complete
explain analyze select count(*) from t;
--
Thomas Munro
http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 03:13 Amit Kapila <amit.kapila16@gmail.com>
parent: Thomas Munro <thomas.munro@enterprisedb.com>
0 siblings, 1 reply; 16+ messages in thread
From: Amit Kapila @ 2018-07-25 03:13 UTC (permalink / raw)
To: Thomas Munro <thomas.munro@enterprisedb.com>; +Cc: Andres Freund <andres@anarazel.de>; Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Wed, Jul 25, 2018 at 8:29 AM, Thomas Munro
<thomas.munro@enterprisedb.com> wrote:
> On Wed, Jul 25, 2018 at 2:08 PM, Andres Freund <andres@anarazel.de> wrote:
>> On 2018-07-25 14:04:11 +1200, Thomas Munro wrote:
>>> Ok, I see it:
>>>
>>> /* check for interrupts while we're not
>>> holding any buffer lock */
>>> CHECK_FOR_INTERRUPTS();
>>> /* step right one page */
>>> so->currPos.buf = _bt_getbuf(rel, blkno, BT_READ);
>>> ...
>>> /* nope, keep going */
>>> if (scan->parallel_scan != NULL)
>>> {
>>> status = _bt_parallel_seize(scan, &blkno);
>>>
>>> That leads to a condition variable wait, while we still hold that
>>> buffer lock. That prevents interrupts. Oops.
>>
Well spotted. I think here we can release the current page lock
before calling _bt_parallel_seize as we don't need it to get the next
page. See the backward scan case, in particular, I am referring to
the below code:
_bt_readnextpage()
{
..
* For parallel scans, get the last page scanned as it is quite
* possible that by the time we try to seize the scan, some other
* worker has already advanced the scan to a different page. We
* must continue based on the latest page scanned by any worker.
*/
if (scan->parallel_scan != NULL)
{
_bt_relbuf(rel, so->currPos.buf);
status = _bt_parallel_seize(scan, &blkno);
..
}
This needs some more analysis. I will continue the analysis and
shared findings.
Thanks, Thomas for pinging me offlist and including me here.
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 05:46 Amit Kapila <amit.kapila16@gmail.com>
parent: Amit Kapila <amit.kapila16@gmail.com>
0 siblings, 2 replies; 16+ messages in thread
From: Amit Kapila @ 2018-07-25 05:46 UTC (permalink / raw)
To: Thomas Munro <thomas.munro@enterprisedb.com>; +Cc: Andres Freund <andres@anarazel.de>; Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Wed, Jul 25, 2018 at 8:43 AM, Amit Kapila <amit.kapila16@gmail.com> wrote:
> On Wed, Jul 25, 2018 at 8:29 AM, Thomas Munro
> <thomas.munro@enterprisedb.com> wrote:
>> On Wed, Jul 25, 2018 at 2:08 PM, Andres Freund <andres@anarazel.de> wrote:
>>> On 2018-07-25 14:04:11 +1200, Thomas Munro wrote:
>>>> Ok, I see it:
>>>>
>>>> /* check for interrupts while we're not
>>>> holding any buffer lock */
>>>> CHECK_FOR_INTERRUPTS();
>>>> /* step right one page */
>>>> so->currPos.buf = _bt_getbuf(rel, blkno, BT_READ);
>>>> ...
>>>> /* nope, keep going */
>>>> if (scan->parallel_scan != NULL)
>>>> {
>>>> status = _bt_parallel_seize(scan, &blkno);
>>>>
>>>> That leads to a condition variable wait, while we still hold that
>>>> buffer lock. That prevents interrupts. Oops.
>>>
>
> Well spotted. I think here we can release the current page lock
> before calling _bt_parallel_seize as we don't need it to get the next
> page.
>
I have written a patch on the above lines and manually verified (by
reproducing the issue via debugger) that it fixes the issue. Thomas,
Victor, is it possible for you guys to see if the attached fixes the
issue for you?
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
Attachments:
rel_buf_before_seize_pi_v1.patch (application/octet-stream, 757B) download
diff --git a/src/backend/access/nbtree/nbtsearch.c b/src/backend/access/nbtree/nbtsearch.c
index 0bcfa10b864..6831bc8c032 100644
--- a/src/backend/access/nbtree/nbtsearch.c
+++ b/src/backend/access/nbtree/nbtsearch.c
@@ -1497,17 +1497,19 @@ _bt_readnextpage(IndexScanDesc scan, BlockNumber blkno, ScanDirection dir)
/* nope, keep going */
if (scan->parallel_scan != NULL)
{
+ _bt_relbuf(rel, so->currPos.buf);
status = _bt_parallel_seize(scan, &blkno);
if (!status)
{
- _bt_relbuf(rel, so->currPos.buf);
BTScanPosInvalidate(so->currPos);
return false;
}
}
else
+ {
blkno = opaque->btpo_next;
- _bt_relbuf(rel, so->currPos.buf);
+ _bt_relbuf(rel, so->currPos.buf);
+ }
}
}
else
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-25 09:55 Thomas Munro <thomas.munro@enterprisedb.com>
parent: Amit Kapila <amit.kapila16@gmail.com>
1 sibling, 0 replies; 16+ messages in thread
From: Thomas Munro @ 2018-07-25 09:55 UTC (permalink / raw)
To: Amit Kapila <amit.kapila16@gmail.com>; +Cc: Andres Freund <andres@anarazel.de>; Victor Yegorov <vyegorov@gmail.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Wed, Jul 25, 2018 at 5:46 PM, Amit Kapila <amit.kapila16@gmail.com> wrote:
>> I think here we can release the current page lock
>> before calling _bt_parallel_seize as we don't need it to get the next
>> page.
>
> I have written a patch on the above lines and manually verified (by
> reproducing the issue via debugger) that it fixes the issue. Thomas,
> Victor, is it possible for you guys to see if the attached fixes the
> issue for you?
The patch looks good to me. It fixes the problem for my reproducer
(BTW that works better with an extra zero on the generate_series
number).
--
Thomas Munro
http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-26 10:23 Victor Yegorov <vyegorov@gmail.com>
parent: Amit Kapila <amit.kapila16@gmail.com>
1 sibling, 1 reply; 16+ messages in thread
From: Victor Yegorov @ 2018-07-26 10:23 UTC (permalink / raw)
To: amit.kapila16@gmail.com; +Cc: thomas.munro@enterprisedb.com; pgsql-bugs@lists.postgresql.org
ср, 25 июл. 2018 г. в 8:46, Amit Kapila <amit.kapila16@gmail.com>:
> On Wed, Jul 25, 2018 at 8:43 AM, Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> > Well spotted. I think here we can release the current page lock
> > before calling _bt_parallel_seize as we don't need it to get the next
> > page.
> >
>
> I have written a patch on the above lines and manually verified (by
> reproducing the issue via debugger) that it fixes the issue. Thomas,
> Victor, is it possible for you guys to see if the attached fixes the
> issue for you?
>
First, I failed to reproduce Thomas' case on the VM with just 1 core.
But it is reproduced just fine on an 8-core machine, make sure to warm up
the index first though.
Patch fixes the issue for me here.
--
Victor Yegorov
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: BUG #15290: Stuck Parallel Index Scan query
@ 2018-07-27 05:47 Amit Kapila <amit.kapila16@gmail.com>
parent: Victor Yegorov <vyegorov@gmail.com>
0 siblings, 0 replies; 16+ messages in thread
From: Amit Kapila @ 2018-07-27 05:47 UTC (permalink / raw)
To: Victor Yegorov <vyegorov@gmail.com>; +Cc: Thomas Munro <thomas.munro@enterprisedb.com>; PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Thu, Jul 26, 2018 at 3:53 PM, Victor Yegorov <vyegorov@gmail.com> wrote:
> ср, 25 июл. 2018 г. в 8:46, Amit Kapila <amit.kapila16@gmail.com>:
>>
>> On Wed, Jul 25, 2018 at 8:43 AM, Amit Kapila <amit.kapila16@gmail.com>
>> wrote:
>> > Well spotted. I think here we can release the current page lock
>> > before calling _bt_parallel_seize as we don't need it to get the next
>> > page.
>> >
>>
>> I have written a patch on the above lines and manually verified (by
>> reproducing the issue via debugger) that it fixes the issue. Thomas,
>> Victor, is it possible for you guys to see if the attached fixes the
>> issue for you?
>
>
> First, I failed to reproduce Thomas' case on the VM with just 1 core.
> But it is reproduced just fine on an 8-core machine, make sure to warm up
> the index first though.
>
> Patch fixes the issue for me here.
>
Thanks, pushed the fix. I have not included Thomas's test as it is
timing dependent and it seems risky to include such a test.
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 16+ messages in thread
end of thread, other threads:[~2018-07-27 05:47 UTC | newest]
Thread overview: 16+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2018-07-22 18:30 BUG #15290: Stuck Parallel Index Scan query PG Bug reporting form <noreply@postgresql.org>
2018-07-22 18:33 ` Victor Yegorov <vyegorov@gmail.com>
2018-07-22 20:52 ` Victor Yegorov <vyegorov@gmail.com>
2018-07-23 04:30 ` Thomas Munro <thomas.munro@enterprisedb.com>
2018-07-23 04:35 ` Andres Freund <andres@anarazel.de>
2018-07-23 07:57 ` Victor Yegorov <vyegorov@gmail.com>
2018-07-23 08:46 ` Thomas Munro <thomas.munro@enterprisedb.com>
2018-07-23 11:42 ` Victor Yegorov <vyegorov@gmail.com>
2018-07-25 02:04 ` Thomas Munro <thomas.munro@enterprisedb.com>
2018-07-25 02:08 ` Andres Freund <andres@anarazel.de>
2018-07-25 02:59 ` Thomas Munro <thomas.munro@enterprisedb.com>
2018-07-25 03:13 ` Amit Kapila <amit.kapila16@gmail.com>
2018-07-25 05:46 ` Amit Kapila <amit.kapila16@gmail.com>
2018-07-25 09:55 ` Thomas Munro <thomas.munro@enterprisedb.com>
2018-07-26 10:23 ` Victor Yegorov <vyegorov@gmail.com>
2018-07-27 05:47 ` Amit Kapila <amit.kapila16@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox