Re: BUG #5412: Crash in production SIGSEGV, equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x966508c4) at tupdesc.c

The following bug has been logged online:

Bug reference: 5412
Logged by: Rusty Conover
Email address: rconover(at)infogears(dot)com
PostgreSQL version: 8.4.3
Operating system: Fedora Core 10, 2.6.27.30-170.2.82.fc10.i686.PAE
Description: Crash in production SIGSEGV, equalTupleDescs
(tupdesc1=0x7f7f7f7f, tupdesc2=0x966508c4) at tupdesc.c
Details:

Hi,

8.4.3 is crashing for me under load, below is the stack trace:

#0 equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x966508c4) at
tupdesc.c:311
#1 0x0832451b in RelationClearRelation (relation=0x96654178, rebuild=<value
optimized out>) at relcache.c:1901
#2 0x08324b9f in RelationFlushRelation () at relcache.c:1991
#3 RelationCacheInvalidateEntry (relationId=322615) at relcache.c:2042
#4 0x0831dd89 in LocalExecuteInvalidationMessage (msg=0xa218b54) at
inval.c:510
#5 0x0831d341 in ProcessInvalidationMessages (hdr=0xa2010c4, func=0x831dc50
<LocalExecuteInvalidationMessage>) at inval.c:397
#6 0x0831d3dc in CommandEndInvalidationMessages () at inval.c:1006
#7 0x080c9035 in AtCommit_LocalCache () at xact.c:1009
#8 CommandCounterIncrement () at xact.c:634
#9 0x0826dcc9 in finish_xact_command () at postgres.c:2363
#10 0x0826ed4d in exec_simple_query (
query_string=0xa1e88d4 "insert into product_refer_urls (item_id,
destination_url) select product_info.oid, product_info_static.affiliate_url
from real_products, product_parts, product_info left join
product_info_static on ("...) at postgres.c:1022
#11 0x0827042c in PostgresMain (argc=4, argv=0xa17c5d0, username=0xa17c590
"gb") at postgres.c:3614
#12 0x0823a4d3 in BackendRun () at postmaster.c:3449
#13 BackendStartup () at postmaster.c:3063
#14 ServerLoop () at postmaster.c:1387
#15 0x0823b503 in PostmasterMain (argc=4, argv=0xa179678) at
postmaster.c:1040
#16 0x081dc0a6 in main (argc=4, argv=0xa179678) at main.c:188

The bug is reproducible, I'm not sure how to proceed. Here is the output
from the log:

LOG: server process (PID 8886) was terminated by signal 11: Segmentation
fault
LOG: terminating any other active server processes
WARNING: terminating connection because of crash of another server process

I have been seeing these messages:

LOG: autovacuum: found orphan temp table "pg_temp_7"."found_sizes" in
database "gb_render_footwear_db"
LOG: autovacuum: found orphan temp table "pg_temp_7"."classification_tree"
in database "gb_render_footwear_db"

Could they be the result of previous crashes? Any help is greatly
appreciated.

All of this code ran perfectly under 8.3.

Thanks,

Rusty

Rusty Conover wrote:
> The bug is reproducible, I'm not sure how to proceed.

How do you reproduce it? Can you make a self-contained test case?

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

On Apr 9, 2010, at 2:23 PM, Heikki Linnakangas wrote:

> Rusty Conover wrote:
>> The bug is reproducible, I'm not sure how to proceed.
>
> How do you reproduce it? Can you make a self-contained test case?
>

I can reproduce it by running my code, I haven't found a good test case yet because the bug seems to depend on an interaction between postgres processes.

I have about 12 different db sessions creating temporary tables with the same name them dropping them very quickly in the same database. While other processes are just running queries in other databases. The process that is crashing isn't one of the processes that is creating and dropping temporary tables, its completely separate in a different database.

Here a new crash from today with the same trace:

#0 equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x9661e430) at tupdesc.c:311
311 if (tupdesc1->natts != tupdesc2->natts)
(gdb) bt
#0 equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x9661e430) at tupdesc.c:311
#1 0x0832451b in RelationClearRelation (relation=0x96617200, rebuild=<value optimized out>) at relcache.c:1901
#2 0x08324b9f in RelationFlushRelation () at relcache.c:1991
#3 RelationCacheInvalidateEntry (relationId=276951) at relcache.c:2042
#4 0x0831dd89 in LocalExecuteInvalidationMessage (msg=0xa21c328) at inval.c:510
#5 0x0831d341 in ProcessInvalidationMessages (hdr=0xa2075fc, func=0x831dc50 <LocalExecuteInvalidationMessage>)
at inval.c:397
#6 0x0831d3dc in CommandEndInvalidationMessages () at inval.c:1006
#7 0x080c9035 in AtCommit_LocalCache () at xact.c:1009
#8 CommandCounterIncrement () at xact.c:634
#9 0x0826dcc9 in finish_xact_command () at postgres.c:2363
#10 0x0826ed4d in exec_simple_query (
query_string=0xa1e89ec "insert into pch_oid_archive (url, product_name, oid) select product_combined_history_names.url, product_combined_history_names.product_name, product_info.oid from product_info, product_combined_histor"...)
at postgres.c:1022
#11 0x0827042c in PostgresMain (argc=4, argv=0xa17c740, username=0xa17c700 "gb") at postgres.c:3614
#12 0x0823a4d3 in BackendRun () at postmaster.c:3449
#13 BackendStartup () at postmaster.c:3063
#14 ServerLoop () at postmaster.c:1387
#15 0x0823b503 in PostmasterMain (argc=4, argv=0xa179678) at postmaster.c:1040
#16 0x081dc0a6 in main (argc=4, argv=0xa179678) at main.c:188
(gdb)

Thanks,

Rusty
-
Rusty Conover
rconover(at)infogears(dot)com
InfoGears Inc / GearBuyer.com / FootwearBuyer.com
http://www.infogears.com
http://www.gearbuyer.com
http://www.footwearbuyer.com

Hi Heikki and everybody else,

It seems like this is a race condition cause by the system catalog cache not being locked properly. I've included a perl script below that causes the crash on my box consistently.

The script forks two different types of processes:

#1 - begin transaction, create a few temp tables and analyze them in a transaction, commit (running in database foobar_1)
#2 - begin transaction, truncate table, insert records into table from select in a transaction, commit (running in database foobar_2)

I setup the process to have 10 instances of task #1 and 1 instance of task #2.

Running this script causes the crash of postgres within seconds on my box.

If you change the parameters to say <6 of task #1, no crash happens, but if you have >7 the crash does happen.

The box that I'm running the script on has 8 cores, so CPU contention and some improper locking might cause some of the problem.

The specs of the box are:

Fedora release 10 (Cambridge)
Intel(R) Xeon(R) CPU E5420 @ 2.50GHz
glibc-2.9-3.i686
Linux 2.6.27.30-170.2.82.fc10.i686.PAE #1 SMP Mon Aug 17 08:24:23 EDT 2009 i686 i686 i386 GNU/Linux
PostgreSQL: 8.4.3

I tried to reproduce it on one of my 16-core x64 boxes and the same crash doesn't occur, also I tried on a dual core box and couldn't get a crash but I haven't exhaustively tested the right number of parameters for task #1.

If the script doesn't cause a crash for you please try changing the variable $total_job_1_children to be a greater number then the number of CPU cores of the machine that you're running it on.

Any help would be appreciated and if I can be of further assistance please let me know,

Rusty
--
Rusty Conover
rconover(at)infogears(dot)com
InfoGears Inc / GearBuyer.com / FootwearBuyer.com
http://www.infogears.com
http://www.gearbuyer.com
http://www.footwearbuyer.com

#!/usr/bin/perl
use strict;
use warnings;
use DBI;
use POSIX ":sys_wait_h";

# Number of children for job1, create temp tables and analyze them

# The number of jobs here matters: (on my 8 core box you need to have some contention to get a failure)
# >11=fail
# 10=fail
# 9=fail
# 8=fail
# 7=fail
# <6 works,
my $total_job_1_children = 11;

# Number of children for job 2 run a truncate and insert query loop.
# we only need one of these jobs to be running really, because the truncate locks.
my $total_job_2_children = 1;

# Just need two databases on your machine, foobar_1 and foobar_2 are the defaults.
my $database_1_dsn = ['dbi:Pg:dbname=foobar_1', 'postgres'];
my $database_2_dsn = ['dbi:Pg:dbname=foobar_2', 'postgres'];

# Do some setup transactions.
if(1) {
my $dbh = DBI->connect(@$database_2_dsn);

$dbh->do("drop table foo_dest");
$dbh->do("drop table foobar_source");
$dbh->begin_work();
eval {
$dbh->do("create table foobar_source (id integer, name text, size integer)") || die("Failed to create foobar_source: " . $dbh->errstr());
for(my $k = 0; $k < 3500; $k++) {
$dbh->do("insert into foobar_source (id, name, size) values (?, 'test me', ?)", undef, $k, int(rand(400000))) || die("Failed to insert into foobar_source: " . $dbh->errstr());
}

$dbh->do("analyze foobar_source");

$dbh->do("create table foo_dest (id integer, name text, size integer)");
};
if($@) {
print "Error doing init of tables: " . $@ . "\n";
$dbh->rollback();
$dbh->disconnect();
exit(0);
}

$dbh->commit();
$dbh->disconnect();
}

my @child_pids;

for(my $i =0; $i < $total_job_1_children; $i++) {
print "Forking\n";
my $pid = fork();
if($pid == 0) {
run_child('job1');
exit(0);
} else {
push @child_pids, $pid;
}
}

for(my $i =0; $i < $total_job_2_children; $i++) {
print "Forking\n";
my $pid = fork();
if($pid == 0) {
run_child('job2');
exit(0);
} else {
push @child_pids, $pid;
}
}

foreach my $pid (@child_pids) {
print "Waiting for $pid\n";
waitpid($pid, 0);
print "Got it\n";
}
exit(0);

sub run_child {
my $job_type = shift;
my $dsn;
if($job_type eq 'job1') {
$dsn = $database_1_dsn;
} else {
$dsn = $database_2_dsn;
}
my $dbh = DBI->connect(@$dsn);
defined($dbh) || die("Failed to get connection to database");

for(my $i =0; $i < 400; $i++) {

$dbh->begin_work();
eval {

if($job_type eq 'job1') {
$dbh->{Warn} = 0;
$dbh->do("create temp table c_products (id INTEGER NOT NULL, product_name_stemmed text, average_price numeric(12,2), cset_bitmap bit(437), gender text) WITHOUT OIDS ON COMMIT DROP");
$dbh->do("create temp table c_products_oids (c_products_id INTEGER NOT NULL, oid INTEGER NOT NULL UNIQUE, price numeric(12,2) not null, product_name_stemmed text not null) WITHOUT OIDS ON COMMIT DROP");
$dbh->{Warn} = 1;

$dbh->do("analyze c_products");
$dbh->do("analyze c_products_oids");
} else {
$dbh->do("truncate table foo_dest");
$dbh->do("insert into foo_dest (id, name, size) select id, name, size from foobar_source");
}
};
if($@) {
print "Got error in job $job_type: $(at)\n";
$dbh->rollback();
$dbh->disconnect();
exit(0);
}

$dbh->commit();
}
$dbh->disconnect();
print "Child finished\n";
return;
}

Rusty Conover wrote:
> It seems like this is a race condition cause by the system catalog cache not being locked properly. I've included a perl script below that causes the crash on my box consistently.
>
> The script forks two different types of processes:
>
> #1 - begin transaction, create a few temp tables and analyze them in a transaction, commit (running in database foobar_1)
> #2 - begin transaction, truncate table, insert records into table from select in a transaction, commit (running in database foobar_2)
>
> I setup the process to have 10 instances of task #1 and 1 instance of task #2.
>
> Running this script causes the crash of postgres within seconds on my box.

Thanks, that script crashes on my laptop too, with assertions enabled.

According to the comments above RelationClearRelation(), if it's called
with 'rebuild=true', the caller should hold a lock on the relation, i.e
refcnt > 0. That's not the case in RelationFlushRelation() when it
rebuilds a new relcache entry.

Attached patch should fix that, by incrementing the reference count
while the entry is rebuilt. It also adds an Assertion in
RelationClearRelation() to check that the refcnt is indeed > 0.
Comments?

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

On Apr 14, 2010, at 7:10 AM, Heikki Linnakangas wrote:

> Rusty Conover wrote:
>> It seems like this is a race condition cause by the system catalog cache not being locked properly. I've included a perl script below that causes the crash on my box consistently.
>>
>> The script forks two different types of processes:
>>
>> #1 - begin transaction, create a few temp tables and analyze them in a transaction, commit (running in database foobar_1)
>> #2 - begin transaction, truncate table, insert records into table from select in a transaction, commit (running in database foobar_2)
>>
>> I setup the process to have 10 instances of task #1 and 1 instance of task #2.
>>
>> Running this script causes the crash of postgres within seconds on my box.
>
> Thanks, that script crashes on my laptop too, with assertions enabled.
>
> According to the comments above RelationClearRelation(), if it's called
> with 'rebuild=true', the caller should hold a lock on the relation, i.e
> refcnt > 0. That's not the case in RelationFlushRelation() when it
> rebuilds a new relcache entry.
>
> Attached patch should fix that, by incrementing the reference count
> while the entry is rebuilt. It also adds an Assertion in
> RelationClearRelation() to check that the refcnt is indeed > 0.
> Comments?

Hi Heikki,

This patch allows my machine to run the script without crashing, so its working for me as well.

Many thanks,

Rusty
--
Rusty Conover
rconover(at)infogears(dot)com
InfoGears Inc / GearBuyer.com / FootwearBuyer.com
http://www.infogears.com
http://www.gearbuyer.com
http://www.footwearbuyer.com

Heikki Linnakangas <heikki(dot)linnakangas(at)enterprisedb(dot)com> writes:
> According to the comments above RelationClearRelation(), if it's called
> with 'rebuild=true', the caller should hold a lock on the relation, i.e
> refcnt > 0. That's not the case in RelationFlushRelation() when it
> rebuilds a new relcache entry.

> Attached patch should fix that, by incrementing the reference count
> while the entry is rebuilt. It also adds an Assertion in
> RelationClearRelation() to check that the refcnt is indeed > 0.
> Comments?

Why would this patch fix anything? It doesn't change the lock status.

regards, tom lane

I wrote:
> Why would this patch fix anything? It doesn't change the lock status.

I have not been able to reproduce the crash using Rusty's script on my
own machine, but after contemplating his stack trace for awhile I have a
theory about what is happening. I think that while we are building a
new relation entry (the RelationBuildDesc call in RelationClearRelation)
for a locally-created relation, we receive an sinval reset event caused
by sinval queue overflow. (That could only happen with a lot of
concurrent catalog update activity, which is why there's a significant
number of concurrent "job1" clients needed to provoke the problem.)
The sinval reset will be serviced by RelationCacheInvalidate, which will
blow away any relcache entries with refcount zero, including the one
that the outer instance of RelationClearRelation is trying to rebuild.
So when control returns the next thing that happens is we try to do the
equalTupleDescs() comparison against a trashed pointer, as seen in the
stack trace.

This behavior is new in 8.4.3; before that RelationClearRelation
temporarily unhooked the target rel from the relcache hash table,
so it wouldn't be found by RelationCacheInvalidate. So that explains
why Rusty's app worked before.

In short, then, Heikki's fix is good, although it desperately needs
some comment updates: there's effectively an API change happening here,
because RelationClearRelation's contract with its caller is not the
same as before. I'll clean it up a bit and apply. It will need to
go into all the branches this patch went into:
http://archives.postgresql.org/pgsql-committers/2010-01/msg00186.php

regards, tom lane

