Обсуждение: Seeing high query planning time on Azure Postgres Single Server version 11.

It'd be worth checking that your default_statistics_target isn't set
to anything wild, but beyond that, it'd be interesting to look at the
output of vacuum verbose on some of the system catalogs as istm you
might have catalog bloat.

I should also mention that you're running a non-longer-supported
version of Postgres (v11) and not even the latest release of said EOL
version. And if I am not mistaken, "Azure Postgres single server
version" is also deprecated, so you should really focus on getting
upgraded to something more modern.

Robert Treat
https://xzilla.net

On Sat, Mar 9, 2024 at 8:12 AM hassan rafi <haassaan.khann@gmail.com> wrote:
>
> Postgres version: PostgreSQL 11.18, compiled by Visual C++ build 1800, 64-bit
> relname              |relpages|reltuples|relallvisible|relkind|relnatts|relhassubclass|reloptions|pg_table_size|
> ---------------------+--------+---------+-------------+-------+--------+--------------+----------+-------------+
> store_seller_products|16007942|843460096|       797033|r      |      16|false         |NULL      | 131980795904|
>
>
> relname                 |relpages|reltuples|relallvisible|relkind|relnatts|relhassubclass|reloptions|pg_table_size|
> ------------------------+--------+---------+-------------+-------+--------+--------------+----------+-------------+
> products_inventory_delta| 2847202|259351648|      1606201|r      |       4|false         |NULL      |  23330758656|
>
> Peak load (write): 3000 TPS (mostly updates).
> Peak load (read): 800 TPS.
>
>
> On Sat, Mar 9, 2024 at 5:58 PM Ron Johnson <ronljohnsonjr@gmail.com> wrote:
>>
>> On Sat, Mar 9, 2024 at 7:18 AM hassan rafi <haassaan.khann@gmail.com> wrote:
>>>
>>> Hi team,
>>>
>>> We are seeing unusually high query planning times on our Postgres server. I am attaching a few query plans.
>>
>>
>> Postgresql version number?
>> Rows in the tables?
>> System load?

hassan rafi <haassaan.khann@gmail.com> writes:
> The issue of high query planning time seems to intermittently resolve
> itself, only to reoccur after a few hours.

I wonder if you are running into the lack of this fix:

Author: Tom Lane <tgl@sss.pgh.pa.us>
Branch: master Release: REL_16_BR [9c6ad5eaa] 2022-11-22 14:40:20 -0500
Branch: REL_15_STABLE Release: REL_15_2 [2debceed2] 2022-11-22 14:40:44 -0500
Branch: REL_14_STABLE Release: REL_14_7 [bd06fe4de] 2022-11-22 14:40:45 -0500
Branch: REL_13_STABLE Release: REL_13_10 [6e639267a] 2022-11-22 14:40:45 -0500
Branch: REL_12_STABLE Release: REL_12_14 [ec10b6139] 2022-11-22 14:40:45 -0500
Branch: REL_11_STABLE Release: REL_11_19 [b96a096db] 2022-11-22 14:40:46 -0500

    YA attempt at taming worst-case behavior of get_actual_variable_range.

    We've made multiple attempts at preventing get_actual_variable_range
    from taking an unreasonable amount of time (3ca930fc3, fccebe421).
    But there's still an issue for the very first planning attempt after
    deletion of a large number of extremal-valued tuples.  While that
    planning attempt will set "killed" bits on the tuples it visits and
    thereby reduce effort for next time, there's still a lot of work it
    has to do to visit the heap and then set those bits.  It's (usually?)
    not worth it to do that much work at plan time to have a slightly
    better estimate, especially in a context like this where the table
    contents are known to be mutating rapidly.

    Therefore, let's bound the amount of work to be done by giving up
    after we've visited 100 heap pages.  Giving up just means we'll
    fall back on the extremal value recorded in pg_statistic, so it
    shouldn't mean that planner estimates suddenly become worthless.

    Note that this means we'll still gradually whittle down the problem
    by setting a few more index "killed" bits in each planning attempt;
    so eventually we'll reach a good state (barring further deletions),
    even in the absence of VACUUM.

    Simon Riggs, per a complaint from Jakub Wartak (with cosmetic
    adjustments by me).  Back-patch to all supported branches.

    Discussion: https://postgr.es/m/CAKZiRmznOwi0oaV=4PHOCM4ygcH4MgSvt8=5cu_vNCfc8FSUug@mail.gmail.com

As noted, that did make it into the 11.x branch, but not till 11.19.

            regards, tom lane

On Fri, 15 Mar 2024 at 08:01, hassan rafi <haassaan.khann@gmail.com> wrote:
> We have migrated to postgres version 16.1, but still due to very high update activity on our DB, we are seeing
elevatedresponse times, though now the planning time is less.
 

>    Buffers: shared hit=33359 read=6590 dirtied=9379

>  Execution Time: 5049.131 ms

You could try "SET track_io_timing = 1;" to see how much of that time
is spent in reads.

David

On Fri, 2024-03-15 at 00:31 +0530, hassan rafi wrote:
> We have migrated to postgres version 16.1, but still due to very high update
> activity on our DB, we are seeing elevated response times, though now the
> planning time is less.
>
> catalog-v2=> explain (analyze, verbose, settings, buffers) SELECT products_inventory_delta.upc FROM
products_inventory_deltaWHERE products_inventory_delta.modality = 'pickup' AND products_inventory_delta.store_id =
'70600372'ORDER BY upc DESC LIMIT 51 OFFSET 30000; 
>                                                                                             QUERY PLAN              
                                                                             
>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Limit  (cost=1450.68..1450.73 rows=1 width=14) (actual time=5049.115..5049.116 rows=0 loops=1)
>    Output: upc
>    Buffers: shared hit=33359 read=6590 dirtied=9379
>    ->  Index Only Scan Backward using products_inventory_delta_pkey on public.products_inventory_delta 
(cost=0.57..1450.68rows=28606 width=14) (actual time=1.056..5047.472 rows=28299 loops=1) 
>          Output: upc
>          Index Cond: ((products_inventory_delta.store_id = '70600372'::text) AND (products_inventory_delta.modality =
'pickup'::modality))
>          Heap Fetches: 16840
>          Buffers: shared hit=33359 read=6590 dirtied=9379
>  Settings: effective_cache_size = '192GB', jit = 'off', random_page_cost = '2', work_mem = '2097151kB'
>  Query Identifier: 220372279818787780
>  Planning Time: 0.062 ms
>  Execution Time: 5049.131 ms

Your problem are probably the "Heap Fetches: 16840".

If you VACUUM the table, the performance should improve.

The best solution is to make sure that autovacuum processes that table more often:

  ALTER TABLE public.products_inventory_delta SET (autovacuum_vacuum_scale_factor = 0.01);

Yours,
Laurenz Albe