Cache invalidation bug in RelationGetIndexAttrBitmap()
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
On 2014-05-14 15:08:08 +0200, Tomas Vondra wrote:
Apparently there's something wrong with 'test-decoding-check':
Man. I shouldn't have asked... My code. There's some output in there
that's probably triggered by the extraordinarily long runtimes, but
there's definitely something else wrong.
My gut feeling says it's in RelationGetIndexList().
Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
Tomas, thanks for that. I've never (and probably will never) run
CLOBBER_CACHE_RECURSIVELY during development. Having a machine do that
regularly is really helpful. How long does a single testrun take? It
takes hundreds of seconds here to do a single UPDATE?
There were some more differences but those are all harmless and caused
by the extraordinarily long runtime (autovacuums). I think we need to
add a feature to test_decoding to suppress displaying transactions
without changes. Ick.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
Attachments:
0001-Fix-cache-invalidation-hazard-in-RelationGetIndexAtt.patchtext/x-patch; charset=us-asciiDownload
>From 9dfe879d2b6940b6072e277b0104e9cbe4af691e Mon Sep 17 00:00:00 2001
From: Andres Freund <andres@anarazel.de>
Date: Wed, 14 May 2014 17:12:57 +0200
Subject: [PATCH] Fix cache invalidation hazard in
RelationGetIndexAttrBitmap().
When a cache invalidation arrived inside RelationGetIndexAttrBitmap()
inbetween the call to RelationGetIndexList() and one of the
index_open() calls relation->rd_replidindex would be reset leading to
a corrupted INDEX_ATTR_BITMAP_IDENTITY_KEY return value. That in turn
could lead to the old REPLICA IDENTITY not being logged if set to
DEFAULT or INDEX.
---
src/backend/utils/cache/relcache.c | 9 ++++++++-
1 file changed, 8 insertions(+), 1 deletion(-)
diff --git a/src/backend/utils/cache/relcache.c b/src/backend/utils/cache/relcache.c
index 5ff0d9e..4fc18b5 100644
--- a/src/backend/utils/cache/relcache.c
+++ b/src/backend/utils/cache/relcache.c
@@ -3976,6 +3976,7 @@ RelationGetIndexAttrBitmap(Relation relation, IndexAttrBitmapKind attrKind)
List *indexoidlist;
ListCell *l;
MemoryContext oldcxt;
+ Oid relreplindex;
/* Quick exit if we already computed the result. */
if (relation->rd_indexattr != NULL)
@@ -4005,6 +4006,12 @@ RelationGetIndexAttrBitmap(Relation relation, IndexAttrBitmapKind attrKind)
return NULL;
/*
+ * Store after computing the index list above, to be safe against cache
+ * flushes inside index_open() below.
+ */
+ relreplindex = relation->rd_replidindex;
+
+ /*
* For each index, add referenced attributes to indexattrs.
*
* Note: we consider all indexes returned by RelationGetIndexList, even if
@@ -4038,7 +4045,7 @@ RelationGetIndexAttrBitmap(Relation relation, IndexAttrBitmapKind attrKind)
indexInfo->ii_Predicate == NIL;
/* Is this index the configured (or default) replica identity? */
- isIDKey = indexOid == relation->rd_replidindex;
+ isIDKey = indexOid == relreplindex;
/* Collect simple attribute references */
for (i = 0; i < indexInfo->ii_NumIndexAttrs; i++)
--
2.0.0.rc2.4.g1dc51c6.dirty
Andres Freund <andres@2ndquadrant.com> writes:
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
My gut feeling says it's in RelationGetIndexList().
Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
TBH, I don't believe this patch at all. Where exactly is rd_replidindex
reset? If it's supposed to have similar lifespan to, say, rd_oidindex,
why isn't it being handled like rd_oidindex? And why does the header
comment for RelationGetIndexList make no mention of this new side-effect?
Somebody did a seriously poor job of adding this functionality to
relcache.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 2014-05-14 12:15:27 -0400, Tom Lane wrote:
Andres Freund <andres@2ndquadrant.com> writes:
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
My gut feeling says it's in RelationGetIndexList().
Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
TBH, I don't believe this patch at all. Where exactly is rd_replidindex
reset? If it's supposed to have similar lifespan to, say, rd_oidindex,
why isn't it being handled like rd_oidindex?
I don't see why it'd have a different lifespan than rd_oidindex at all?
If the latter were used inside the loop it'd be a bug as well.
And why does the header
comment for RelationGetIndexList make no mention of this new side-effect?
Somebody did a seriously poor job of adding this functionality to
relcache.
It's not like it's not documented: There's a comment about it in struct
RelationData. I must have missed that rd_oidindex has a comment abou
it's lifetime over RelationGetIndexList().
I personally actually prefer the struct as the location for the
lifetime. I can send a patch to commonalize the location in either place
with the other location pointing to it.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Andres Freund <andres@2ndquadrant.com> writes:
On 2014-05-14 12:15:27 -0400, Tom Lane wrote:
And why does the header
comment for RelationGetIndexList make no mention of this new side-effect?
Somebody did a seriously poor job of adding this functionality to
relcache.
It's not like it's not documented: There's a comment about it in struct
RelationData. I must have missed that rd_oidindex has a comment abou
it's lifetime over RelationGetIndexList().
If rd_replidindex is being managed like rd_oidindex, then it should be
managed just like rd_oidindex, including getting reset in all the places
rd_oidindex is. This might be just a matter of cleanliness but I think
it's important for readability and debuggability.
I notice also that rd_keyattr and rd_idattr have been implemented with
bad copies of the logic for rd_indexattr. This is at least leading
to a permanent memory leak in CacheMemoryContext during every relcache
flush, and maybe worse things. The bugs for rd_keyattr appear to predate
your patch though.
Working on a patch for this now. One thing I'm wondering about is
RelationSetIndexList. It's probably okay for it not to touch rd_keyattr
and rd_idattr, but I'm not too clear on what the use cases for those
attnum sets are.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 2014-05-14 13:32:43 -0400, Tom Lane wrote:
Andres Freund <andres@2ndquadrant.com> writes:
On 2014-05-14 12:15:27 -0400, Tom Lane wrote:
And why does the header
comment for RelationGetIndexList make no mention of this new side-effect?
Somebody did a seriously poor job of adding this functionality to
relcache.It's not like it's not documented: There's a comment about it in struct
RelationData. I must have missed that rd_oidindex has a comment abou
it's lifetime over RelationGetIndexList().If rd_replidindex is being managed like rd_oidindex, then it should be
managed just like rd_oidindex, including getting reset in all the places
rd_oidindex is. This might be just a matter of cleanliness but I think
it's important for readability and debuggability.
Agreed. I am not against resetting it. I think I might not have been
aware of rd_oidindex when writing that code...
I notice also that rd_keyattr and rd_idattr have been implemented with
bad copies of the logic for rd_indexattr. This is at least leading
to a permanent memory leak in CacheMemoryContext during every relcache
flush, and maybe worse things. The bugs for rd_keyattr appear to predate
your patch though.
Hm. Yes, the bitmapsets should be freed. I guess I copied the logic for
keyattr and didn't find any relevant places that touch it. rd_keyattr
should go back to 9.3.
Working on a patch for this now. One thing I'm wondering about is
RelationSetIndexList. It's probably okay for it not to touch rd_keyattr
and rd_idattr, but I'm not too clear on what the use cases for those
attnum sets are.
rd_keyattr is used to determine whether a heap_update() changed any keys
that could be referenced by a foreign key. That's then used to determine
which locklevel an update requires.
rd_idattr does something similar. It decides whether the configured
REPLICA IDENTITY key has changed so whether to log the old primary key
for logical decoding or not.
I can't see why either would need to care about forced index lists right
now, but will do a scan of the sources to see if I am wrong.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 14.5.2014 17:52, Andres Freund wrote:
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
On 2014-05-14 15:08:08 +0200, Tomas Vondra wrote:
Apparently there's something wrong with 'test-decoding-check':
Man. I shouldn't have asked... My code. There's some output in there
that's probably triggered by the extraordinarily long runtimes, but
there's definitely something else wrong.
My gut feeling says it's in RelationGetIndexList().Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
Tomas, thanks for that. I've never (and probably will never) run
CLOBBER_CACHE_RECURSIVELY during development. Having a machine do that
regularly is really helpful. How long does a single testrun take? It
takes hundreds of seconds here to do a single UPDATE?
Don't know yet, as it fails at the beginning. But I suppose it will be
tens or possibly hundreds of hours. For example these are the logs from
regular build (no clobber etc.)
May 14 19:00 SCM-checkout.log
May 14 19:00 githead.log
May 14 19:00 configure.log
May 14 19:00 config.log
May 14 19:05 make.log
May 14 19:05 check.log
May 14 19:06 make-contrib.log
May 14 19:06 make-install.log
May 14 19:06 install-contrib.log
May 14 19:07 check-pg_upgrade.log
May 14 19:08 test-decoding-check.log
while these are the logs from recursive clobber:
May 14 00:19 SCM-checkout.log
May 14 00:20 configure.log
May 14 00:20 config.log
May 14 00:26 make.log
May 14 03:12 check.log
May 14 03:13 make-contrib.log
May 14 03:13 make-install.log
May 14 03:13 install-contrib.log
May 14 08:25 check-pg_upgrade.log
May 14 09:07 test-decoding-check.log
May 14 09:07 web-txn.data
So with the regular build, it took <1 minute to do 'make check' and ~1
minute to test pg_upgrade, with recursive clobber it takes ~3 hours and
~5 hours. That's a factor of ~300, although it's a very rough estimate.
Without clobber the whole run (for a "C" locale) takes ~10 minutes, so
my estimate is ~50 hours for the recursive one. But I wouldn't be
surprised by 100 hours.
There were some more differences but those are all harmless and caused
by the extraordinarily long runtime (autovacuums). I think we need to
add a feature to test_decoding to suppress displaying transactions
without changes. Ick.
I expect to hit more timing-related issues with the recursive clobber
tests - not necessarily in the code/tests itself, but I guess the
buildfarm tooling doesn't really expect runs that long.
regards
Tomas
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Hi,
On 2014-05-14 21:04:41 +0200, Tomas Vondra wrote:
On 14.5.2014 17:52, Andres Freund wrote:
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
On 2014-05-14 15:08:08 +0200, Tomas Vondra wrote:
Apparently there's something wrong with 'test-decoding-check':
Man. I shouldn't have asked... My code. There's some output in there
that's probably triggered by the extraordinarily long runtimes, but
there's definitely something else wrong.
My gut feeling says it's in RelationGetIndexList().Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
Tomas, thanks for that. I've never (and probably will never) run
CLOBBER_CACHE_RECURSIVELY during development. Having a machine do that
regularly is really helpful. How long does a single testrun take? It
takes hundreds of seconds here to do a single UPDATE?Don't know yet, as it fails at the beginning.
test decoding is at the beginning? That's somewhat odd?
But I suppose it will be
tens or possibly hundreds of hours. For example these are the logs from
regular build (no clobber etc.)
May 14 19:00 SCM-checkout.log
May 14 19:00 githead.log
May 14 19:00 configure.log
May 14 19:00 config.log
May 14 19:05 make.log
May 14 19:05 check.log
May 14 19:06 make-contrib.log
May 14 19:06 make-install.log
May 14 19:06 install-contrib.log
May 14 19:07 check-pg_upgrade.log
May 14 19:08 test-decoding-check.logwhile these are the logs from recursive clobber:
May 14 00:19 SCM-checkout.log
May 14 00:20 configure.log
May 14 00:20 config.log
May 14 00:26 make.log
May 14 03:12 check.log
May 14 03:13 make-contrib.log
May 14 03:13 make-install.log
May 14 03:13 install-contrib.log
May 14 08:25 check-pg_upgrade.log
May 14 09:07 test-decoding-check.log
May 14 09:07 web-txn.dataSo with the regular build, it took <1 minute to do 'make check' and ~1
minute to test pg_upgrade, with recursive clobber it takes ~3 hours and
~5 hours. That's a factor of ~300, although it's a very rough
estimate.
I seriously doubt that's recursive clobber. That should take *way* much
longer. And indeed you have:
-DCLOBBER_CACHE_ALWAYS -DCLOBBER_FREED_MEMORY -DMEMORY_CONTEXT_CHECKING
-DRANDOMIZE_ALLOCATED_MEMORY -DCLOBBER_CACHE_RECURSIVELYit does not happen with
CPPFLAGS => '-DCLOBBER_CACHE_ALWAYS -DCLOBBER_FREED_MEMORY
-DMEMORY_CONTEXT_CHECKING -DRANDOMIZE_ALLOCATED_MEMORY',
#if defined(CLOBBER_CACHE_ALWAYS)
{
static bool in_recursion = false;
if (!in_recursion)
{
in_recursion = true;
InvalidateSystemCaches();
in_recursion = false;
}
}
#elif defined(CLOBBER_CACHE_RECURSIVELY)
InvalidateSystemCaches();
#endif
i.e. you can't specifiy -DCLOBBER_CACHE_ALWAYS and
-DCLOBBER_CACHE_RECURSIVELY together. The former will take precedence.
Without clobber the whole run (for a "C" locale) takes ~10 minutes, so
my estimate is ~50 hours for the recursive one. But I wouldn't be
surprised by 100 hours.
I'm afraid it's more in the year range from what i've seen. I.e. not
practical.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 14.5.2014 22:29, Andres Freund wrote:
Hi,
On 2014-05-14 21:04:41 +0200, Tomas Vondra wrote:
On 14.5.2014 17:52, Andres Freund wrote:
On 2014-05-14 15:17:39 +0200, Andres Freund wrote:
On 2014-05-14 15:08:08 +0200, Tomas Vondra wrote:
Apparently there's something wrong with 'test-decoding-check':
Man. I shouldn't have asked... My code. There's some output in there
that's probably triggered by the extraordinarily long runtimes, but
there's definitely something else wrong.
My gut feeling says it's in RelationGetIndexList().Nearly right. It's in RelationGetIndexAttrBitmap(). Fix attached.
Tomas, thanks for that. I've never (and probably will never) run
CLOBBER_CACHE_RECURSIVELY during development. Having a machine do that
regularly is really helpful. How long does a single testrun take? It
takes hundreds of seconds here to do a single UPDATE?Don't know yet, as it fails at the beginning.
test decoding is at the beginning? That's somewhat odd?
Judging from the timestamps of log files, it seems to be running after
pg_upgrade checks. Or maybe I'm reading that wrong.
But I suppose it will be
tens or possibly hundreds of hours. For example these are the logs from
regular build (no clobber etc.)May 14 19:00 SCM-checkout.log
May 14 19:00 githead.log
May 14 19:00 configure.log
May 14 19:00 config.log
May 14 19:05 make.log
May 14 19:05 check.log
May 14 19:06 make-contrib.log
May 14 19:06 make-install.log
May 14 19:06 install-contrib.log
May 14 19:07 check-pg_upgrade.log
May 14 19:08 test-decoding-check.logwhile these are the logs from recursive clobber:
May 14 00:19 SCM-checkout.log
May 14 00:20 configure.log
May 14 00:20 config.log
May 14 00:26 make.log
May 14 03:12 check.log
May 14 03:13 make-contrib.log
May 14 03:13 make-install.log
May 14 03:13 install-contrib.log
May 14 08:25 check-pg_upgrade.log
May 14 09:07 test-decoding-check.log
May 14 09:07 web-txn.dataSo with the regular build, it took <1 minute to do 'make check' and ~1
minute to test pg_upgrade, with recursive clobber it takes ~3 hours and
~5 hours. That's a factor of ~300, although it's a very rough
estimate.I seriously doubt that's recursive clobber. That should take *way* much
longer. And indeed you have:-DCLOBBER_CACHE_ALWAYS -DCLOBBER_FREED_MEMORY -DMEMORY_CONTEXT_CHECKING
-DRANDOMIZE_ALLOCATED_MEMORY -DCLOBBER_CACHE_RECURSIVELYit does not happen with
CPPFLAGS => '-DCLOBBER_CACHE_ALWAYS -DCLOBBER_FREED_MEMORY
-DMEMORY_CONTEXT_CHECKING -DRANDOMIZE_ALLOCATED_MEMORY',#if defined(CLOBBER_CACHE_ALWAYS)
{
static bool in_recursion = false;if (!in_recursion)
{
in_recursion = true;
InvalidateSystemCaches();
in_recursion = false;
}
}
#elif defined(CLOBBER_CACHE_RECURSIVELY)
InvalidateSystemCaches();
#endifi.e. you can't specifiy -DCLOBBER_CACHE_ALWAYS and
-DCLOBBER_CACHE_RECURSIVELY together. The former will take precedence.
Oh, I see :-/
Without clobber the whole run (for a "C" locale) takes ~10 minutes, so
my estimate is ~50 hours for the recursive one. But I wouldn't be
surprised by 100 hours.I'm afraid it's more in the year range from what i've seen. I.e. not
practical.
Yeah, that wouldn't be very practical. I'll try to run it though and if
it'd run more than a few days, I'll switch it to CLOBBER_CACHE_ALWAYS.
Tomas
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Tomas Vondra <tv@fuzzy.cz> writes:
On 14.5.2014 22:29, Andres Freund wrote:
I'm afraid it's more in the year range from what i've seen. I.e. not
practical.
Yeah, that wouldn't be very practical. I'll try to run it though and if
it'd run more than a few days, I'll switch it to CLOBBER_CACHE_ALWAYS.
I think it might be interesting to try running CLOBBER_CACHE_RECURSIVELY
on some subset of the regression tests. But I'm not sure which subset,
nor whether the buildfarm scripts could readily be coaxed to do that.
Let's see how far you get with a full run before you get bored ...
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers