Thread: Help needed to understand query planner regression with incremental sort
Help needed to understand query planner regression with incremental sort
From
"Henrik Peinar (nodeSWAT.com)"
Date:
Quick description: After upgrading our Aurora PostgreSQL engine from v11 to v15, one of our often run SQL's started taking tens of seconds instead of running sub 100ms. Explain analyze showed that the query planner had switched to using incremental sort. Running ANALYZE on the table fixed the issue temporarily, but it came back after few days.
I'm looking to dig a bit deeper to be able to submit a bug report to the PostgreSQL team so maybe something can be done to fix this, as this definitely feels as a bug (the query running times are 100x in difference) but I need a bit of help as I'm new to this deep PostgreSQL analysis and I'm struggling finding resource how to proceed in such a case. And maybe it's an issue with my own setup or database configuration instead (ie. me just being stupid).
I know that I can solve the issue for my own environments with turning incremental sort off in the DB parameters, but I feel this might be worth putting a bit time into to be able to find the root cause and help me understand the planner a bit better.
I'm looking to dig a bit deeper to be able to submit a bug report to the PostgreSQL team so maybe something can be done to fix this, as this definitely feels as a bug (the query running times are 100x in difference) but I need a bit of help as I'm new to this deep PostgreSQL analysis and I'm struggling finding resource how to proceed in such a case. And maybe it's an issue with my own setup or database configuration instead (ie. me just being stupid).
I know that I can solve the issue for my own environments with turning incremental sort off in the DB parameters, but I feel this might be worth putting a bit time into to be able to find the root cause and help me understand the planner a bit better.
More detailed description:
Note: I don't have reproduction steps at this time, this is one of the reasons I'm asking help to figure out what could I try to do to start trying reproducing this in local setup. Below info is just giving out as much info as I can to help understand the setup I have.
The query under question is rather simplistic as far as SQL itself goes at least (attached: original_query.sql):
select * from "products" inner join "shops" on "shops"."id" = "products"."shop_id" where "products"."status" = 'published' and products.desc_tsv @@ to_tsquery('simple', 'nike:*') order by "products"."pinned_at" ASC, "products"."listed_at" DESC limit 61;
select * from "products" inner join "shops" on "shops"."id" = "products"."shop_id" where "products"."status" = 'published' and products.desc_tsv @@ to_tsquery('simple', 'nike:*') order by "products"."pinned_at" ASC, "products"."listed_at" DESC limit 61;
With normal running conditions this query produces the following query plan: https://explain.dalibo.com/plan/af8ch7a59ch6459d (attached: good_planner_path.txt)
With incremental sorting path, it produces the following https://explain.dalibo.com/plan/428564152aa3ba37 (attached: incremental_sort_planner_path.txt)
I've tried to include as slim table / index setup as possible, but the tables are actually bigger and there are a lot more indexes present, I don't know how other indexes and / or columns might affect the planner path in this case.
https://dbdiagram.io/d/64771e48722eb7749422715e (attached: schema_setup.sql)
https://dbdiagram.io/d/64771e48722eb7749422715e (attached: schema_setup.sql)
In production DB the size of products table is around 5 452 840 rows.
According to the information_schema the size of the products table is around 8.1GB.
If the incremental sort query plan starts happening, running ANALYZE products; fixes the issue and the planner switches back to the original plan.
What am I asking for?
Any ideas / help / queries that would get me closer to understanding why planner chooses so much slower query in this case or ideas how to start trying to reproduce this locally as it seems to happen intermittently in production environment, I'm unsure if I can replicate that type of load locally. Maybe someone spots very obvious mistakes / issues with the table / index / query setup right away that I've missed.
Any help appreciated,
Henrik.
Attachment
"Henrik Peinar (nodeSWAT.com)" <henrik@nodeswat.com> writes:
> *Quick description: *After upgrading our Aurora PostgreSQL engine from v11
> to v15, one of our often run SQL's started taking tens of seconds instead
> of running sub 100ms. Explain analyze showed that the query planner had
> switched to using incremental sort. Running ANALYZE on the table fixed the
> issue temporarily, but it came back after few days.
Hmm. I think it's quite accidental that you get one plan over the other,
because it looks like the key difference is something the planner doesn't
account for. In the fast case you have
-> Index Scan using products_pinned_at_listed_at_ix on products (cost=0.43..3929423.12 rows=26523 width=1463)
(actualtime=2.325..32.872 rows=61 loops=1)
Filter: ((desc_tsv @@ '''nike'':*'::tsquery) AND (status = 'published'::prod_status))
Rows Removed by Filter: 3376
The index is only being used to produce ordered output here: the filter
condition isn't related to the index. And what we see is that the
query is fast because the desired rows are found in the first 3376+61
rows visited in this direction. Meanwhile in the slow case you have
-> Index Scan Backward using products_pinned_at_ix on products (cost=0.43..1172249.47 rows=26139
width=1460)(actual time=5.263..5203.180 rows=18411 loops=1)
Filter: ((desc_tsv @@ '''nike'':*'::tsquery) AND (status = 'published'::prod_status))
Rows Removed by Filter: 5415895
Again, the filter condition isn't exploiting the index, we're just using
the index to (partially) satisfy the ORDER BY. This one takes a long time
because it has to trawl through 5415895+61 rows before reaching the LIMIT.
So AFAICS, the runtime differential is mostly/entirely because the rows
satisfying the filter condition are located near one end of the range of
pinned_at. That is not a correlation that the planner knows anything
about, so it's unable to see that these two ways of scanning the table
will have significantly different costs. Moreover, I think you'd be
mistaken to draw any great conclusions from this specific example,
because with some other search term(s) the results might be totally
different due to the required rows not falling in the same place.
What I'd think about if this type of query is important is to set up
an index that can actually be used to satisfy the filter condition,
so that you're not forcing it into "scan the whole table till you
find the rows you want". It looks like you already have such an
index, ie a GIN index on the desc_tsv column, although I don't trust
that your schema attachment is actually accurate because if it is
then you have a bunch of duplicative indexes. You might try
dropping the other indexes to see if you can coerce the planner
into using that one, and then seeing what the cost estimate is.
regards, tom lane
Re: Help needed to understand query planner regression with incremental sort
From
"Henrik Peinar (nodeSWAT.com)"
Date:
Thank you for taking the time to look this through.
After reading your answer it obviously makes perfect sense, I was just thrown off by a fact that when it started happening, it happened on every query execution (for the same test query that I used). But I failed to think about trying different search keywords to see if that made any difference in the query plan / estimations.
I'll investigate this further and will try to clean the indexes up and make sure the filter has correct index to use.
On Wed, May 31, 2023 at 6:31 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
"Henrik Peinar (nodeSWAT.com)" <henrik@nodeswat.com> writes:
> *Quick description: *After upgrading our Aurora PostgreSQL engine from v11
> to v15, one of our often run SQL's started taking tens of seconds instead
> of running sub 100ms. Explain analyze showed that the query planner had
> switched to using incremental sort. Running ANALYZE on the table fixed the
> issue temporarily, but it came back after few days.
Hmm. I think it's quite accidental that you get one plan over the other,
because it looks like the key difference is something the planner doesn't
account for. In the fast case you have
-> Index Scan using products_pinned_at_listed_at_ix on products (cost=0.43..3929423.12 rows=26523 width=1463) (actual time=2.325..32.872 rows=61 loops=1)
Filter: ((desc_tsv @@ '''nike'':*'::tsquery) AND (status = 'published'::prod_status))
Rows Removed by Filter: 3376
The index is only being used to produce ordered output here: the filter
condition isn't related to the index. And what we see is that the
query is fast because the desired rows are found in the first 3376+61
rows visited in this direction. Meanwhile in the slow case you have
-> Index Scan Backward using products_pinned_at_ix on products (cost=0.43..1172249.47 rows=26139 width=1460) (actual time=5.263..5203.180 rows=18411 loops=1)
Filter: ((desc_tsv @@ '''nike'':*'::tsquery) AND (status = 'published'::prod_status))
Rows Removed by Filter: 5415895
Again, the filter condition isn't exploiting the index, we're just using
the index to (partially) satisfy the ORDER BY. This one takes a long time
because it has to trawl through 5415895+61 rows before reaching the LIMIT.
So AFAICS, the runtime differential is mostly/entirely because the rows
satisfying the filter condition are located near one end of the range of
pinned_at. That is not a correlation that the planner knows anything
about, so it's unable to see that these two ways of scanning the table
will have significantly different costs. Moreover, I think you'd be
mistaken to draw any great conclusions from this specific example,
because with some other search term(s) the results might be totally
different due to the required rows not falling in the same place.
What I'd think about if this type of query is important is to set up
an index that can actually be used to satisfy the filter condition,
so that you're not forcing it into "scan the whole table till you
find the rows you want". It looks like you already have such an
index, ie a GIN index on the desc_tsv column, although I don't trust
that your schema attachment is actually accurate because if it is
then you have a bunch of duplicative indexes. You might try
dropping the other indexes to see if you can coerce the planner
into using that one, and then seeing what the cost estimate is.
regards, tom lane