Subject: Re: Missing dependency tracking for TableFunc nodes
To: Tomas Vondra <tomas.vondra@2ndquadrant.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, pgsql-hackers@lists.postgresql.org
References: <18427.1573508501@sss.pgh.pa.us>
 <997cbcae-7739-f871-84a0-1192380abb54@gmail.com>
 <20191114004631.z4mg5nucvrxiewxe@development>
From: Mark Dilger <hornschnorter@gmail.com>
Message-ID: <bfc09232-599b-482b-8a5e-f532ba7cfbd8@gmail.com>
Date: Wed, 13 Nov 2019 17:38:02 -0800
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101
 Thunderbird/60.7.1
MIME-Version: 1.0
In-Reply-To: <20191114004631.z4mg5nucvrxiewxe@development>
Content-Type: multipart/mixed;
 boundary="------------3174FFF1936E78DC843782F9"
Content-Language: en-US
Precedence: bulk

This is a multi-part message in MIME format.
--------------3174FFF1936E78DC843782F9
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit


On 11/13/19 4:46 PM, Tomas Vondra wrote:
> On Wed, Nov 13, 2019 at 03:00:03PM -0800, Mark Dilger wrote:
>>
>>
>> On 11/11/19 1:41 PM, Tom Lane wrote:
>>> I happened to notice that find_expr_references_walker has not
>>> been taught anything about TableFunc nodes, which means it will
>>> miss the type and collation OIDs embedded in such a node.
>>>
>>> This can be demonstrated to be a problem by the attached script,
>>> which will end up with a "cache lookup failed for type NNNNN"
>>> error because we allow dropping a type the XMLTABLE construct
>>> references.
>>>
>>> This isn't hard to fix, as per the attached patch, but it makes
>>> me nervous.  I wonder what other dependencies we might be missing.
>>
>> I can consistently generate errors like the following in master:
>>
>>  ERROR:  cache lookup failed for statistics object 31041
>>
>> This happens in a stress test in which multiple processes are making 
>> changes to the schema.  So far, all the sessions that report this 
>> cache lookup error do so when performing one of ANALYZE, VACUUM 
>> ANALYZE, UPDATE, DELETE or EXPLAIN ANALYZE on a table that has MCV 
>> statistics. All processes running simultaneously are running the same 
>> set of functions, which create and delete tables, indexes, and 
>> statistics objects, insert, update, and delete rows in those tables, etc.
>>
>> The fact that the statistics are of the MCV type might not be 
>> relevant; I'm creating those on tables as part of testing Tomas 
>> Vondra's MCV statistics patch, so all the tables have statistics of 
>> that kind on them.
>>
> 
> Hmmm, I don't know the details of the test, but this seems a bit like
> we're trying to use the stats during estimation but it got dropped
> meanwhile. If that's the case, it probably affects all stats types, not
> just MCV lists - there should no significant difference between
> different statistics types, I think.
> 
> I've managed to reproduce this with a stress-test, and I do get these
> failures with both dependencies and mcv stats, although in slightly
> different places.
> 
> And I think I see the issue - when dropping the statistics, we do
> RemoveObjects which however does not acquire any lock on the table. So
> we get the list of stats (without the serialized data), but before we
> get to load the contents, someone drops it. If that's the root cause,
> it's there since pg 10.
> 
> I'm not sure what's the right solution. An straightforward option would
> be to lock the relation, but will that work after adding support for
> stats on joins? An alternative would be to just ignore those failures,
> but that kinda breaks the estimation (we should have picked a different
> stats in this case).
> 
>> I can try to distill my test case a bit, but first I'd like to know if 
>> you are interested.  Currently, the patch is over 2.2MB, gzip'd.  I'll 
>> only bother distilling it if you don't already know about these cache 
>> lookup failures.
>>
> 
> Not sure. But I do wonder if we see the same issue.

I don't know.  If you want to reproduce what I'm seeing....

I added a parallel_schedule target:

