Thread: Memory exhaustion due to temporary tables?
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.
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
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.
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
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
Thomas Carroll <tomfecarroll@yahoo.com> 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 <tgl@sss.pgh.pa.us> wrote:
Thomas Carroll <tomfecarroll@yahoo.com> 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.
> 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 <tgl@sss.pgh.pa.us> 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
Thomas Carroll <tomfecarroll@yahoo.com> writes: > On Monday, December 10, 2018, 3:45:33 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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 functionusing: > 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
On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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 hopefully-helpful short excerpt from the top:
> 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:
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
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
Thomas Carroll <tomfecarroll@yahoo.com> writes: > On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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 hardto read, but I tried to pick one that referenced all the same tables used in the function. I put one such dump (188lines) 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
On Monday, December 10, 2018, 7:45:07 PM EST, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Thomas Carroll <tomfecarroll@yahoo.com> writes:
> On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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.
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,
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}'
> On Monday, December 10, 2018, 5:50:22 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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
[ please don't re-quote the entire thread when replying ] Thomas Carroll <tomfecarroll@yahoo.com> writes: > On Monday, December 10, 2018, 7:45:07 PM EST, Tom Lane <tgl@sss.pgh.pa.us> 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
> 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
> 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 <laurenz.albe@cybertec.at> 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
--
> 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 | Startseite - Cybertec
|
Thanks for your reply. There are many memory context dumps