pg11.1: dsa_area could not attach to segment

classic Classic list List threaded Threaded
32 messages Options
12
Reply | Threaded
Open this post in threaded view
|

pg11.1: dsa_area could not attach to segment

Justin Pryzby
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 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%', -- 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=147 width=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.70 rows=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) exited with 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 code 1
 2018-12-31 15:39:11.935-05 | 30831 |            6 | background worker "parallel worker" (PID 8101) exited with exit code 1
 2018-12-31 16:40:47.42-05  | 30831 |            7 | background worker "parallel worker" (PID 7239) exited with exit code 1
 2018-12-31 16:40:47.42-05  | 30831 |            8 | background worker "parallel worker" (PID 7240) exited with exit code 1
 2018-12-31 16:41:00.151-05 | 30831 |            9 | background worker "parallel worker" (PID 7371) exited with exit code 1
 2018-12-31 16:41:00.151-05 | 30831 |           10 | background worker "parallel worker" (PID 7372) exited with exit code 1
 2018-12-31 16:41:04.024-05 | 30831 |           11 | background worker "parallel worker" (PID 7451) exited with exit code 1
 2018-12-31 16:41:04.024-05 | 30831 |           12 | background worker "parallel worker" (PID 7450) exited with exit code 1
 2018-12-31 16:41:23.845-05 | 30831 |           13 | background worker "parallel worker" (PID 7658) exited with exit code 1
 2018-12-31 16:41:23.845-05 | 30831 |           14 | background worker "parallel worker" (PID 7659) exited with exit code 1
 2018-12-31 16:43:58.854-05 | 30831 |           15 | background worker "parallel worker" (PID 10825) exited with exit code 1
 2018-12-31 16:43:58.854-05 | 30831 |           16 | background worker "parallel worker" (PID 10824) exited with exit code 1

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@...

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

|commit fd7c0fa732d97a4b4ebb58730e6244ea30d0a618
|Author: Robert Haas <[hidden email]>
|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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
Hi Justin,

On Tue, Jan 1, 2019 at 11:17 AM Justin Pryzby <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Justin Pryzby
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_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

(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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
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 WHERE start_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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
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<1900 OR 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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
On Wed, Feb 6, 2019 at 1:10 PM Justin Pryzby <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
On Wed, Feb 6, 2019 at 4:22 PM Thomas Munro
<[hidden email]> wrote:
> On Wed, Feb 6, 2019 at 1:10 PM Justin Pryzby <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Thomas Munro-3
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

Reply | Threaded
Open this post in threaded view
|

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

Jakub Glapa
Hi Justin
I'm seeing dsa_allocate on two different servers.
One is virtualized with VMWare the other is bare metal.

ubuntu@db1:~$ grep dsa_allocate /var/log/postgresql/postgresql-11-main.log
2019-02-03 17:03:03 CET:192.168.10.83(48336):foo@bar:[27979]: FATAL:  dsa_allocate could not find 7 free pages
2019-02-05 17:05:12 CET:192.168.10.83(38138):foo@bar:[2725]: FATAL:  dsa_allocate could not find 49 free pages
2019-02-06 09:04:18 CET::@:[22120]: FATAL:  dsa_allocate could not find 13 free pages
2019-02-06 09:04:18 CET:192.168.10.83(55740):foo@bar:[21725]: ERROR:  dsa_allocate could not find 13 free pages
ubuntu@db1:~$ sudo dmidecode -s system-product-name
VMware Virtual Platform

----------------------------------
ubuntu@db2:~$ grep dsa_allocate /var/log/postgresql/postgresql-11-main2.log
2019-02-03 07:45:45 CET::@:[28592]: FATAL:  dsa_allocate could not find 25 free pages
2019-02-03 07:45:45 CET:127.0.0.1(41920):foo1@bar:[27320]: ERROR:  dsa_allocate could not find 25 free pages
2019-02-03 07:46:03 CET:127.0.0.1(41920):foo1@bar:[27320]: FATAL:  dsa_allocate could not find 25 free pages
2019-02-04 11:56:28 CET::@:[31713]: FATAL:  dsa_allocate could not find 7 free pages
2019-02-04 11:56:28 CET:127.0.0.1(41950):foo1@bar:[30465]: ERROR:  dsa_allocate could not find 7 free pages
2019-02-04 11:57:59 CET::@:[31899]: FATAL:  dsa_allocate could not find 7 free pages
2019-02-04 11:57:59 CET:127.0.0.1(44096):foo1@bar:[31839]: ERROR:  dsa_allocate could not find 7 free pages
ubuntu@db2:~$ sudo dmidecode -s system-product-name
ProLiant DL380 Gen9






--
regards,
pozdrawiam,
Jakub Glapa


On Wed, Feb 6, 2019 at 6:19 PM Justin Pryzby <[hidden email]> wrote:
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
Reply | Threaded
Open this post in threaded view
|

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

Sergei Kornilov
In reply to this post by Justin Pryzby
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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Jakub Glapa
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

Reply | Threaded
Open this post in threaded view
|

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

Jakub Glapa
It might be interesting to have CPU info, too.

model name    : Intel(R) Xeon(R) CPU E5-2637 v4 @ 3.50GHz (virtualized vmware)
and
model name    : Intel(R) Xeon(R) CPU E5-2667 v3 @ 3.20GHz (bare metal)


--
regards,
pozdrawiam,
Jakub Glapa


On Wed, Feb 6, 2019 at 7:52 PM Justin Pryzby <[hidden email]> wrote:
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
Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Justin Pryzby
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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
On Thu, Feb 7, 2019 at 12:47 PM Justin Pryzby <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Justin Pryzby
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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Justin Pryzby
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

Reply | Threaded
Open this post in threaded view
|

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

Sergei Kornilov
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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
On Tue, Feb 12, 2019 at 1:51 AM Sergei Kornilov <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Thomas Munro-3
On Tue, Feb 12, 2019 at 10:57 AM Thomas Munro
<[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

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

Justin Pryzby
In reply to this post by Thomas Munro-3
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

12