Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Benjamin Coutu
Hello,

please consider the following SQL query:

SELECT * FROM "transactions" WHERE 
"account" IN (SELECT "ID" FROM "accounts" WHERE "name" ~~* '%test%') OR
"contract" IN (SELECT "ID" FROM "contracts" WHERE "name" ~~* '%test%')

This yields the following plan on Postgres 11:

Seq Scan on transactions  (cost=67.21..171458.03 rows=1301316 width=1206)
  Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
  SubPlan 1
->  Bitmap Heap Scan on accounts  (cost=33.36..61.16 rows=46 width=4)
  Recheck Cond: ((name)::text ~~* '%test%'::text)
  ->  Bitmap Index Scan on s_accounts  (cost=0.00..33.35 rows=46 
width=0)
Index Cond: ((name)::text ~~* '%test%'::text)
  SubPlan 2
->  Seq Scan on contracts  (cost=0.00..5.93 rows=5 width=4)
  Filter: ((name)::text ~~* '%test%'::text)

So the where clause of this query has just two subplans OR-ed together, one is 
estimated to yield 46 rows and one is estimated to yield 5 rows.
I'd expect the total rows for the seqscan to be estimated at 46 then, following 
the logic that rows_seqscan = max(rows_subplan1, rows_subplan2). As you can 
see, the optimizer estimates a whopping 1301316 rows instead.

I am absolutely aware that those are hashed sub plans below a seqscan and that 
Postgres therefore has to scan all tuples of the table. But the problem is that 
upper nodes (which are excluded from this example for simplicity) think they 
will receive 1301316 rows from the seqscan, when in fact they will probably 
only see a hand full, which the planner could have (easily?) deduced by taking 
the greater of the two subplan row estimates.

What am I missing, or is this perhaps a shortfall of the planner?

Thanks,

Ben

-- 

Bejamin Coutu
[email protected]

ZeyOS GmbH & Co. KG
http://www.zeyos.com




Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Laurenz Albe
On Fri, 2020-06-19 at 17:12 +0200, Benjamin Coutu wrote:
> please consider the following SQL query:
> 
> SELECT * FROM "transactions" WHERE 
> "account" IN (SELECT "ID" FROM "accounts" WHERE "name" ~~* '%test%') 
> OR
> "contract" IN (SELECT "ID" FROM "contracts" WHERE "name" ~~* '%test%')
> 
> This yields the following plan on Postgres 11:
> 
> Seq Scan on transactions  (cost=67.21..171458.03 rows=1301316 width=1206)
>   Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
>   SubPlan 1
> ->  Bitmap Heap Scan on accounts  (cost=33.36..61.16 rows=46 width=4)
>   Recheck Cond: ((name)::text ~~* '%test%'::text)
>   ->  Bitmap Index Scan on s_accounts  (cost=0.00..33.35 rows=46 
> width=0)
> Index Cond: ((name)::text ~~* '%test%'::text)
>   SubPlan 2
> ->  Seq Scan on contracts  (cost=0.00..5.93 rows=5 width=4)
>   Filter: ((name)::text ~~* '%test%'::text)
> 
> So the where clause of this query has just two subplans OR-ed together, one 
> is estimated to yield 46 rows and one is estimated to yield 5 rows.
> I'd expect the total rows for the seqscan to be estimated at 46 then, 
> following the logic that rows_seqscan = max(rows_subplan1, rows_subplan2). As 
> you can see, the optimizer estimates a whopping
> 1301316 rows instead.
> 
> I am absolutely aware that those are hashed sub plans below a seqscan and 
> that Postgres therefore has to scan all tuples of the table. But the problem 
> is that upper nodes (which are excluded from
> this example for simplicity) think they will receive 1301316 rows from the 
> seqscan, when in fact they will probably only see a hand full, which the 
> planner could have (easily?) deduced by taking the
> greater of the two subplan row estimates.
> 
> What am I missing, or is this perhaps a shortfall of the planner?

The subplans are executed *fpr each row* found in "transactions",
and the estimate on the subplans is *per execution".

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com





Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Tom Lane
"Benjamin Coutu"  writes:
> please consider the following SQL query:

> SELECT * FROM "transactions" WHERE 
>   "account" IN (SELECT "ID" FROM "accounts" WHERE "name" ~~* '%test%') OR
>   "contract" IN (SELECT "ID" FROM "contracts" WHERE "name" ~~* '%test%')

> This yields the following plan on Postgres 11:

> Seq Scan on transactions  (cost=67.21..171458.03 rows=1301316 width=1206)
>   Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
>   SubPlan 1
> ->  Bitmap Heap Scan on accounts  (cost=33.36..61.16 rows=46 width=4)
>   Recheck Cond: ((name)::text ~~* '%test%'::text)
>   ->  Bitmap Index Scan on s_accounts  (cost=0.00..33.35 rows=46 
> width=0)
> Index Cond: ((name)::text ~~* '%test%'::text)
>   SubPlan 2
> ->  Seq Scan on contracts  (cost=0.00..5.93 rows=5 width=4)
>   Filter: ((name)::text ~~* '%test%'::text)

> So the where clause of this query has just two subplans OR-ed together, one 
> is estimated to yield 46 rows and one is estimated to yield 5 rows.
> I'd expect the total rows for the seqscan to be estimated at 46 then, 
> following the logic that rows_seqscan = max(rows_subplan1, rows_subplan2). As 
> you can see, the optimizer estimates a whopping 1301316 rows instead.

No.  The subplan estimates are for the number of rows produced by one
execution of the subplan, ie the numbers of "accounts" or "contracts"
rows that match those inner WHERE conditions.  This has very little
a-priori relationship to the number of "transactions" rows that will
satisfy the outer WHERE condition.  If we knew that transactions.account
and transactions.contract were unique columns, then we might be able
to say that there shouldn't be more than one outer match per subplan
result row ... but you didn't say that, and it seems unlikely.

(Having said that, I think that the estimates for these cases very
possibly are quite stupid.  But that doesn't mean that 46+5 would
be the right answer.)

regards, tom lane




Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread David G. Johnston
On Friday, June 19, 2020, Laurenz Albe  wrote:

>
> > I am absolutely aware that those are hashed sub plans below a seqscan
> and that Postgres therefore has to scan all tuples of the table. But the
> problem is that upper nodes (which are excluded from
> > this example for simplicity) think they will receive 1301316 rows from
> the seqscan, when in fact they will probably only see a hand full, which
> the planner could have (easily?) deduced by taking the
> > greater of the two subplan row estimates.
> >
> > What am I missing, or is this perhaps a shortfall of the planner?
>
> The subplans are executed *fpr each row* found in "transactions",
> and the estimate on the subplans is *per execution".
>

I understood Tom’s nearby answer but not this one.  This seems to be
referring to correlated subplans which the examples are not.

David J.


Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Benjamin Coutu
> No.  The subplan estimates are for the number of rows produced by one
> execution of the subplan, ie the numbers of "accounts" or "contracts"
> rows that match those inner WHERE conditions.  This has very little
> a-priori relationship to the number of "transactions" rows that will
> satisfy the outer WHERE condition.  If we knew that transactions.account
> and transactions.contract were unique columns, then we might be able
> to say that there shouldn't be more than one outer match per subplan
> result row ... but you didn't say that, and it seems unlikely.

Thanks Tom, I understand your point.

I don't want to waste your time but maybe there is room for improvement as both 
"account" and "contract" are highly distinct and the individual subplan 
estimates are quite accurate:

Seq Scan on transactions  (cost=67.81..171458.63 rows=1301316 width=1206) 
(actual time=69.418..917.594 rows=112 loops=1)
  Filter: ((hashed SubPlan 1) OR (hashed SubPlan 2))
  Rows Removed by Filter: 1792937
  SubPlan 1
->  Bitmap Heap Scan on accounts  (cost=33.96..61.76 rows=46 width=4) 
(actual time=3.053..3.292 rows=111 loops=1)
  Recheck Cond: ((name)::text ~~* '%test%'::text)
  Rows Removed by Index Recheck: 4
  Heap Blocks: exact=104
  ->  Bitmap Index Scan on s_accounts  (cost=0.00..33.95 rows=46 
width=0) (actual time=0.505..0.505 rows=118 loops=1)
Index Cond: ((name)::text ~~* '%test%'::text)
  SubPlan 2
->  Seq Scan on contracts  (cost=0.00..5.93 rows=5 width=4) (actual 
time=2.531..2.836 rows=4 loops=1)
  Filter: ((name)::text ~~* '%test%'::text)
  Rows Removed by Filter: 272

For comparison here are the plans for the queries with the individual where 
clauses:

SELECT * FROM "transactions" WHERE "account" IN (SELECT "ID" FROM "accounts" 
WHERE "name" ~~* '%test%')

Nested Loop  (cost=34.38..488.93 rows=155 width=1206) (actual time=0.599..1.393 
rows=112 loops=1)
  ->  Bitmap Heap Scan on accounts  (cost=33.96..61.76 rows=46 width=4) (actual 
time=0.541..0.796 rows=111 loops=1)
Recheck Cond: ((name)::text ~~* '%test%'::text)
Rows Removed by Index Recheck: 4
Heap Blocks: exact=104
->  Bitmap Index Scan on s_accounts  (cost=0.00..33.95 rows=46 width=0) 
(actual time=0.521..0.521 rows=118 loops=1)
  Index Cond: ((name)::text ~~* '%test%'::text)
  ->  Index Scan using fk_transactions_account on transactions  
(cost=0.43..9.08 rows=21 width=1206) (actual time=0.004..0.005 rows=1 loops=111)
Index Cond: (account = accounts."ID")

SELECT * FROM "transactions" WHERE "contract" IN (SELECT "ID" FROM "contracts" 
WHERE "name" ~~* '%test%')

Nested Loop  (cost=3.76..10.10 rows=31662 width=1206) (actual time=0.082..0.082 
rows=0 loops=1)
  ->  Bitmap Heap Scan on contracts  (cost=3.64..5.74 rows=5 width=4) (actual 
time=0.069..0.075 rows=4 loops=1)
Recheck Cond: ((name)::text ~~* '%test%'::text)
Heap Blocks: exact=2
->  Bitmap Index Scan on s_contracts  (cost=0.00..3.64 rows=5 width=0) 
(actual time=0.060..0.060 rows=4 loops=1)
  Index Cond: ((name)::text ~~* '%test%'::text)
  ->  Index Scan using fk_transactions_contract on transactions  
(cost=0.12..0.86 rows=1 width=1206) (actual time=0.001..0.001 rows=0 loops=4)
Index Cond: (contract = contracts."ID")

The statistics for the columns are:

SELECT attname, null_frac, n_distinct from pg_stats WHERE tablename = 
'transactions' AND attname IN ('account', 'contract')

transactions.account:   null_frac=0.025 n_distinct=80277
transactions.contract:  null_frac=1 n_distinct=0 (there are basically 
no non-null values for field "contract" in transactions)

According to pg_class.reltuples the table "transactions" has 1735088 rows.

I'd naively expect the selectivity for an OR of those two hashed subplans given 
uniform distribution to be:

rows_total = 
((rows_transactions * (1 - null_frac_account)) / n_distinct_account) * 
expected_rows_from_subplan1 +
((rows_transactions * (1 - null_frac_contract)) / n_distinct_contract) 
* expected_rows_from_subplan2

=> rows_total = 
((1735088 * (1 - 0.025)) / 80277) * 46 +
((1735088 * (1 - 1)) / 0) * 5

=> rows_total = 969 + 0 /* no non-null values for contract field */

Please forgive the sloppy math but something along this line could be promising.

Btw, I don't quite understand why the nested loop on contract only is expected 
to yield 31662 rows, when the null_frac of field transactions.contract is 1. 
Shouldn't that indicate zero rows or some kind of default minimum estimate for 
that query?

Thanks again!

Benjamin Coutu




Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Tom Lane
"Benjamin Coutu"  writes:
> I don't want to waste your time but maybe there is room for improvement as 
> both "account" and "contract" are highly distinct and the individual subplan 
> estimates are quite accurate:

Yeah, as I said, the estimates you're getting for the OR'd subplans are
pretty stupid.  Once you throw the OR in there, it's not possible to
convert the IN clauses to semi-joins, so they just stay as generic
subplans.  It looks like we have exactly zero intelligence about the
generic case --- unless I'm missing something in clause_selectivity,
you just end up with a default 0.5 selectivity estimate.  So yeah,
there's a lot of room for improvement, whenever anyone finds some
round tuits to work on that.

While you're waiting, you might think about recasting the query to
avoid the OR.  Perhaps you could do a UNION of two scans of the
transactions table?

> Btw, I don't quite understand why the nested loop on contract only is 
> expected to yield 31662 rows, when the null_frac of field 
> transactions.contract is 1. Shouldn't that indicate zero rows or some kind of 
> default minimum estimate for that query?

That I don't understand.  I get a minimal rowcount estimate for an
all-nulls outer table, as long as I'm using just one IN rather than
an OR:

regression=# create table contracts (id int);
CREATE TABLE
regression=# insert into contracts values(1),(2),(3),(4);
INSERT 0 4
regression=# analyze contracts ;
ANALYZE
regression=# create table transactions (contract int);
CREATE TABLE
regression=# insert into transactions select null from 
generate_series(1,10);
INSERT 0 10
regression=# analyze transactions;
ANALYZE
regression=# explain select * from transactions where contract in (select id 
from contracts);
QUERY PLAN
--
 Hash Semi Join  (cost=1.09..1607.59 rows=1 width=4)
   Hash Cond: (transactions.contract = contracts.id)
   ->  Seq Scan on transactions  (cost=0.00..1344.00 rows=10 width=4)
   ->  Hash  (cost=1.04..1.04 rows=4 width=4)
 ->  Seq Scan on contracts  (cost=0.00..1.04 rows=4 width=4)
(5 rows)

regards, tom lane




Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Michael Lewis
>
> While you're waiting, you might think about recasting the query to
> avoid the OR.  Perhaps you could do a UNION of two scans of the
> transactions table?
>

Minor note- use UNION ALL to avoid the dedupe work if you already know
those will be distinct sets, or having duplicates is fine.


PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Kenneth Marshall
Hi PostgreSQL users,

I was looking at a slow query in our CMDB that using postgresql-12.3 as its
backend. I since I am using the pg_trgm extension elsewhere I decided to give
it a try. To my surprise, the query plan did not change. But when I disabled
the index scan I got the much, much faster scan using a bitmap index scan.
Any ideas about why that is being chosen? Here are the details:

shared_buffers = 12GB
work_mem = 128MB
maintenance_work_mem = 2GB
effective_io_concurrency = 200
max_worker_processes = 24
max_parallel_maintenance_workers = 4
max_parallel_workers_per_gather = 4
max_parallel_workers = 24 
random_page_cost = 1.1
seq_page_cost = 1.0
effective_cache_size = 36GB
default_statistics_target = 500
from_collapse_limit = 30
join_collapse_limit = 30

Slow version with index scan:

# explain analyze SELECT DISTINCT main.* FROM Articles main JOIN 
ObjectCustomFieldValues ObjectCustomFieldValues_1  ON ( 
ObjectCustomFieldValues_1.Disabled = '0' ) AND ( 
ObjectCustomFieldValues_1.ObjectId = main.id )  WHERE 
(ObjectCustomFieldValues_1.LargeContent ILIKE '%958575%' OR 
ObjectCustomFieldValues_1.Content ILIKE '%958575%') AND (main.Disabled = '0')  
ORDER BY main.SortOrder ASC, main.Name ASC;

 QUERY PLAN 
 
-
 Unique  (cost=892.65..892.68 rows=1 width=137) (actual 
time=21165.464..21165.464 rows=0 loops=1)
   ->  Sort  (cost=892.65..892.66 rows=1 width=137) (actual 
time=21165.462..21165.462 rows=0 loops=1)
 Sort Key: main.sortorder, main.name, main.id, main.summary, 
main.class, main.parent, main.uri, main.creator, main.created, 
main.lastupdatedby, main.lastupdated
 Sort Method: quicksort  Memory: 25kB
 ->  Merge Join  (cost=0.71..892.64 rows=1 width=137) (actual 
time=21165.453..21165.453 rows=0 loops=1)
   Merge Cond: (main.id = objectcustomfieldvalues_1.objectid)
   ->  Index Scan using articles_pkey on articles main  
(cost=0.14..9.08 rows=142 width=137) (actual time=0.007..0.007 rows=1 loops=1)
 Filter: (disabled = '0'::smallint)
   ->  Index Scan using objectcustomfieldvalues3 on 
objectcustomfieldvalues objectcustomfieldvalues_1  (cost=0.56..807603.40 
rows=915 width=4) (actual time=21165.441..21165.441 rows=0 loops=1)
 Filter: ((disabled = 0) AND ((largecontent ~~* 
'%958575%'::text) OR ((content)::text ~~* '%958575%'::text)))
 Rows Removed by Filter: 19030904
 Planning Time: 1.198 ms
 Execution Time: 21165.552 ms
(13 rows)

Time: 21167.239 ms (00:21.167)


Fast version with enable_indexscan = 0:

# explain analyze SELECT DISTINCT main.* FROM Articles main JOIN 
ObjectCustomFieldValues ObjectCustomFieldValues_1  ON ( 
ObjectCustomFieldValues_1.Disabled = '0' ) AND ( 
ObjectCustomFieldValues_1.ObjectId = main.id )  WHERE 
(ObjectCustomFieldValues_1.LargeContent ILIKE '%958575%' OR 
ObjectCustomFieldValues_1.Content ILIKE '%958575%') AND (main.Disabled = '0')  
ORDER BY main.SortOrder ASC, main.Name ASC;

QUERY PLAN  
   
---
 Unique  (cost=1315.42..1315.45 rows=1 width=137) (actual time=0.306..0.306 
rows=0 loops=1)
   ->  Sort  (cost=1315.42..1315.43 rows=1 width=137) (actual time=0.305..0.305 
rows=0 loops=1)
 Sort Key: main.sortorder, main.name, main.id, main.summary, 
main.class, main.parent, main.uri, main.creator, main.created, 
main.lastupdatedby, main.lastupdated
 Sort Method: quicksort  Memory: 25kB
 ->  Hash Join  (cost=52.89..1315.41 rows=1 width=137) (actual 
time=0.296..0.297 rows=0 loops=1)
   Hash Cond: (objectcustomfieldvalues_1.objectid = main.id)
   ->  Bitmap Heap Scan on objectcustomfieldvalues 
