Out of memory with "create extension postgis"

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

Out of memory with "create extension postgis"

Daniel Westermann (DWE)
Hi,

we have a very strange behavior on PostgreSQL 12.3 when we try to create the extension postgis. Postgres and postgis have both been installed from packages:

postgresql12-server-12.3-5PGDG
postgis30_12-3.0.1-5.rhel7

The OS is RedHat 7.7.

Creating other extensions works fine, we only see this for postgis. A gdb session attached to the psql process while creating the extension gives:

Program received signal SIGINT, Interrupt.
0x00007f19c0de9740 in __read_nocancel () from /lib64/libpthread.so.0
Detaching from program: /usr/pgsql-12/bin/psql, process 44202

The process eats all the available memory and finally dies:
# create extension postgis;
ERROR:  out of memory
DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
Time: 773569.877 ms (12:53.570)


Stats file from /proc:

# cat status
Name:   psql
Umask:  0022
State:  S (sleeping)
Tgid:   45958
Ngid:   0
Pid:    45958
PPid:   44075
TracerPid:      0
Uid:    280     280     280     280
Gid:    280     280     280     280
FDSize: 256
Groups: 280
VmPeak:   184604 kB
VmSize:   184600 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:      4304 kB
VmRSS:      4304 kB
RssAnon:             980 kB
RssFile:            3324 kB
RssShmem:              0 kB
VmData:      672 kB
VmStk:       132 kB
VmExe:       604 kB
VmLib:     11288 kB
VmPTE:       180 kB
VmSwap:        0 kB
Threads:        1
SigQ:   0/15635
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000000000
SigCgt: 0000000180000002
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: 0000001fffffffff
CapAmb: 0000000000000000
NoNewPrivs:     0
Seccomp:        0
Speculation_Store_Bypass:       thread vulnerable
Cpus_allowed:   ffffffff,ffffffff,ffffffff,ffffffff
Cpus_allowed_list:      0-127
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:      0
voluntary_ctxt_switches:        47

stack file from /proc:
# cat stack
[<ffffffffa0c60805>] poll_schedule_timeout+0x55/0xc0
[<ffffffffa0c61f9d>] do_sys_poll+0x48d/0x590
[<ffffffffa0c621a4>] SyS_poll+0x74/0x110
[<ffffffffa118dede>] system_call_fastpath+0x25/0x2a
[<ffffffffffffffff>] 0xffffffffffffffff

limits from /proc:
# cat limits
Limit                     Soft Limit           Hard Limit           Units
Max cpu time              unlimited            unlimited            seconds
Max file size             unlimited            unlimited            bytes
Max data size             unlimited            unlimited            bytes
Max stack size            8388608              unlimited            bytes
Max core file size        0                    0                    bytes
Max resident set          unlimited            unlimited            bytes
Max processes             4096                 15635                processes
Max open files            1024                 4096                 files
Max locked memory         65536                65536                bytes
Max address space         unlimited            unlimited            bytes
Max file locks            unlimited            unlimited            locks
Max pending signals       15635                15635                signals
Max msgqueue size         819200               819200               bytes
Max nice priority         0                    0
Max realtime priority     0                    0
Max realtime timeout      unlimited            unlimited            us

Stracing the psql process shows no activity. Looking at the used swap shows that the postmaster uses a huge amount:

find /proc -maxdepth 2 -path "/proc/[0-9]*/status" -readable -exec awk -v FS=":" '{process[$1]=$2;sub(/^[ \t]+/,"",process[$1]);} END {if(process["VmSwap"] && process["VmSwap"] != "0 kB") printf "%10s %-30s %20s\n",process["Pid"],process["Name"],process["VmSwap"]}' '{}' \;
...
     48043 psql                                        1004 kB
     48044 postmaster                              21948064 kB
     49059 postmaster                                  1008 kB
     52550 rhsmcertd                                    144 kB
...
 
Any hints what could be the issue? Can I provide any other information that would help troubleshooting this issue?

Thanks in advance
Daniel




Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Tom Lane-2
"Daniel Westermann (DWE)" <[hidden email]> writes:
> we have a very strange behavior on PostgreSQL 12.3 when we try to create the extension postgis. Postgres and postgis have both been installed from packages:
> ...
> The process eats all the available memory and finally dies:
> # create extension postgis;
> ERROR:  out of memory
> DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
> Time: 773569.877 ms (12:53.570)

Quite odd.  There should have been a memory context dump written to the
postmaster's stderr, can you show that?  Also possibly useful would be
a backtrace (set a breakpoint at errfinish):

https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend

                        regards, tom lane


Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
>"Daniel Westermann (DWE)" <[hidden email]> writes:
>> we have a very strange behavior on PostgreSQL 12.3 when we try to create the extension postgis. Postgres and postgis have both been installed from packages:
>> ...
>> The process eats all the available memory and finally dies:
>> # create extension postgis;
>> ERROR:  out of memory
>> DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
>> Time: 773569.877 ms (12:53.570)

>Quite odd.  There should have been a memory context dump written to the
>postmaster's stderr, can you show that?  Also possibly useful would be
>a backtrace (set a breakpoint at errfinish):

>https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend

There is nothing in the log file except these (not from today, but the messages are always the same):
2020-07-03 16:52:16 CEST 53617 LOG:  server process (PID 54070) was terminated by signal 9: Killed
2020-07-03 16:52:16 CEST 53617 DETAIL:  Failed process was running: create extension postgis;
2020-07-03 16:52:16 CEST 53617 LOG:  terminating any other active server processes

I will take care of the backtrace

Regards
Daniel

Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Tom Lane-2
"Daniel Westermann (DWE)" <[hidden email]> writes:
>> "Daniel Westermann (DWE)" <[hidden email]> writes:
>>> The process eats all the available memory and finally dies:
>>> # create extension postgis;
>>> ERROR:  out of memory
>>> DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
>>> Time: 773569.877 ms (12:53.570)

> There is nothing in the log file except these (not from today, but the messages are always the same):
> 2020-07-03 16:52:16 CEST 53617 LOG:  server process (PID 54070) was terminated by signal 9: Killed

A process that was killed by the OOM killer would not have managed to
produce an "out of memory" ERROR report, so these two are different
symptoms.  You need to reproduce the first case, or you won't have
any luck setting an error breakpoint either.

If you can't manage to get back to that state, you might get somewhere
by waiting for the process to grow large and then attaching with gdb
and getting a stack trace.  That's a bit less reliable than the
errfinish approach, though.

                        regards, tom lane


Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
>>> "Daniel Westermann (DWE)" <[hidden email]> writes:
>>>> The process eats all the available memory and finally dies:
>>>> # create extension postgis;
>>>> ERROR:  out of memory
>>>> DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
>>>> Time: 773569.877 ms (12:53.570)

>> There is nothing in the log file except these (not from today, but the messages are always the same):
>> 2020-07-03 16:52:16 CEST 53617 LOG:  server process (PID 54070) was terminated by signal 9: Killed

>A process that was killed by the OOM killer would not have managed to
>produce an "out of memory" ERROR report, so these two are different
>symptoms.  You need to reproduce the first case, or you won't have
>any luck setting an error breakpoint either.

You're right, that was before we adjusted the oom behavior. Will get back once I have more information.

Regards
Daniel
Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
>>>> "Daniel Westermann (DWE)" <[hidden email]> writes:
>>>>> The process eats all the available memory and finally dies:
>>>>> # create extension postgis;
>>>>> ERROR:  out of memory
>>>>> DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
>>>>> Time: 773569.877 ms (12:53.570)

>>> There is nothing in the log file except these (not from today, but the messages are always the same):
>>> 2020-07-03 16:52:16 CEST 53617 LOG:  server process (PID 54070) was terminated by signal 9: Killed

>>A process that was killed by the OOM killer would not have managed to
>>produce an "out of memory" ERROR report, so these two are different
>>symptoms.  You need to reproduce the first case, or you won't have
>>any luck setting an error breakpoint either.

>You're right, that was before we adjusted the oom behavior. Will get back once I have more information.

So this is what we got today. In the log file there is this:

2020-07-29 16:33:23 CEST 101995 ERROR:  out of memory
2020-07-29 16:33:23 CEST 101995 DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
2020-07-29 16:33:23 CEST 101995 STATEMENT:  create extension postgis;
2020-07-29 16:35:00 CEST 106695 LOG:  disconnection: session time: 0:04:45.200 user=monitor database=pcl_l800 host=127.0.0.1 port=52160
2020-07-29 16:35:00 CEST 107063 LOG:  connection received: host=127.0.0.1 port=52212
2020-07-29 16:35:00 CEST 107063 LOG:  connection authorized: user=monitor database=pdb_l80_oiz application_name=pg_statsinfod
2020-07-29 16:35:00 CEST 53630 ALERT:  pg_statsinfo: memory swap size exceeds threshold in snapshot '2020-07-29 16:35:00' --- 17383584 KiB (threshold = 1000000 KiB)
2020-07-29 16:35:15 CEST 107063 LOG:  disconnection: session time: 0:00:14.770 user=monitor database=pdb_l80_oiz host=127.0.0.1 port=52212
2020-07-29 16:35:15 CEST 107269 LOG:  connection received: host=127.0.0.1 port=52220

The GDB session shows this:
(gdb) set pagination off
(gdb) set logging file postgis.log
(gdb)
(gdb) set logging on
Copying output to postgis.log.
(gdb) b errfinish
Breakpoint 1 at 0x87e210: file elog.c, line 411.
(gdb) cont
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     elog.c: No such file or directory.
(gdb) cont
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     in elog.c
Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64
(gdb)
Continuing.


The GDB logfile shows this:
[root@tstm49012 ~]# cat postgis.log
Breakpoint 1 at 0x87e210: file elog.c, line 411.
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     elog.c: No such file or directory.
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     in elog.c
Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64
Continuing.
Program received signal SIGINT, Interrupt.
0x00007f94f4af2e93 in __epoll_wait_nocancel () from /lib64/libc.so.6
Detaching from program: /usr/pgsql-12/bin/postgres, process 101995
[root@tstm49012 ~]#

Is that of any help?

Regards
Daniel








Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Tom Lane-2
"Daniel Westermann (DWE)" <[hidden email]> writes:
> So this is what we got today. In the log file there is this:

> 2020-07-29 16:33:23 CEST 101995 ERROR:  out of memory
> 2020-07-29 16:33:23 CEST 101995 DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
> 2020-07-29 16:33:23 CEST 101995 STATEMENT:  create extension postgis;

Is there not a dump of memory context sizes just before the "ERROR: out of
memory" line?  It should look something like

TopMemoryContext: 68720 total in 5 blocks; 17040 free (15 chunks); 51680 used
  MessageContext: 8192 total in 1 blocks; 6880 free (1 chunks); 1312 used
...
  ErrorContext: 8192 total in 1 blocks; 7928 free (3 chunks); 264 used
Grand total: 1063328 bytes in 190 blocks; 312376 free (159 chunks); 750952 used

(this taken from an idle backend, so numbers from a backend that's hit
OOM would be a lot larger).  If you don't see that then you must be
using some logging mechanism that fails to capture the postmaster's
stderr output, such as syslog.  If your postmaster start script doesn't
actually send stderr to /dev/null, you might find the context map in some
other log file.

> The GDB session shows this:

Umm ... you didn't issue a "bt" when you got to errfinish, so there's
no useful info here.

> Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64

This is a little weird and scary; I would not expect most of those
libraries to have gotten linked into a Postgres backend.  What
extensions are you using?  (And what the devil would any of them
want with sqlite or libcurl?  boost-thread is even scarier, because
we absolutely do not support multithreading in a backend process.)

                        regards, tom lane


Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
From: Tom Lane <[hidden email]>
Sent: Wednesday, July 29, 2020 17:05
To: Daniel Westermann (DWE) <[hidden email]>
Cc: [hidden email] <[hidden email]>
Subject: Re: Out of memory with "create extension postgis"
 
"Daniel Westermann (DWE)" <[hidden email]> writes:
>> So this is what we got today. In the log file there is this:

>> 2020-07-29 16:33:23 CEST 101995 ERROR:  out of memory
>> 2020-07-29 16:33:23 CEST 101995 DETAIL:  Failed on request of size 8265691 in memory context "PortalContext".
>> 2020-07-29 16:33:23 CEST 101995 STATEMENT:  create extension postgis;

>Is there not a dump of memory context sizes just before the "ERROR: out of
>memory" line?  It should look something like

>TopMemoryContext: 68720 total in 5 blocks; 17040 free (15 chunks); 51680 used
>  MessageContext: 8192 total in 1 blocks; 6880 free (1 chunks); 1312 used
>...
>  ErrorContext: 8192 total in 1 blocks; 7928 free (3 chunks); 264 used
>Grand total: 1063328 bytes in 190 blocks; 312376 free (159 chunks); 750952 used

>(this taken from an idle backend, so numbers from a backend that's hit
>OOM would be a lot larger).  If you don't see that then you must be
>using some logging mechanism that fails to capture the postmaster's
>stderr output, such as syslog.  If your postmaster start script doesn't
>actually send stderr to /dev/null, you might find the context map in some
>other log file.

Thanks for the hint, will check

>Umm ... you didn't issue a "bt" when you got to errfinish, so there's
>no useful info here.

Here is a new one with bt at the end:

Breakpoint 1 at 0x87e210: file elog.c, line 411.
Continuing.

Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411 elog.c: No such file or directory.
Continuing.

Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411 in elog.c
Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64
Continuing.

Program received signal SIGINT, Interrupt.
0x00007f94f4af2e93 in __epoll_wait_nocancel () from /lib64/libc.so.6
#0  0x00007f94f4af2e93 in __epoll_wait_nocancel () from /lib64/libc.so.6
#1  0x000000000073fdae in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffcf3b4bc30, cur_timeout=-1, set=0x27c3718) at latch.c:1080
#2  WaitEventSetWait (set=0x27c3718, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffcf3b4bc30, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=100663296) at latch.c:1032
#3  0x000000000064fbd7 in secure_read (port=0x27c3900, ptr=0xd45a80 <PqRecvBuffer>, len=8192) at be-secure.c:185
#4  0x000000000065aa38 in pq_recvbuf () at pqcomm.c:964
#5  0x000000000065b655 in pq_getbyte () at pqcomm.c:1007
#6  0x0000000000761aaa in SocketBackend (inBuf=0x7ffcf3b4bda0) at postgres.c:341
#7  ReadCommand (inBuf=0x7ffcf3b4bda0) at postgres.c:514
#8  PostgresMain (argc=<optimized out>, argv=argv@entry=0x27cb420, dbname=0x27cb2e8 "pcl_l800", username=<optimized out>) at postgres.c:4189
#9  0x0000000000484022 in BackendRun (port=<optimized out>, port=<optimized out>) at postmaster.c:4448
#10 BackendStartup (port=0x27c3900) at postmaster.c:4139
#11 ServerLoop () at postmaster.c:1704
#12 0x00000000006f14c3 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x278c280) at postmaster.c:1377
#13 0x0000000000484f23 in main (argc=3, argv=0x278c280) at main.c:228
A debugging session is active.

        Inferior 1 [process 97279] will be detached.

Quit anyway? (y or n) Detaching from program: /usr/pgsql-12/bin/postgres, process 97279


>> Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64

>This is a little weird and scary; I would not expect most of those
>libraries to have gotten linked into a Postgres backend.  What
>extensions are you using?  (And what the devil would any of them
>want with sqlite or libcurl?  boost-thread is even scarier, because
>we absolutely do not support multithreading in a backend process.)

These are the extensions in use:
$ psql -X -c "\dx"
                                     List of installed extensions
        Name        | Version |   Schema   |                        Description
--------------------+---------+------------+-----------------------------------------------------------
 pg_buffercache     | 1.3     | public     | examine the shared buffer cache
 pg_stat_statements | 1.7     | public     | track execution statistics of all SQL statements executed
 pg_store_plans     | 1.4     | public     | track plan statistics of all SQL statements executed
 pgstattuple        | 1.5     | public     | show tuple-level statistics
 plpgsql            | 1.0     | pg_catalog | PL/pgSQL procedural language
 plpythonu          | 1.0     | pg_catalog | PL/PythonU untrusted procedural language
(6 rows)

$ rpm -qa | grep pg_statsinfo
pg_statsinfo-12.0-1.pg12.rhel7.x86_64
$ rpm -qa | grep pg_cron_12
pg_cron_12-1.2.0-1.rhel7.1.x86_64

Regards
Daniel

Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Tom Lane-2
"Daniel Westermann (DWE)" <[hidden email]> writes:
>> Umm ... you didn't issue a "bt" when you got to errfinish, so there's
>> no useful info here.

