Memory exhaustion due to temporary tables?

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

Memory exhaustion due to temporary tables?

Thomas Carroll
We have a situation where a long-persistent Postgres connection consumes more and more memory.  If ignored, we eventually get “Cannot allocate memory” errors in the Postgres log.  If still ignored, the box will eventually crash.  This takes about 3 weeks to happen.  It issues a call to a single function about once every 15 seconds.  What can I do to prevent this outcome?

What the function does: The purpose of the function is to refresh a cache in an application, not make meaningful updates. It does write to the database, but only a temporary table.  If I remove the temporary table (just as an experiment, it makes the function useless) the memory consumption does not occur.

There are no transactions left hanging open, no locks holding resources for long periods of time.  The temporary table is about half a meg in size, about 5500 rows.

The memory usage is identified by examining and totaling the lines beginning with “Private” in the /proc/1234/smaps file, where 1234 is the process ID for the connection.  The memory consumption starts out at under 20 meg, but swells to hundreds of megabytes over the three weeks.  I have been able to reproduce the issue on my own Linux workstation with an accelerated schedule.

Other loads: None, this is a dedicated Postgres server

Postgres version: 10.5.  work_mem setting: 4MB, shared_buffers setting: 800 MB, connections typically around 30-40.

Linux kernel version: 3.10 and CentOS 7.  Also kernel 4.19 and OpenSUSE Tumbleweed when I recreate the issue on my workstation.

Server: An AWS EC2 instance: t2.medium.  In other words, 2 CPUs, 4 GB of memory.  Not big, but we do have a bunch of them.

Workaround: We monitor the process and bounce it periodically.  I don't love this approach.  We could rewrite the function to avoid the temporary table.  It would be my shame as a DBA to ask a developer to do that :).

Thanks for any insight!

Tom
Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Laurenz Albe
Thomas Carroll wrote:
> We have a situation where a long-persistent Postgres connection consumes more
> and more memory.  If ignored, we eventually get “Cannot allocate memory”
> errors in the Postgres log.  If still ignored, the box will eventually crash.
> This takes about 3 weeks to happen.  It issues a call to a single function
> about once every 15 seconds.  What can I do to prevent this outcome?

There should be a memory context dump in the log file.
What does it look like?

Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com


Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Tom Lane-2
In reply to this post by Thomas Carroll
Thomas Carroll <[hidden email]> writes:
> Postgres version: 10.5.  work_mem setting: 4MB, shared_buffers setting: 800 MB, connections typically around 30-40.

I imagine you checked this already, but ... what is temp_buffers set to?
That constrains the maximum memory used for temporary-table buffers in
each process, and an unreasonable setting for it could lead to the
described behavior.

Another thing to keep in mind with long-lived "temporary" tables is
that autovacuum can't do anything with them; so it's incumbent on your
application to periodically VACUUM and/or ANALYZE them as needed.
Otherwise such tables will bloat, which could contribute to excessive
use of temporary-table buffers.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Thomas Carroll
On Monday, December 10, 2018, 3:45:33 PM EST, Tom Lane <[hidden email]> wrote:


Thomas Carroll <[hidden email]> writes:

> Postgres version: 10.5.  work_mem setting: 4MB, shared_buffers setting: 800 MB, connections typically around 30-40.


I imagine you checked this already, but ... what is temp_buffers set to?
That constrains the maximum memory used for temporary-table buffers in
each process, and an unreasonable setting for it could lead to the
described behavior.

Another thing to keep in mind with long-lived "temporary" tables is
that autovacuum can't do anything with them; so it's incumbent on your
application to periodically VACUUM and/or ANALYZE them as needed.
Otherwise such tables will bloat, which could contribute to excessive
use of temporary-table buffers.

            regards, tom lane

On Monday, December 10, 2018, 3:45:33 PM EST, Tom Lane <[hidden email]> wrote:

> I imagine you checked this already, but ... what is temp_buffers set to?

Thanks for your reply!  temp_buffers is the default 8MB, and I should have included that in my first email.

> Another thing to keep in mind with long-lived "temporary" tables...

WRT temp tables and autovacuum: I realize I need to add an important detail here: The table is created by the function using:

CREATE TEMPORARY TABLE table_name ON COMMIT DROP AS SELECT...

So my perhaps-wrong expectation is that all remnants of the old temporary table are discarded from the previous invocation, so there is no need to do any vacuuming.

Thanks again,
Tom




Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Tom Lane-2
Thomas Carroll <[hidden email]> writes:
>    On Monday, December 10, 2018, 3:45:33 PM EST, Tom Lane <[hidden email]> wrote:  
>> I imagine you checked this already, but ... what is temp_buffers set to?

> Thanks for your reply!  temp_buffers is the default 8MB, and I should have included that in my first email.

Hm.  Well, the temporary-buffer arena definitely won't grow any larger
than that, so the problem is somewhere else.

> WRT temp tables and autovacuum: I realize I need to add an important detail here: The table is created by the function using:
> CREATE TEMPORARY TABLE table_name ON COMMIT DROP AS SELECT...
> So my perhaps-wrong expectation is that all remnants of the old temporary table are discarded from the previous invocation, so there is no need to do any vacuuming.

I see.  The contents of the temp tables certainly go away at commit,
then, but the system catalog entries describing a temp table are just
as real as those for a regular table.  So if you're creating and
dropping temp tables quickly, there's a potential for bloat in the
system catalogs (particularly pg_attribute), which autovacuum might
or might not keep up with at default settings.  Still, I'd only expect
that to lead to disk space growth not memory consumption.

Is the error message spelling really exactly "Cannot allocate memory"?
Because that string appears nowhere in the Postgres backend sources,
and I don't think it's strerror's canonical phrasing for ENOMEM either.
So I'm wondering just where it's coming from.

Also, as mentioned upthread, it'd be interesting to see if there's
a memory context dump showing up in your server log.  It'd look
something roughly like this:

TopMemoryContext: 67440 total in 5 blocks; 14016 free (27 chunks); 53424 used
  TopTransactionContext: 32768 total in 3 blocks; 14992 free (21 chunks); 17776 used
    Combo CIDs: 8192 total in 1 blocks; 1544 free (0 chunks); 6648 used
  LocalBufferContext: 8397248 total in 8 blocks; 7936 free (0 chunks); 8389312 used
  Local Buffer Lookup Table: 32768 total in 3 blocks; 6368 free (7 chunks); 26400 used
  ... lots more ...
Grand total: 9603680 bytes in 238 blocks; 283976 free (240 chunks); 9319704 used

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Thomas Carroll


On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <[hidden email]> wrote:

> Is the error message spelling really exactly "Cannot allocate memory"?

Yes - but I think the message is forwarded from Linux.  Here is an example:

2018-12-08 00:00:00.070 EST,,,32506,,5bc71a25.7efa,25643,,2018-10-17 07:16:53 EDT,,0,LOG,00000,"could not fork autovacuum worker process: Cannot allocate memory",,,,,,,,,""

Should have been more thoughtful in what I chose to mention.  Here is one that may be more familiar, and directly related to the issue I am encountering:

2018-12-08 00:00:03.642 EST,"schema_name","db_name",24949,"10.12.113.56:50138",5bfed8cd.6175,17637,"SELECT",2018-11-28 13:05:01 EST,24/223502,0,ERROR,53200,"out of memory","Failed on request of size 24.",,,,"SQL statement ""CREATE TEMPORARY TABLE table_name ON COMMIT DROP AS

> Also, as mentioned upthread, it'd be interesting to see if there's
> a memory context dump showing up in your server log.

There are many memory context dumps, and they are long (well over 100 lines apiece).  To me these are unfamiliar and hard to read, but I tried to pick one that referenced all the same tables used in the function.  I put one such dump (188 lines) here:




A hopefully-helpful short excerpt from the top:

TopMemoryContext: 174216 total in 7 blocks; 12520 free (27 chunks); 161696 used
  pgstat TabStatusArray lookup hash table: 8192 total in 1 blocks; 632 free (0 chunks); 7560 used
  TopTransactionContext: 24576 total in 2 blocks; 7288 free (3 chunks); 17288 used
    Combo CIDs: 8192 total in 1 blocks; 1800 free (0 chunks); 6392 used
    ExecutorState: 8192 total in 1 blocks; 7400 free (0 chunks); 792 used
      ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
    SPI Exec: 2088960 total in 8 blocks; 865976 free (7 chunks); 1222984 used
      ExecutorState: 262216 total in 6 blocks; 94344 free (11 chunks); 167872 used
        HashTableContext: 8192 total in 1 blocks; 7584 free (0 chunks); 608 used
          HashBatchContext: 197104 total in 6 blocks; 0 free (0 chunks); 197104 used
        HashTableContext: 8192 total in 1 blocks; 7968 free (0 chunks); 224 used
          HashBatchContext: 49240 total in 2 blocks; 8136 free (0 chunks); 41104 used
        HashTableContext: 8192 total in 1 blocks; 7584 free (0 chunks); 608 used
          HashBatchContext: 197104 total in 6 blocks; 0 free (0 chunks); 197104 used


Anything I can do to zero in on helpful information, I'm all ears.

Thanks so much!
Tom



Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Tom Lane-2
Thomas Carroll <[hidden email]> writes:
>   On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <[hidden email]> wrote:  
>> Also, as mentioned upthread, it'd be interesting to see if there's
>> a memory context dump showing up in your server log.

> There are many memory context dumps, and they are long (well over 100 lines apiece).  To me these are unfamiliar and hard to read, but I tried to pick one that referenced all the same tables used in the function.  I put one such dump (188 lines) here:
> https://drive.google.com/file/d/1QI4nffdZByIehb_-GULOagI_dKpKElg_/view

Thanks.  Here's the smoking gun:

  CacheMemoryContext: 221241400 total in 38 blocks; 152192 free (90 chunks); 221089208 used

This looks like something is leaking memory directly in CacheMemoryContext
(not in any of its child contexts).  Can you confirm that all the memory
context dumps in your logs are showing similarly very-large total space
values for CacheMemoryContext?

This doesn't seem to be related to temp table usage, at least not
directly.  (As a cross-check, I created and dropped 10000 temp tables in a
session, and the process's VM footprint didn't budge.)  My guess is that
something else you are doing is tickling the leak.

You said you'd been able to reproduce this problem outside production.
Any chance you could boil that down to a sharable test case?  I'd bet
long odds that it's not related to your data particularly, but rather
to your schema or something your function is doing, so you probably
could reproduce it with some dummy data (and, perhaps, not even very
much of that; repeating some DDL action many times is probably what
is making the leak grow to something noticeable).

If I had to guess at this point, I'd wonder if it's something to do
with partitioned tables.  That code is still relatively wet behind
the ears, and memory leaks are the kind of bug I'd be expecting to
still be shaking out of it now.  But you might not be using partitioned
tables at all.  Anyway, anything you're doing with new-in-v10 features,
particularly schema-related features, would be a good bet for the
source of the problem.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Thomas Carroll

On Monday, December 10, 2018, 7:45:07 PM EST, Tom Lane <[hidden email]> wrote:


Thomas Carroll <[hidden email]> writes:

>  On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <[hidden email]> wrote: 
>> Also, as mentioned upthread, it'd be interesting to see if there's
>> a memory context dump showing up in your server log.

> There are many memory context dumps, and they are long (well over 100 lines apiece).  To me these are unfamiliar and hard to read, but I tried to pick one that referenced all the same tables used in the function.  I put one such dump (188 lines) here:

> https://drive.google.com/file/d/1QI4nffdZByIehb_-GULOagI_dKpKElg_/view

Thanks.  Here's the smoking gun:

  CacheMemoryContext: 221241400 total in 38 blocks; 152192 free (90 chunks); 221089208 used

This looks like something is leaking memory directly in CacheMemoryContext
(not in any of its child contexts).  Can you confirm that all the memory
context dumps in your logs are showing similarly very-large total space
values for CacheMemoryContext?

This doesn't seem to be related to temp table usage, at least not
directly.  (As a cross-check, I created and dropped 10000 temp tables in a
session, and the process's VM footprint didn't budge.)  My guess is that
something else you are doing is tickling the leak.

You said you'd been able to reproduce this problem outside production.
Any chance you could boil that down to a sharable test case?  I'd bet
long odds that it's not related to your data particularly, but rather
to your schema or something your function is doing, so you probably
could reproduce it with some dummy data (and, perhaps, not even very
much of that; repeating some DDL action many times is probably what
is making the leak grow to something noticeable).

If I had to guess at this point, I'd wonder if it's something to do
with partitioned tables.  That code is still relatively wet behind
the ears, and memory leaks are the kind of bug I'd be expecting to
still be shaking out of it now.  But you might not be using partitioned
tables at all.  Anyway, anything you're doing with new-in-v10 features,
particularly schema-related features, would be a good bet for the
source of the problem.

            regards, tom lane



Thanks for your response and sorry for the delay in getting back to this. 
Because holidays.

To refresh your memory, the issue I encountered is that a long-persistent
connection that periodically issues function calls consumes more and more
memory - eventually causing memory exhaustion.  Admittedly, it does take
weeks.

This email is about creating a shareable test case.

The test case is simple - so simple that I am surprised no one has encountered
this before, and therefore I am really more fearing that I am doing something
stupid in my effort to make it shareable and simple.  In creating this example
I have not run the code till it crashed the server; instead I used the
measuring methodology you will see below (monitoring the smaps file).

I have put needed files here:

https://drive.google.com/open?id=1ff074Qxn7Bx9Ud9GRaegDfuJn_Tf_NTi

Table of contents:

testbed.public.backup # database dump, not compressed, includes "create database"
pg_hba.conf # self explanatory; allows local postgres to log in as trusted
postgresql.conf # self explanatory. nothing weird
loop_query.bash # sends a query via named pipe to Postgres once per second

