SEO

We have encountered a very nasty but apparently rare bug which appears to
result in catalog corruption. I have not been able to pin down an exact
sequence of events which cause this problem, it appears to be a race
condition of some sort. This is what I have been able to figure out so
far.

* It appears to be related to temp table creation/deletion.
* It requires at least 2 clients be connected simultaneously.
* It seems to be related to the autovacuum (not sure, just a theory).

I will attempt to explain the circumstances leading up to the problem, and
then show the symptoms.

We are working on a project which uses postgresql to store data which has
been decomposed into a large number of rows in stored procedures
(plpgsql/plperl). The implementation we have been working with recently
has used temp tables to store intermediate stages of this decomposition so
that we can run multiple queries over it in the course of adding it to our
final tables without having to regenerate the set each time. We were
running a timing test for a load of data which would result in tens of
millions of rows. This load creates temp tables with "on commit drop" and
also explitly drops them. It appears to do so at a rate of approximately
10 per second (also transactions are being created/committed at that same
rate). This works fine. While this load was running we were
working on some testing code to determine whether it might be better to
create the temp table with "on commit delete rows" instead and use a
plpgsql function to create the temp table with an EXCEPTION
duplicate_table block to handle when the table has already been created
for this connection. We wrote the function at first on a postgres 8.0 box
which was not running the load, but when we were attempting to determine
what the error code thrown was we noticed that the SQLSTATE variable was
not available in 8.0 and copied the function onto the 8.1 box (which was
running the load) to try it out. We ran this function a couple times to
get the error, and then had it catch the duplicate_table exception. We
got the function working, and when we looked at the status of our load we
found that it had died with a message saying

"ERROR: pg_class entry for relid 7502381 vanished during vacuuming"

We found this interesting, figuring it was a bug in postgres. Googling
the non-variable pieces of that message turned up nothing relevant, so we
set about trying to reproduce it.

During the course of doing so, we restarted our load several times and
called the function. We later put the calling of the function into a loop
in bash calling psql (so we could disconnect/reconnect) to speed up the
finding of the problem.

These are some of the interesting errors which we got while doing this
(all from the server log):

ERROR: duplicate key violates unique constraint
"pg_class_relname_nsp_index"
CONTEXT: SQL statement "CREATE TEMP TABLE foo (a integer, b integer) ON
COMMIT
DELETE ROWS"
PL/pgSQL function "temp_table_test" line 2 at SQL statement
ERROR: relation "foo" does not exist
ERROR: duplicate key violates unique constraint
"pg_class_relname_nsp_index"
CONTEXT: SQL statement "CREATE TEMP TABLE foo (a integer, b integer) ON
COMMIT
DELETE ROWS"
PL/pgSQL function "temp_table_test" line 2 at SQL statement



ERROR: relation "foo" does not exist
FATAL: cache lookup failed for relation 7600066
LOG: server process (PID 20942) exited with exit code 1
LOG: terminating any other active server processes
WARNING: terminating connection because of crash of another server process
DETAIL: The postmaster has commanded this server process to roll back the
current transaction and exit, because another server process exited abnormally
and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and repeat your command.


We also managed to get an error which was more bothersome than the
mysterious disappearing/reappearing temp tables.

ERROR: relation "windowpos" does not exist
ERROR: type "windowpos" already exists
ERROR: cache lookup failed for relation 794218

Later:
ERROR: relation "windowpos" already exists
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269
ERROR: catalog is missing 14 attribute(s) for relid 7577269




Here is the temp table function we were testing:

CREATE OR REPLACE FUNCTION temp_table_test() RETURNS boolean AS $$
BEGIN
CREATE TEMP TABLE foo (a integer, b integer) ON COMMIT DELETE ROWS;
RETURN true;
EXCEPTION WHEN duplicate_table THEN
RETURN false;
END;
$$ LANGUAGE plpgsql;


And our bash command line for stressing:
for i in `seq 1 10000`; do
echo -e 'select temp_table_test();\n insert into foo select a, b from generate_series(1,200) a, generate_series(1,200) b;\n' | psql -o /dev/null cruft;
if (($? != 0)); then
break;
fi;
done

