Subject: Failing to allocate memory when I think it shouldn't

From: Thomas Ziegler <[email-masked]>
Date: Fri, 13 Sep 2024 05:22:47 +0000

Hello Community!

I have had my database killed by the kernel oom-killer. After that I set turned off memory over-committing and that is where things got weird.

I have a PostgreSQL 16.2 running on a Debian Bookworm. The machine has 64GB of RAM and runs in a VM in an OpenStack environment.
I have `shared_buffers` at `16000MB`, `work_mem` at `80MB`, `temp_buffers` at `8MB`, `max_connections` at `300` and `maintenance_work_mem` at `1GB`.
So all in all, I get to roughly 42GB of max memory usage (`16000+(80+8)*300=42400`).

But now, I have connections fail because they can't allocate enough memory. I thought they should start creating temporary files if that is the case (and I tested this with trivial examples in psql) but the connections from my applications sometimes fail. I suspect that the queries are so large, that the execution-plans etc. are too large to fit into the 80MB of RAM. This is the "simpler" one of my problems, but it would be nice if somebody could tell me if my suspicion makes sense.

The harder issue is, that in multiple instances those memory-issues actually lead to the database "crashing" and having to recover from the redo-log. To be precise, the master-process doesn't crash and the database automatically starts the recovery (in contrast to the oom-kill, where I had to restart the database manually).
I can't get to the bottom of why that happens. At the point in time where that happens, there was more than enough usable memory on the system (>17GB) and I don't understand how it can kill the whole database if a worker-process breaks because it can't get more RAM. Also why wasn't it able to get more RAM, the kernel should have been more than happy to give it more as there was so much usable RAM available. (By "usable" I mean free + cache - shared)

Here are logs of one of those instances:

TopMemoryContext: 166384 total in 7 blocks; 33128 free (10 chunks); 133256 used
  smgr relation table: 16384 total in 2 blocks; 4640 free (2 chunks); 11744 used
  PgStat Shared Ref Hash: 7216 total in 2 blocks; 688 free (0 chunks); 6528 used
  PgStat Shared Ref: 1024 total in 1 blocks; 328 free (0 chunks); 696 used
  PgStat Pending: 4096 total in 3 blocks; 2168 free (6 chunks); 1928 used
  TopTransactionContext: 8192 total in 1 blocks; 4536 free (9 chunks); 3656 used
  TransactionAbortContext: 32768 total in 1 blocks; 32504 free (0 chunks); 264 used
  Portal hash: 8192 total in 1 blocks; 592 free (0 chunks); 7600 used
  TopPortalContext: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
  Relcache by OID: 16384 total in 2 blocks; 7712 free (2 chunks); 8672 used
  CacheMemoryContext: 262144 total in 6 blocks; 160 free (2 chunks); 261984 used
    index info: 2048 total in 2 blocks; 760 free (2 chunks); 1288 used: pg_rewrite_rel_rulename_index
[ ... ]
  WAL record construction: 50200 total in 2 blocks; 6376 free (0 chunks); 43824 used
  PrivateRefCount: 8192 total in 1 blocks; 2648 free (0 chunks); 5544 used
  MdSmgr: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
  LOCALLOCK hash: 8192 total in 1 blocks; 592 free (0 chunks); 7600 used
  GUCMemoryContext: 24576 total in 2 blocks; 5288 free (5 chunks); 19288 used
    GUC hash table: 32768 total in 3 blocks; 12704 free (5 chunks); 20064 used
  Timezones: 104112 total in 2 blocks; 2648 free (0 chunks); 101464 used
  Postmaster: 8192 total in 1 blocks; 6496 free (10 chunks); 1696 used
    ident parser context: 1024 total in 1 blocks; 760 free (0 chunks); 264 used
    hba parser context: 17408 total in 5 blocks; 6944 free (7 chunks); 10464 used
  ErrorContext: 8192 total in 1 blocks; 7928 free (6 chunks); 264 used
