Re: Out of memory with "create extension postgis"

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