We may have reproduced the issue using another bash script instead of our
timing test, but we are not sure whether this was due to the problem, or
due to the catalog already being corrupt in the database.

In this test, we did this initally in psql:

CREATE TABLE junk (a integer, b integer);
CREATE INDEX junk_a_idx ON junk(a);
CREATE INDEX junk_b_idx ON junk(b);
CREATE INDEX junk_a_b_idx ON junk(a, b);
INSERT INTO junk SELECT a, b FROM generate_series(1,200) a, generate_series(1,200) b;
TRUNCATE junk;
TRUNCATE junk;

Then immediately in bash we ran

for i in `seq 1 10000`; do
echo -e 'insert into junk SELECT a, b FROM generate_series(1,200) a, generate_series(1,200) b;\nCREATE TEMP TABLE goo (a integer, b integer) ON COMMIT DROP;\n' | psql -o /dev/null cruft;
if (($? != 0)); then
break;
fi;
done


Here is my postgres version:

PostgreSQL 8.1.0 on x86_64-pc-linux-gnu, compiled by GCC
x86_64-pc-linux-gnu-gcc (GCC) 3.4.4 (Gentoo 3.4.4-r1, ssp-3.4.4-1.0,
pie-8.7.8)

And here is the CONFIGURE line from pg_config:
CONFIGURE = '--prefix=/usr' '--mandir=/usr/share/man'
'--host=x86_64-pc-linux-gnu'
'--with-docdir=/usr/share/doc/postgresql-8.1.0' '--libdir=/usr/lib64'
'--enable-depend' '--with-tcl' '--with-python' '--with-perl'
'--with-openssl' '--enable-nls' '--with-CXX' '--with-pam' 'CFLAGS=-O2
-pipe -march=nocona -mtune=nocona' 'host_alias=x86_64-pc-linux-gnu'


This was built from the gentoo ebuild version 8.1.0

My kernel version is
Linux samir 2.6.13-gentoo-r5 #1 SMP Thu Nov 17 13:26:09 PST 2005 x86_64 Intel(R) Xeon(TM) CPU 3.00GHz GenuineIntel GNU/Linux

We also saw a similar error about a type not being found in the cache on
another box which has the same postgres version and platform, but was an
Opteron vs the EM64T Xeon, and was running a different project which also
used temp tables which were on commit drop.

I am sorry I could not provide an exact reproduction case, but this is
just one of those things that is too timing dependant to be able to do
that.

Let me know if you need any additional information and I will attempt to
provide it.


--
Half the world is composed of people who have something to say and can't,
and the other half who have nothing to say and keep on saying it.

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Jeremy Drake <pgsql@jdrake.com> writes:
> We have encountered a very nasty but apparently rare bug which appears to
> result in catalog corruption.

How much of this can you reproduce on 8.1.1? We've fixed a few issues
already.

> This was built from the gentoo ebuild version 8.1.0

I'd be even more interested if you can reproduce it on a non-gentoo
machine. Gentoo is not noted for stability.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

On Wed, 21 Dec 2005, Tom Lane wrote:

> Jeremy Drake <pgsql@jdrake.com> writes:
> > We have encountered a very nasty but apparently rare bug which appears to
> > result in catalog corruption.
>
> How much of this can you reproduce on 8.1.1? We've fixed a few issues
> already.

We did not see this problem for a while. I upgraded the second gentoo box
to show this problem to 8.1.1 basically as soon as the ebuild for it was
out. It just started acting up today (but we have not stressed it for a
while). It appears to be acting similarly (although corruption which
persisted into other backends has not appeared).

Here is the error message I currently get on 8.1.1 (names have been
changed):

DBD::Pg::st execute failed: ERROR: type "push_temp" already exists
CONTEXT: SQL statement "CREATE TEMPORARY TABLE push_temp (val text) ON
COMMIT DROP"
PL/pgSQL function "push_func" line 6 at SQL statement
DBD::Pg::st execute failed: ERROR: type "push_temp" already exists
CONTEXT: SQL statement "CREATE TEMPORARY TABLE push_temp (val text) ON
COMMIT DROP"
PL/pgSQL function "push_func" line 6 at SQL statement

