Обсуждение: Planning time is time-consuming

On Fri, 2023-09-08 at 18:51 +0800, Mikhail Balayan wrote:
> I have three tables:
>     - test_db_bench_1
>     - test_db_bench_tenants
>     - test_db_bench_tenant_closure
>
> And the query to join them:
> SELECT "test_db_bench_1"."id" id, "test_db_bench_1"."tenant_id"
>   FROM "test_db_bench_1"
>   JOIN "test_db_bench_tenants" AS "tenants_child" ON (("tenants_child"."uuid" = "test_db_bench_1"."tenant_id")
>                                                  AND ("tenants_child"."is_deleted" != true))
>   JOIN "test_db_bench_tenant_closure" AS "tenants_closure" ON (("tenants_closure"."child_id" = "tenants_child"."id")
>                                                           AND ("tenants_closure"."barrier" <= 0))
>   JOIN "test_db_bench_tenants" AS "tenants_parent" ON (("tenants_parent"."id" = "tenants_closure"."parent_id")
>                                                   AND ("tenants_parent"."uuid" IN
('4c79c1c5-21ae-45a0-8734-75d67abd0330'))
>                                                   AND ("tenants_parent"."is_deleted" != true))
>  LIMIT 1
>
>
> With following execution plan:
>
>                                                                                                      QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> ---------------
>  Limit  (cost=1.56..1.92 rows=1 width=44) (actual time=0.010..0.011 rows=0 loops=1)
>    ->  Nested Loop  (cost=1.56..162.42 rows=438 width=44) (actual time=0.009..0.009 rows=0 loops=1)
>          ->  Nested Loop  (cost=1.13..50.27 rows=7 width=36) (actual time=0.008..0.009 rows=0 loops=1)
>                ->  Nested Loop  (cost=0.84..48.09 rows=7 width=8) (actual time=0.008..0.009 rows=0 loops=1)
>                      ->  Index Scan using test_db_bench_tenants_uuid on test_db_bench_tenants tenants_parent
 (cost=0.41..2.63rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=1) 
>                            Index Cond: ((uuid)::text = '4c79c1c5-21ae-45a0-8734-75d67abd0330'::text)
>                            Filter: (NOT is_deleted)
>                      ->  Index Scan using test_db_bench_tenant_closure_pkey on test_db_bench_tenant_closure
tenants_closure (cost=0.42..45.06 rows=40 width=16) (never executed) 
>                            Index Cond: (parent_id = tenants_parent.id)
>                            Filter: (barrier <= 0)
>                ->  Index Scan using test_db_bench_tenants_pkey on test_db_bench_tenants tenants_child
 (cost=0.29..0.31rows=1 width=44) (never executed) 
>                      Index Cond: (id = tenants_closure.child_id)
>                      Filter: (NOT is_deleted)
>          ->  Index Scan using test_db_bench_1_idx_tenant_id_3 on acronis_db_bench_heavy  (cost=0.43..14.66 rows=136
width=44)(never executed) 
>                Index Cond: ((tenant_id)::text = (tenants_child.uuid)::text)
>  Planning Time: 0.732 ms
>  Execution Time: 0.039 ms
>
>
> Where the planning time gets in the way as it takes an order of magnitude more time than the actual execution.
>
> Is there a possibility to reduce this time? And, in general, to understand why planning takes so much time.

You could try to VACUUM the involved tables; indexes with many entries pointing to dead tuples
can cause a long planing time.

Also, there are quite a lot of indexes on "test_db_bench_1".  On a test database, drop some
indexes and see if that makes a difference.

Finally, check if "default_statistics_target" is set to a high value, or if the "Stats target"
for some column in the "\d+ tablename" output is set higher than 100.

Yours,
Laurenz Albe

On 11 September 2023 03:15:43 CEST, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
>On Fri, 2023-09-08 at 18:51 +0800, Mikhail Balayan wrote:
>> I have three tables:
>>     - test_db_bench_1
>>     - test_db_bench_tenants
>>     - test_db_bench_tenant_closure
>>
>> And the query to join them:
>> SELECT "test_db_bench_1"."id" id, "test_db_bench_1"."tenant_id"
>>   FROM "test_db_bench_1"
>>   JOIN "test_db_bench_tenants" AS "tenants_child" ON (("tenants_child"."uuid" = "test_db_bench_1"."tenant_id")
>>                                                  AND ("tenants_child"."is_deleted" != true))
>>   JOIN "test_db_bench_tenant_closure" AS "tenants_closure" ON (("tenants_closure"."child_id" = "tenants_child"."id")
>>                                                           AND ("tenants_closure"."barrier" <= 0))
>>   JOIN "test_db_bench_tenants" AS "tenants_parent" ON (("tenants_parent"."id" = "tenants_closure"."parent_id")
>>                                                   AND ("tenants_parent"."uuid" IN
('4c79c1c5-21ae-45a0-8734-75d67abd0330'))
>>                                                   AND ("tenants_parent"."is_deleted" != true))
>>  LIMIT 1
>>
>>
>> With following execution plan:
>>
>>                                                                                                      QUERY PLAN
>>
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>> ---------------
>>  Limit  (cost=1.56..1.92 rows=1 width=44) (actual time=0.010..0.011 rows=0 loops=1)
>>    ->  Nested Loop  (cost=1.56..162.42 rows=438 width=44) (actual time=0.009..0.009 rows=0 loops=1)
>>          ->  Nested Loop  (cost=1.13..50.27 rows=7 width=36) (actual time=0.008..0.009 rows=0 loops=1)
>>                ->  Nested Loop  (cost=0.84..48.09 rows=7 width=8) (actual time=0.008..0.009 rows=0 loops=1)
>>                      ->  Index Scan using test_db_bench_tenants_uuid on test_db_bench_tenants tenants_parent
 (cost=0.41..2.63rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=1) 
>>                            Index Cond: ((uuid)::text = '4c79c1c5-21ae-45a0-8734-75d67abd0330'::text)
>>                            Filter: (NOT is_deleted)
>>                      ->  Index Scan using test_db_bench_tenant_closure_pkey on test_db_bench_tenant_closure
tenants_closure (cost=0.42..45.06 rows=40 width=16) (never executed) 
>>                            Index Cond: (parent_id = tenants_parent.id)
>>                            Filter: (barrier <= 0)
>>                ->  Index Scan using test_db_bench_tenants_pkey on test_db_bench_tenants tenants_child
 (cost=0.29..0.31rows=1 width=44) (never executed) 
>>                      Index Cond: (id = tenants_closure.child_id)
>>                      Filter: (NOT is_deleted)
>>          ->  Index Scan using test_db_bench_1_idx_tenant_id_3 on acronis_db_bench_heavy  (cost=0.43..14.66 rows=136
width=44)(never executed) 
>>                Index Cond: ((tenant_id)::text = (tenants_child.uuid)::text)
>>  Planning Time: 0.732 ms
>>  Execution Time: 0.039 ms
>>
>>
>> Where the planning time gets in the way as it takes an order of magnitude more time than the actual execution.
>>
>> Is there a possibility to reduce this time? And, in general, to understand why planning takes so much time.
>
>You could try to VACUUM the involved tables; indexes with many entries pointing to dead tuples
>can cause a long planing time.
>
>Also, there are quite a lot of indexes on "test_db_bench_1".  On a test database, drop some
>indexes and see if that makes a difference.

You can use pg_stat_user_indexes to check if those indexes are in use or not.



>
>Finally, check if "default_statistics_target" is set to a high value, or if the "Stats target"
>for some column in the "\d+ tablename" output is set higher than 100.
>
>Yours,
>Laurenz Albe
>
>

On Mon, 2023-09-11 at 12:57 +0800, Mikhail Balayan wrote:
> Thanks for the idea. I was surprised to find that this is not the way it works and the planning time remains the
same.

To benefit from the speed gains of a prepared statement, you'd have to execute it
at least seven times.  If a generic plan is used (which should happen), you will
see $1 instead of the literal argument in the execution plan.

Prepared statements are probably your best bet.

Yours,
Laurenz Albe

On Mon, 11 Sept 2023 at 18:16, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
> Also, there are quite a lot of indexes on "test_db_bench_1".  On a test database, drop some
> indexes and see if that makes a difference.

Yeah, I count 3 that either have the key columns as some prefix of
another index or are just a duplicate of some other index.

Getting rid of those 3 will save some time in create_index_paths().

David

On Mon, 11 Sept 2023 at 21:54, Mikhail Balayan <mv.balayan@gmail.com> wrote:
> Could it be a regression? I'll check it on PG14 when I get a chance.

I'm not sure if you're asking for help here because you need planning
to be faster than it currently is, or if it's because you believe that
planning should always be faster than execution. If you think the
latter, then you're mistaken. It seems to me that the complexity of
planning this query is much more complex than executing it.  The outer
side of the inner-most nested loop finds 0 rows, so it need not scan
the inner side, which results in that nested loop producing 0 rows,
therefore the outer side of none of the subsequent nested loops find
any rows. This is why you see "(never executed)" in the EXPLAIN
ANALYZE.

You could use perf record or perf top to dig into what's slow.

On the other hand, please report back if you find PG14 to be much faster here.

You could also experiment with a set of tables which are empty.  It's
possible getting the relation sizes are a factor to consider here.
mdnblocks() needs to do a bit more work when the relation has multiple
segments.

David

David Rowley <dgrowleyml@gmail.com> writes:
> I'm not sure if you're asking for help here because you need planning
> to be faster than it currently is, or if it's because you believe that
> planning should always be faster than execution. If you think the
> latter, then you're mistaken.

Yeah.  I don't see anything particularly troubling here.  Taking
circa three-quarters of a millisecond (on typical current hardware)
to plan a four-way join on large tables is not unreasonable.
In most cases one could expect the execution of such a query to
take a good bit longer than that.  I think the OP is putting too
much emphasis on an edge case where execution finishes quickly
because there are in fact zero rows matching the uuid restriction.

BTW, in addition to the duplicative indexes, I wonder why the
uuid columns being joined on aren't all of "uuid" type.  While
I doubt fixing that would move the needle greatly, it still
seems sloppy.

            regards, tom lane

On Tue, 12 Sept 2023 at 02:27, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> David Rowley <dgrowleyml@gmail.com> writes:
> > I'm not sure if you're asking for help here because you need planning
> > to be faster than it currently is, or if it's because you believe that
> > planning should always be faster than execution. If you think the
> > latter, then you're mistaken.
>
> Yeah.  I don't see anything particularly troubling here.  Taking
> circa three-quarters of a millisecond (on typical current hardware)
> to plan a four-way join on large tables is not unreasonable.

I took a few minutes to reverse engineer the tables in question (with
assistance from an AI bot) and ran the query in question.
Unsurprisingly, I also see planning as slower than execution, but with
a ratio of about planning being 12x slower than execution vs the
reported ~18x.

Planning Time: 0.581 ms
Execution Time: 0.048 ms

Nothing alarming in perf top of executing the query in pgbench with -M
simple.  I think this confirms the problem is just with expectations.

   5.09%  postgres          [.] AllocSetAlloc
   2.99%  postgres          [.] SearchCatCacheInternal
   2.52%  postgres          [.] palloc
   2.38%  postgres          [.] expression_tree_walker_impl
   1.82%  postgres          [.] add_path_precheck
   1.78%  postgres          [.] add_path
   1.73%  postgres          [.] MemoryContextAllocZeroAligned
   1.63%  postgres          [.] base_yyparse
   1.61%  postgres          [.] CatalogCacheComputeHashValue
   1.38%  postgres          [.] try_nestloop_path
   1.36%  postgres          [.] stack_is_too_deep
   1.33%  postgres          [.] add_paths_to_joinrel
   1.19%  postgres          [.] core_yylex
   1.18%  postgres          [.] lappend
   1.15%  postgres          [.] initial_cost_nestloop
   1.13%  postgres          [.] hash_search_with_hash_value
   1.01%  postgres          [.] palloc0
   0.95%  postgres          [.] get_memoize_path
   0.90%  postgres          [.] equal
   0.88%  postgres          [.] get_eclass_for_sort_expr
   0.81%  postgres          [.] compare_pathkeys
   0.80%  postgres          [.] bms_is_subset
   0.77%  postgres          [.] ResourceArrayRemove
   0.77%  postgres          [.] check_stack_depth
   0.77%  libc.so.6         [.] __memmove_avx_unaligned_erms
   0.74%  libc.so.6         [.] __memset_avx2_unaligned
   0.73%  postgres          [.] AllocSetFree
   0.71%  postgres          [.] final_cost_nestloop
   0.69%  postgres          [.] compare_path_costs_fuzzily
   0.68%  postgres          [.] initial_cost_mergejoin
   0.64%  libc.so.6         [.] __memset_avx2_unaligned_erms
   0.61%  postgres          [.] create_nestloop_path
   0.61%  postgres          [.] examine_variable
   0.59%  postgres          [.] hash_bytes
   0.56%  postgres          [.] truncate_useless_pathkeys
   0.56%  postgres          [.] bms_overlap

David