Fwd: Planning time is time-consuming

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(at)hotmail(dot)com> 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 <https://aka.ms/AAb9ysg>
> ------------------------------
> *From:* Laurenz Albe <laurenz(dot)albe(at)cybertec(dot)at>
> *Sent:* Sunday, September 10, 2023 6:15:43 PM
> *To:* Mikhail Balayan <mv(dot)balayan(at)gmail(dot)com>;
> pgsql-performance(at)postgresql(dot)org <pgsql-performance(at)postgresql(dot)org>
> *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
>
>
>