postgres=# select version();
version
------------------------------------------------------------------------------------------------------------------------------------------
PostgreSQL 8.1.1 on x86_64-pc-linux-gnu, compiled by GCC
x86_64-pc-linux-gnu-gcc (GCC) 3.4.4 (Gentoo 3.4.4-r1, ssp-3.4.4-1.0,
pie-8.7.8)
(1 row)

>
> > This was built from the gentoo ebuild version 8.1.0
>
> I'd be even more interested if you can reproduce it on a non-gentoo
> machine. Gentoo is not noted for stability.

This one was also on Gentoo, this time ebuild version 8.1.1. They are
applying a couple patches it looks like, one of which looks like it just
changes some makefile stuff around, and the other appears to add support
for the SH platform in s_lock.h.

Unfortunately, I don't have any non-gentoo boxes around which are on a par
with these two hardware-wise. Also, I think my test cases I tried to come
up with were most likely wrong. This code which is currently croaking is
basically amounting to 9 processes calling functions which do SELECT,
INSERT, SELECT FOR UPDATE, DELETE, and UPDATE, as well as CREATE TEMP
TABLE ... ON COMMIT DROP. ON COMMIT DROP is the only kind of temp table
that this code uses.

I could probably try to re-arrange the code in such a way that I can send
it, if that would be helpful (although I wouldn't want to waste the effort
if it wouldn't be helpful).

Also, what do you figure are the chances of that plperl locale problem
causing this? I would guess pretty slim seeing as I am only using ASCII
for my schemas, and all of my databases are SQL_ASCII. I am calling
plperl functions in both of the projects which are breaking... Also, if I
run the command 'locale' all of the things it prints out are either empty
or "POSIX"

--
Take your dying with some seriousness, however. Laughing on the way to
your execution is not generally understood by less advanced life forms,
and they'll call you crazy.
-- "Messiah's Handbook: Reminders for the Advanced Soul"

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Jeremy Drake <pgsql@jdrake.com> writes:
>>> We have encountered a very nasty but apparently rare bug which appears to
>>> result in catalog corruption.

I've been fooling around with this report today. In several hours of
trying, I've been able to get one Assert failure from running Jeremy's
example on CVS tip. (I would've given up long ago, except the Assert
happened very soon after I started trying...) The assert was from this
line in hio.c:

Assert(PageIsNew((PageHeader) pageHeader));

which we've seen before in connection with the
vacuum-vs-relation-extension race condition found last May. It seems
we still have an issue of that sort :-(.

While fruitlessly waiting for the test to fail again, I've been combing
through the code looking for possible failure paths, and I've found
something that might explain it. I think this is definitely a bug even
if it isn't what's happening in Jeremy's test:

mdread() is defined to not fail, but silently return a page of zeroes,
if asked to read a page that's at or beyond the end of the table file.
(As noted therein, this seems like pretty sucky design, but there are
various reasons that make it hard to change the behavior.)

Therefore, if for some reason a process tries to read the page just at
EOF, it will leave behind a buffer pool entry that is marked BM_VALID
but contains zeroes. There are a number of scenarios that could cause
this, but all seem rather low-probability. One way is if a process'
rd_targblock field for a relation is pointing at the last page of the
file and then VACUUM comes along and truncates off that page because
it's empty. The next insertion attempt by the process will try to
fetch that page, obtain all-zeroes, decide the page has no free space
(PageGetFreeSpace is carefully coded to be sure that happens), and
go looking for free space elsewhere.

Now suppose someone tries to obtain a new page in the relation by
calling ReadBuffer(rel, P_NEW). The location of the new page is
determined by asking lseek() how long the file is. ReadBuffer then
obtains a buffer for that file offset --- and it is going to get a
hit on the all-zeroes buffer previously left behind. Since the buffer
is marked BM_VALID, the test "if it was already in the buffer pool,
we're done" succeeds and the buffer is returned as-is. This is fine
as far as the caller knows: it's expecting to get back an all-zero
page, so it goes merrily along. The problem is that if that code
path is taken, we *have not extended the file on disk*.

That means, until we get around to writing the dirty buffer to disk
(eg via checkpoint), the kernel thinks the file doesn't contain that
block yet. So if someone else comes along and again does
ReadBuffer(rel, P_NEW), the lseek computation will return the same
offset as before, and we'll wind up handing back the very same buffer
as before. Now we get the above-mentioned Assert, if we are lucky
enough to be running an assert-enabled build. Otherwise the code
in hio.c will just wipe and reinitialize the page, leading to loss
of whatever rows were previously placed in it.

Based on this analysis, the logic in ReadBuffer is wrong: if it finds
an existing buffer in the P_NEW case, it still has to zero the page
and do smgrextend() to be sure that the kernel thinks the page has
been added to the file.

I'm also thinking that the test for empty page in hio.c ought to be
an actual test and elog, not just an Assert. Now that we've seen
two different bugs allowing the "can't happen" case to happen, I'm no
longer satisfied with not having any check there in a non-assert build.
The consequences of not detecting an overwrite are too severe.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Here is some additional information that I have managed to gather today
regarding this. It is not really what causes it, so much as what does
not.

I removed all plperl from the loading processes. I did a VACUUM FULL
ANALYZE, and then I reindexed everything in the database (Including
starting the backend in standalone mode and running REINDEX SYSTEM
dbname). They still failed.

So it is apparently not that plperl issue which was being discussed
earlier.

Also, what I said about the corruption not having persisted into other
backends was not quite correct. It was leaving behind types in pg_type
which were in some of the pg_temp* schemas which corresponded to some of
the temp tables. But I took those out and still had issues (slightly
different).

Here is some interesting stuff too. I just stopped my processes to start
up a batch again to copy the error message I got now, but before doing so
I was doing a VACUUM FULL ANALYZE VERBOSE so I could hopefully start from
a relatively clean state. I got a few warnings I don't remember seeing
before.

INFO: vacuuming "pg_catalog.pg_shdepend"
INFO: "pg_shdepend": found 108 removable, 440 nonremovable row versions
in 15 p
ages
DETAIL: 0 dead row versions cannot be removed yet.
Nonremovable row versions range from 53 to 53 bytes long.
There were 1492 unused item pointers.
Total free space (including removable row versions) is 89780 bytes.
7 pages are or will become empty, including 0 at the end of the table.
12 pages containing 89744 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "pg_shdepend_depender_index" now contains 448 row versions in
33 pages
DETAIL: 108 index row versions were removed.
23 index pages have been deleted, 23 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.10 sec.
WARNING: index "pg_shdepend_depender_index" contains 448 row versions,
but table contains 440 row versions
HINT: Rebuild the index with REINDEX.
INFO: index "pg_shdepend_reference_index" now contains 448 row versions
in 12 pages
DETAIL: 108 index row versions were removed.
3 index pages have been deleted, 3 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
WARNING: index "pg_shdepend_reference_index" contains 448 row versions,
but table contains 440 row versions
HINT: Rebuild the index with REINDEX.
INFO: "pg_shdepend": moved 4 row versions, truncated 15 to 4 pages
DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "pg_shdepend_depender_index" now contains 448 row versions in
33 pages
DETAIL: 4 index row versions were removed.
23 index pages have been deleted, 23 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
WARNING: index "pg_shdepend_depender_index" contains 448 row versions,
but table contains 440 row versions
HINT: Rebuild the index with REINDEX.
INFO: index "pg_shdepend_reference_index" now contains 448 row versions
in 12 pages
DETAIL: 4 index row versions were removed.
4 index pages have been deleted, 4 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
WARNING: index "pg_shdepend_reference_index" contains 448 row versions,
but table contains 440 row versions
HINT: Rebuild the index with REINDEX.
INFO: analyzing "pg_catalog.pg_shdepend"
INFO: "pg_shdepend": scanned 4 of 4 pages, containing 440 live rows and 0
dead rows; 440 rows in sample, 440 estimated total rows



Similar for pg_type, there being 248 index row versions vs 244 row
versions in the table.

1631 vs 1619 in pg_attribute
95 vs 94 in pg_index


Looks like it may be time to start a standalone backend and REINDEX
again...

--
Don't smoke the next cigarette. Repeat.

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Jeremy Drake <pgsql@jdrake.com> writes:
> Here is some additional information that I have managed to gather today
> regarding this. It is not really what causes it, so much as what does
> not.
> ...
> Similar for pg_type, there being 248 index row versions vs 244 row
> versions in the table.

The ReadBuffer bug I just fixed could result in disappearance of catalog
rows, so this observation is consistent with the theory that that's
what's biting you. It's not proof though...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

On Thu, 5 Jan 2006, Tom Lane wrote:

> The ReadBuffer bug I just fixed could result in disappearance of catalog
> rows, so this observation is consistent with the theory that that's
> what's biting you. It's not proof though...

Well, I applied that patch that you sent me the link to (the bufmgr.c
one), and rebuilt (PORTDIR_OVERLAY is cool...)

I ran my nine processes which hammer things overnight, and in the
morning one of them was dead.

DBD::Pg::st execute failed: ERROR: duplicate key violates unique
constraint "pg_type_typname_nsp_index"
CONTEXT: SQL statement "CREATE TEMPORARY TABLE push_tmp (val text) ON
COMMIT DROP"
PL/pgSQL function "push_func" line 6 at SQL statement
DBD::Pg::st execute failed: ERROR: duplicate key violates unique
constraint "pg_type_typname_nsp_index"
CONTEXT: SQL statement "CREATE TEMPORARY TABLE push_tmp (val text) ON
COMMIT DROP"
PL/pgSQL function "push_func" line 6 at SQL statement


I also write out the time as my processes progress, so I know roughly when
it happened too. It happened at 1136534029 (that's result of perl time()
function), which when run through localtime() yields Thu Jan 5 23:53:49
2006. It looks like I started the processes at about 18:30, so they
lasted a while at least.

Let me know if there is anything else I can try to help debug this
(asserts on?).

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Jeremy Drake <pgsql@jdrake.com> writes:
> Well, I applied that patch that you sent me the link to (the bufmgr.c
> one), and rebuilt (PORTDIR_OVERLAY is cool...)

> I ran my nine processes which hammer things overnight, and in the
> morning one of them was dead.

> DBD::Pg::st execute failed: ERROR: duplicate key violates unique
> constraint "pg_type_typname_nsp_index"

Hm, did you REINDEX things beforehand? This could be leftover corruption...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

On Fri, 6 Jan 2006, Tom Lane wrote:

> Jeremy Drake <pgsql@jdrake.com> writes:
> > Well, I applied that patch that you sent me the link to (the bufmgr.c
> > one), and rebuilt (PORTDIR_OVERLAY is cool...)
>
> > I ran my nine processes which hammer things overnight, and in the
> > morning one of them was dead.
>
> > DBD::Pg::st execute failed: ERROR: duplicate key violates unique
> > constraint "pg_type_typname_nsp_index"
>
> Hm, did you REINDEX things beforehand? This could be leftover corruption...

Yes. I ran that VACUUM FULL ANALYZE VERBOSE which I emailed part of the
excerpt from, and then I started a standalone backend (postgres -D data
-P) and ran REINDEX SYSTEM dbname on the database in question.

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

Jeremy Drake <pgsql@jdrake.com> writes:
>>> DBD::Pg::st execute failed: ERROR: duplicate key violates unique
>>> constraint "pg_type_typname_nsp_index"
>>
>> Hm, did you REINDEX things beforehand? This could be leftover corruption...

> Yes. I ran that VACUUM FULL ANALYZE VERBOSE which I emailed part of the
> excerpt from, and then I started a standalone backend (postgres -D data
> -P) and ran REINDEX SYSTEM dbname on the database in question.

OK, this must be a different issue then. I think we have seen reports
like this one before, but not been able to reproduce it.

Could you rebuild with Asserts enabled and see if any asserts trigger?
Also, at this point it'd be worth trying to boil it down to a test case
you can give to other people.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly