Обсуждение: pg11.1: dsa_area could not attach to segment

In our query logs I saw:

postgres=# SELECT log_time, session_id, session_line, left(message,99), left(query,99) FROM postgres_log WHERE
error_severity='ERROR'AND message NOT LIKE 'cancel%';
 
-[ RECORD 1 ]+----------------------------------------------------------------------------------------------------
log_time     | 2018-12-31 15:39:11.917-05
session_id   | 5c2a7e6f.1fa4
session_line | 1
left         | dsa_area could not attach to segment
left         | SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array
-[ RECORD 2 ]+----------------------------------------------------------------------------------------------------
log_time     | 2018-12-31 15:39:11.917-05
session_id   | 5c2a7e6f.1fa3
session_line | 4
left         | dsa_area could not attach to segment
left         | SELECT colcld.child c, parent p, array_agg(colpar.attname::text ORDER BY colpar.attnum) cols, array

The full query + plan is:

|ts=# explain 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
ANDcolcld.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%', -- Do them last
|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;

|QUERY PLAN
|Limit  (cost=67128.06..67128.06 rows=1 width=307)
|  ->  Sort  (cost=67128.06..67137.84 rows=3912 width=307)
|        Sort Key: (((qa_1.parent)::text ~~ 'unused%'::text)),
(regexp_replace((((pg_attribute.attrelid)::regclass)::text),
'.*_((([0-9]{4}_[0-9]{2})_[0-9]{2})|(([0-9]{6})([0-9]{2})?))$'::text,'\3\5'::text)) DESC,
(regexp_replace((((pg_attribute.attrelid)::regclass)::text),'.*_'::text, ''::text)) DESC
 
|        ->  GroupAggregate  (cost=66893.34..67108.50 rows=3912 width=307)
|              Group Key: (((pg_attribute.attrelid)::regclass)::text), qa_1.parent
|              ->  Sort  (cost=66893.34..66903.12 rows=3912 width=256)
|                    Sort Key: (((pg_attribute.attrelid)::regclass)::text), qa_1.parent
|                    ->  Gather  (cost=40582.28..66659.91 rows=3912 width=256)
|                          Workers Planned: 2
|                          ->  Parallel Hash Join  (cost=39582.28..65268.71 rows=1630 width=256)
|                                Hash Cond: (((to_regclass((qa_1.child)::text))::oid = pg_attribute.attrelid) AND
(colpar.attname= pg_attribute.attname))
 
|                                Join Filter: (colpar.atttypid <> pg_attribute.atttypid)
|                                ->  Nested Loop  (cost=0.43..25614.89 rows=11873 width=366)
|                                      ->  Parallel Append  (cost=0.00..12.00 rows=105 width=292)
|                                            ->  Parallel Seq Scan on queued_alters_child qa_1  (cost=0.00..11.47
rows=147width=292)
 
|                                            ->  Parallel Seq Scan on queued_alters qa  (cost=0.00..0.00 rows=1
width=292)
|                                      ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute colpar
(cost=0.43..242.70rows=114 width=78)
 
|                                            Index Cond: ((attrelid = (to_regclass((qa_1.parent)::text))::oid) AND
(attnum> 0))
 
|                                            Filter: (NOT attisdropped)
|                                ->  Parallel Hash  (cost=33651.38..33651.38 rows=395365 width=72)
|                                      ->  Parallel Seq Scan on pg_attribute  (cost=0.00..33651.38 rows=395365
width=72)
|                                            Filter: ((NOT attisdropped) AND (attnum > 0))
|

queued_alters is usually empty, and looks like it would've last been nonempty on 2018-12-10.

ts=# \d queued_alters
                  Table "public.queued_alters"
 Column |         Type          | Collation | Nullable | Default
--------+-----------------------+-----------+----------+---------
 child  | character varying(64) |           |          |
 parent | character varying(64) |           |          |
Indexes:
    "queued_alters_child_parent_key" UNIQUE CONSTRAINT, btree (child, parent)
Number of child tables: 1 (Use \d+ to list them.)

I found this other log at that time:
 2018-12-31 15:39:11.918-05 | 30831 | 5bf38e71.786f |            5 | background worker "parallel worker" (PID 8100)
exitedwith exit code 1
 

Which is the postmaster, or its PID in any case..

[pryzbyj@telsasoft-db ~]$ ps -wwwf 30831
UID        PID  PPID  C STIME TTY      STAT   TIME CMD
postgres 30831     1  0 Nov19 ?        S     62:44 /usr/pgsql-11/bin/postmaster -D /var/lib/pgsql/11/data