diff --git a/src/test/regress/parallel_schedule 
b/src/test/regress/parallel_schedule
index fc0f14122b..5ace7c7a8a 100644
--- a/src/test/regress/parallel_schedule
+++ b/src/test/regress/parallel_schedule
@@ -85,6 +85,8 @@ test: create_table_like alter_generic alter_operator 
misc async dbsize misc_func
  # collate.*.utf8 tests cannot be run in parallel with each other
  test: rules psql psql_crosstab amutils stats_ext collate.linux.utf8

+test: mcv_huge_stress_a mcv_huge_stress_b mcv_huge_stress_c 
mcv_huge_stress_d mcv_huge_stress_e mcv_huge_stress_f mcv_huge_stress_g
+
  # run by itself so it can run parallel workers
  test: select_parallel
  test: write_parallel


And used the attached script to generate the contents of the seven 
parallel tests.  If you want to duplicate this, you'll have to manually 
run gen.pl and direct its output to those src/test/regress/sql/ files. 
The src/test/regress/expected/ files are just empty, as I don't care 
about whether the test results match.  I'm just checking what kinds of 
errors I get and whether any of them are concerning.

After my most recent run of the stress tests, I grep'd for cache 
failures and got 23 of them, all coming from get_relation_statistics(), 
statext_store() and statext_mcv_load().  Two different adjacent spots in 
get_relation_statistics() were involved:

         htup = SearchSysCache1(STATEXTOID, ObjectIdGetDatum(statOid));
         if (!HeapTupleIsValid(htup))
             elog(ERROR, "cache lookup failed for statistics object %u", 
statOid);
         staForm = (Form_pg_statistic_ext) GETSTRUCT(htup);

         dtup = SearchSysCache1(STATEXTDATASTXOID, 
ObjectIdGetDatum(statOid));
         if (!HeapTupleIsValid(dtup))
             elog(ERROR, "cache lookup failed for statistics object %u", 
statOid);

Most were from the first SearchSysCache1 call, but one of them was from 
the second.

-- 
Mark Dilger

--------------3174FFF1936E78DC843782F9
Content-Type: application/x-perl;
 name="gen.pl"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="gen.pl"

#!/usr/bin/perl

use strict;
use warnings;

my @prefix = qw(i f d n t v);
my @suffix = qw(1 2 3 4 5 6 7 8 9);

sub tablename {
	my $dice = int(rand(10));
	if ($dice == 0) {
		return "mcv_huge";
	}
	return "mcv_huge_$dice";
}

sub indexname {
	my $tablename = shift;
	return join("_", $tablename, int(rand(10)), "idx");
}

sub random_fields {
	my %fields = ();
	my $count = int(rand(7))+2;
	while (scalar(keys %fields) < $count)
	{
		my $prefix = $prefix[int(rand(@prefix))];
		my $suffix = $suffix[int(rand(@suffix))];
		$fields{$prefix . $suffix} = 1;
	}
	return keys %fields;
}

