Обсуждение: Query run in 27s with 15.2 vs 37ms with 14.6

Charles <peacech@gmail.com> writes:
> I have just upgraded my postgresql from 14.6 to 15.2 and my query that runs
> in 37ms in 14.6 run requires 27 seconds to complete. The table is a typical
> OHLC table (date date, code text, open int, high int, low int, close int,
> volume bigint, value bigint), 2725207 rows in table.

You need to do something to fix this poor row-count estimate:

>   ->  Index Scan using idx_stock_price_date on stock_price s
>  (cost=0.43..1152.53 rows=1 width=29) (actual time=0.180..4.060 rows=779 loops=1)
>         Index Cond: (date = '2023-02-20'::date)
>         Filter: ((open > 0) AND (value > 0) AND (length(code) = 4))
>         Rows Removed by Filter: 210

Considering that 14.x also estimated this as returning only one row,
I'm fairly surprised that you didn't get the same poor plan choice there.

The length(code) condition suggests a fairly poor choice of data
representation; can you change that?

On Mon, Feb 20, 2023 at 11:11 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Charles <peacech@gmail.com> writes:
> I have just upgraded my postgresql from 14.6 to 15.2 and my query that runs
> in 37ms in 14.6 run requires 27 seconds to complete. The table is a typical
> OHLC table (date date, code text, open int, high int, low int, close int,
> volume bigint, value bigint), 2725207 rows in table.

You need to do something to fix this poor row-count estimate:

>   ->  Index Scan using idx_stock_price_date on stock_price s
>  (cost=0.43..1152.53 rows=1 width=29) (actual time=0.180..4.060 rows=779 loops=1)
>         Index Cond: (date = '2023-02-20'::date)
>         Filter: ((open > 0) AND (value > 0) AND (length(code) = 4))
>         Rows Removed by Filter: 210

Considering that 14.x also estimated this as returning only one row,
I'm fairly surprised that you didn't get the same poor plan choice there.

The length(code) condition suggests a fairly poor choice of data
representation; can you change that?

Thanks, removing the length filter do restore the execution time to 30ms.

The plan from 15.2:

Nested Loop  (cost=63003.26..64440.14 rows=1 width=89) (actual time=23.234..27407.834 rows=779 loops=1)

Plan generated by 14.6

Merge Join  (cost=61456.65..61716.09 rows=1 width=89) (actual time=25.509..37.185 rows=779 loops=1)

On Mon, Feb 20, 2023 at 10:56 AM Charles <peacech@gmail.com> wrote:

 

The plan from 15.2:

Nested Loop  (cost=63003.26..64440.14 rows=1 width=89) (actual time=23.234..27407.834 rows=779 loops=1)

 

Plan generated by 14.6

Merge Join  (cost=61456.65..61716.09 rows=1 width=89) (actual time=25.509..37.185 rows=779 loops=1)

Given how close those plan estimates are to each other, I would say your query was very fragile under 14.6, and it was just a matter of luck of how the statistics were computed that you got the better plan on the older version.  As opposed to some important coding changes that happened between versions.  To verify that, Can you force each version to choose the other plan, for example by fiddling with enable_nestedloop on one and enable_mergjoin on the other?

Greetings,

* Charles (peacech@gmail.com) wrote:
> Wrapping the query with a select * from (...) t where length(code) = 4 puts
> the execution time back to 27 seconds.
>
> This is a bit unexpected since I expect that the result from the inner
> query to be executed first and then filtered.

It's really not- PG will (correctly) attempt to pull in such subselects
into the overall optimization, which is generally better for everyone.
If you want to force it, you can use a WITH MATERIALIZED CTE, or throw
in an 'OFFSET 0' as a hack into your sub-select, but really it's a much
better idea to generate extended stats on what you're filtering as has
been suggested, or come up with a better data representation where
you're not doing a search on a 'length()' as you are.

On Tue, Feb 21, 2023 at 3:58 AM Stephen Frost <sfrost@snowman.net> wrote:

Greetings,

* Charles (peacech@gmail.com) wrote:
> Wrapping the query with a select * from (...) t where length(code) = 4 puts
> the execution time back to 27 seconds.
>
> This is a bit unexpected since I expect that the result from the inner
> query to be executed first and then filtered.

It's really not- PG will (correctly) attempt to pull in such subselects
into the overall optimization, which is generally better for everyone.
If you want to force it, you can use a WITH MATERIALIZED CTE, or throw
in an 'OFFSET 0' as a hack into your sub-select, but really it's a much
better idea to generate extended stats on what you're filtering as has
been suggested, or come up with a better data representation where
you're not doing a search on a 'length()' as you are.

Generating extended statistics on the expression (length(code)) causes the planner to generate has join which runs in 183ms (still slower than 37ms on 14.6). Using materialized cte (no extended stats) results in nested loop that runs in 229ms. I think I'll revert back to postgresql 14 for now. Thank you for the suggestions.

Greetings,

On Mon, Feb 20, 2023 at 20:54 Charles <peacech@gmail.com> wrote:

On Tue, Feb 21, 2023 at 3:58 AM Stephen Frost <sfrost@snowman.net> wrote:

Greetings,

* Charles (peacech@gmail.com) wrote:
> Wrapping the query with a select * from (...) t where length(code) = 4 puts
> the execution time back to 27 seconds.
>
> This is a bit unexpected since I expect that the result from the inner
> query to be executed first and then filtered.

It's really not- PG will (correctly) attempt to pull in such subselects
into the overall optimization, which is generally better for everyone.
If you want to force it, you can use a WITH MATERIALIZED CTE, or throw
in an 'OFFSET 0' as a hack into your sub-select, but really it's a much
better idea to generate extended stats on what you're filtering as has
been suggested, or come up with a better data representation where
you're not doing a search on a 'length()' as you are.

Generating extended statistics on the expression (length(code)) causes the planner to generate has join which runs in 183ms (still slower than 37ms on 14.6). Using materialized cte (no extended stats) results in nested loop that runs in 229ms. I think I'll revert back to postgresql 14 for now. Thank you for the suggestions.

As pointed out elsewhere, the query costs seem pretty close and so you’re likely going to get with the bad plan at some point on 14 also. Have you tried tweaking the statistics target?  Might help.  Though really, as was said before, modeling the data better likely would help a lot. 

On Tue, 21 Feb 2023 at 14:38, Charles <peacech@gmail.com> wrote:
> Disabling mergejoin on 14.6 and disabling nestedloop on 15.2 causes both to use hashjoin where it runs for 37ms in 14.6 and 208ms in 15.2.
>
> 14.6:
>                           ->  Parallel Index Scan using idx_stock_price_date on stock_price  (cost=0.43..59671.39 rows=81248 width=13) (actual time=0.021..0.689 rows=1427 loops=3)
>                                 Index Cond: (date > $0)
>                                 Filter: (value > 0)
>                                 Rows Removed by Filter: 222

> 15.2:
>                                       ->  Parallel Seq Scan on stock_price  (cost=0.00..64038.54 rows=91275 width=13) (actual time=130.043..173.124 rows=1427 loops=3)
>                                             Filter: ((value > 0) AND (date > $0))
>                                             Rows Removed by Filter: 906975

The difference in the two above fragments likely accounts for the
majority of the remaining performance difference.  Possibly 15.2 is
using a Seq Scan because it's estimating slightly more rows from
stock_price for these two quals. For the date > $0 qual, the stats
don't really help as the planner does not know what $0 will be during
planning, so it'll just assume that the selectivity is 1/3rd of rows.
For the value > 0, there could be some variation there just between
ANALYZE runs. That might be enough to account for the difference in
estimate between 14 and 15.

You might also want to check that effective_cache_size is set to
something realistic on 15. random_page_cost is also a factor for index
scan vs seq scan. 

On Tue, Feb 21, 2023 at 2:25 AM Jeff Janes <jeff.janes@gmail.com> wrote:

On Mon, Feb 20, 2023 at 10:56 AM Charles <peacech@gmail.com> wrote:

 

The plan from 15.2:

Nested Loop  (cost=63003.26..64440.14 rows=1 width=89) (actual time=23.234..27407.834 rows=779 loops=1)

 

Plan generated by 14.6

Merge Join  (cost=61456.65..61716.09 rows=1 width=89) (actual time=25.509..37.185 rows=779 loops=1)

Given how close those plan estimates are to each other, I would say your query was very fragile under 14.6, and it was just a matter of luck of how the statistics were computed that you got the better plan on the older version.  As opposed to some important coding changes that happened between versions.  To verify that, Can you force each version to choose the other plan, for example by fiddling with enable_nestedloop on one and enable_mergjoin on the other?

Disabling mergejoin on 14.6 and disabling nestedloop on 15.2 causes both to use hashjoin where it runs for 37ms in 14.6 and 208ms in 15.2.