Horton

Thread

Commits

  1. Fix race in dsm_attach() when handles are reused.

  2. Refactor pid, random seed and start time initialization.

  1. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-07T01:47:19Z

    FYI, I wasn't yet able to make this work yet.
(gdb) print *segment_map->header
Cannot access memory at address 0x7f347e554000

However I *did* reproduce the error in an isolated, non-production postgres
instance.  It's a total empty, untuned v11.1 initdb just for this, running ONLY
a few simultaneous loops around just one query It looks like the simultaneous
loops sometimes (but not always) fail together.  This has happened a couple
times.  

It looks like one query failed due to "could not attach" in leader, one failed
due to same in worker, and one failed with "not pinned", which I hadn't seen
before and appears to be related to DSM, not DSA...

|ERROR:  dsa_area could not attach to segment
|ERROR:  cannot unpin a segment that is not pinned
|ERROR:  dsa_area could not attach to segment
|CONTEXT:  parallel worker
|
|[2]   Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do
|    :;
|done > /dev/null
|[5]-  Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do
|    :;
|done > /dev/null
|[6]+  Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do

I'm also trying to reproduce on other production servers.  But so far nothing
else has shown the bug, including the other server which hit our original
(other) DSA error with the queued_alters query.  So I tentatively think there
really may be something specific to the server (not the hypervisor so maybe the
OS, libraries, kernel, scheduler, ??).

Find the schema for that table here:
https://www.postgresql.org/message-id/20181231221734.GB25379%40telsasoft.com

Note, for unrelated reasons, that query was also previously discussed here:
https://www.postgresql.org/message-id/20171110204043.GS8563%40telsasoft.com

Justin

  2. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-07T03:31:39Z

    On Thu, Feb 7, 2019 at 12:47 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> However I *did* reproduce the error in an isolated, non-production postgres
> instance.  It's a total empty, untuned v11.1 initdb just for this, running ONLY
> a few simultaneous loops around just one query It looks like the simultaneous
> loops sometimes (but not always) fail together.  This has happened a couple
> times.
>
> It looks like one query failed due to "could not attach" in leader, one failed
> due to same in worker, and one failed with "not pinned", which I hadn't seen
> before and appears to be related to DSM, not DSA...

Hmm.  I hadn't considered that angle...  Some kind of interference
between unrelated DSA areas, or other DSM activity?  I will also try
to repro that here...

> I'm also trying to reproduce on other production servers.  But so far nothing
> else has shown the bug, including the other server which hit our original
> (other) DSA error with the queued_alters query.  So I tentatively think there
> really may be something specific to the server (not the hypervisor so maybe the
> OS, libraries, kernel, scheduler, ??).

Initially I thought these might be two symptoms of the same corruption
but I'm now starting to wonder if there are two bugs here: "could not
allocate %d pages" (rare) might be a logic bug in the computation of
contiguous_pages that requires a particular allocation pattern to hit,
and "dsa_area could not attach to segment" (rarissimo) might be
something else requiring concurrency/a race.

One thing that might be useful would be to add a call to
dsa_dump(area) just before the errors are raised, which will write a
bunch of stuff out to stderr and might give us some clues.  And to
print out the variable "index" from get_segment_by_index() when it
fails.  I'm also going to try to work up some better assertions.
--
Thomas Munro
http://www.enterprisedb.com

  3. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-07T15:08:32Z

    On Wed, Feb 06, 2019 at 07:47:19PM -0600, Justin Pryzby wrote:
> FYI, I wasn't yet able to make this work yet.
> (gdb) print *segment_map->header
> Cannot access memory at address 0x7f347e554000

I'm still not able to make this work.  Actually this doesn't work even:

(gdb) print *segment_map
Cannot access memory at address 0x4227dcdd0

Thomas thought it's due to coredump_filter, but 0xff doesn't work (actually
0x7f seems to be the max here).  Any other ideas?  The core is not being
truncated, since this is on a "toy" instance with 128MB buffers.

-rw-r-----. 1 pryzbyj root 279M Feb  7 09:52 coredump

[pryzbyj@telsasoft-db postgresql]$ ~/src/postgresql.bin/bin/pg_ctl -c start -D /var/lib/pgsql/test -o '-c operator_precedence_warning=on -c maintenance_work_mem=1GB -c max_wal_size=16GB -c full_page_writes=off -c autovacuum=off -c fsync=off -c port=5678 -c unix_socket_directories=/tmp'                                                                                              waiting for server to start....2019-02-07 09:25:45.745 EST [30741] LOG:  listening on IPv6 address "::1", port 5678                                                                           2019-02-07 09:25:45.745 EST [30741] LOG:  listening on IPv4 address "127.0.0.1", port 5678                                                                                                    2019-02-07 09:25:45.746 EST [30741] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5678"
.2019-02-07 09:25:46.798 EST [30741] LOG:  redirecting log output to logging collector process
2019-02-07 09:25:46.798 EST [30741] HINT:  Future log output will appear in directory "log".
 done
server started

[pryzbyj@telsasoft-db postgresql]$ echo 0xff |sudo tee /proc/30741/coredump_filter

Justin

  4. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-11T04:01:32Z

    Hi,