postgres=# SELECT log_time, pid, session_line, left(message,99) FROM postgres_log WHERE session_id='5bf38e71.786f' ;
          log_time          |  pid  | session_line |                                  left

----------------------------+-------+--------------+-------------------------------------------------------------------------
 2018-12-31 15:39:11.918-05 | 30831 |            5 | background worker "parallel worker" (PID 8100) exited with exit
code1
 
 2018-12-31 15:39:11.935-05 | 30831 |            6 | background worker "parallel worker" (PID 8101) exited with exit
code1
 
 2018-12-31 16:40:47.42-05  | 30831 |            7 | background worker "parallel worker" (PID 7239) exited with exit
code1
 
 2018-12-31 16:40:47.42-05  | 30831 |            8 | background worker "parallel worker" (PID 7240) exited with exit
code1
 
 2018-12-31 16:41:00.151-05 | 30831 |            9 | background worker "parallel worker" (PID 7371) exited with exit
code1
 
 2018-12-31 16:41:00.151-05 | 30831 |           10 | background worker "parallel worker" (PID 7372) exited with exit
code1
 
 2018-12-31 16:41:04.024-05 | 30831 |           11 | background worker "parallel worker" (PID 7451) exited with exit
code1
 
 2018-12-31 16:41:04.024-05 | 30831 |           12 | background worker "parallel worker" (PID 7450) exited with exit
code1
 
 2018-12-31 16:41:23.845-05 | 30831 |           13 | background worker "parallel worker" (PID 7658) exited with exit
code1
 
 2018-12-31 16:41:23.845-05 | 30831 |           14 | background worker "parallel worker" (PID 7659) exited with exit
code1
 
 2018-12-31 16:43:58.854-05 | 30831 |           15 | background worker "parallel worker" (PID 10825) exited with exit
code1
 
 2018-12-31 16:43:58.854-05 | 30831 |           16 | background worker "parallel worker" (PID 10824) exited with exit
code1
 

I seem to be missing logs for session_lines 1-4 , which would've been rotated
to oblivion if older than 24h.

I found these:

https://www.postgresql.org/message-id/flat/CAPa4P2YzgRTBHHRx2KAPUO1_xkmqQgT2xP0tS_e%3DphWvNzWdkA%40mail.gmail.com#4a1a94bc71d4c99c01babc759fe5b6ec
https://www.postgresql.org/message-id/CAEepm=0Mv9BigJPpribGQhnHqVGYo2+kmzekGUVJJc9Y_ZVaYA@mail.gmail.com

Which appears to have been commited so I think this error is not unexpected.

|commit fd7c0fa732d97a4b4ebb58730e6244ea30d0a618
|Author: Robert Haas <rhaas@postgresql.org>
|Date:   Mon Dec 18 12:17:37 2017 -0500
|
|Fix crashes on plans with multiple Gather (Merge) nodes.

I will try to reproduce and provide bt...but all I can think to do is run a
tight loop around that query and hope something else comes by and tickles it a
few more times.

Happy Grecian newyear.

Justin

Hi Justin,

