Re: ERROR: could not resize shared memory segment...No space left on device

On Mon, Dec 16, 2019 at 12:49:06PM -0600, Justin Pryzby wrote:
>A customer's report query hit this error.
>ERROR: could not resize shared memory segment "/PostgreSQL.2011322019" to 134217728 bytes: No space left on device
>
>I found:
>https://www.postgresql.org/message-id/flat/CAEepm%3D2D_JGb8X%3DLa-0PX9C8dBX9%3Dj9wY%2By1-zDWkcJu0%3DBQbA%40mail.gmail.com
>
>work_mem | 128MB
>dynamic_shared_memory_type | posix
>version | PostgreSQL 12.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.4.7 20120313 (Red Hat 4.4.7-23), 64-bit
>Running centos 6.9 / linux 2.6.32-696.23.1.el6.x86_64
>
>$ free -m
> total used free shared buffers cached
>Mem: 7871 7223 648 1531 5 1988
>-/+ buffers/cache: 5229 2642
>Swap: 4095 2088 2007
>
>$ mount | grep /dev/shm
>tmpfs on /dev/shm type tmpfs (rw)
>
>$ du -hs /dev/shm
>0 /dev/shm
>
>$ df /dev/shm
>Filesystem 1K-blocks Used Available Use% Mounted on
>tmpfs 4030272 24 4030248 1% /dev/shm
>
>Later, I see:
>$ df -h /dev/shm
>Filesystem Size Used Avail Use% Mounted on
>tmpfs 3.9G 3.3G 601M 85% /dev/shm
>
>I can reproduce the error running a single instance of the query.
>
>The query plan is 1300 lines long, and involves 482 "Scan" nodes on a table
>which currently has 93 partitions, and for which current partitions are
>"daily". I believe I repartitioned its history earlier this year to "monthly",
>probably to avoid "OOM with many sorts", as reported here:
>https://www.postgresql.org/message-id/20190708164401.GA22387%40telsasoft.com
>

Interestingly enough, I ran into the same ERROR (not sure if the same
root cause) while investigating bug #16104 [1], i.e. on a much simpler
query (single join).

This This particular machine is a bit smaller (only 8GB of RAM and less
disk space) so I created a smaller table with "just" 1.5B rows:

create table test as select generate_series(1, 1500000000)::bigint i;
set work_mem = '150MB';
set max_parallel_workers_per_gather = 8;
analyze test;

explain select count(*) from test t1 join test t2 using (i);

QUERY PLAN
------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=67527436.36..67527436.37 rows=1 width=8)
-> Gather (cost=67527435.53..67527436.34 rows=8 width=8)
Workers Planned: 8
-> Partial Aggregate (cost=67526435.53..67526435.54 rows=1 width=8)
-> Parallel Hash Join (cost=11586911.03..67057685.47 rows=187500024 width=0)
Hash Cond: (t1.i = t2.i)
-> Parallel Seq Scan on test t1 (cost=0.00..8512169.24 rows=187500024 width=8)
-> Parallel Hash (cost=8512169.24..8512169.24 rows=187500024 width=8)
-> Parallel Seq Scan on test t2 (cost=0.00..8512169.24 rows=187500024 width=8)
(9 rows)

explain analyze select count(*) from test t1 join test t2 using (i);

ERROR: could not resize shared memory segment "/PostgreSQL.1743102822" to 536870912 bytes: No space left on device

Now, work_mem = 150MB might be a bit too high considering the machine
only has 8GB of RAM (1GB of which is shared_buffers). But that's still
just 1.2GB of RAM and this is not an OOM. This actually fills the
/dev/shm mount, which is limited to 4GB on this box

bench ~ # df | grep shm
shm 3994752 16 3994736 1% /dev/shm

So somewhere in the parallel hash join, we allocate 4GB of shared segments ...

The filesystem usage from the moment of the query execution to the
failure looks about like this:

Time fs 1K-blocks Used Available Use% Mounted on
--------------------------------------------------------------
10:13:34 shm 3994752 34744 3960008 1% /dev/shm
10:13:35 shm 3994752 35768 3958984 1% /dev/shm
10:13:36 shm 3994752 37816 3956936 1% /dev/shm
10:13:39 shm 3994752 39864 3954888 1% /dev/shm
10:13:42 shm 3994752 41912 3952840 2% /dev/shm
10:13:46 shm 3994752 43960 3950792 2% /dev/shm
10:13:49 shm 3994752 48056 3946696 2% /dev/shm
10:13:56 shm 3994752 52152 3942600 2% /dev/shm
10:14:02 shm 3994752 56248 3938504 2% /dev/shm
10:14:09 shm 3994752 60344 3934408 2% /dev/shm
10:14:16 shm 3994752 68536 3926216 2% /dev/shm
10:14:30 shm 3994752 76728 3918024 2% /dev/shm
10:14:43 shm 3994752 84920 3909832 3% /dev/shm
10:14:43 shm 3994752 84920 3909832 3% /dev/shm
10:14:57 shm 3994752 93112 3901640 3% /dev/shm
10:15:11 shm 3994752 109496 3885256 3% /dev/shm
10:15:38 shm 3994752 125880 3868872 4% /dev/shm
10:16:06 shm 3994752 142264 3852488 4% /dev/shm
10:19:57 shm 3994752 683208 3311544 18% /dev/shm
10:19:58 shm 3994752 1338568 2656184 34% /dev/shm
10:20:02 shm 3994752 1600712 2394040 41% /dev/shm
10:20:03 shm 3994752 2125000 1869752 54% /dev/shm
10:20:04 shm 3994752 2649288 1345464 67% /dev/shm
10:20:08 shm 3994752 2518216 1476536 64% /dev/shm
10:20:10 shm 3994752 3173576 821176 80% /dev/shm
10:20:14 shm 3994752 3697864 296888 93% /dev/shm
10:20:15 shm 3994752 3417288 577464 86% /dev/shm
10:20:16 shm 3994752 3697864 296888 93% /dev/shm
10:20:20 shm 3994752 3828936 165816 96% /dev/shm

And at the end, the contents of /dev/shm looks like this:

-rw------- 1 postgres postgres 33624064 Dec 16 22:19 PostgreSQL.1005341478
-rw------- 1 postgres postgres 1048576 Dec 16 22:20 PostgreSQL.1011142277
-rw------- 1 postgres postgres 1048576 Dec 16 22:20 PostgreSQL.1047241463
-rw------- 1 postgres postgres 16777216 Dec 16 22:16 PostgreSQL.1094702083
-rw------- 1 postgres postgres 268435456 Dec 16 22:20 PostgreSQL.1143288540
-rw------- 1 postgres postgres 536870912 Dec 16 22:20 PostgreSQL.1180709918
-rw------- 1 postgres postgres 7408 Dec 14 15:43 PostgreSQL.1239805533
-rw------- 1 postgres postgres 134217728 Dec 16 22:20 PostgreSQL.1292496162
-rw------- 1 postgres postgres 268435456 Dec 16 22:20 PostgreSQL.138443773
-rw------- 1 postgres postgres 4194304 Dec 16 22:15 PostgreSQL.1442035225
-rw------- 1 postgres postgres 67108864 Dec 16 22:20 PostgreSQL.147930162
-rw------- 1 postgres postgres 16777216 Dec 16 22:20 PostgreSQL.1525896026
-rw------- 1 postgres postgres 67108864 Dec 16 22:20 PostgreSQL.1541133044
-rw------- 1 postgres postgres 33624064 Dec 16 22:14 PostgreSQL.1736434498
-rw------- 1 postgres postgres 134217728 Dec 16 22:20 PostgreSQL.1845631548
-rw------- 1 postgres postgres 33624064 Dec 16 22:19 PostgreSQL.1952212453
-rw------- 1 postgres postgres 134217728 Dec 16 22:20 PostgreSQL.1965950370
-rw------- 1 postgres postgres 8388608 Dec 16 22:15 PostgreSQL.1983158004
-rw------- 1 postgres postgres 33624064 Dec 16 22:19 PostgreSQL.1997631477
-rw------- 1 postgres postgres 16777216 Dec 16 22:20 PostgreSQL.2071391455
-rw------- 1 postgres postgres 2097152 Dec 16 22:20 PostgreSQL.210551357
-rw------- 1 postgres postgres 67108864 Dec 16 22:20 PostgreSQL.2125755117
-rw------- 1 postgres postgres 8388608 Dec 16 22:14 PostgreSQL.2133152910
-rw------- 1 postgres postgres 2097152 Dec 16 22:20 PostgreSQL.255342242
-rw------- 1 postgres postgres 2097152 Dec 16 22:20 PostgreSQL.306663870
-rw------- 1 postgres postgres 536870912 Dec 16 22:20 PostgreSQL.420982703
-rw------- 1 postgres postgres 134217728 Dec 16 22:20 PostgreSQL.443494372
-rw------- 1 postgres postgres 134217728 Dec 16 22:20 PostgreSQL.457417415
-rw------- 1 postgres postgres 4194304 Dec 16 22:20 PostgreSQL.462376479
-rw------- 1 postgres postgres 16777216 Dec 16 22:16 PostgreSQL.512403457
-rw------- 1 postgres postgres 8388608 Dec 16 22:14 PostgreSQL.546049346
-rw------- 1 postgres postgres 196864 Dec 16 22:13 PostgreSQL.554918510
-rw------- 1 postgres postgres 687584 Dec 16 22:13 PostgreSQL.585813590
-rw------- 1 postgres postgres 4194304 Dec 16 22:15 PostgreSQL.612034010
-rw------- 1 postgres postgres 33624064 Dec 16 22:19 PostgreSQL.635077233
-rw------- 1 postgres postgres 7408 Dec 15 17:28 PostgreSQL.69856210
-rw------- 1 postgres postgres 268435456 Dec 16 22:20 PostgreSQL.785623413
-rw------- 1 postgres postgres 4194304 Dec 16 22:14 PostgreSQL.802559608
-rw------- 1 postgres postgres 67108864 Dec 16 22:20 PostgreSQL.825442833
-rw------- 1 postgres postgres 8388608 Dec 16 22:15 PostgreSQL.827813234
-rw------- 1 postgres postgres 268435456 Dec 16 22:20 PostgreSQL.942923396
-rw------- 1 postgres postgres 536870912 Dec 16 22:20 PostgreSQL.948192559
-rw------- 1 postgres postgres 2097152 Dec 16 22:20 PostgreSQL.968081079

That's a lot of shared segments, considering there are only ~8 workers
for the parallel hash join. And some of the segments are 512MB, so not
exactly tiny/abiding to the work_mem limit :-(

I'm not very familiar with the PHJ internals, but this seems a bit
excessive. I mean, how am I supposed to limit memory usage in these
queries? Why shouldn't this be subject to work_mem?

regards

[1] https://www.postgresql.org/message-id/flat/16104-dc11ed911f1ab9df%40postgresql.org

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services