Thread: BUG #3483: Dropped temporary tables filled up the disk
The following bug has been logged online:
Bug reference: 3483
Logged by: Brent Reid
Email address: bfraci@aol.com
PostgreSQL version: 8.1.9
Operating system: Red Hat Linux 3.2.3-53
Description: Dropped temporary tables filled up the disk
Details:
Our application opens several pooled sessions to the database. These
sessions will typically never be closed. One of the threads, Thread A, of
our application will use one of these sessions to create a temporary table.
One of the columns in this table is of data type text. It will then insert
into this table several rows. Typically the amount of data put into the
text column is several 100K in length. However, on a recent Friday, the
application tried to insert several 100M into this text column. When it did
that, it got an out of memory error. In this situation, the application
closes the connection, gets a new connection from the pool, and tries again.
It will repeat this until it is able to succeed.
Our application has another thread, Thread B, that is continually looping on
a select from a large table looking for work to do. This select will
typically return in a few milliseconds. However, it can take up to 5
minutes to return depending on how much data is in the table and how much
work there is to do. The only relationship between Thread A and Thread B
is they are run from the same application and access the same database.
They don't reference the same tables.
When we came in on Monday morning, we had discovered that the application
had stopped putting data into the database because the disk containing the
database was 100% full. At least df said that it was 100% full, du said
that it was only 10% full. Thread A had stopped because it was not able to
create the temporary table because the disk was full. Thread B was still
looping looking for work to do â it was still using its original
connection. At this point, there was no more work for it to do because the
other threads were not able to put anymore data into the database.
We executed the command âlsof +aL1 /usr/localâ. This showed us the
following (this is just a portion of what was listed):
-sh-2.05b# lsof +aL1 /usr/local
COMMAND PID USER FD TYPE DEVICE SIZE NLINK NODE NAME
postmaste 30061 postgres 42u REG 9,0 79773696 0 32555014
/usr/local/pgsql/data8.1/base/159232015/164866273 (deleted)
postmaste 30061 postgres 65u REG 9,0 79773696 0 803521
/usr/local/pgsql/data8.1/base/159232015/164865706 (deleted)
postmaste 30061 postgres 66u REG 9,0 1228800 0 803522
/usr/local/pgsql/data8.1/base/159232015/164865708 (deleted)
postmaste 30061 postgres 73u REG 9,0 79773696 0 803502
/usr/local/pgsql/data8.1/base/159232015/164865754 (deleted)
postmaste 30061 postgres 74u REG 9,0 1228800 0 803517
/usr/local/pgsql/data8.1/base/159232015/164865756 (deleted)
postmaste 30061 postgres 75u REG 9,0 79773696 0 803524
/usr/local/pgsql/data8.1/base/159232015/164865802 (deleted)
postmaste 30061 postgres 76u REG 9,0 1228800 0 803529
/usr/local/pgsql/data8.1/base/159232015/164865804 (deleted)
postmaste 30061 postgres 77u REG 9,0 1228800 0 32555015
/usr/local/pgsql/data8.1/base/159232015/164866275 (deleted)
postmaste 30061 postgres 78u REG 9,0 79773696 0 32555023
/usr/local/pgsql/data8.1/base/159232015/164866609 (deleted)
postmaste 30061 postgres 79u REG 9,0 79773696 0 32555011
/usr/local/pgsql/data8.1/base/159232015/164866321 (deleted)
postmaste 30061 postgres 80u REG 9,0 1228800 0 32555012
/usr/local/pgsql/data8.1/base/159232015/164866323 (deleted)
postmaste 30061 postgres 81u REG 9,0 79773696 0 32555013
/usr/local/pgsql/data8.1/base/159232015/164866369 (deleted)
postmaste 30061 postgres 82u REG 9,0 1228800 0 32555016
/usr/local/pgsql/data8.1/base/159232015/164866371 (deleted)
postmaste 30061 postgres 96u REG 9,0 79773696 0 32555019
/usr/local/pgsql/data8.1/base/159232015/164866465 (deleted)
postmaste 30061 postgres 97u REG 9,0 1228800 0 32555020
/usr/local/pgsql/data8.1/base/159232015/164866467 (deleted)
postmaste 30061 postgres 98u REG 9,0 79773696 0 32555017
/usr/local/pgsql/data8.1/base/159232015/164866513 (deleted)
postmaste 30061 postgres 99u REG 9,0 1228800 0 32555018
/usr/local/pgsql/data8.1/base/159232015/164866515 (deleted)
postmaste 30061 postgres 100u REG 9,0 1228800 0 32555024
/usr/local/pgsql/data8.1/base/159232015/164866611 (deleted)
Process 30061 is the backend process for Thread B.
The steps to reproduce this situation:
1.In terminal session A create a file, let's say a.sql, that contains the
following:
create temporary table tmp_foo( col1 int, col2 text ) on commit delete
rows;
insert into tmp_foo select s.a, repeat('Testing',s.a*1024000) from
generate_series(1,100) as s(a);
2.Execute the following shell commands in terminal session A:
while [ 1 ] ; do date; /usr/local/pgsql/bin/psql -U testuser < a.sql; sleep
1; done
3.While that is running in terminal session A, in terminal session B start a
psql session to the database and execute the following commands:
create table foo( col1 int, col2 text );
insert into foo select s.a, repeat('Testing',2000) from
generate_series(1,10000000) as s(a);
select count(*) from foo; -- repeat this command to continue to experience
the problem
4.In terminal session C run the lsof command to look for deleted files that
are still open. You will see session B start to have several of these files
that never go away, at least until you close session B's psql session.
One of my observations was whatever was run in session B needed to run for
several seconds before you would have the problem. When I ran several short
queries, the longest of which took 0.493 ms, I did not experience the
problem. I did not spend the time to find out exactly how long a query
needed to run.
"Brent Reid" <bfraci@aol.com> writes:
> Description: Dropped temporary tables filled up the disk
I believe what's going on in your test case is that
(1) The two sessions are competing for shared buffers; this means that
sometimes the SELECT (session B) has to flush buffers that were dirtied
by session A. This means it will set up SmgrRelation cache entries
(effectively, open files) for tables that it would otherwise never have
reason to access --- specifically, the temp tables that your sessions A
are generating.
(2) There is a mechanism to signal smgr cache invalidation when a
table is dropped; and that should result in the open file getting
closed. However, the inval message queue is only checked
by a backend when it starts a command or needs to open a new table.
Thus, if you've got a long-running command in session B it would not
act on the inval messages right away, and would accumulate open file
entries for temp tables that might have been dropped later.
What's not real apparent to me is how your Thread B managed to avoid
processing inval messages for a long time, as apparently it must have
done to acquire open file pointers for a large number of tables later
dropped by Thread A. Your description doesn't suggest that it was
engaged in a single very long SQL command. It could also avoid inval
processing if it were idle, of course, but it wasn't idle according to
your description, and anyway it certainly couldn't accumulate new open
files while sitting idle. So there something about your coding methods
for Thread B that's a bit out of the ordinary. Can you show us anything
of that code, or more accurately the SQL it's using?
Another factor in this is that temp tables ordinarily wouldn't compete
for shared buffer space, and thus situation (1) shouldn't arise in the
first place if all the tables being created/dropped are temp. However,
if a temp table has a toast table for wide fields, the toast table is
not currently treated as temp --- that is, access to it goes through
shared buffers. This is something we oughta fix sometime, but it's
certainly not going to change in 8.1.x.
Aside from tweaking Thread B in whatever way is needed to get it to
check the inval queue more often, you might look at whether you can
reasonably increase shared_buffers to reduce the degree of competition.
regards, tom lane
"Tom Lane" <tgl ( at ) sss ( dot ) pgh ( dot ) pa ( dot ) us> writes:
> for Thread B that's a bit out of the ordinary. Can you show us anything
> of that code, or more accurately the SQL it's using?
The company that I work for is very paranoid about sharing specific
information about what we do with the outside world. Therefore, I have
changed the table and column names to protect the innocent.
The table definition that session B is using is:
Column | Type | Modifiers
--------------+-----------------------+--------------------
col1 | character varying(64) | not null
col2 | integer | not null
col3 | character varying(64) |
col4 | bigint | not null default 0
col5 | integer | not null default 0
col6 | integer | not null
col7 | bytea |
col8 | date |
col9 | integer | not null default 0
col10 | bigint | not null default 0
col11 | bytea |
Indexes:
"foo_pkey" PRIMARY KEY, btree (col1)
"foo_col9ix" btree (col9)
"foo_col10ix" btree (col10)
"foo_col5ix" btree (col5)
Rules:
delrule_foo20070716 AS
ON DELETE TO foo
WHERE old.col8 < '2007-07-17'::date DO INSTEAD DELETE FROM foo20070716
WHERE foo20070716.col1::text = old.col1::text
delrule_foo20070717 AS
ON DELETE TO foo
WHERE old.col8 >= '2007-07-17'::date AND old.col8 < '2007-07-18'::date DO
INSTEAD DELETE FROM foo20070717
WHERE foo20070717.col1::text = old.col1::text
delrule_foo20070718 AS
ON DELETE TO foo
WHERE old.col8 >= '2007-07-18'::date DO INSTEAD DELETE FROM foo20070718
WHERE foo20070718.col1::text = old.col1::text
insrule_foo20070716 AS
ON INSERT TO foo
WHERE new.col8 < '2007-07-17'::date DO INSTEAD INSERT INTO foo20070716
(col1, col2, col3, col4, col5, "location", col7, col8, col9, col10, col11)
VALUES (new.col1, new.col2, new.col3, new.col4, new.col5, new."col6",
new.col7, new.col8, new.col9, new.col10, new.col11)
insrule_foo20070717 AS
ON INSERT TO foo
WHERE new.col8 >= '2007-07-17'::date AND new.col8 < '2007-07-18'::date DO
INSTEAD INSERT INTO foo20070717 (col1, col2, charset, col4, col5, "col6",
col7, col8, col9, col10, col11)
VALUES (new.col1, new.col2, new.col3, new.col4, new.col5 , new."col6",
new.col7, new.col8, new.col9, new.col10, new.col11)
insrule_foo20070718 AS
ON INSERT TO foo
WHERE new.col8 >= '2007-07-18'::date DO INSTEAD INSERT INTO foo20070718
(col1, col2, col3, col4, col5, "location", col7, col8, col9, col10, col11)
VALUES (new.col1, new.col2, new.col3, new.col4, new.col5, new."col6",
new.col7, new.col8, new.col9, new.col10, new.col11)
updrule_foo20070716 AS
ON UPDATE TO foo
WHERE old.col8 < '2007-07-17'::date DO INSTEAD UPDATE foo20070716 SET
col1 = new.col1, col2 = new.col2, col3 = new.charset, col4 = new.col4, col5
= new.col5, "col6" = new."col6", col7 = new.col7, col8 = new.col8, col9 =
new.indexed, col10 = new.col10, col11 = new.col11
WHERE foo20070716.col1::text = old.col1::text
updrule_foo20070717 AS
ON UPDATE TO foo
WHERE old.col8 >= '2007-07-17'::date AND old.col8 < '2007-07-18'::date DO
INSTEAD UPDATE foo20070717 SET col1 = new.col1, datatype = new.col2, col3 =
new.col3, col4 = new.col4, col5 = new.col5, "col6" = new."col6", col7 =
new.col7, partition = new.col8, col9 = new.col9, col10 = new.col10, col11 =
new.col11
WHERE foo20070717.col1::text = old.col1::text
updrule_foo20070718 AS
ON UPDATE TO foo
WHERE old.col8 >= '2007-07-18'::date DO INSTEAD UPDATE foo20070718 SET
col1 = new.col1, col2 = new.col2, col3 = new.charset, col4 = new.col4, col5
= new.col5, "col6" = new."col6", col7 = new.col7, col8 = new.col8, col9 =
new.indexed, col10 = new.col10, col11 = new.col11
WHERE foo20070718.col1::text = old.col1::text
Session B loops on the following SQL statements with a one minute delay
between each loop:
BEGIN;
SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM foo WHERE col5 = $1 AND
col8 >= '20070716' LIMIT 100;
-- The following is repeated as many times as there are rows from the above
select that need to be updated
UPDATE foo SET col4 = $1, col5 = $2 WHERE col1 = $3 AND col8 = $4;
COMMIT;
The following is a snippet from the postgres log showing the loop session B
was in as we were trying to figure out how we got into this situation:
2007-07-23 15:46:06 MDT [30061]LOG: duration: 0.005 ms statement: EXECUTE
<unnamed> [PREPARE: BEGIN]
2007-07-23 15:46:06 MDT [30061]LOG: duration: 2.417 ms statement: EXECUTE
<unnamed> [PREPARE: SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM
foo WHERE col5 = $1 AND col8 >= '20070716' LIMIT 100]
2007-07-23 15:46:06 MDT [30061]LOG: duration: 0.055 ms statement: EXECUTE
<unnamed> [PREPARE: COMMIT]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 0.007 ms statement: EXECUTE
<unnamed> [PREPARE: BEGIN]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 2.605 ms statement: EXECUTE
<unnamed> [PREPARE: SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM
foo WHERE col5 = $1 AND col8 >= '20070716' LIMIT 100]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 0.032 ms statement: EXECUTE
<unnamed> [PREPARE: COMMIT]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 0.020 ms statement: EXECUTE
<unnamed> [PREPARE: BEGIN]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 2.325 ms statement: EXECUTE
<unnamed> [PREPARE: SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM
foo WHERE col5 = $1 AND col8 >= '20070716' LIMIT 100]
2007-07-23 15:47:06 MDT [30061]LOG: duration: 0.041 ms statement: EXECUTE
<unnamed> [PREPARE: COMMIT]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 0.008 ms statement: EXECUTE
<unnamed> [PREPARE: BEGIN]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 2.537 ms statement: EXECUTE
<unnamed> [PREPARE: SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM
foo WHERE col5 = $1 AND col8 >= '20070716' LIMIT 100]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 0.032 ms statement: EXECUTE
<unnamed> [PREPARE: COMMIT]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 0.021 ms statement: EXECUTE
<unnamed> [PREPARE: BEGIN]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 2.551 ms statement: EXECUTE
<unnamed> [PREPARE: SELECT col1,col2,col3,col4,col5,col6,col8,col9 FROM
foo WHERE col5 = $1 AND col8 >= '20070716' LIMIT 100]
2007-07-23 15:48:06 MDT [30061]LOG: duration: 0.043 ms statement: EXECUTE
<unnamed> [PREPARE: COMMIT]
However, I was able to get the same results by following the steps I had
listed in the bug report. Were you not able to duplicate this by following
those steps?
Thanks for you help.
Brent