objectcustomfieldvalues_1  (cost=45.27..1305.40 rows=915 width=4) (actual 
time=0.213..0.213 rows=0 loops=1)
 Recheck Cond: ((largecontent ~~* '%958575%'::text) OR 
((content)::text ~~* '%958575%'::text))
 Filter: (disabled = 0)
 ->  BitmapOr  (cost=45.27..45.27 rows=1136 width=0) 
(actual time=0.210..0.210 rows=0 loops=1)
   ->  Bitmap Index Scan on 
objectcustomfieldvalues_largecontent_trgm  (cost=0.00..15.40 rows=1 width=0) 
(actual time=0.041..0.041 rows=0 loops=1)
 Index Cond: (largecontent ~~*

Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Tom Lane
Kenneth Marshall  writes:
> I was looking at a slow query in our CMDB that using postgresql-12.3 as its
> backend. I since I am using the pg_trgm extension elsewhere I decided to give
> it a try. To my surprise, the query plan did not change. But when I disabled
> the index scan I got the much, much faster scan using a bitmap index scan.
> Any ideas about why that is being chosen? Here are the details:

It looks like the planner is being too optimistic about how quickly the
mergejoin will end:

>  ->  Merge Join  (cost=0.71..892.64 rows=1 width=137) (actual 
> time=21165.453..21165.453 rows=0 loops=1)
>Merge Cond: (main.id = objectcustomfieldvalues_1.objectid)
>->  Index Scan using articles_pkey on articles main  
> (cost=0.14..9.08 rows=142 width=137) (actual time=0.007..0.007 rows=1 loops=1)
>  Filter: (disabled = '0'::smallint)
>->  Index Scan using objectcustomfieldvalues3 on 
> objectcustomfieldvalues objectcustomfieldvalues_1  (cost=0.56..807603.40 
> rows=915 width=4) (actual time=21165.441..21165.441 rows=0 loops=1)
>  Filter: ((disabled = 0) AND ((largecontent ~~* 
> '%958575%'::text) OR ((content)::text ~~* '%958575%'::text)))
>  Rows Removed by Filter: 19030904

This merge cost estimate is way lower than the sum of the input scan
estimates, where normally it would be that sum plus a nontrivial charge
for comparisons.  So the planner must think that the input scans won't
run to completion.  Which is something that can happen; merge join
will stop as soon as either input is exhausted.  But in this case it
looks like the objectcustomfieldvalues scan is the one that ran to
completion, while the articles scan had only one row demanded from it.
(We can see from the other plan that articles has 146 rows satisfying
the filter, so that scan must have been shut down before completion.)
The planner must have been expecting the other way around, with not
very much of the expensive objectcustomfieldvalues scan actually getting
done.

The reason for such an estimation error usually is that the maximum
join key values recorded in pg_stats are off: the join side that is
going to be exhausted is the one with the smaller max join key.
"articles" seems to be small enough that the stats for it will be
exact, so your problem is a poor estimate of the max value of
objectcustomfieldvalues.objectid.  You might try raising the statistics
target for that table.  Or maybe it's just that ANALYZE hasn't been
done lately on one table or the other?

regards, tom lane




Re: Unclamped row estimates whith OR-ed subplans

2020-06-19 Thread Benjamin Coutu
> While you're waiting, you might think about recasting the query to
> avoid the OR.  Perhaps you could do a UNION of two scans of the
> transactions table?

Thanks for the hint, I am well aware of the workaround for OR via UNION. I am 
not trying to improve this query per se as it is the small root of a very 
complex generated query and it's unfeasible to rewrite it to a UNION in this 
case.

The point of my message to the list was to highlight the misestimation, which I 
couldn't wrap my head around. Maybe this discussion can give some food for 
thought to someone who might tackle this in the future. It would surely be 
great to have selectivity estimate smarts for the generic case of OR-ed 
SubPlans someday.

> 
> > Btw, I don't quite understand why the nested loop on contract only is 
> > expected to yield 31662 rows, when the null_frac of field 
> > transactions.contract is 1. Shouldn't that indicate zero rows or some kind 
> > of default minimum estimate for that query?
> 
> That I don't understand.  I get a minimal rowcount estimate for an
> all-nulls outer table, as long as I'm using just one IN rather than

Yeah, that might be worth digging into. Is there any other info apart from 
those stats that I could provide?




Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Kenneth Marshall
On Fri, Jun 19, 2020 at 04:11:10PM -0400, Tom Lane wrote:
> 
> It looks like the planner is being too optimistic about how quickly the
> mergejoin will end:
> 
> >  ->  Merge Join  (cost=0.71..892.64 rows=1 width=137) (actual 
> > time=21165.453..21165.453 rows=0 loops=1)
> >Merge Cond: (main.id = objectcustomfieldvalues_1.objectid)
> >->  Index Scan using articles_pkey on articles main  
> > (cost=0.14..9.08 rows=142 width=137) (actual time=0.007..0.007 rows=1 
> > loops=1)
> >  Filter: (disabled = '0'::smallint)
> >->  Index Scan using objectcustomfieldvalues3 on 
> > objectcustomfieldvalues objectcustomfieldvalues_1  (cost=0.56..807603.40 
> > rows=915 width=4) (actual time=21165.441..21165.441 rows=0 loops=1)
> >  Filter: ((disabled = 0) AND ((largecontent ~~* 
> > '%958575%'::text) OR ((content)::text ~~* '%958575%'::text)))
> >  Rows Removed by Filter: 19030904
> 
> This merge cost estimate is way lower than the sum of the input scan
> estimates, where normally it would be that sum plus a nontrivial charge
> for comparisons.  So the planner must think that the input scans won't
> run to completion.  Which is something that can happen; merge join
> will stop as soon as either input is exhausted.  But in this case it
> looks like the objectcustomfieldvalues scan is the one that ran to
> completion, while the articles scan had only one row demanded from it.
> (We can see from the other plan that articles has 146 rows satisfying
> the filter, so that scan must have been shut down before completion.)
> The planner must have been expecting the other way around, with not
> very much of the expensive objectcustomfieldvalues scan actually getting
> done.
> 
> The reason for such an estimation error usually is that the maximum
> join key values recorded in pg_stats are off: the join side that is
> going to be exhausted is the one with the smaller max join key.
> "articles" seems to be small enough that the stats for it will be
> exact, so your problem is a poor estimate of the max value of
> objectcustomfieldvalues.objectid.  You might try raising the statistics
> target for that table.  Or maybe it's just that ANALYZE hasn't been
> done lately on one table or the other?
> 
>   regards, tom lane

Hi Tod,

Thank you for the information and suggestion. I tried bumping the statistics 
for the
objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an 
analyze and
the query plan stayed the same. I also analyzed the article table
repeatedly and their was no change in the plan. The table articles only has 151 
rows
while the objectcustomfieldvalues table has 19031909 rows. Any idea
about why it is so far off?

Regards,
Ken




Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Tom Lane
Kenneth Marshall  writes:
> On Fri, Jun 19, 2020 at 04:11:10PM -0400, Tom Lane wrote:
>> The reason for such an estimation error usually is that the maximum
>> join key values recorded in pg_stats are off: the join side that is
>> going to be exhausted is the one with the smaller max join key.
>> "articles" seems to be small enough that the stats for it will be
>> exact, so your problem is a poor estimate of the max value of
>> objectcustomfieldvalues.objectid.  You might try raising the statistics
>> target for that table.  Or maybe it's just that ANALYZE hasn't been
>> done lately on one table or the other?

> Thank you for the information and suggestion. I tried bumping the statistics 
> for the
> objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an 
> analyze and
> the query plan stayed the same. I also analyzed the article table
> repeatedly and their was no change in the plan. The table articles only has 
> 151 rows
> while the objectcustomfieldvalues table has 19031909 rows. Any idea
> about why it is so far off?

What's the actual maximum value of objectcustomfieldvalues.objectid,
and how does that compare to the endpoint value in the pg_stats
histogram for that column?  If you've got one outlier in the table,
it might get missed by ANALYZE.

regards, tom lane




Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Kenneth Marshall
On Fri, Jun 19, 2020 at 04:59:15PM -0400, Tom Lane wrote:
> 
> > Thank you for the information and suggestion. I tried bumping the 
> > statistics for the
> > objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an 
> > analyze and
> > the query plan stayed the same. I also analyzed the article table
> > repeatedly and their was no change in the plan. The table articles only has 
> > 151 rows
> > while the objectcustomfieldvalues table has 19031909 rows. Any idea
> > about why it is so far off?
> 
> What's the actual maximum value of objectcustomfieldvalues.objectid,
> and how does that compare to the endpoint value in the pg_stats
> histogram for that column?  If you've got one outlier in the table,
> it might get missed by ANALYZE.
> 
>   regards, tom lane

Hi Tom,

max(objectcustomfieldvalues.objectid) = 28108423 and here is the
histogram for that column:


 schemaname |tablename| attname  | inherited | null_frac | 
avg_width | n_distinct |
most_common_vals
 |  
 most_common_freqs  
  | 





















 histogram_bounds   





















   | correlation | most_common_elems | 
most_common_elem_freqs | elem_count_histogram 
--

Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Tom Lane
Kenneth Marshall  writes:
> On Fri, Jun 19, 2020 at 04:59:15PM -0400, Tom Lane wrote:
>> What's the actual maximum value of objectcustomfieldvalues.objectid,
>> and how does that compare to the endpoint value in the pg_stats
>> histogram for that column?  If you've got one outlier in the table,
>> it might get missed by ANALYZE.

> max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> histogram for that column:

 ... 3304313,3693956,27667772}

Hmm, does seem like you have some outlier keys.  Are any of the keys in
the column you're trying to join to larger than 27667772?

regards, tom lane




Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Kenneth Marshall
On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
> > max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> > histogram for that column:
> 
>  ... 3304313,3693956,27667772}
> 
> Hmm, does seem like you have some outlier keys.  Are any of the keys in
> the column you're trying to join to larger than 27667772?
> 
>   regards, tom lane

Hi Tom,

The only values above 27667772? for objectid are:

# select * from objectcustomfieldvalues where objectid > 27667772;
id| objectid | customfield |  content   | creator |
created   | lastupdatedby | lastupdated |   objecttype|
largecontent | contenttype | contentencoding | sortorder | disabled 
--+--+-++-+-+---+-+-+--+-+-+---+--
 19012927 | 27667773 | 375 | 2020-05-12 | 3768865 | 2020-05-13
16:10:39 |   3768865 | 2020-05-13 16:10:39 | RT::Transaction |
| | | 0 |0
 19012928 | 27667774 | 375 | 2020-05-12 | 3768865 | 2020-05-13
16:10:39 |   3768865 | 2020-05-13 16:10:39 | RT::Transaction |
| | | 0 |0
 19020166 | 27680053 | 375 | 2020-05-14 | 3570362 | 2020-05-14
14:14:20 |   3570362 | 2020-05-14 14:14:20 | RT::Transaction |
| | | 0 |0
 19025163 | 27688649 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 |0
 19025164 | 27688650 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 |0
 19025165 | 27688651 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 |0
 19025166 | 27688652 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 |0
 19025167 | 27688676 | 375 | 2020-05-14 | 3768865 | 2020-05-14
20:27:29 |   3768865 | 2020-05-14 20:27:29 | RT::Transaction |
| | | 0 |0
 19031374 | 27698358 | 375 | 2020-05-13 | 3768865 | 2020-05-15
15:32:57 |   3768865 | 2020-05-15 15:32:57 | RT::Transaction |
| | | 0 |0
 19031384 | 27698376 | 375 | 2020-05-14 | 3768865 | 2020-05-15
15:33:50 |   3768865 | 2020-05-15 15:33:50 | RT::Transaction |
| | | 0 |0
 19031385 | 27698377 | 375 | 2020-05-14 | 3768865 | 2020-05-15
15:33:50 |   3768865 | 2020-05-15 15:33:50 | RT::Transaction |
| | | 0 |0
 19033205 | 27701391 | 375 | 2020-05-15 | 3197295 | 2020-05-15
18:21:36 |   3197295 | 2020-05-15 18:21:36 | RT::Transaction |
| | | 0 |0
 19042369 | 27715839 | 375 | 2020-05-18 | 1403795 | 2020-05-18
14:12:35 |   1403795 | 2020-05-18 14:12:35 | RT::Transaction |
| | | 0 |0
 19047274 | 27723981 | 375 | 2020-05-18 | 3197295 | 2020-05-18
19:29:14 |   3197295 | 2020-05-18 19:29:14 | RT::Transaction |
| | | 0 |0
 19048566 | 27726800 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048567 | 27726801 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048568 | 27726802 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048569 | 27726803 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048570 | 27726804 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048571 | 27726805 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 |0
 19048572 | 27726806 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:19 |   3768865 | 2020-05-18 20:23:19 | RT::Transaction |
| | | 0 |0
 19048573 | 27726807 | 375

Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Tom Lane
Kenneth Marshall  writes:
> On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
>> Hmm, does seem like you have some outlier keys.  Are any of the keys in
>> the column you're trying to join to larger than 27667772?

> The only values above 27667772? for objectid are:

Sorry, I meant the other join column, ie articles.id.

regards, tom lane




Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Kenneth Marshall
On Fri, Jun 19, 2020 at 05:25:33PM -0500, Kenneth Marshall wrote:
> On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
> > > max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> > > histogram for that column:
> > 
> >  ... 3304313,3693956,27667772}
> > 
> > Hmm, does seem like you have some outlier keys.  Are any of the keys in
> > the column you're trying to join to larger than 27667772?
> > 
> > regards, tom lane
> 
> Hi Tom,
> 
> The only values above 27667772? for objectid are:
> 
> # select * from objectcustomfieldvalues where objectid > 27667772;
> id| objectid | customfield |  content   | creator |
> created   | lastupdatedby | lastupdated |   objecttype|
> largecontent | contenttype | contentencoding | sortorder | disabled 
> --+--+-++-+-+---+-+-+--+-+-+---+--
>  19012927 | 27667773 | 375 | 2020-05-12 | 3768865 | 2020-05-13
> 16:10:39 |   3768865 | 2020-05-13 16:10:39 | RT::Transaction |
> | | | 0 |0
>  19012928 | 27667774 | 375 | 2020-05-12 | 3768865 | 2020-05-13
> 16:10:39 |   3768865 | 2020-05-13 16:10:39 | RT::Transaction |
> | | | 0 |0
>  19020166 | 27680053 | 375 | 2020-05-14 | 3570362 | 2020-05-14
> 14:14:20 |   3570362 | 2020-05-14 14:14:20 | RT::Transaction |
> | | | 0 |0
>  19025163 | 27688649 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 |0
>  19025164 | 27688650 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 |0
>  19025165 | 27688651 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 |0
>  19025166 | 27688652 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 |   3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 |0
>  19025167 | 27688676 | 375 | 2020-05-14 | 3768865 | 2020-05-14
> 20:27:29 |   3768865 | 2020-05-14 20:27:29 | RT::Transaction |
> | | | 0 |0
>  19031374 | 27698358 | 375 | 2020-05-13 | 3768865 | 2020-05-15
> 15:32:57 |   3768865 | 2020-05-15 15:32:57 | RT::Transaction |
> | | | 0 |0
>  19031384 | 27698376 | 375 | 2020-05-14 | 3768865 | 2020-05-15
> 15:33:50 |   3768865 | 2020-05-15 15:33:50 | RT::Transaction |
> | | | 0 |0
>  19031385 | 27698377 | 375 | 2020-05-14 | 3768865 | 2020-05-15
> 15:33:50 |   3768865 | 2020-05-15 15:33:50 | RT::Transaction |
> | | | 0 |0
>  19033205 | 27701391 | 375 | 2020-05-15 | 3197295 | 2020-05-15
> 18:21:36 |   3197295 | 2020-05-15 18:21:36 | RT::Transaction |
> | | | 0 |0
>  19042369 | 27715839 | 375 | 2020-05-18 | 1403795 | 2020-05-18
> 14:12:35 |   1403795 | 2020-05-18 14:12:35 | RT::Transaction |
> | | | 0 |0
>  19047274 | 27723981 | 375 | 2020-05-18 | 3197295 | 2020-05-18
> 19:29:14 |   3197295 | 2020-05-18 19:29:14 | RT::Transaction |
> | | | 0 |0
>  19048566 | 27726800 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  19048567 | 27726801 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  19048568 | 27726802 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  19048569 | 27726803 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  19048570 | 27726804 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  19048571 | 27726805 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 |   3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 |0
>  

Re: PostgreSQL 12.3 slow index scan chosen

2020-06-19 Thread Tom Lane
[ please keep the mailing list cc'd ]

Kenneth Marshall  writes:
> Here are the stats for articles.id:

> 4,7,9,11,13,14,16,17,18,19,20,21,22,23,
> 24,25,26,32,33,34,36,40,41,42,43,44,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,99,100,101,102,106,107,108,109,113,1
>  
> 14,115,116,117,118,119,120,121,122,123,125,126,127,128,129,130,131,133,134,135,136,137,140,141,142,143,144,145,146,14
>  
> 7,148,149,150,151,152,153,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177
>  
> ,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,
>  207,208,1209,1210,1212,1213,1214,1215,1216,1219,1220,1221,1222,1223} 
>  
> That completely matches the max(id) for articles.id.

Hm, well it's clear why the planner is going for the mergejoin strategy:
it expects to only have to scan a very small fraction of the other table
before it's up past objectid = 1223 and can stop merging.  And it
seems like it's right ...

... oh, now I see: apparently, your filter condition is such that *no*
rows of the objectcustomfieldvalues table get past the filter:

  ->  Index Scan using objectcustomfieldvalues3 on 
objectcustomfieldvalues objectcustomfieldvalues_1  (cost=0.56..807603.40 
rows=915 width=4) (actual time=21165.441..21165.441 rows=0 loops=1)
 Filter: ((disabled = 0) AND ((largecontent ~~* 
'%958575%'::text) OR ((content)::text ~~* '%958575%'::text)))
 Rows Removed by Filter: 19030904

"rows=0" is the telltale.  So even after we're past objectid = 1223, that
scan continues, because the mergejoin needs to see a higher key before it
knows it can stop.

That's kind of annoying :-(.  I wonder if there's a way to be smarter?
This case would work a lot better if the filter conditions were not
applied till after the merge; but of course that wouldn't be an
improvement in general.  Or maybe we should penalize the mergejoin
cost estimate if there's a highly selective filter in the way.
(It does look like the planner is correctly estimating that the
filter is quite selective --- it's just not considering the potential
impact on the scan-until-finding-a-greater-key behavior.)

Right now I don't have any better suggestion than disabling mergejoin
if you think the filter is going to be very selective.

regards, tom lane