On Mon, Feb 11, 2019 at 11:11:32AM +1100, Thomas Munro wrote:
> I haven't ever managed to reproduce that one yet.  It's great you have
> a reliable repro...  Let's discuss it on the #15585 thread.

I realized that I gave bad information (at least to Thomas).  On the server
where I've been reproducing this, it wasn't in an empty DB cluster, but one
where I'd restored our DB schema.  I think that's totally irrelevant, except
that pg_attribute needs to be big enough to get parallel scan.

Here's confirmed steps to reproduce

initdb -D /var/lib/pgsql/test
pg_ctl -c start -D /var/lib/pgsql/test -o '-c operator_precedence_warning=on -c maintenance_work_mem=1GB -c max_wal_size=16GB -c full_page_writes=off -c autovacuum=off -c fsync=off -c port=5678 -c unix_socket_directories=/tmp'
PGPORT=5678 PGHOST=/tmp psql postgres -c 'CREATE TABLE queued_alters(child text,parent text); CREATE TABLE queued_alters_child()INHERITS(queued_alters); ANALYZE queued_alters, pg_attribute'

# Inflate pg_attribute to nontrivial size:
echo "CREATE TABLE t(`for c in $(seq 1 222); do echo "c$c int,"; done |xargs |sed 's/,$//'`)" |PGHOST=/tmp PGPORT=5678 psql postgres 
for a in `seq 1 999`; do echo "CREATE TABLE t$a() INHERITS(t);"; done |PGHOST=/tmp PGPORT=5678 psql -q postgres

while PGOPTIONS='-cmin_parallel_table_scan_size=0' PGPORT=5678 PGHOST=/tmp psql postgres -c "explain analyze SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\3\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do :; done >/dev/null &

# Verify this is planning parallel workers, then repeat 10-20x.

Typically fails on this server in under 10min.

Sorry for the error.

Justin

On Wed, Feb 06, 2019 at 07:47:19PM -0600, Justin Pryzby wrote:
> FYI, I wasn't yet able to make this work yet.
> (gdb) print *segment_map->header
> Cannot access memory at address 0x7f347e554000
> 
> However I *did* reproduce the error in an isolated, non-production postgres
> instance.  It's a total empty, untuned v11.1 initdb just for this, running ONLY
> a few simultaneous loops around just one query It looks like the simultaneous
> loops sometimes (but not always) fail together.  This has happened a couple
> times.  
> 
> It looks like one query failed due to "could not attach" in leader, one failed
> due to same in worker, and one failed with "not pinned", which I hadn't seen
> before and appears to be related to DSM, not DSA...
> 
> |ERROR:  dsa_area could not attach to segment
> |ERROR:  cannot unpin a segment that is not pinned
> |ERROR:  dsa_area could not attach to segment
> |CONTEXT:  parallel worker
> |
> |[2]   Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do
> |    :;
> |done > /dev/null
> |[5]-  Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do
> |    :;
> |done > /dev/null
> |[6]+  Done                    while PGHOST=/tmp PGPORT=5678 psql postgres -c "SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod) ORDER BY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON to_regclass(qa.parent)=colpar.attrelid AND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *, attrelid::regclass::text AS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND colcld.attnum>0 AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid GROUP BY 1,2 ORDER BY parent LIKE 'unused%', regexp_replace(colcld.child, '.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$', '\\3\\5') DESC, regexp_replace(colcld.child, '.*_', '') DESC LIMIT 1"; do
> 
> I'm also trying to reproduce on other production servers.  But so far nothing
> else has shown the bug, including the other server which hit our original
> (other) DSA error with the queued_alters query.  So I tentatively think there
> really may be something specific to the server (not the hypervisor so maybe the
> OS, libraries, kernel, scheduler, ??).
> 
> Find the schema for that table here:
> https://www.postgresql.org/message-id/20181231221734.GB25379%40telsasoft.com
> 
> Note, for unrelated reasons, that query was also previously discussed here:
> https://www.postgresql.org/message-id/20171110204043.GS8563%40telsasoft.com

  5. Re: pg11.1: dsa_area could not attach to segment

    Sergei Kornilov <sk@zsrv.org> — 2019-02-11T14:51:09Z

    Hi

> Here's confirmed steps to reproduce

Wow, i confirm this testcase is reproducible for me. On my 4-core desktop i see "dsa_area could not attach to segment" error after minute or two.
On current REL_11_STABLE branch with PANIC level i see this backtrace for failed parallel process:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f3b36983535 in __GI_abort () at abort.c:79
#2  0x000055f03ab87a4e in errfinish (dummy=dummy@entry=0) at elog.c:555
#3  0x000055f03ab899e0 in elog_finish (elevel=elevel@entry=22, fmt=fmt@entry=0x55f03ad86900 "dsa_area could not attach to segment") at elog.c:1376
#4  0x000055f03abaa1e2 in get_segment_by_index (area=area@entry=0x55f03cdd6bf0, index=index@entry=7) at dsa.c:1743
#5  0x000055f03abaa8ab in get_best_segment (area=area@entry=0x55f03cdd6bf0, npages=npages@entry=8) at dsa.c:1993
#6  0x000055f03ababdb8 in dsa_allocate_extended (area=0x55f03cdd6bf0, size=size@entry=32768, flags=flags@entry=0) at dsa.c:701
#7  0x000055f03a921469 in ExecParallelHashTupleAlloc (hashtable=hashtable@entry=0x55f03cdfd498, size=104, shared=shared@entry=0x7ffc9f355748) at nodeHash.c:2837
#8  0x000055f03a9219fc in ExecParallelHashTableInsertCurrentBatch (hashtable=hashtable@entry=0x55f03cdfd498, slot=<optimized out>, hashvalue=2522126815) at nodeHash.c:1747
#9  0x000055f03a9227ef in ExecParallelHashJoinNewBatch (hjstate=hjstate@entry=0x55f03cde17b0) at nodeHashjoin.c:1153
#10 0x000055f03a924115 in ExecHashJoinImpl (parallel=true, pstate=0x55f03cde17b0) at nodeHashjoin.c:534
#11 ExecParallelHashJoin (pstate=0x55f03cde17b0) at nodeHashjoin.c:581
#12 0x000055f03a90d91c in ExecProcNodeFirst (node=0x55f03cde17b0) at execProcnode.c:445
#13 0x000055f03a905f3b in ExecProcNode (node=0x55f03cde17b0) at ../../../src/include/executor/executor.h:247
#14 ExecutePlan (estate=estate@entry=0x55f03cde0d38, planstate=0x55f03cde17b0, use_parallel_mode=<optimized out>, operation=operation@entry=CMD_SELECT, sendTuples=sendTuples@entry=true, numberTuples=numberTuples@entry=0, 
    direction=ForwardScanDirection, dest=0x55f03cd7e4e8, execute_once=true) at execMain.c:1723
#15 0x000055f03a906b4d in standard_ExecutorRun (queryDesc=0x55f03cdd13e0, direction=ForwardScanDirection, count=0, execute_once=execute_once@entry=true) at execMain.c:364
#16 0x000055f03a906c08 in ExecutorRun (queryDesc=queryDesc@entry=0x55f03cdd13e0, direction=direction@entry=ForwardScanDirection, count=<optimized out>, execute_once=execute_once@entry=true) at execMain.c:307
#17 0x000055f03a90b44f in ParallelQueryMain (seg=seg@entry=0x55f03cd320a8, toc=toc@entry=0x7f3b2d877000) at execParallel.c:1402
#18 0x000055f03a7ce4cc in ParallelWorkerMain (main_arg=<optimized out>) at parallel.c:1409
#19 0x000055f03a9e11cb in StartBackgroundWorker () at bgworker.c:834
#20 0x000055f03a9eea1a in do_start_bgworker (rw=rw@entry=0x55f03cd2d460) at postmaster.c:5698
#21 0x000055f03a9eeb5b in maybe_start_bgworkers () at postmaster.c:5911
#22 0x000055f03a9ef5f0 in sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5091
#23 <signal handler called>
#24 0x00007f3b36a52327 in __GI___select (nfds=nfds@entry=6, readfds=readfds@entry=0x7ffc9f356160, writefds=writefds@entry=0x0, exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x7ffc9f356150)
    at ../sysdeps/unix/sysv/linux/select.c:41
#25 0x000055f03a9effaa in ServerLoop () at postmaster.c:1670
#26 0x000055f03a9f1285 in PostmasterMain (argc=3, argv=<optimized out>) at postmaster.c:1379
#27 0x000055f03a954f3d in main (argc=3, argv=0x55f03cd03200) at main.c:228

regards, Sergei

  6. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-11T23:57:51Z

    On Tue, Feb 12, 2019 at 1:51 AM Sergei Kornilov <sk@zsrv.org> wrote:
> > Here's confirmed steps to reproduce
>
> Wow, i confirm this testcase is reproducible for me. On my 4-core desktop i see "dsa_area could not attach to segment" error after minute or two.

Well that's something -- thanks for this report.  I've had 3 different
machines (laptops and servers, with an without optimisation enabled,
clang and gcc, 3 different OSes) grinding away on Justin's test case
for many hours today, without seeing the problem.

> On current REL_11_STABLE branch with PANIC level i see this backtrace for failed parallel process:
>
> #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> #1  0x00007f3b36983535 in __GI_abort () at abort.c:79
> #2  0x000055f03ab87a4e in errfinish (dummy=dummy@entry=0) at elog.c:555
> #3  0x000055f03ab899e0 in elog_finish (elevel=elevel@entry=22, fmt=fmt@entry=0x55f03ad86900 "dsa_area could not attach to segment") at elog.c:1376
> #4  0x000055f03abaa1e2 in get_segment_by_index (area=area@entry=0x55f03cdd6bf0, index=index@entry=7) at dsa.c:1743
> #5  0x000055f03abaa8ab in get_best_segment (area=area@entry=0x55f03cdd6bf0, npages=npages@entry=8) at dsa.c:1993
> #6  0x000055f03ababdb8 in dsa_allocate_extended (area=0x55f03cdd6bf0, size=size@entry=32768, flags=flags@entry=0) at dsa.c:701

Ok, this contains some clues I didn't have before.  Here we see that a
request for a 32KB chunk of memory led to a traversal the linked list
of segments in a given bin, and at some point we followed a link to
segment index number 7, which turned out to be bogus.  We tried to
attach to the segment whose handle is stored in
area->control->segment_handles[7] and it was not known to dsm.c.  It
wasn't DSM_HANDLE_INVALID, or you'd have got a different error
message.  That means that it wasn't a segment that had been freed by
destroy_superblock(), or it'd hold DSM_HANDLE_INVALID.

Hmm.  So perhaps the bin list was corrupted (the segment index was bad
due to some bogus list manipulation logic or memory overrun or...), or
we corrupted our array of handles, or there is some missing locking
somewhere (all bin manipulation and traversal should be protected by
the area lock), or a valid DSM handle was unexpectedly missing (dsm.c
bug, bogus shm_open() EEXIST from the OS).

Can we please see the stderr output of dsa_dump(area), added just
before the PANIC?  Can we see the value of "handle" when the error is
raised, and the directory listing for /dev/shm (assuming Linux) after
the crash (maybe you need restart_after_crash = off to prevent
automatic cleanup)?

-- 
Thomas Munro
http://www.enterprisedb.com

  7. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-12T00:07:35Z

    On Tue, Feb 12, 2019 at 10:57 AM Thomas Munro
<thomas.munro@enterprisedb.com> wrote:
> bogus shm_open() EEXIST from the OS

Strike that particular idea... it'd be the non-DSM_OP_CREATE case, and
if the file was somehow bogusly not visible to us we'd get ENOENT and
that'd raise an error, and we aren't seeing that.

-- 
Thomas Munro
http://www.enterprisedb.com

  8. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-12T02:14:28Z

    On Tue, Feb 12, 2019 at 10:57:51AM +1100, Thomas Munro wrote:
> > On current REL_11_STABLE branch with PANIC level i see this backtrace for failed parallel process:
> >
> > #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> > #1  0x00007f3b36983535 in __GI_abort () at abort.c:79
> > #2  0x000055f03ab87a4e in errfinish (dummy=dummy@entry=0) at elog.c:555
> > #3  0x000055f03ab899e0 in elog_finish (elevel=elevel@entry=22, fmt=fmt@entry=0x55f03ad86900 "dsa_area could not attach to segment") at elog.c:1376
> > #4  0x000055f03abaa1e2 in get_segment_by_index (area=area@entry=0x55f03cdd6bf0, index=index@entry=7) at dsa.c:1743
> > #5  0x000055f03abaa8ab in get_best_segment (area=area@entry=0x55f03cdd6bf0, npages=npages@entry=8) at dsa.c:1993
> > #6  0x000055f03ababdb8 in dsa_allocate_extended (area=0x55f03cdd6bf0, size=size@entry=32768, flags=flags@entry=0) at dsa.c:701
> 
> Ok, this contains some clues I didn't have before.  Here we see that a
> request for a 32KB chunk of memory led to a traversal the linked list
> of segments in a given bin, and at some point we followed a link to
> segment index number 7, which turned out to be bogus.  We tried to
> attach to the segment whose handle is stored in
> area->control->segment_handles[7] and it was not known to dsm.c.  It
> wasn't DSM_HANDLE_INVALID, or you'd have got a different error
> message.  That means that it wasn't a segment that had been freed by
> destroy_superblock(), or it'd hold DSM_HANDLE_INVALID.
> 
> Hmm.  So perhaps the bin list was corrupted (the segment index was bad

I think there is corruption *somewhere* due to never being able to do
this (and looks very broken?)

(gdb) p segment_map
$1 = (dsa_segment_map *) 0x1

(gdb) print segment_map->header 
Cannot access memory at address 0x11

> Can we please see the stderr output of dsa_dump(area), added just
> before the PANIC?  Can we see the value of "handle" when the error is
> raised, and the directory listing for /dev/shm (assuming Linux) after
> the crash (maybe you need restart_after_crash = off to prevent
> automatic cleanup)?

PANIC:  dsa_area could not attach to segment index:8 handle:1076305344

I think it needs to be:

|               if (segment == NULL) {
|                       LWLockRelease(DSA_AREA_LOCK(area));
|                       dsa_dump(area);
|                       elog(PANIC, "dsa_area could not attach to segment index:%zd handle:%d", index, handle);
|               }

..but that triggers recursion:

#0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
#1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
#2  0x0000000000a395c0 in errfinish (dummy=0) at elog.c:567
#3  0x0000000000a3bbf6 in elog_finish (elevel=22, fmt=0xc9faa0 "dsa_area could not attach to segment index:%zd handle:%d") at elog.c:1389
#4  0x0000000000a6b97a in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1747
#5  0x0000000000a6a3dc in dsa_dump (area=0x1659200) at dsa.c:1093
#6  0x0000000000a6b946 in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1744
[...]
#717 0x0000000000a6a3dc in dsa_dump (area=0x1659200) at dsa.c:1093
#718 0x0000000000a6b946 in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1744
#719 0x0000000000a6a3dc in dsa_dump (area=0x1659200) at dsa.c:1093
#720 0x0000000000a6b946 in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1744
#721 0x0000000000a6c150 in get_best_segment (area=0x1659200, npages=8) at dsa.c:1997
#722 0x0000000000a69680 in dsa_allocate_extended (area=0x1659200, size=32768, flags=0) at dsa.c:701
#723 0x00000000007052eb in ExecParallelHashTupleAlloc (hashtable=0x7f56ff9b40e8, size=112, shared=0x7fffda8c36a0) at nodeHash.c:2837
#724 0x00000000007034f3 in ExecParallelHashTableInsert (hashtable=0x7f56ff9b40e8, slot=0x1608948, hashvalue=2677813320) at nodeHash.c:1693
#725 0x0000000000700ba3 in MultiExecParallelHash (node=0x1607f40) at nodeHash.c:288
#726 0x00000000007007ce in MultiExecHash (node=0x1607f40) at nodeHash.c:112
#727 0x00000000006e94d7 in MultiExecProcNode (node=0x1607f40) at execProcnode.c:501
[...]

[pryzbyj@telsasoft-db postgresql]$ ls -lt /dev/shm |head
total 353056
-rw-------. 1 pryzbyj  pryzbyj   1048576 Feb 11 13:51 PostgreSQL.821164732
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 13:51 PostgreSQL.1990121974
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 12:54 PostgreSQL.847060172
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 12:48 PostgreSQL.1369859581
-rw-------. 1 postgres postgres    21328 Feb 10 21:00 PostgreSQL.1155375187
-rw-------. 1 pryzbyj  pryzbyj    196864 Feb 10 18:52 PostgreSQL.2136009186
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.1648026537
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.827867206
-rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.1684837530

Justin

  9. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-12T02:36:14Z

    On Mon, Feb 11, 2019 at 08:14:28PM -0600, Justin Pryzby wrote:
> > Can we please see the stderr output of dsa_dump(area), added just
> > before the PANIC?  Can we see the value of "handle" when the error is
> > raised, and the directory listing for /dev/shm (assuming Linux) after
> > the crash (maybe you need restart_after_crash = off to prevent
> > automatic cleanup)?
> 
> PANIC:  dsa_area could not attach to segment index:8 handle:1076305344
> 
> I think it needs to be:
> 
> |               if (segment == NULL) {
> |                       LWLockRelease(DSA_AREA_LOCK(area));
> |                       dsa_dump(area);
> |                       elog(PANIC, "dsa_area could not attach to segment index:%zd handle:%d", index, handle);
> |               }
> 
> ..but that triggers recursion:

Here's my dsa_log (which is repeated many times and 400kB total)..

dsa_area handle 0:
  max_total_segment_size: 18446744073709551615
  total_segment_size: 15740928
  refcnt: 2
  pinned: f
  segment bins:
    segment bin 0 (at least -2147483648 contiguous pages free):
      segment index 2, usable_pages = 256, contiguous_pages = 0, mapped at 0x7f56ff9d5000
      segment index 0, usable_pages = 0, contiguous_pages = 0, mapped at 0x7f56ffbd6840
    segment bin 3 (at least 4 contiguous pages free):
      segment index 7, usable_pages = 510, contiguous_pages = 6, mapped at 0x7f56ff0b4000
      segment index 6, usable_pages = 510, contiguous_pages = 6, mapped at 0x7f56ff2b4000
      segment index 5, usable_pages = 510, contiguous_pages = 5, mapped at 0x7f56ff4b4000
      segment index 4, usable_pages = 510, contiguous_pages = 5, mapped at 0x7f56ff6b4000
      segment index 3, usable_pages = 255, contiguous_pages = 6, mapped at 0x7f56ff8b4000
      segment index 1, usable_pages = 255, contiguous_pages = 6, mapped at 0x7f56ffad6000
    segment bin 10 (at least 512 contiguous pages free):

Note negative pages.  Let me know if you want more of it (span descriptors?)

Justin

  10. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-12T04:09:42Z

    On Tue, Feb 12, 2019 at 1:14 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> On Tue, Feb 12, 2019 at 10:57:51AM +1100, Thomas Munro wrote:
> > > On current REL_11_STABLE branch with PANIC level i see this backtrace for failed parallel process:
> > >
> > > #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> > > #1  0x00007f3b36983535 in __GI_abort () at abort.c:79
> > > #2  0x000055f03ab87a4e in errfinish (dummy=dummy@entry=0) at elog.c:555
> > > #3  0x000055f03ab899e0 in elog_finish (elevel=elevel@entry=22, fmt=fmt@entry=0x55f03ad86900 "dsa_area could not attach to segment") at elog.c:1376
> > > #4  0x000055f03abaa1e2 in get_segment_by_index (area=area@entry=0x55f03cdd6bf0, index=index@entry=7) at dsa.c:1743
> > > #5  0x000055f03abaa8ab in get_best_segment (area=area@entry=0x55f03cdd6bf0, npages=npages@entry=8) at dsa.c:1993
> > > #6  0x000055f03ababdb8 in dsa_allocate_extended (area=0x55f03cdd6bf0, size=size@entry=32768, flags=flags@entry=0) at dsa.c:701
> >
> > Ok, this contains some clues I didn't have before.  Here we see that a
> > request for a 32KB chunk of memory led to a traversal the linked list
> > of segments in a given bin, and at some point we followed a link to
> > segment index number 7, which turned out to be bogus.  We tried to
> > attach to the segment whose handle is stored in
> > area->control->segment_handles[7] and it was not known to dsm.c.  It
> > wasn't DSM_HANDLE_INVALID, or you'd have got a different error
> > message.  That means that it wasn't a segment that had been freed by
> > destroy_superblock(), or it'd hold DSM_HANDLE_INVALID.
> >
> > Hmm.  So perhaps the bin list was corrupted (the segment index was bad
>
> I think there is corruption *somewhere* due to never being able to do
> this (and looks very broken?)
>
> (gdb) p segment_map
> $1 = (dsa_segment_map *) 0x1
>
> (gdb) print segment_map->header
> Cannot access memory at address 0x11

If you're in get_segment_by_index() in a core dumped at the "could not
attach" error, the variable segment_map hasn't been assigned a value
yet so that's uninitialised junk on the stack.

> > Can we please see the stderr output of dsa_dump(area), added just
> > before the PANIC?  Can we see the value of "handle" when the error is
> > raised, and the directory listing for /dev/shm (assuming Linux) after
> > the crash (maybe you need restart_after_crash = off to prevent
> > automatic cleanup)?
>
> PANIC:  dsa_area could not attach to segment index:8 handle:1076305344
>
> I think it needs to be:
>
> |               if (segment == NULL) {
> |                       LWLockRelease(DSA_AREA_LOCK(area));
> |                       dsa_dump(area);
> |                       elog(PANIC, "dsa_area could not attach to segment index:%zd handle:%d", index, handle);
> |               }

Right.

> ..but that triggers recursion:
>
> #0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
> #1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
> #2  0x0000000000a395c0 in errfinish (dummy=0) at elog.c:567
> #3  0x0000000000a3bbf6 in elog_finish (elevel=22, fmt=0xc9faa0 "dsa_area could not attach to segment index:%zd handle:%d") at elog.c:1389
> #4  0x0000000000a6b97a in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1747
> #5  0x0000000000a6a3dc in dsa_dump (area=0x1659200) at dsa.c:1093
> #6  0x0000000000a6b946 in get_segment_by_index (area=0x1659200, index=8) at dsa.c:1744

Ok, that makes sense.

> [pryzbyj@telsasoft-db postgresql]$ ls -lt /dev/shm |head
> total 353056
> -rw-------. 1 pryzbyj  pryzbyj   1048576 Feb 11 13:51 PostgreSQL.821164732
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 13:51 PostgreSQL.1990121974
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 12:54 PostgreSQL.847060172
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 11 12:48 PostgreSQL.1369859581
> -rw-------. 1 postgres postgres    21328 Feb 10 21:00 PostgreSQL.1155375187
> -rw-------. 1 pryzbyj  pryzbyj    196864 Feb 10 18:52 PostgreSQL.2136009186
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.1648026537
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.827867206
> -rw-------. 1 pryzbyj  pryzbyj   2097152 Feb 10 18:49 PostgreSQL.1684837530

Hmm.  While contemplating this evidence that you have multiple
postgres clusters running, I started wondering if there could be some
way for two different DSA areas to get their DSM segments mixed up,
perhaps related to the way that 11 generates identical sequences of
random() numbers in all parallel workers.  But I'm not seeing it; the
O_CREAT | O_EXCL protocol seems to avoid that (not to mention
permissions).

You truncated that list at 10 lines with "head"... do you know if
PostgreSQL.1076305344 was present?  Or if you do it again, the one who
name matches the value of "handle".


--
Thomas Munro
http://www.enterprisedb.com

  11. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-12T05:00:58Z

    On Mon, Feb 11, 2019 at 08:43:14PM -0600, Justin Pryzby wrote:
> I have a suspicion that this doesn't happen if
> parallel_leader_participation=off.

I think this is tentatively confirmed..I ran 20 loops for over 90 minutes with
no crash when parallel_leader_participation=off.

On enabling parallel_leader_participation, crash within 10min.

Sergei, could you confirm ?

Thomas:

2019-02-11 23:56:20.611 EST [12699] PANIC:  dsa_area could not attach to segment index:6 handle:1376636277
[pryzbyj@telsasoft-db postgresql]$ ls /dev/shm/ |grep PostgreSQL.1376636277 || echo Not present.
Not present.

Thanks,
Justin

  12. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-12T05:27:01Z

    On Tue, Feb 12, 2019 at 4:01 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> On Mon, Feb 11, 2019 at 08:43:14PM -0600, Justin Pryzby wrote:
> > I have a suspicion that this doesn't happen if
> > parallel_leader_participation=off.
>
> I think this is tentatively confirmed..I ran 20 loops for over 90 minutes with
> no crash when parallel_leader_participation=off.
>
> On enabling parallel_leader_participation, crash within 10min.

That's quite interesting.  I wonder if it's something specific about
the leader's behaviour, or if it's just because it takes one more
process to hit the bad behaviour on your system.

> Sergei, could you confirm ?
>
> Thomas:
>
> 2019-02-11 23:56:20.611 EST [12699] PANIC:  dsa_area could not attach to segment index:6 handle:1376636277
> [pryzbyj@telsasoft-db postgresql]$ ls /dev/shm/ |grep PostgreSQL.1376636277 || echo Not present.
> Not present.

Ok, based on the absence of the file, it seems like we destroyed it
but didn't remove the segment from our the list (unless of course it's
a bogus handle that never existed).  Perhaps that could happen if the
DSM segment's ref count got out of whack so it was destroyed too soon,
or if it didn't but our list manipulation code is borked or somehow we
didn't reach it or something concurrent confused it due to
insufficient locking or data being overwritten...

I need to reproduce this and load it up with instrumentation and
checks.   Will keep trying.

Were you running with assertions enabled?


--
Thomas Munro
http://www.enterprisedb.com

  13. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-12T05:33:31Z

    On Tue, Feb 12, 2019 at 4:27 PM Thomas Munro
<thomas.munro@enterprisedb.com> wrote:
> On Tue, Feb 12, 2019 at 4:01 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> > On Mon, Feb 11, 2019 at 08:43:14PM -0600, Justin Pryzby wrote:
> > > I have a suspicion that this doesn't happen if
> > > parallel_leader_participation=off.
> >
> > I think this is tentatively confirmed..I ran 20 loops for over 90 minutes with
> > no crash when parallel_leader_participation=off.
> >
> > On enabling parallel_leader_participation, crash within 10min.
>
> That's quite interesting.  I wonder if it's something specific about
> the leader's behaviour, or if it's just because it takes one more
> process to hit the bad behaviour on your system.

.  o O ( is there some way that getting peppered with signals from the
shm tuple queue machinery could break something here? )

-- 
Thomas Munro
http://www.enterprisedb.com

  14. Re: pg11.1: dsa_area could not attach to segment

    Sergei Kornilov <sk@zsrv.org> — 2019-02-12T09:14:59Z

    Hi

> I think this is tentatively confirmed..I ran 20 loops for over 90 minutes with
> no crash when parallel_leader_participation=off.
>
> On enabling parallel_leader_participation, crash within 10min.
>
> Sergei, could you confirm ?

I still have error with parallel_leader_participation = off. One difference is time: with parallel_leader_participation = on i have error after minute-two, with off - error was after 20 min.

My desktop is 
- debian testing with actual updates, 4.19.0-2-amd64 #1 SMP Debian 4.19.16-1 (2019-01-17) x86_64 GNU/Linux
- gcc version 8.2.0 (Debian 8.2.0-16)
- i build fresh REL_11_STABLE postgresql with  ./configure --enable-cassert --enable-debug CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer" --enable-tap-tests --prefix=/...

Can't provide dsa_dump(area) due recursion. With such dirty hack:

             fprintf(stderr,
-                    "    segment bin %zu (at least %d contiguous pages free):\n",
-                    i, 1 << (i - 1));
-            segment_index = area->control->segment_bins[i];
-            while (segment_index != DSA_SEGMENT_INDEX_NONE)
-            {
-                dsa_segment_map *segment_map;
-
-                segment_map =
-                    get_segment_by_index(area, segment_index);
-
-                fprintf(stderr,
-                        "      segment index %zu, usable_pages = %zu, "
-                        "contiguous_pages = %zu, mapped at %p\n",
-                        segment_index,
-                        segment_map->header->usable_pages,
-                        fpm_largest(segment_map->fpm),
-                        segment_map->mapped_address);
-                segment_index = segment_map->header->next;
-            }
+                    "    segment bin %zu (at least %d contiguous pages free), segment_index=%zu\n",
+                    i, 1 << (i - 1), area->control->segment_bins[i]);

i have result:

dsa_area handle 0:
  max_total_segment_size: 18446744073709551615
  total_segment_size: 2105344
  refcnt: 2
  pinned: f
  segment bins:
    segment bin 0 (at least -2147483648 contiguous pages free), segment_index=0
    segment bin 3 (at least 4 contiguous pages free), segment_index=1
    segment bin 8 (at least 128 contiguous pages free), segment_index=2
  pools:
    pool for blocks of span objects:
      fullness class 0 is empty
      fullness class 1:
        span descriptor at 0000010000001000, superblock at 0000010000001000, pages = 1, objects free = 54/72
      fullness class 2 is empty
      fullness class 3 is empty
    pool for large object spans:
      fullness class 0 is empty
      fullness class 1:
        span descriptor at 00000100000013b8, superblock at 0000020000009000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001380, superblock at 0000020000001000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001348, superblock at 00000100000f2000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001310, superblock at 00000100000ea000, pages = 8, objects free = 0/0
        span descriptor at 00000100000012d8, superblock at 00000100000e2000, pages = 8, objects free = 0/0
        span descriptor at 00000100000012a0, superblock at 00000100000da000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001268, superblock at 00000100000d2000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001230, superblock at 00000100000ca000, pages = 8, objects free = 0/0
        span descriptor at 00000100000011f8, superblock at 00000100000c2000, pages = 8, objects free = 0/0
        span descriptor at 00000100000011c0, superblock at 00000100000ba000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001188, superblock at 00000100000b2000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001150, superblock at 00000100000aa000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001118, superblock at 00000100000a2000, pages = 8, objects free = 0/0
        span descriptor at 00000100000010e0, superblock at 000001000009a000, pages = 8, objects free = 0/0
        span descriptor at 00000100000010a8, superblock at 0000010000092000, pages = 8, objects free = 0/0
        span descriptor at 0000010000001070, superblock at 0000010000012000, pages = 128, objects free = 0/0
      fullness class 2 is empty
      fullness class 3 is empty
    pool for size class 32 (object size 3640 bytes):
      fullness class 0 is empty
      fullness class 1:
        span descriptor at 0000010000001038, superblock at 0000010000002000, pages = 16, objects free = 17/18
      fullness class 2 is empty
      fullness class 3 is empty

"at least -2147483648" seems surprise.


melkij@melkij:~$ LANG=C ls -lt /dev/shm
total 0
-rw------- 1 melkij melkij 4194304 Feb 12 11:56 PostgreSQL.1822959854

only one segment, restart_after_crash = off and no more postgresql instances running.

regards, Sergei

  15. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-14T12:12:35Z

    On Tue, Feb 12, 2019 at 10:15 PM Sergei Kornilov <sk@zsrv.org> wrote:
> I still have error with parallel_leader_participation = off.

Justin very kindly set up a virtual machine similar to the one where
he'd seen the problem so I could experiment with it.  Eventually I
also managed to reproduce it locally, and have finally understood the
problem.

It doesn't happen on master (hence some of my initial struggle to
reproduce it) because of commit 197e4af9, which added srandom() to set
a different seed for each parallel workers.  Perhaps you see where
this is going already...

The problem is that a DSM handle (ie a random number) can be reused
for a new segment immediately after the shared memory object has been
destroyed but before the DSM slot has been released.  Now two DSM
slots have the same handle, and dsm_attach() can be confused by the
old segment and give up.

Here's a draft patch to fix that.  It also clears the handle in a case
where it wasn't previously cleared, but that wasn't strictly
necessary.  It just made debugging less confusing.


--
Thomas Munro
http://www.enterprisedb.com

  16. Re: pg11.1: dsa_area could not attach to segment

    Sergei Kornilov <sk@zsrv.org> — 2019-02-14T13:31:22Z

    Hi!

Great work, thank you!

I can not reproduce bug after 30min test long. (without patch bug was after minute-two)

regards Sergei

  17. Re: pg11.1: dsa_area could not attach to segment

    Justin Pryzby <pryzby@telsasoft.com> — 2019-02-14T16:20:10Z

    On Fri, Feb 15, 2019 at 01:12:35AM +1300, Thomas Munro wrote:
> The problem is that a DSM handle (ie a random number) can be reused
> for a new segment immediately after the shared memory object has been
> destroyed but before the DSM slot has been released.  Now two DSM
> slots have the same handle, and dsm_attach() can be confused by the
> old segment and give up.
> 
> Here's a draft patch to fix that.  It also clears the handle in a case
> where it wasn't previously cleared, but that wasn't strictly
> necessary.  It just made debugging less confusing.

Thanks.

Do you think that plausibly explains and resolves symptoms of bug#15585, too?

Justin

  18. Re: pg11.1: dsa_area could not attach to segment

    Sergei Kornilov <sk@zsrv.org> — 2019-02-14T16:36:55Z

    Hi

> Do you think that plausibly explains and resolves symptoms of bug#15585, too?

I think yes. Bug#15585 raised only after "dsa_area could not attach to segment" in different parallel worker. Leader stuck because waiting all parallel workers, but one worker has unexpected recursion in dsm_backend_shutdown [1] and will never shutdown. Backtrace show previous error in this backend: "cannot unpin a segment that is not pinned" - root cause is earlier and in a different process.

* https://www.postgresql.org/message-id/70942611548327380%40myt6-7734411c649e.qloud-c.yandex.net

regards, Sergei

  19. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-14T21:00:12Z

    On Fri, Feb 15, 2019 at 5:36 AM Sergei Kornilov <sk@zsrv.org> wrote:
> > Do you think that plausibly explains and resolves symptoms of bug#15585, too?
>
> I think yes. Bug#15585 raised only after "dsa_area could not attach to segment" in different parallel worker. Leader stuck because waiting all parallel workers, but one worker has unexpected recursion in dsm_backend_shutdown [1] and will never shutdown. Backtrace show previous error in this backend: "cannot unpin a segment that is not pinned" - root cause is earlier and in a different process.

Agreed.  Even though it's an unpleasant failure mode, I'm not entirely
sure if it's a good idea to make changes to avoid it.  We could move
the code around so that the error is raised after releasing the lock,
but then you'd either blow the stack or loop forever due to longjmp (I
haven't checked which).  To avoid that you'd have to clean out the
book-keeping in shared memory eagerly so that at the next level of
error recursion you've at least made progress (and admittedly there
are examples of things like that in the code), but how far should we
go to tolerate cases that shouldn't happen?  Practically, if we had
that behaviour and this bug, you'd eventually eat all the DSM slots
with leaked segments of shared memory, and your system wouldn't work
too well.  For now I think it's better to treat the root cause of the
unexpected error.

-- 
Thomas Munro
http://www.enterprisedb.com

  20. Re: pg11.1: dsa_area could not attach to segment

    Thomas Munro <thomas.munro@enterprisedb.com> — 2019-02-15T02:08:41Z

    On Fri, Feb 15, 2019 at 2:31 AM Sergei Kornilov <sk@zsrv.org> wrote:
> I can not reproduce bug after 30min test long. (without patch bug was after minute-two)

Thank you Justin and Sergei for all your help reproducing and testing this.

Fix pushed to all supported releases.  It's lightly refactored from
the version I posted yesterday.  Just doing s/break/continue/ made for
a cute patch, but this way the result is easier to understand IMHO.  I
also didn't bother with the non-essential change.

-- 
Thomas Munro
http://www.enterprisedb.com