> Here is a new one with bt at the end:

That's just showing the stack when the backend is idle waiting for input.
We need to capture the stack at the moment when the "out of memory" error
is reported (errfinish() should be the top of stack).

>> libraries to have gotten linked into a Postgres backend.  What
>> extensions are you using?

> These are the extensions in use:
>  plpythonu          | 1.0     | pg_catalog | PL/PythonU untrusted procedural language

Hm.  If you've been actively using plpython in this session, perhaps
libpython would have pulled all this other weirdness in with it.

                        regards, tom lane


Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
>> Here is a new one with bt at the end:

>That's just showing the stack when the backend is idle waiting for input.
>We need to capture the stack at the moment when the "out of memory" error
>is reported (errfinish() should be the top of stack).

Then I don't know what/how to do it. Here is a complete trace of what we did today:

-- First session

$ psql
# select pg_backend_pid();
 pg_backend_pid
----------------
          22480
(1 row)


-- Second session

# gdb -p 22480
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-115.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 22480
Reading symbols from /usr/pgsql-12/bin/postgres...Reading symbols from /usr/lib/debug/usr/pgsql-12/bin/postgres.debug...done.
done.
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libxml2.so.2...Reading symbols from /lib64/libxml2.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libxml2.so.2
Reading symbols from /lib64/libpam.so.0...Reading symbols from /lib64/libpam.so.0...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libpam.so.0
Reading symbols from /lib64/libssl.so.10...Reading symbols from /lib64/libssl.so.10...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libssl.so.10
Reading symbols from /lib64/libcrypto.so.10...Reading symbols from /lib64/libcrypto.so.10...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypto.so.10
Reading symbols from /lib64/libgssapi_krb5.so.2...Reading symbols from /lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libgssapi_krb5.so.2
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libldap-2.4.so.2...Reading symbols from /lib64/libldap-2.4.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libldap-2.4.so.2
Reading symbols from /lib64/libicui18n.so.50...Reading symbols from /lib64/libicui18n.so.50...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libicui18n.so.50
Reading symbols from /lib64/libicuuc.so.50...Reading symbols from /lib64/libicuuc.so.50...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libicuuc.so.50
Reading symbols from /lib64/libsystemd.so.0...Reading symbols from /lib64/libsystemd.so.0...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libsystemd.so.0
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libz.so.1...Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /lib64/liblzma.so.5...Reading symbols from /lib64/liblzma.so.5...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/liblzma.so.5
Reading symbols from /lib64/libaudit.so.1...Reading symbols from /lib64/libaudit.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libaudit.so.1
Reading symbols from /lib64/libkrb5.so.3...Reading symbols from /lib64/libkrb5.so.3...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5.so.3
Reading symbols from /lib64/libcom_err.so.2...Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /lib64/libk5crypto.so.3...Reading symbols from /lib64/libk5crypto.so.3...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libk5crypto.so.3
Reading symbols from /lib64/libkrb5support.so.0...Reading symbols from /lib64/libkrb5support.so.0...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /lib64/liblber-2.4.so.2...Reading symbols from /lib64/liblber-2.4.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/liblber-2.4.so.2
Reading symbols from /lib64/libsasl2.so.3...Reading symbols from /lib64/libsasl2.so.3...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libsasl2.so.3
Reading symbols from /lib64/libssl3.so...Reading symbols from /lib64/libssl3.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libssl3.so
Reading symbols from /lib64/libsmime3.so...Reading symbols from /lib64/libsmime3.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libsmime3.so
Reading symbols from /lib64/libnss3.so...Reading symbols from /lib64/libnss3.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss3.so
Reading symbols from /lib64/libnssutil3.so...Reading symbols from /lib64/libnssutil3.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libnssutil3.so
Reading symbols from /lib64/libplds4.so...Reading symbols from /lib64/libplds4.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libplds4.so
Reading symbols from /lib64/libplc4.so...Reading symbols from /lib64/libplc4.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libplc4.so
Reading symbols from /lib64/libnspr4.so...Reading symbols from /lib64/libnspr4.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libnspr4.so
Reading symbols from /lib64/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libstdc++.so.6
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libicudata.so.50...Reading symbols from /lib64/libicudata.so.50...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libicudata.so.50
Reading symbols from /lib64/libcap.so.2...Reading symbols from /lib64/libcap.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libcap.so.2
Reading symbols from /lib64/libselinux.so.1...Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libselinux.so.1
Reading symbols from /lib64/liblz4.so.1...Reading symbols from /lib64/liblz4.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/liblz4.so.1
Reading symbols from /lib64/libgcrypt.so.11...Reading symbols from /lib64/libgcrypt.so.11...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcrypt.so.11
Reading symbols from /lib64/libgpg-error.so.0...Reading symbols from /lib64/libgpg-error.so.0...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libgpg-error.so.0
Reading symbols from /lib64/libdw.so.1...Reading symbols from /lib64/libdw.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libdw.so.1
Reading symbols from /lib64/libcap-ng.so.0...Reading symbols from /lib64/libcap-ng.so.0...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libcap-ng.so.0
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libattr.so.1...Reading symbols from /lib64/libattr.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libattr.so.1
Reading symbols from /lib64/libpcre.so.1...Reading symbols from /lib64/libpcre.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libpcre.so.1
Reading symbols from /lib64/libelf.so.1...Reading symbols from /lib64/libelf.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libelf.so.1
Reading symbols from /lib64/libbz2.so.1...Reading symbols from /lib64/libbz2.so.1...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libbz2.so.1
Reading symbols from /lib64/libfreebl3.so...Reading symbols from /lib64/libfreebl3.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libfreebl3.so
Reading symbols from /usr/pgsql-12/lib/auto_explain.so...Reading symbols from /usr/lib/debug/usr/pgsql-12/lib/auto_explain.so.debug...done.
done.
Loaded symbols for /usr/pgsql-12/lib/auto_explain.so
Reading symbols from /usr/pgsql-12/lib/pg_stat_statements.so...Reading symbols from /usr/lib/debug/usr/pgsql-12/lib/pg_stat_statements.so.debug...done.
done.
Loaded symbols for /usr/pgsql-12/lib/pg_stat_statements.so
Reading symbols from /usr/pgsql-12/lib/pg_cron.so...Reading symbols from /usr/pgsql-12/lib/pg_cron.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/pgsql-12/lib/pg_cron.so
Reading symbols from /usr/pgsql-12/lib/libpq.so.5...Reading symbols from /usr/lib/debug/usr/pgsql-12/lib/libpq.so.5.12.debug...done.
done.
Loaded symbols for /usr/pgsql-12/lib/libpq.so.5
Reading symbols from /lib64/libldap_r-2.4.so.2...Reading symbols from /lib64/libldap_r-2.4.so.2...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /lib64/libldap_r-2.4.so.2
Reading symbols from /usr/pgsql-12/lib/pg_statsinfo.so...Reading symbols from /usr/pgsql-12/lib/pg_statsinfo.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/pgsql-12/lib/pg_statsinfo.so
Reading symbols from /usr/pgsql-12/lib/pg_store_plans.so...Reading symbols from /usr/pgsql-12/lib/pg_store_plans.so...(no debugging symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/pgsql-12/lib/pg_store_plans.so
Reading symbols from /lib64/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_files.so.2
0x00007f94f4af2e93 in __epoll_wait_nocancel () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install audit-libs-2.8.5-4.el7.x86_64 bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-23.el7.x86_64 elfutils-libelf-0.176-2.el7.x86_64 elfutils-libs-0.176-2.el7.x86_64 glibc-2.17-307.el7.1.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-37.el7_7.2.x86_64 libattr-2.4.46-13.el7.x86_64 libcap-2.22-10.el7.x86_64 libcap-ng-0.7.5-4.el7.x86_64 libcom_err-1.42.9-16.el7.x86_64 libgcc-4.8.5-39.el7.x86_64 libgcrypt-1.5.3-14.el7.x86_64 libgpg-error-1.12-3.el7.x86_64 libicu-50.2-3.el7.x86_64 libselinux-2.5-14.1.el7.x86_64 libstdc++-4.8.5-39.el7.x86_64 libxml2-2.9.1-6.el7_2.3.x86_64 lz4-1.7.5-3.el7.x86_64 nspr-4.21.0-1.el7.x86_64 nss-3.44.0-7.el7_7.x86_64 nss-softokn-freebl-3.44.0-8.el7_7.x86_64 nss-util-3.44.0-4.el7_7.x86_64 openldap-2.4.44-21.el7_6.x86_64 openssl-libs-1.0.2k-19.el7.x86_64 pam-1.1.8-22.el7.x86_64 pcre-8.32-17.el7.x86_64 pg_cron_12-1.2.0-1.rhel7.1.x86_64 pg_statsinfo-12.0-1.pg12.rhel7.x86_64 pg_store_plans12-1.4-1.el7.x86_64 systemd-libs-219-67.el7_7.3.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) set pagination off
(gdb) set logging file postgis.log
(gdb) set logging on
Copying output to postgis.log.
(gdb) b errfinish
Breakpoint 1 at 0x87e210: file elog.c, line 411.
(gdb) cont
Continuing.

-- First session (nothing else, just creating the extension)
# create extension postgis;


-- Second session
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     elog.c: No such file or directory.
(gdb) bt
#0  errfinish (dummy=dummy@entry=0) at elog.c:411
#1  0x0000000000760de5 in exec_simple_query (query_string=0x27916e0 "create extension postgis;") at postgres.c:1042
#2  0x0000000000761d92 in PostgresMain (argc=<optimized out>, argv=argv@entry=0x27cb420, dbname=0x27cb2e8 "pcl_l800", username=<optimized out>) at postgres.c:4247
#3  0x0000000000484022 in BackendRun (port=<optimized out>, port=<optimized out>) at postmaster.c:4448
#4  BackendStartup (port=0x27c3900) at postmaster.c:4139
#5  ServerLoop () at postmaster.c:1704
#6  0x00000000006f14c3 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x278c280) at postmaster.c:1377
#7  0x0000000000484f23 in main (argc=3, argv=0x278c280) at main.c:228
(gdb) cont
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     in elog.c
Missing separate debuginfos, use: debuginfo-install CGAL-4.7-1.rhel7.1.x86_64 boost-date-time-1.53.0-27.el7.x86_64 boost-serialization-1.53.0-27.el7.x86_64 boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64 jbigkit-libs-2.0-11.el7.x86_64 json-c-0.11-4.el7_0.x86_64 libcurl-7.29.0-54.el7_7.2.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-8.el7.x86_64 libssh2-1.8.0-3.el7.x86_64 libtiff-4.0.3-32.el7.x86_64 mpfr-3.1.1-4.el7.x86_64 postgis30_12-3.0.1-5.rhel7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 sqlite33-libs-3.30.1-1.rhel7.x86_64
(gdb)
Continuing.
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:411
411     in elog.c
(gdb)
Continuing.