I wrote:
> [ theory about cause of Rusty's crash ]

I started to doubt this theory after wondering why the problem hadn't
been exposed by CLOBBER_CACHE_ALWAYS testing, which is done routinely
by the buildfarm. That setting would surely cause the cache flush to
happen at the troublesome time. After a good deal more investigation,
I found out why it doesn't crash with that. The problematic case is
for a relation that has rd_newRelfilenodeSubid nonzero but
rd_createSubid zero (ie, it's been truncated in the current xact).
Given that, RelationFlushRelation will attempt a rebuild but
RelationCacheInvalidate won't exempt the relation from destruction.
However, if you do a TRUNCATE under CLOBBER_CACHE_ALWAYS, the relcache
entry gets blown away immediately at the conclusion of that command,
because we'll do a RelationCacheInvalidate as a consequence of
CLOBBER_CACHE_ALWAYS. When the relcache entry is rebuilt for later use,
it won't have rd_newRelfilenodeSubid set, so it's not a hazard anymore.
In order to expose this bug, the relcache entry has to survive past the
TRUNCATE and then a cache flush has to occur while we are in process of
rebuilding it, not before.

What this suggests is that CLOBBER_CACHE_ALWAYS is actually too strong
to provide a thorough test of cache flush hazards. Maybe we need an
alternate setting along the lines of CLOBBER_CACHE_SOMETIMES that would
randomly choose whether or not to flush at any given opportunity. But
if such a setup did produce a crash, it'd be awfully hard to reproduce
for investigation. Ideas?

There is another slightly odd thing here, which is that the stack trace
Rusty provided clearly shows the crash occurring during processing of a
local relcache invalidation message for the truncated relation. This
would be expected during execution of the TRUNCATE itself, but at that
point the rel has positive refcnt so there's no problem. According to
the stack trace the active SQL command is an INSERT ... SELECT, and I
wouldn't expect that to queue any relcache invals. Are there any
triggers or other unusual things in the real application (not the
watered-down test case) that would be triggered in INSERT/SELECT?

regards, tom lane

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> What this suggests is that CLOBBER_CACHE_ALWAYS is actually too
> strong to provide a thorough test of cache flush hazards. Maybe
> we need an alternate setting along the lines of
> CLOBBER_CACHE_SOMETIMES that would randomly choose whether or not
> to flush at any given opportunity. But if such a setup did produce
> a crash, it'd be awfully hard to reproduce for investigation.
> Ideas?

Seed the random number generator such that each run of the test gets
the same "random" numbers? Or *allow* the seed to be set, with the
default being a random seed which is logged so that it can be forced
for a repeat of the run?

-Kevin

On Apr 14, 2010, at 2:31 PM, Tom Lane wrote:

> I wrote:
>> [ theory about cause of Rusty's crash ]
>
> I started to doubt this theory after wondering why the problem hadn't
> been exposed by CLOBBER_CACHE_ALWAYS testing, which is done routinely
> by the buildfarm. That setting would surely cause the cache flush to
> happen at the troublesome time. After a good deal more investigation,
> I found out why it doesn't crash with that. The problematic case is
> for a relation that has rd_newRelfilenodeSubid nonzero but
> rd_createSubid zero (ie, it's been truncated in the current xact).
> Given that, RelationFlushRelation will attempt a rebuild but
> RelationCacheInvalidate won't exempt the relation from destruction.
> However, if you do a TRUNCATE under CLOBBER_CACHE_ALWAYS, the relcache
> entry gets blown away immediately at the conclusion of that command,
> because we'll do a RelationCacheInvalidate as a consequence of
> CLOBBER_CACHE_ALWAYS. When the relcache entry is rebuilt for later use,
> it won't have rd_newRelfilenodeSubid set, so it's not a hazard anymore.
> In order to expose this bug, the relcache entry has to survive past the
> TRUNCATE and then a cache flush has to occur while we are in process of
> rebuilding it, not before.
>
> What this suggests is that CLOBBER_CACHE_ALWAYS is actually too strong
> to provide a thorough test of cache flush hazards. Maybe we need an
> alternate setting along the lines of CLOBBER_CACHE_SOMETIMES that would
> randomly choose whether or not to flush at any given opportunity. But
> if such a setup did produce a crash, it'd be awfully hard to reproduce
> for investigation. Ideas?
>
> There is another slightly odd thing here, which is that the stack trace
> Rusty provided clearly shows the crash occurring during processing of a
> local relcache invalidation message for the truncated relation. This
> would be expected during execution of the TRUNCATE itself, but at that
> point the rel has positive refcnt so there's no problem. According to
> the stack trace the active SQL command is an INSERT ... SELECT, and I
> wouldn't expect that to queue any relcache invals. Are there any
> triggers or other unusual things in the real application (not the
> watered-down test case) that would be triggered in INSERT/SELECT?
>
> regards, tom lane

There are no triggers or other unusual things going on in the real application. This worked in 8.3.9 but started failing when going to 8.4.3.

The test case program was the smallest thing I could write to reproduce the problem consistently on my machine, but I couldn't reproduce it consistently on other machines and architectures. I'm glad Heikki was able to also see the crash on his hardware. I can take Heikki's patch back out and get a new stack trace from the test program if that would be useful to you.

Thanks,

Rusty
--
Rusty Conover
rconover(at)infogears(dot)com
InfoGears Inc / GearBuyer.com / FootwearBuyer.com
http://www.infogears.com
http://www.gearbuyer.com
http://www.footwearbuyer.com

Rusty Conover <rconover(at)infogears(dot)com> writes:
> On Apr 14, 2010, at 2:31 PM, Tom Lane wrote:
>> There is another slightly odd thing here, which is that the stack trace
>> Rusty provided clearly shows the crash occurring during processing of a
>> local relcache invalidation message for the truncated relation.

> The test case program was the smallest thing I could write to reproduce the problem consistently on my machine, but I couldn't reproduce it consistently on other machines and architectures. I'm glad Heikki was able to also see the crash on his hardware. I can take Heikki's patch back out and get a new stack trace from the test program if that would be useful to you.

Yeah, I'm curious to know if the stack trace is the same for crashes in
the watered-down test case. AFAICS, relcache invals triggered by the
TRUNCATE itself ought to be serviced before we get out of the TRUNCATE;
and after that, the xact is holding exclusive lock on the table so
there's no way that we should get a remote inval on the specific relation
(not to mention that the trace is clearly about a local inval not an
incoming remote inval). So I don't understand why the trace says that
it's happening during a subsequent INSERT.

Mind you, Heikki's patch looks like a good idea in any case; but I'm
not sure that there isn't something else going on here.

regards, tom lane

On Apr 14, 2010, at 3:30 PM, Tom Lane wrote:

> Rusty Conover <rconover(at)infogears(dot)com> writes:
>> On Apr 14, 2010, at 2:31 PM, Tom Lane wrote:
>>> There is another slightly odd thing here, which is that the stack trace
>>> Rusty provided clearly shows the crash occurring during processing of a
>>> local relcache invalidation message for the truncated relation.
>
>> The test case program was the smallest thing I could write to reproduce the problem consistently on my machine, but I couldn't reproduce it consistently on other machines and architectures. I'm glad Heikki was able to also see the crash on his hardware. I can take Heikki's patch back out and get a new stack trace from the test program if that would be useful to you.
>
> Yeah, I'm curious to know if the stack trace is the same for crashes in
> the watered-down test case. AFAICS, relcache invals triggered by the
> TRUNCATE itself ought to be serviced before we get out of the TRUNCATE;
> and after that, the xact is holding exclusive lock on the table so
> there's no way that we should get a remote inval on the specific relation
> (not to mention that the trace is clearly about a local inval not an
> incoming remote inval). So I don't understand why the trace says that
> it's happening during a subsequent INSERT.
>
> Mind you, Heikki's patch looks like a good idea in any case; but I'm
> not sure that there isn't something else going on here.
>
> regards, tom lane

Hi Tom,

Here is a backtrace from the test case script (using 8.4.3 as released):

#0 equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x966c3b80) at tupdesc.c:311
311 if (tupdesc1->natts != tupdesc2->natts)
(gdb) bt
#0 equalTupleDescs (tupdesc1=0x7f7f7f7f, tupdesc2=0x966c3b80) at tupdesc.c:311
#1 0x0832451b in RelationClearRelation (relation=0x966c7998, rebuild=<value optimized out>) at relcache.c:1901
#2 0x08324b9f in RelationFlushRelation () at relcache.c:1991
#3 RelationCacheInvalidateEntry (relationId=7217555) at relcache.c:2042
#4 0x0831dd89 in LocalExecuteInvalidationMessage (msg=0x89e2b50) at inval.c:510
#5 0x0831d341 in ProcessInvalidationMessages (hdr=0x89d20f4, func=0x831dc50 <LocalExecuteInvalidationMessage>)
at inval.c:397
#6 0x0831d3dc in CommandEndInvalidationMessages () at inval.c:1006
#7 0x080c9035 in AtCommit_LocalCache () at xact.c:1009
#8 CommandCounterIncrement () at xact.c:634
#9 0x0826dcc9 in finish_xact_command () at postgres.c:2363
#10 0x0826ed4d in exec_simple_query (
query_string=0x89b9904 "insert into foo_dest (id, name, size) select id, name, size from foobar_source")
at postgres.c:1022
#11 0x0827042c in PostgresMain (argc=4, argv=0x894d5c8, username=0x894d590 "postgres") at postgres.c:3614
#12 0x0823a4d3 in BackendRun () at postmaster.c:3449
#13 BackendStartup () at postmaster.c:3063
#14 ServerLoop () at postmaster.c:1387
#15 0x0823b503 in PostmasterMain (argc=4, argv=0x894a678) at postmaster.c:1040
#16 0x081dc0a6 in main (argc=4, argv=0x894a678) at main.c:188
(gdb)

Hope that helps,

Rusty
--
Rusty Conover
rconover(at)infogears(dot)com
InfoGears Inc / GearBuyer.com / FootwearBuyer.com
http://www.infogears.com
http://www.gearbuyer.com
http://www.footwearbuyer.com

Rusty Conover <rconover(at)infogears(dot)com> writes:
> [ same stack trace for the simplified test case ]

Ah, got it finally. There *is* a relcache flush happening during INSERT
in the 8.4 code, because of FSM extension:

(gdb) bt
#0 RegisterRelcacheInvalidation (dbId=40264, relId=848094) at inval.c:439
#1 0x000000000067a30d in CacheInvalidateRelcache (relation=0x7f39b88403f0)
at inval.c:1141
#2 0x00000000005c9c45 in fsm_extend (fsm_nblocks=<value optimized out>,
rel=<value optimized out>) at freespace.c:589
#3 fsm_readbuf (fsm_nblocks=<value optimized out>, rel=<value optimized out>)
at freespace.c:522
#4 0x00000000005ca2e4 in fsm_set_and_search (rel=0x9d48,
addr=<value optimized out>, slot=0, newValue=220 '\334',
minValue=200 '\310') at freespace.c:608
#5 0x00000000005ca675 in RecordAndGetPageWithFreeSpace (rel=0x7f39b88403f0,
oldPage=<value optimized out>, oldSpaceAvail=<value optimized out>,
spaceNeeded=<value optimized out>) at freespace.c:163
#6 0x0000000000464149 in RelationGetBufferForTuple (relation=0x7f39b88403f0,
len=<value optimized out>, otherBuffer=0, options=<value optimized out>,
bistate=<value optimized out>) at hio.c:303
#7 0x0000000000462e77 in heap_insert (relation=0x7f39b88403f0, tup=0x14aa580,
cid=<value optimized out>, options=0, bistate=0x0) at heapam.c:1890