sub print_create_table {
	my $tablename = tablename();
	print("
CREATE TABLE $tablename (
	i1 INTEGER, i2 INTEGER, i3 INTEGER, i4 INTEGER, i5 INTEGER, i6 INTEGER, i7 INTEGER, i8 INTEGER, i9 INTEGER,
	f1 FLOAT,   f2 FLOAT,   f3 FLOAT,   f4 FLOAT,   f5 FLOAT,   f6 FLOAT,   f7 FLOAT,   f8 FLOAT,   f9 FLOAT,
	d1 FLOAT8,  d2 FLOAT8,  d3 FLOAT8,  d4 FLOAT8,  d5 FLOAT8,  d6 FLOAT8,  d7 FLOAT8,  d8 FLOAT8,  d9 FLOAT8,
	n1 NUMERIC, n2 NUMERIC, n3 NUMERIC, n4 NUMERIC, n5 NUMERIC, n6 NUMERIC, n7 NUMERIC, n8 NUMERIC, n9 NUMERIC,
	t1 TEXT,    t2 TEXT,    t3 TEXT,    t4 TEXT,    t5 TEXT,    t6 TEXT,    t7 TEXT,    t8 TEXT,    t9 TEXT,
	v1 VARCHAR, v2 VARCHAR, v3 VARCHAR, v4 VARCHAR, v5 VARCHAR, v6 VARCHAR, v7 VARCHAR, v8 VARCHAR, v9 VARCHAR);\n");
}

sub print_create_index {
	my $tablename = tablename();
	my $indexname = indexname($tablename);
	my @fields = random_fields();
	print("CREATE INDEX $indexname ON $tablename (", join(", ", @fields), ");\n");
}

sub print_drop_table {
	my $tablename = tablename();
	print("DROP TABLE $tablename;\n");
}

sub print_drop_index {
	my $tablename = tablename();
	my $indexname = indexname($tablename);
	print("DROP INDEX $indexname;\n");
}

sub print_insert {
	my $tablename = tablename();
	printf("
INSERT INTO $tablename VALUES (
		%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d,
		%d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d, %d,
		'%d', '%d', '%d', '%d', '%d', '%d', '%d', '%d', '%d',
		'%d', '%d', '%d', '%d', '%d', '%d', '%d', '%d', '%d');\n",
	map { int(rand(5000)) } (1..54)
		);
}

sub print_delete {
	my $tablename = tablename();
	printf("DELETE FROM $tablename WHERE %s%d = %d;\n", $prefix[int(rand(4))], $suffix[int(rand(@suffix))], int(rand(5000)));
}

sub print_update {
	my $tablename = tablename();
	printf("UPDATE $tablename SET %s%d = %d WHERE %s%d = %d;\n",
		$prefix[int(rand(4))], $suffix[int(rand(@suffix))], int(rand(5000)),
		$prefix[int(rand(4))], $suffix[int(rand(@suffix))], int(rand(5000))
		);
}

sub print_vacuum {
	my $tablename = tablename();
	my $dice = int(rand(5));
	if ($dice == 0) {
		printf("VACUUM $tablename;\n");
	}
	elsif ($dice == 1) {
		printf("ANALYZE $tablename;\n");
	}
	elsif ($dice == 2) {
		printf("VACUUM ANALYZE $tablename;\n");
	}
	if ($dice == 3) {
		printf("VACUUM FULL $tablename;\n");
	}
	if ($dice == 4) {
		my $indexname = indexname($tablename);
		printf("CLUSTER $tablename ON $indexname;\n");
	}
}

sub print_create_statistics {
	my $tablename = tablename();
	my @fields = random_fields();
	print("CREATE STATISTICS mcv_huge_", int(rand(5000)), " (mcv) ON ", join(", ", @fields), " FROM $tablename;\n");
}

sub print_drop_statistics {
	print("DROP STATISTICS mcv_huge_", int(rand(5000)), ";\n");
}

sub randval {
	my $field = shift;
	if ($field =~ m/^[tv]/) {
		return("'" . int(rand(5000)) . "'");
	}
	return int(rand(5000));
}

sub print_explain {
	my $tablename = tablename();
	my %fields = ();
	my $count = int(rand(15))+2;
	while (scalar(keys %fields) < $count)
	{
		my $prefix = $prefix[int(rand(@prefix))];
		my $suffix = $suffix[int(rand(@suffix))];
		$fields{$prefix . $suffix} = 1;
	}
	print("EXPLAIN ANALYZE SELECT * FROM $tablename WHERE ",
		join(" AND ", map { "$_ = " . randval($_) } keys %fields),
	";\n");
}

sub print_something {
	my $dice = int(rand(732));
	if    ($dice < 100) { print_insert(); }
	elsif ($dice < 200) { print_delete(); }
	elsif ($dice < 300) { print_update(); }
	elsif ($dice < 400) { print_vacuum(); }
	elsif ($dice < 500) { print_create_statistics(); }
	elsif ($dice < 600) { print_drop_statistics(); }
	elsif ($dice < 700) { print_explain(); }
	elsif ($dice < 710) { print_create_table(); }
	elsif ($dice < 720) { print_create_index(); }
	elsif ($dice < 730) { print_drop_table(); }
	else                { print_drop_index(); }
}

for(1..100000) {
	print_something();
}

--------------3174FFF1936E78DC843782F9--