Re: Out of memory with "create extension postgis"

From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Sent: Wednesday, July 29, 2020 17:05
To: Daniel Westermann (DWE) <daniel(dot)westermann(at)dbi-services(dot)com>
Cc: pgsql-general(at)lists(dot)postgresql(dot)org <pgsql-general(at)lists(dot)postgresql(dot)org>
Subject: Re: Out of memory with "create extension postgis"
 
"Daniel Westermann (DWE)" <daniel(dot)westermann(at)dbi-services(dot)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(at)entry=0) at elog.c:411
411 elog.c: No such file or directory.
Continuing.

Breakpoint 1, errfinish (dummy=dummy(at)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(at)entry=-1, occurred_events=occurred_events(at)entry=0x7ffcf3b4bc30, nevents=nevents(at)entry=1, wait_event_info=wait_event_info(at)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(at)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(at)entry=3, argv=argv(at)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