To recreate the issue, load the "testbed" database into a Postgres server,
configured so that psql does not need to send a password for user postgres.

I created the server with this:
initdb $PGDATA --locale="en_US.UTF-8" -E "UTF-8" -k

Then run as postgres:

cd /my/directory
mkfifo qpipe # named pipe conduit to persistent Postgres connection
cat > qpipe & # keep pipe from closing and terminating the PG connection
psql -h localhost -d testbed -U postgres < qpipe & # listener connection
./query_loop.bash # Send function call over and over once per second
# Observe output; should be 78 rows per second

# Switch to a new terminal session
# Identify the PID of the psql process
# Monitor with this command, but plug in the real PID for the 1234
grep "^Private" /proc/1234/smaps | awk '{a+=$2}END{print a/1024.0}'

Give it a few minutes, and you will observe memory usage climbing steadily
(if my measurement technique is good).  From last night to this morning I
observed memory consumption grow from 3.5 to 46.6 MB.

Tested on Postgres version 10.5.

Again, thanks for any help.

Tom Carroll
Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Tom Lane-2
[ please don't re-quote the entire thread when replying ]

Thomas Carroll <[hidden email]> writes:
>     On Monday, December 10, 2018, 7:45:07 PM EST, Tom Lane <[hidden email]> wrote:  
>> You said you'd been able to reproduce this problem outside production.
>> Any chance you could boil that down to a sharable test case?

> The test case is simple - so simple that I am surprised no one has encountered
> this before, and therefore I am really more fearing that I am doing something
> stupid in my effort to make it shareable and simple.  In creating this example
> I have not run the code till it crashed the server; instead I used the
> measuring methodology you will see below (monitoring the smaps file).

Hmm.  So what this test case is doing is repeatedly creating a temp table
with ON COMMIT DROP, querying that table, and then closing the transaction
(allowing the temp table to go away).  It does leak memory in
CacheMemoryContext, and as far as I can tell, the leakage consists
entirely of negative catcache entries for pg_statistic rows.  That happens
because while querying the temp table, the planner tries to look up
statistics for the table; but there are none, since you haven't ANALYZEd
it.  So negative catcache entries get made in hopes of saving the cost of
probing pg_statistic again later.  But, when we drop the table, those
catcache entries don't get cleared because they do not match any catalog
rows that get deleted during the drop.

In a lot of use-cases, this wouldn't matter too much, either because the
session isn't long-lived enough to accumulate huge numbers of negative
entries, or because other catalog activity causes the entries to get
flushed anyway.  But if you don't have much DDL going on other than
this temp table activity, then yeah it could build up.

Not sure about good ways to fix this.  I can think of various more-or-less
klugy fixes that are specific to the pg_statistic case.  There's been some
ongoing discussion about trying to limit accumulation of negative catcache
entries more generally, but that's not very close to being committable
I think.

In the meantime, you might think about switching over to some process
that doesn't create and drop the same table constantly.  Perhaps
along the lines of

create temp table if not exists tt_preTally (...) on commit delete rows;

if (tt_preTally contains no rows) then
   insert into tt_preTally select ...
end if;

This'd have the advantage of reducing catalog churn in other catalogs
besides pg_statistic, too.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Memory exhaustion due to temporary tables?

Thomas Carroll
In reply to this post by Thomas Carroll
> In the meantime, you might think about switching over to some process
> that doesn't create and drop the same table constantly.  Perhaps
> along the lines of

> create temp table if not exists tt_preTally (...) on commit delete rows;

> if (tt_preTally contains no rows) then
>  insert into tt_preTally select ...
> end if;

> This'd have the advantage of reducing catalog churn in other catalogs
> besides pg_statistic, too.

Just to close the loop, doing the CREATE TEMP TABLE IF NOT EXISTS etc. helped a lot.  Still a tiny increase in memory over time, but this is much much better.

Thanks for the help, and amazed at the responsiveness of Mr. Lane and this community!

Tom Carroll

On Monday, December 10, 2018, 4:59:47 PM EST, Laurenz Albe <[hidden email]> wrote:


Thomas Carroll wrote:

> We have a situation where a long-persistent Postgres connection consumes more
> and more memory.  If ignored, we eventually get “Cannot allocate memory”
> errors in the Postgres log.  If still ignored, the box will eventually crash.
> This takes about 3 weeks to happen.  It issues a call to a single function
> about once every 15 seconds.  What can I do to prevent this outcome?


There should be a memory context dump in the log file.
What does it look like?

Yours,
Laurenz Albe
--



Thanks for your reply.  There are many memory context dumps