Fwd: Planning time is time-consuming

[Mikhail Balayan <mv.balayan@xxxxxxxxx>]

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 keep the experiment clean, I ran it several times, first a couple of times explain analyze, then a couple of times the query itself:

# PREPARE the_query (varchar) AS
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 ($1))
                                                                AND ("tenants_parent"."is_deleted" != true))
 LIMIT 1;

# explain analyze EXECUTE the_query('4c79c1c5-21ae-45a0-8734-75d67abd0330');
                                                                                                      QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1.98..152.05 rows=1 width=152) (actual time=0.014..0.015 rows=0 loops=1)
   ->  Nested Loop  (cost=1.98..1052.49 rows=7 width=152) (actual time=0.013..0.013 rows=0 loops=1)
         ->  Nested Loop  (cost=1.55..1022.18 rows=7 width=108) (actual time=0.013..0.013 rows=0 loops=1)
               ->  Nested Loop  (cost=1.12..1019.03 rows=7 width=63) (actual time=0.012..0.013 rows=0 loops=1)
                     ->  Index Scan using test_db_bench_tenants_uuid on test_db_bench_tenants tenants_parent  (cost=0.56..2.77 rows=1 width=45) (actual time=0.012..0.012 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.56..1006.97 rows=929 width=18) (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.43..0.45 rows=1 width=45) (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 test_db_bench_1  (cost=0.43..2.98 rows=135 width=44) (never executed)
               Index Cond: ((tenant_id)::text = (tenants_child.uuid)::text)
 Planning Time: 0.982 ms
 Execution Time: 0.059 ms
(17 rows)

# explain analyze EXECUTE the_query('4c79c1c5-21ae-45a0-8734-75d67abd0330');
                                                                                                      QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1.98..152.05 rows=1 width=152) (actual time=0.011..0.012 rows=0 loops=1)
   ->  Nested Loop  (cost=1.98..1052.49 rows=7 width=152) (actual time=0.010..0.011 rows=0 loops=1)
         ->  Nested Loop  (cost=1.55..1022.18 rows=7 width=108) (actual time=0.010..0.011 rows=0 loops=1)
               ->  Nested Loop  (cost=1.12..1019.03 rows=7 width=63) (actual time=0.010..0.010 rows=0 loops=1)
                     ->  Index Scan using test_db_bench_tenants_uuid on test_db_bench_tenants tenants_parent  (cost=0.56..2.77 rows=1 width=45) (actual time=0.010..0.010 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.56..1006.97 rows=929 width=18) (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.43..0.45 rows=1 width=45) (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 test_db_bench_1  (cost=0.43..2.98 rows=135 width=44) (never executed)
               Index Cond: ((tenant_id)::text = (tenants_child.uuid)::text)
 Planning Time: 0.843 ms
 Execution Time: 0.046 ms
(17 rows)

# EXECUTE the_query('4c79c1c5-21ae-45a0-8734-75d67abd0330');
 id | tenant_id
----+-----------
(0 rows)

Time: 1.311 ms

# EXECUTE the_query('4c79c1c5-21ae-45a0-8734-75d67abd0330');
 id | tenant_id
----+-----------
(0 rows)

Time: 1.230 ms

--

Mikhail

On Mon, 11 Sept 2023 at 09:23, Anupam b <abordia99@xxxxxxxxxxx> wrote:

Also, if you write sql with bind params, planning time should be once for the sql.  Subsequent sql will use cached stmt. 

Get Outlook for Android

---

From: Laurenz Albe <laurenz.albe@xxxxxxxxxxx>
Sent: Sunday, September 10, 2023 6:15:43 PM
To: Mikhail Balayan <mv.balayan@xxxxxxxxx>; pgsql-performance@xxxxxxxxxxxxxx <pgsql-performance@xxxxxxxxxxxxxx>
Subject: Re: 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.63 rows=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.31 rows=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