Thread: Out of memory with "create extension postgis"
Hi,
we have a very strange behavior on PostgreSQL 12.3 when we try to create the extension postgis. Postgres and postgis
haveboth 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
creatingthe 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
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> writes: > we have a very strange behavior on PostgreSQL 12.3 when we try to create the extension postgis. Postgres and postgis haveboth 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
>"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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
>> 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 processesI will take care of the backtrace
Regards
Daniel
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> writes:
>> "Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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
>>> "Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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.
>>>> # 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
>>>> "Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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.1port=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.1port=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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64 gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64
gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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
From: Tom Lane <tgl@sss.pgh.pa.us>
Sent: Wednesday, July 29, 2020 17:05
To: Daniel Westermann (DWE) <daniel.westermann@dbi-services.com>
Cc: pgsql-general@lists.postgresql.org <pgsql-general@lists.postgresql.org>
Subject: Re: Out of memory with "create extension postgis"
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64
gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64
gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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
"Daniel Westermann (DWE)" <daniel.westermann@dbi-services.com> 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
>> 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
symbolsfound)...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
symbolsfound)...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
symbolsfound)...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
debuggingsymbols 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...(nodebugging 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_64elfutils-libelf-0.176-2.el7.x86_64 elfutils-libs-0.176-2.el7.x86_64
glibc-2.17-307.el7.1.x86_64keyutils-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_64libcap-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_64libgcrypt-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_64libstdc++-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_64nss-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_64openldap-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_64pg_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_64systemd-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=<optimizedout>) 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_64boost-system-1.53.0-27.el7.x86_64 boost-thread-1.53.0-27.el7.x86_64
gmp-6.0.0-15.el7.x86_64jbigkit-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_64libjpeg-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_64postgis30_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
>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 theexact 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