This code path doesn't exist in CVS HEAD, which means (I think) that the
given test case can't fail in HEAD. I think I got myself confused by
experimenting variously with HEAD and 8.4 in regular and
CLOBBER_CACHE_ALWAYS modes --- only one of those four combinations will
exhibit a failure with this test case.

Although the particular case apparently can't arise in HEAD, I'm going
to apply Heikki's patch there anyway, since there's clearly a risk of
related problems.

regards, tom lane

"Kevin Grittner" <Kevin(dot)Grittner(at)wicourts(dot)gov> writes:
> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> What this suggests is that CLOBBER_CACHE_ALWAYS is actually too
>> strong to provide a thorough test of cache flush hazards. Maybe
>> we need an alternate setting along the lines of
>> CLOBBER_CACHE_SOMETIMES that would randomly choose whether or not
>> to flush at any given opportunity. But if such a setup did produce
>> a crash, it'd be awfully hard to reproduce for investigation.
>> Ideas?

> Seed the random number generator such that each run of the test gets
> the same "random" numbers? Or *allow* the seed to be set, with the
> default being a random seed which is logged so that it can be forced
> for a repeat of the run?

The seed alone wouldn't be enough to duplicate the behavior, since
the behavior of random() typically varies across platforms. So we
might get a report and still be unable to reproduce it.

regards, tom lane

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> The seed alone wouldn't be enough to duplicate the behavior, since
> the behavior of random() typically varies across platforms. So we
> might get a report and still be unable to reproduce it.

At least the person getting the initial failure would be able to
recreate it, and possibly provide a stack trace.

-Kevin

"Kevin Grittner" <Kevin(dot)Grittner(at)wicourts(dot)gov> writes:
> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> The seed alone wouldn't be enough to duplicate the behavior, since
>> the behavior of random() typically varies across platforms. So we
>> might get a report and still be unable to reproduce it.

> At least the person getting the initial failure would be able to
> recreate it, and possibly provide a stack trace.

On second thought, since there's no need for a particularly high-quality
RNG here, we could just embed some brain-dead one-liner implementation,
which should behave the same everywhere.

regards, tom lane

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> On second thought, since there's no need for a particularly
> high-quality RNG here, we could just embed some brain-dead
> one-liner implementation, which should behave the same everywhere.

Sounds good to me.

-Kevin