On Tue, Jan 1, 2019 at 11:17 AM Justin Pryzby <pryzby@telsasoft.com> wrote:
> dsa_area could not attach to segment

                /*
                 * If we are reached by dsa_free or dsa_get_address,
there must be at
                 * least one object allocated in the referenced
segment.  Otherwise,
                 * their caller has a double-free or access-after-free
bug, which we
                 * have no hope of detecting.  So we know it's safe to
access this
                 * array slot without holding a lock; it won't change
underneath us.
                 * Furthermore, we know that we can see the latest
contents of the
                 * slot, as explained in check_for_freed_segments, which those
                 * functions call before arriving here.
                 */
                handle = area->control->segment_handles[index];

                /* It's an error to try to access an unused slot. */
                if (handle == DSM_HANDLE_INVALID)
                        elog(ERROR,
                                 "dsa_area could not attach to a
segment that has been freed");

                segment = dsm_attach(handle);
                if (segment == NULL)
                        elog(ERROR, "dsa_area could not attach to segment");

Hmm.  We observed a valid handle, but then couldn't attach to it,
which could indicate that the value we saw was stale (and the theory
stated above has a hole?), or the segment was in the process of being
freed and we have a use-after-free problem leading to this race, or
something else along those lines.  If you can reproduce this on a dev
system, it'd be good to see the backtrace and know which of several
call paths led here, perhaps by changing that error to PANIC.  I'll
try that too.

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

I finally reproduced this with core..

For some reason I needed to write assert() rather than elog(PANIC), otherwise
it failed with ERROR and no core..

@@ -1741,4 +1743,5 @@ get_segment_by_index(dsa_area *area, dsa_segment_index index)
                segment = dsm_attach(handle);
+               assert (segment != NULL);
                if (segment == NULL)
-                       elog(ERROR, "dsa_area could not attach to segment");
+                       elog(PANIC, "dsa_area could not attach to segment");
                if (area->mapping_pinned)

On Mon, Dec 03, 2018 at 11:45:00AM +1300, Thomas Munro wrote:
                                                                     
 
> If anyone can reproduce this problem with a debugger, it'd be
                                                                     
 
> interesting to see the output of dsa_dump(area), and
                                                                     
 
> FreePageManagerDump(segment_map->fpm).

Looks like this will take some work, is it ok if I make a coredump available to
you ?  I'm not sure how sensitive it is to re/compilation, but I'm using PG11.1
compiled locally on centos6.

/var/log/postgresql/postgresql-2019-02-05_111730.log-< 2019-02-05 11:17:31.372 EST  >LOG:  background worker "parallel
worker"(PID 17110) was terminated by signal 6: Aborted
 
/var/log/postgresql/postgresql-2019-02-05_111730.log:< 2019-02-05 11:17:31.372 EST  >DETAIL:  Failed process was
running: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_attributecolpar 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>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 1
 

(gdb) bt
#0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
#1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
#2  0x00000037b9c2b60e in __assert_fail_base () from /lib64/libc.so.6
#3  0x00000037b9c2b6d0 in __assert_fail () from /lib64/libc.so.6
#4  0x00000000008c4a72 in get_segment_by_index (area=0x2788440, index=<value optimized out>) at dsa.c:1744
#5  0x00000000008c58e9 in get_best_segment (area=0x2788440, npages=8) at dsa.c:1995
#6  0x00000000008c6c99 in dsa_allocate_extended (area=0x2788440, size=32768, flags=0) at dsa.c:703
#7  0x000000000064c6fe in ExecParallelHashTupleAlloc (hashtable=0x27affb0, size=104, shared=0x7ffc6b5cfc48) at
nodeHash.c:2837
#8  0x000000000064cb92 in ExecParallelHashTableInsert (hashtable=0x27affb0, slot=<value optimized out>,
hashvalue=423104953)at nodeHash.c:1693
 
#9  0x000000000064cf17 in MultiExecParallelHash (node=0x27a1ed8) at nodeHash.c:288
#10 MultiExecHash (node=0x27a1ed8) at nodeHash.c:112
#11 0x000000000064e1f8 in ExecHashJoinImpl (pstate=0x2793038) at nodeHashjoin.c:290
#12 ExecParallelHashJoin (pstate=0x2793038) at nodeHashjoin.c:581
#13 0x0000000000638ce0 in ExecProcNodeInstr (node=0x2793038) at execProcnode.c:461
#14 0x00000000006349c7 in ExecProcNode (queryDesc=0x2782cd0, direction=<value optimized out>, count=0, execute_once=56)
at../../../src/include/executor/executor.h:237
 
#15 ExecutePlan (queryDesc=0x2782cd0, direction=<value optimized out>, count=0, execute_once=56) at execMain.c:1723
#16 standard_ExecutorRun (queryDesc=0x2782cd0, direction=<value optimized out>, count=0, execute_once=56) at
execMain.c:364
#17 0x00007f84a97c8618 in pgss_ExecutorRun (queryDesc=0x2782cd0, direction=ForwardScanDirection, count=0,
execute_once=true)at pg_stat_statements.c:892
 
#18 0x00007f84a93357dd in explain_ExecutorRun (queryDesc=0x2782cd0, direction=ForwardScanDirection, count=0,
execute_once=true)at auto_explain.c:268
 
#19 0x0000000000635071 in ParallelQueryMain (seg=0x268fba8, toc=0x7f84a9578000) at execParallel.c:1402
#20 0x0000000000508f34 in ParallelWorkerMain (main_arg=<value optimized out>) at parallel.c:1409
#21 0x0000000000704760 in StartBackgroundWorker () at bgworker.c:834
#22 0x000000000070e11c in do_start_bgworker () at postmaster.c:5698
#23 maybe_start_bgworkers () at postmaster.c:5911
#24 0x0000000000710786 in sigusr1_handler (postgres_signal_arg=<value optimized out>) at postmaster.c:5091
#25 <signal handler called>
#26 0x00000037b9ce1603 in __select_nocancel () from /lib64/libc.so.6
#27 0x000000000071300e in ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1670
#28 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1379
#29 0x000000000067e8c0 in main (argc=3, argv=0x265f960) at main.c:228

#0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00000037b9c2b60e in __assert_fail_base () from /lib64/libc.so.6
No symbol table info available.
#3  0x00000037b9c2b6d0 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#4  0x00000000008c4a72 in get_segment_by_index (area=0x2788440, index=<value optimized out>) at dsa.c:1744
        handle = <value optimized out>
        segment = 0x0
        segment_map = <value optimized out>
        __func__ = "get_segment_by_index"
        __PRETTY_FUNCTION__ = "get_segment_by_index"
#5  0x00000000008c58e9 in get_best_segment (area=0x2788440, npages=8) at dsa.c:1995
        segment_map = <value optimized out>
        next_segment_index = <value optimized out>
        contiguous_pages = <value optimized out>
        threshold = 512
        segment_index = 10
        bin = <value optimized out>
#6  0x00000000008c6c99 in dsa_allocate_extended (area=0x2788440, size=32768, flags=0) at dsa.c:703
        npages = 8
        first_page = <value optimized out>
        span_pointer = 8796097199728
        pool = 0x7f84a9579730
        size_class = <value optimized out>
        start_pointer = <value optimized out>
        segment_map = <value optimized out>
        result = 140207753496128
        __func__ = "dsa_allocate_extended"
        __PRETTY_FUNCTION__ = "dsa_allocate_extended"
#7  0x000000000064c6fe in ExecParallelHashTupleAlloc (hashtable=0x27affb0, size=104, shared=0x7ffc6b5cfc48) at
nodeHash.c:2837
        pstate = 0x7f84a9578540
        chunk_shared = <value optimized out>
        chunk = <value optimized out>
        chunk_size = 32768
        result = <value optimized out>
        curbatch = 0
#8  0x000000000064cb92 in ExecParallelHashTableInsert (hashtable=0x27affb0, slot=<value optimized out>,
hashvalue=423104953)at nodeHash.c:1693
 
        hashTuple = <value optimized out>
        tuple = 0x27b00c8
        shared = <value optimized out>
        bucketno = 1577401
        batchno = 0
#9  0x000000000064cf17 in MultiExecParallelHash (node=0x27a1ed8) at nodeHash.c:288
        outerNode = 0x27a1ff0
        hashkeys = 0x27af110
        slot = 0x27a3d70
        econtext = 0x27a3798
        hashvalue = 423104953
        i = <value optimized out>
        pstate = 0x7f84a9578540
        hashtable = 0x27affb0
        build_barrier = 0x7f84a9578590
#10 MultiExecHash (node=0x27a1ed8) at nodeHash.c:112
No locals.
#11 0x000000000064e1f8 in ExecHashJoinImpl (pstate=0x2793038) at nodeHashjoin.c:290
        outerNode = 0x2792f20
        hashNode = 0x27a1ed8
        econtext = 0x2792c68
        outerTupleSlot = 0x1
        node = 0x2793038
        joinqual = 0x27ac270
        otherqual = 0x0
        hashtable = 0x27affb0
        hashvalue = 0
        batchno = 41493896
        parallel_state = 0x7f84a9578540
#12 ExecParallelHashJoin (pstate=0x2793038) at nodeHashjoin.c:581
No locals.

Justin

And here's the "dsa_allocate could not find %zu free pages" error with core.

@@ -726,5 +728,5 @@ dsa_allocate_extended(dsa_area *area, size_t size, int flags)
                 */
-               if (!FreePageManagerGet(segment_map->fpm, npages, &first_page))
-                       elog(FATAL,
-                                "dsa_allocate could not find %zu free pages", npages);
+               assert (FreePageManagerGet(segment_map->fpm, npages, &first_page));
+
+               // if (!FreePageManagerGet(segment_map->fpm, npages, &first_page)) elog(PANIC, "dsa_allocate could not
find%zu free pages", npages);
 
                LWLockRelease(DSA_AREA_LOCK(area));

< 2019-02-05 13:23:29.137 EST  >LOG:  background worker "parallel worker" (PID 7140) was terminated by signal 6:
Aborted
< 2019-02-05 13:23:29.137 EST  >DETAIL:  Failed process was running: explain analyze SELECT * FROM eric_enodeb_metrics
WHEREstart_time>='2017-10-01' AND (site_id<1900 OR site_id>2700)
 

#0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
#1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
#2  0x00000037b9c2b60e in __assert_fail_base () from /lib64/libc.so.6
#3  0x00000037b9c2b6d0 in __assert_fail () from /lib64/libc.so.6
#4  0x00000000008c6f74 in dsa_allocate_extended (area=0x27c05e0, size=393220, flags=5) at dsa.c:729
#5  0x000000000068521f in pagetable_allocate (pagetable=<value optimized out>, size=<value optimized out>) at
tidbitmap.c:1511
#6  0x00000000006876d2 in pagetable_grow (tbm=0x7f84a8d86a58, pageno=1635) at
../../../src/include/lib/simplehash.h:383
#7  pagetable_insert (tbm=0x7f84a8d86a58, pageno=1635) at ../../../src/include/lib/simplehash.h:508
#8  tbm_get_pageentry (tbm=0x7f84a8d86a58, pageno=1635) at tidbitmap.c:1225
#9  0x0000000000687c50 in tbm_add_tuples (tbm=0x7f84a8d86a58, tids=<value optimized out>, ntids=1, recheck=false) at
tidbitmap.c:405
#10 0x00000000004e43df in btgetbitmap (scan=0x2829fa8, tbm=0x7f84a8d86a58) at nbtree.c:332
#11 0x00000000004d8a91 in index_getbitmap (scan=0x2829fa8, bitmap=<value optimized out>) at indexam.c:726
#12 0x0000000000647c98 in MultiExecBitmapIndexScan (node=0x2829720) at nodeBitmapIndexscan.c:104
#13 0x0000000000646078 in MultiExecBitmapOr (node=0x28046e8) at nodeBitmapOr.c:153
#14 0x0000000000646afd in BitmapHeapNext (node=0x2828db8) at nodeBitmapHeapscan.c:145
#15 0x000000000063a550 in ExecScanFetch (node=0x2828db8, accessMtd=0x6469e0 <BitmapHeapNext>, recheckMtd=0x646740
<BitmapHeapRecheck>)at execScan.c:95
 
#16 ExecScan (node=0x2828db8, accessMtd=0x6469e0 <BitmapHeapNext>, recheckMtd=0x646740 <BitmapHeapRecheck>) at
execScan.c:162
#17 0x0000000000638ce0 in ExecProcNodeInstr (node=0x2828db8) at execProcnode.c:461
#18 0x00000000006414fc in ExecProcNode (pstate=<value optimized out>) at ../../../src/include/executor/executor.h:237
#19 ExecAppend (pstate=<value optimized out>) at nodeAppend.c:294
#20 0x0000000000638ce0 in ExecProcNodeInstr (node=0x27cb0a0) at execProcnode.c:461
#21 0x00000000006349c7 in ExecProcNode (queryDesc=0x7f84a8de7520, direction=<value optimized out>, count=0,
execute_once=160)at ../../../src/include/executor/executor.h:237
 
#22 ExecutePlan (queryDesc=0x7f84a8de7520, direction=<value optimized out>, count=0, execute_once=160) at
execMain.c:1723
#23 standard_ExecutorRun (queryDesc=0x7f84a8de7520, direction=<value optimized out>, count=0, execute_once=160) at
execMain.c:364
#24 0x00007f84a97c8618 in pgss_ExecutorRun (queryDesc=0x7f84a8de7520, direction=ForwardScanDirection, count=0,
execute_once=true)at pg_stat_statements.c:892
 
#25 0x00007f84a91aa7dd in explain_ExecutorRun (queryDesc=0x7f84a8de7520, direction=ForwardScanDirection, count=0,
execute_once=true)at auto_explain.c:268
 
#26 0x0000000000635071 in ParallelQueryMain (seg=0x268fba8, toc=0x7f84a93ed000) at execParallel.c:1402
#27 0x0000000000508f34 in ParallelWorkerMain (main_arg=<value optimized out>) at parallel.c:1409
#28 0x0000000000704760 in StartBackgroundWorker () at bgworker.c:834
#29 0x000000000070e11c in do_start_bgworker () at postmaster.c:5698
#30 maybe_start_bgworkers () at postmaster.c:5911
#31 0x0000000000710786 in sigusr1_handler (postgres_signal_arg=<value optimized out>) at postmaster.c:5091
#32 <signal handler called>
#33 0x00000037b9ce1603 in __select_nocancel () from /lib64/libc.so.6
#34 0x000000000071300e in ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1670
#35 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1379
#36 0x000000000067e8c0 in main (argc=3, argv=0x265f960) at main.c:228

#0  0x00000037b9c32495 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000037b9c33c75 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00000037b9c2b60e in __assert_fail_base () from /lib64/libc.so.6
No symbol table info available.
#3  0x00000037b9c2b6d0 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#4  0x00000000008c6f74 in dsa_allocate_extended (area=0x27c05e0, size=393220, flags=5) at dsa.c:729
        npages = 97
        first_page = <value optimized out>
        span_pointer = 1099511632488
        pool = 0x7f84a93eecf0
        size_class = <value optimized out>
        start_pointer = <value optimized out>
        segment_map = <value optimized out>
        result = 140207751879680
        __func__ = "dsa_allocate_extended"
        __PRETTY_FUNCTION__ = "dsa_allocate_extended"
#5  0x000000000068521f in pagetable_allocate (pagetable=<value optimized out>, size=<value optimized out>) at
tidbitmap.c:1511
        tbm = 0x7f84a8d86a58
        ptbase = <value optimized out>
#6  0x00000000006876d2 in pagetable_grow (tbm=0x7f84a8d86a58, pageno=1635) at
../../../src/include/lib/simplehash.h:383
        olddata = 0x7f84a8d23004
        i = <value optimized out>
        copyelem = <value optimized out>
        startelem = 0
        oldsize = <value optimized out>
        newdata = <value optimized out>
#7  pagetable_insert (tbm=0x7f84a8d86a58, pageno=1635) at ../../../src/include/lib/simplehash.h:508
        hash = 218584604
        startelem = <value optimized out>
        curelem = <value optimized out>
        data = <value optimized out>
        insertdist = 0
#8  tbm_get_pageentry (tbm=0x7f84a8d86a58, pageno=1635) at tidbitmap.c:1225
        page = <value optimized out>
        found = <value optimized out>
#9  0x0000000000687c50 in tbm_add_tuples (tbm=0x7f84a8d86a58, tids=<value optimized out>, ntids=1, recheck=false) at
tidbitmap.c:405
        blk = <value optimized out>
        off = 14
        wordnum = <value optimized out>
        bitnum = <value optimized out>
        currblk = <value optimized out>
        page = <value optimized out>
        i = <value optimized out>
        __func__ = "tbm_add_tuples"
#10 0x00000000004e43df in btgetbitmap (scan=0x2829fa8, tbm=0x7f84a8d86a58) at nbtree.c:332
        so = 0x2843c90
        ntids = 5842
        heapTid = <value optimized out>
#11 0x00000000004d8a91 in index_getbitmap (scan=0x2829fa8, bitmap=<value optimized out>) at indexam.c:726
        ntids = <value optimized out>
        __func__ = "index_getbitmap"
#12 0x0000000000647c98 in MultiExecBitmapIndexScan (node=0x2829720) at nodeBitmapIndexscan.c:104
        tbm = 0x7f84a8d86a58
        scandesc = 0x2829fa8
        nTuples = <value optimized out>
        doscan = <value optimized out>
#13 0x0000000000646078 in MultiExecBitmapOr (node=0x28046e8) at nodeBitmapOr.c:153
        subnode = 0x2829720
        subresult = <value optimized out>
        bitmapplans = <value optimized out>
        nplans = 2
        i = <value optimized out>
        result = 0x7f84a8d86a58
        __func__ = "MultiExecBitmapOr"
#14 0x0000000000646afd in BitmapHeapNext (node=0x2828db8) at nodeBitmapHeapscan.c:145
        econtext = 0x2828b08
        scan = 0x282d808
        tbm = <value optimized out>
        tbmiterator = 0x0
        shared_tbmiterator = 0x0
        tbmres = <value optimized out>
        targoffset = <value optimized out>
        slot = 0x282a888
        pstate = 0x7f84a93eda40
        dsa = 0x27c05e0
        __func__ = "BitmapHeapNext"

Justin

I should have included query plan for the query which caused the "could not
find free pages" error.

This is a contrived query which I made up to try to exercise/stress bitmap
scans based on Thomas's working hypothesis for this error/bug.  This seems to
be easier to hit than the other error ("could not attach to segment") - a loop
around this query has run into "free pages" several times today.

explain (analyze,costs off,timing off) SELECT * FROM eric_enodeb_metrics WHERE start_time>='2017-10-01' AND
(site_id<1900OR site_id>2700)
 

 Gather (actual rows=82257 loops=1)
   Workers Planned: 3
   Workers Launched: 3
   ->  Parallel Append (actual rows=20564 loops=4)
         ->  Parallel Bitmap Heap Scan on eric_enodeb_201901 (actual rows=6366 loops=4)
               Recheck Cond: ((site_id < 1900) OR (site_id > 2700))
               Filter: (start_time >= '2017-10-01 00:00:00-04'::timestamp with time zone)
               Heap Blocks: exact=2549
               ->  BitmapOr (actual rows=0 loops=1)
                     ->  Bitmap Index Scan on eric_enodeb_201901_site_idx (actual rows=0 loops=1)
                           Index Cond: (site_id < 1900)
                     ->  Bitmap Index Scan on eric_enodeb_201901_site_idx (actual rows=25463 loops=1)
                           Index Cond: (site_id > 2700)
         ->  Parallel Bitmap Heap Scan on eric_enodeb_201810 (actual rows=15402 loops=1)
               Recheck Cond: ((site_id < 1900) OR (site_id > 2700))
               Filter: (start_time >= '2017-10-01 00:00:00-04'::timestamp with time zone)
               ->  BitmapOr (actual rows=0 loops=1)
                     ->  Bitmap Index Scan on eric_enodeb_201810_site_idx (actual rows=0 loops=1)
                           Index Cond: (site_id < 1900)
                     ->  Bitmap Index Scan on eric_enodeb_201810_site_idx (actual rows=15402 loops=1)
                           Index Cond: (site_id > 2700)
         ->  Parallel Bitmap Heap Scan on eric_enodeb_201812 (actual rows=14866 loops=1)
               Recheck Cond: ((site_id < 1900) OR (site_id > 2700))
               Filter: (start_time >= '2017-10-01 00:00:00-04'::timestamp with time zone)
               ->  BitmapOr (actual rows=0 loops=1)
                     ->  Bitmap Index Scan on eric_enodeb_201812_site_idx (actual rows=0 loops=1)
                           Index Cond: (site_id < 1900)
                     ->  Bitmap Index Scan on eric_enodeb_201812_site_idx (actual rows=14866 loops=1)
                           Index Cond: (site_id > 2700)
         ->  Parallel Bitmap Heap Scan on eric_enodeb_201811 (actual rows=7204 loops=2)
               Recheck Cond: ((site_id < 1900) OR (site_id > 2700))
               Filter: (start_time >= '2017-10-01 00:00:00-04'::timestamp with time zone)
               Heap Blocks: exact=7372
               ->  BitmapOr (actual rows=0 loops=1)
                     ->  Bitmap Index Scan on eric_enodeb_201811_site_idx (actual rows=0 loops=1)
                           Index Cond: (site_id < 1900)
                     ->  Bitmap Index Scan on eric_enodeb_201811_site_idx (actual rows=14408 loops=1)
                           Index Cond: (site_id > 2700)
         ->  Parallel Bitmap Heap Scan on eric_enodeb_201902 (actual rows=5128 loops=1)
               Recheck Cond: ((site_id < 1900) OR (site_id > 2700))
               Filter: (start_time >= '2017-10-01 00:00:00-04'::timestamp with time zone)
               Heap Blocks: exact=3374
               ->  BitmapOr (actual rows=0 loops=1)
                     ->  Bitmap Index Scan on eric_enodeb_201902_site_idx (actual rows=0 loops=1)
                           Index Cond: (site_id < 1900)
                     ->  Bitmap Index Scan on eric_enodeb_201902_site_idx (actual rows=5128 loops=1)
                           Index Cond: (site_id > 2700)
         [...]

Justin

On Wed, Feb 6, 2019 at 1:10 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> This is a contrived query which I made up to try to exercise/stress bitmap
> scans based on Thomas's working hypothesis for this error/bug.  This seems to
> be easier to hit than the other error ("could not attach to segment") - a loop
> around this query has run into "free pages" several times today.

Thanks.  I'll go and try to repro this with queries that look like that.

It's possibly interesting that you're running on VMWare (as mentioned
in an off-list email), though I haven't got a specific theory about
why that'd be relevant.  I suppose it could be some kind of cache
coherency bug that is more likely there for whatever reason.  I've
being trying to repro on a laptop and a couple of bare metal servers.
Can anyone else who has hit this comment on any virtualisation they
might be using?

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

On Wed, Feb 6, 2019 at 4:22 PM Thomas Munro
<thomas.munro@enterprisedb.com> wrote:
> On Wed, Feb 6, 2019 at 1:10 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
> > This is a contrived query which I made up to try to exercise/stress bitmap
> > scans based on Thomas's working hypothesis for this error/bug.  This seems to
> > be easier to hit than the other error ("could not attach to segment") - a loop
> > around this query has run into "free pages" several times today.
>
> Thanks.  I'll go and try to repro this with queries that look like that.

No luck so far.  My colleague Robert pointed out that the
fpm->contiguous_pages_dirty mechanism (that lazily maintains
fpm->contiguous_pages) is suspicious here, but we haven't yet found a
theory to explain how fpm->contiguous_pages could have a value that is
too large.  Clearly such a bug could result in a segment that claims
too high a number, and that'd result in this error.

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

On Wed, Feb 06, 2019 at 04:22:12PM +1100, Thomas Munro wrote:
> Can anyone else who has hit this comment on any virtualisation they
> might be using?

I don't think most of these people are on -hackers (one of the original reports
was on -performance) so I'm copying them now.

Could you let us know which dsa_* error you were seeing, whether or not you
were running postgres under virtual environment, and (if so) which VM
hypervisor?

Thanks,
Justin

https://www.postgresql.org/message-id/flat/CAMAYy4%2Bw3NTBM5JLWFi8twhWK4%3Dk_5L4nV5%2BbYDSPu8r4b97Zg%40mail.gmail.com

https://www.postgresql.org/message-id/flat/CAEepm%3D0aPq2yEy39gEqVK2m_Qi6jJdy96ysHGJ6VSHOZFz%2Bxbg%40mail.gmail.com#e02bee0220b422fe91a3383916107504
https://www.postgresql.org/message-id/20181231221734.GB25379%40telsasoft.com

Hi

> Could you let us know which dsa_* error you were seeing, whether or not you
> were running postgres under virtual environment, and (if so) which VM
> hypervisor?

System from my report is amazon virtual server. lscpu say:
Hypervisor vendor:     Xen
Virtualization type:   full

regards, Sergei

On Wed, Feb 06, 2019 at 06:37:16PM +0100, Jakub Glapa wrote:
> I'm seeing dsa_allocate on two different servers.
> One is virtualized with VMWare the other is bare metal.

Thanks.  So it's not limited to vmware or VM at all.

FYI here we've seen DSA errors on (and only on) two vmware VMs.

It might be interesting to have CPU info, too.

For us the affected servers are:

Intel(R) Xeon(R) CPU E5-2470 0 @ 2.30GHz stepping 02
microcode: CPU0 sig=0x206d2, pf=0x1, revision=0xb00002e

Intel(R) Xeon(R) CPU E5-2680 v2 @ 2.80GHz stepping 02
microcode: CPU0 sig=0x206d2, pf=0x1, revision=0x710

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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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

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

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:
listeningon IPv6 address "::1", port 5678
2019-02-0709: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
onUnix 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

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
psqlpostgres 
 
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.childc, 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_attributecolpar 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>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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::textORDER BY colpar.attnum) cols, array_agg(format_type(colpar.atttypid, colpar.atttypmod)
ORDERBY colpar.attnum) AS types FROM queued_alters qa JOIN pg_attribute colpar ON
to_regclass(qa.parent)=colpar.attrelidAND colpar.attnum>0 AND NOT colpar.attisdropped JOIN (SELECT *,
attrelid::regclass::textAS child FROM pg_attribute) colcld ON to_regclass(qa.child) =colcld.attrelid AND
colcld.attnum>0AND NOT colcld.attisdropped WHERE colcld.attname=colpar.attname AND colpar.atttypid!=colcld.atttypid
GROUPBY 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, '.*_', '')
DESCLIMIT 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

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"
errorafter 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
tosegment") 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=<optimizedout>, 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

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
attachto 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

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

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
attachto 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)
atdsa.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)
atnodeHash.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

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

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
attachto 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)
atdsa.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

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

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

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

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

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

Hi!

Great work, thank you!

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

regards Sergei

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

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
stuckbecause waiting all parallel workers, but one worker has unexpected recursion in dsm_backend_shutdown [1] and will
nevershutdown. Backtrace show previous error in this backend: "cannot unpin a segment that is not pinned" - root cause
isearlier and in a different process.
 

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

regards, Sergei

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
stuckbecause waiting all parallel workers, but one worker has unexpected recursion in dsm_backend_shutdown [1] and will
nevershutdown. Backtrace show previous error in this backend: "cannot unpin a segment that is not pinned" - root cause
isearlier 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

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