-- In the first session we this after a while
# create extension postgis;
ERROR:  out of memory
DETAIL:  Failed on request of size 8265690 in memory context "ErrorContext".
Time: 1389214.120 ms (23:09.214)

-- the second session stays like this until we exit psql in the first session
(gdb)
Continuing.


I am aware that the behavior is different from what we've seen last week but this is how it looks today.
Anything we missed or did not do correct?

Regards
Daniel



Reply | Threaded
Open this post in threaded view
|

Re: Out of memory with "create extension postgis"

Daniel Westermann (DWE)
>I am aware that the behavior is different from what we've seen last week but this is how it looks today.
>Anything we missed or did not do correct?

Finally this can be re-produced quite easily by installing this extension: https://de.osdn.net/projects/pgstoreplans/downloads/72297/pg_store_plans12-1.4-1.el7.x86_64.rpm/
As soon as pg_store_plans is in shared_preload_libraries the postgis extension can not be installed anymore. This is the exact package list:

[root@rhel77 ~]# rpm -qa | egrep "postgres|postgis|store_plan"
postgresql12-server-12.3-5PGDG.rhel7.x86_64
postgresql12-contrib-12.3-5PGDG.rhel7.x86_64
postgresql12-12.3-5PGDG.rhel7.x86_64
postgis30_12-3.0.1-5.rhel7.x86_64
pg_store_plans12-1.4-1.el7.x86_64
postgresql12-libs-12.3-5PGDG.rhel7.x86_64
postgresql12-llvmjit-12.3-5PGDG.rhel7.x86_64

I will open an issue on the extensions' GitHub repo.

Regards
Daniel