Re: terminate called after throwing an instance of 'std::bad_alloc'

On Wed, Sep 30, 2020 at 09:16:09PM -0500, Justin Pryzby wrote:
> Our DBs use postgis, and today's crash JOINs to the table with geometry
> columns, but does not use them at all.

I'm wrong here - it does return the geometry columns.

We didn't use JIT with v12, but I've been setting jit=on along with v13
upgrades, so I was trying to convince myself that there's a change in v13, and
not just our config..

I've seen repeated OOMs on a small number of reports. It looks like JIT
optimization/inlining used a good deal of RAM in v12, and even more on v13.
Maybe that's what's expected; it looks like this scales with the number of
partitions and number of functions, so it could be arbitrarily large, and not
respectful of work_mem (below, at the 4MB default).

CREATE TABLE t(a int) PARTITION BY RANGE(a);
\pset pager off
SELECT format('CREATE TABLE t%s PARTITION OF t FOR VALUES FROM (%s)TO(%s) WITH (parallel_workers=2)', i, 100*i, 100*i+100) FROM generate_series(0,666)i;
\gexec
INSERT INTO t SELECT i%10000 FROM generate_series(1,99999)i;
CREATE INDEX ON t(left(a::text,1));
VACUUM ANALYZE t;
\o /dev/null \\ SET client_min_messages=debug; SET log_executor_stats=on; SET jit=on; SET jit_expressions=on; SET jit_above_cost=0; SET jit_optimize_above_cost=1; SET jit_inline_above_cost=1; explain( analyze) SELECT * FROM t WHERE substr(a::text,length(a::text)-6,6)='1' OR substr(a::text,length(a::text)-6,6)='2' OR substr(a::text,length(a::text)-6,6)='3' OR substr(a::text,length(a::text)-6,6)='4' OR substr(a::text,length(a::text)-6,6)='5' OR substr(a::text,length(a::text)-6,6)='6';

In v13:
With optimize_above=-1, inline_above=-1: 333472 kB max resident size
With optimize_above=1, inline_above=1: 654036 kB max resident size

In v12:
With optimize_above=-1, inline_above=-1: 330988 kB max resident size
With optimize_above=1, inline_above=1: 556844 kB max resident size

These tests are on the same centos7 server, which has:
llvm5.0-libs-5.0.1-7.el7.x86_64

This appears to be similar under centos8 with LLVM9.

The OOM itself could be due to our JIT settings and maybe not a bug. My
thinking is that when we hit OOM, that sometimes manifests itself as the C++
exception, which somehow trickles up into an SIGABRT in postgres.

I don't know if there's a way to capture useful debugging info on OOM, but the
live processes do seem to leaking memory, or otherwise not reusing it.

For example, look at a this huge backend, which is connected to the process
which have been experiencing OOM. The backend is 4.2GB while idle, so I'd have
hoped for it to have released everything it could. I'm aware that free()
usually cannot return small allocations to the kernel, but then should not lead
to continued growth over time.

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18000 postgres 20 0 4975152 4.2g 4684 S 0.0 55.6 81:29.87 postgres: main main 10.124.252.14(58296) idle

main=# SELECT * FROM pg_stat_activity WHERE pid=18000;
datid | 151510
datname | main
pid | 18000
leader_pid |
usesysid | 16714
usename | main
application_name | run_thresholds --daemon
client_addr | 10.124.252.14
client_hostname |
client_port | 58296
backend_start | 2020-10-02 22:26:16.676936-06
xact_start |
query_start | 2020-10-03 12:37:37.639971-06
state_change | 2020-10-03 12:37:37.640183-06
wait_event_type | Client
wait_event | ClientRead
state | idle
backend_xid |
backend_xmin |
query | ROLLBACK
backend_type | client backend

This is mostly just in "heap":

$ sudo cat /proc/18000/maps |awk -Wnon-decimal -F '[- ]' '{a="0x"$1; b="0x"$2; print (b-a)/1024**2,$0}' |sort -gr |head
3428.65 010d6000-d757c000 rw-p 00000000 00:00 0 [heap]
512.004 7f3ec96e8000-7f3ee96e9000 rw-p 00000000 00:00 0
384.004 7f3e9e6e1000-7f3eb66e2000 rw-p 00000000 00:00 0
148 2aaaaac00000-2aaab4000000 rw-s 00000000 00:0e 44184914 /anon_hugepage (deleted)

The postgres memory contexts don't show anything nearly that large.
MessageContext: 25236472 total in 20 blocks; 2990656 free (4 chunks); 22245816 used
CacheMemoryContext: 25892160 total in 42 blocks; 22770984 free (28285 chunks); 3121176 used
Grand total: 70879896 bytes in 1466 blocks; 29518440 free (29097 chunks); 41361456 used

I was able to make a small, apparent leak like so. This applies to
postgis3.0/postgres12/LLVM5/centos7, and
postgis3.1alpha/postgres13/LLVM9/centos8.

Inlining is essential to see the leak, optimization is not. Showing every 9th
query:

$ for a in `seq 1 99`; do echo "SET jit_inline_above_cost=1; SET jit_optimize_above_cost=-1; SET jit_above_cost=0; SET jit_expressions=on; SET log_executor_stats=on; SET client_min_messages=debug; SET jit=on; explain analyze SELECT st_x(site_geo) FROM sites WHERE site_geo IS NOT NULL;"; done |psql ts 2>&1 |grep 'resident' |sed -n '1~9p'

! 40552 kB max resident size
! 41188 kB max resident size
! 41820 kB max resident size
! 42576 kB max resident size
! 43080 kB max resident size
! 43508 kB max resident size
! 44572 kB max resident size
! 45040 kB max resident size
! 45588 kB max resident size
! 46024 kB max resident size
! 46492 kB max resident size

Which would lead to an OOM in our longlived process.

--
Justin