Grand total: 889064 bytes in 124 blocks; 180840 free (113 chunks); 708224 used
2024-09-12 05:18:36.064 UTC [3808080] _@_ FATAL:  out of memory
2024-09-12 05:18:36.064 UTC [3808080] _@_ DETAIL:  Failed on request of size 190 in memory context "CacheMemoryContext".
TopMemoryContext: 166384 total in 7 blocks; 33128 free (10 chunks); 133256 used
[ ... ]
2024-09-12 05:18:36.065 UTC [3808075] _@_ FATAL:  out of memory
2024-09-12 05:18:36.065 UTC [3808075] _@_ DETAIL:  Failed on request of size 190 in memory context "CacheMemoryContext".
2024-09-12 05:18:36.065 UTC [3808076] ERROR:  out of memory
2024-09-12 05:18:36.065 UTC [3808076] DETAIL:  Failed on request of size 32800 in memory context "HashBatchContext".
2024-09-12 05:18:36.065 UTC [3805724] _@_ ERROR:  out of memory
2024-09-12 05:18:36.065 UTC [3805724] _@_ DETAIL:  Failed on request of size 32800 in memory context "HashBatchContext".
2024-09-12 05:18:36.065 UTC [3805724] _@_ CONTEXT:  parallel worker
2024-09-12 05:18:36.065 UTC [3808078] _@_ FATAL:  out of memory
2024-09-12 05:18:36.065 UTC [3808078] _@_ DETAIL:  Failed on request of size 190 in memory context "CacheMemoryContext".
2024-09-12 05:18:36.065 UTC [3808081] _@_ FATAL:  out of memory
2024-09-12 05:18:36.065 UTC [3808081] _@_ DETAIL:  Failed on request of size 40992 in memory context "TopMemoryContext".
2024-09-12 05:18:36.066 UTC [1932776] LOG:  could not fork new process for connection: Cannot allocate memory
2024-09-12 05:18:36.066 UTC [3808050] _@_ ERROR:  out of memory
2024-09-12 05:18:36.066 UTC [3808050] _@_ DETAIL:  Failed while creating memory context "HashAgg meta context".
2024-09-12 05:18:36.067 UTC [3488999] _@_ ERROR:  out of memory
2024-09-12 05:18:36.067 UTC [3488999] _@_ DETAIL:  Failed on request of size 32800 in memory context "HashBatchContext".
2024-09-12 05:18:36.073 UTC [1932776] LOG:  background worker "parallel worker" (PID 3808076) exited with exit code 1
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
2024-09-12 05:18:36.083 UTC [1932776] LOG:  background worker "parallel worker" (PID 3808077) was terminated by signal 6: Aborted
2024-09-12 05:18:36.083 UTC [1932776] LOG:  terminating any other active server processes
2024-09-12 05:18:36.829 UTC [1932776] LOG:  all server processes terminated; reinitializing
2024-09-12 05:18:39.731 UTC [3808861] LOG:  database system was interrupted; last known up at 2024-09-12 05:08:52 UTC
2024-09-12 05:18:40.277 UTC [3808861] LOG:  database system was not properly shut down; automatic recovery in progress
2024-09-12 05:18:40.303 UTC [3808861] LOG:  redo starts at 3EA1/3AB0CF70
2024-09-12 05:18:50.304 UTC [3808861] LOG:  redo in progress, elapsed time: 10.00 s, current LSN: 3EA1/837DA848
2024-09-12 05:18:55.612 UTC [3808861] LOG:  invalid record length at 3EA1/C42A4A48: expected at least 24, got 0
2024-09-12 05:18:55.612 UTC [3808861] LOG:  redo done at 3EA1/C42A4A20 system usage: CPU: user: 9.04 s, system: 3.49 s, elapsed: 15.31 s
2024-09-12 05:18:55.642 UTC [3808862] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-09-12 05:19:16.215 UTC [3808862] LOG:  checkpoint complete: wrote 294597 buffers (14.4%); 0 WAL file(s) added, 0 removed, 105 recycled; [ ... ]
2024-09-12 05:19:16.340 UTC [1932776] LOG:  database system is ready to accept connections

I would be eternally grateful if somebody could explain to me what is going on there. As I wrote earlier, there should have been more than enough RAM available on the system, so I don't see any reason why the kernel would deny any memory allocations.
The only related item I was able to find is this thread from 2018: https://www.postgresql.org/message-id/flat/e47eec7f-9dbc-cbe3-dd01-32cbee90f332%40neteven.com

Cheers,
Thomas

---

From: Christoph Moench-Tegeder <[email-masked]>
Date: Sat, 14 Sep 2024 22:11:57 +0200

Hi,

## Thomas Ziegler ([email-masked]):

There's a lot of information missing here. Let's start from the top.

> I have had my database killed by the kernel oom-killer. After that I
> set turned off memory over-committing and that is where things got weird.

What exactly did you set? When playing with vm.overcommit, did you
understand "Committed Address Space" and the workings of the
overcommit accounting? This is the document:
https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/Documentation/mm/overcommit-accounting.rst
Hint: when setting overcommit_memory=2 you might end up with way
less available adress space than you thought you would. Also keep
an eye on /proc/meminfo - it's sometimes hard to estimate "just off
your cuff" what's in memory and how it's mapped. (Also, anything
else on that machine which might hog memory?).

> I have `shared_buffers` at `16000MB`, `work_mem` at `80MB`, `temp_buffers`
> at `8MB`, `max_connections` at `300` and `maintenance_work_mem` at `1GB`.

That work_mem is "per query operation", you can have multiple of
those in a single query:
https://www.postgresql.org/docs/current/runtime-config-resource.html#GUC-WORK-MEM
Also, there's hash_mem_multiplier:
https://www.postgresql.org/docs/current/runtime-config-resource.html#GUC-HASH-MEM-MULTIPLIER
Then I've seen that your query uses parallel workers, remember that
each worker requests memory.
Next, maintenance_work_mem is a per process limit, and depending on
what's running at any given time, that can add up.

> 2024-09-12 05:18:36.083 UTC [1932776] LOG:  background worker "parallel worker" (PID 3808077) was terminated by signal 6: Aborted

That "std::bad_alloc" sounds a lot like C++ and not like the C our
database is written in. My first suspicion would be that you're using
LLVM-JIT (unless you have other - maybe even your own - C++ extensions
in the database?) and that in itself can use a good chunk of memory.
And it looks like that exception bubbled up as a signal 6 (SIGABRT)
which made the process terminate immediately without any cleanup,
and after that the server has no other chance than to crash-restart.

I recommend starting with understanding the actual memory limits
as set by your configuration (personally I believe that memory
overcommit is less evil than some people think). Have a close look
at /proc/meminfo and if possible disable JIT and check if it changes
anything. Also if possible try starting with only a few active
connections and increase load carefully once a steady state (in
terms of memory usage) has been reached.

Regards,
Christoph

-- 
Spare Space

---

From: Thomas Ziegler <[email-masked]>
Date: Tue, 17 Sep 2024 09:40:15 +0200

Hello Christoph,

Thanks for your answer and the suggestions, it already helped me out a lot!

> else on that machine which might hog memory?).

I set overcommit_memory=2, but completely missed 'overcommit_ratio'. 
That is most probably why the database got denied the RAM a lot sooner 
than I expected.

> and after that the server has no other chance than to crash-restart.

Except for pgAudit, I don't have any extensions, so it is probably the 
JIT. I had no idea there was a JIT, even it should have been obvious. 
Thanks for pointing this out!

Is the memory the JIT takes limited by 'work_mem' or will it just take 
as much memory as it needs?

> terms of memory usage) has been reached.

Yes, understanding the memory limits is what I was trying to do.
I was questioning my understanding but it seems it was Linux that 
tripped me,
or more like my lack of understanding there, rather than the database.
Memory management and /proc/meminfo still manages to confuse me.

Again, thanks for your help!

Cheers,
Thomas

p.s.: To anybody who stumbles upon this in the future,
if you set `overcommit_memory=2`, don't forget `overcommit_ratio`.