Planning time is time-consuming
Hello,
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.
What I have tried:
- disabled JIT, which resulted in a minor improvement, around 5
microseconds.
- disabled constraint_exclusion, which also didn't have a significant
impact.
Sizes of tables and indexes:
-- test_db_bench_1
List of relations
Schema | Name | Type | Owner | Persistence | Access method |
Size | Description
+-+---++-+---+-+-
public | test_db_bench_1 | table | dbuser | permanent | heap |
5351 MB |
Column | Type | Collation | Nullable
| Default
---++---+--+--
--
id| bigint | | not null
| nextval('test_db_bench_1_id_seq'::regclass)
uuid | uuid | | not null |
checksum | character varying(64) | | not null |
tenant_id | character varying(36) | | not null |
cti_entity_uuid | character varying(36) | | |
euc_id| character varying(64) | | not null |
workflow_id | bigint | | |
state | integer| | not null |
type | character varying(64) | | not null |
queue | character varying(64) | | not null |
priority | integer| | not null |
issuer_id | character varying(64) | | not null |
issuer_cluster_id | character varying(64) | | |
heartbeat_ivl_str | character varying(64) | | |
heartbeat_iv
Fwd: Planning time is time-consuming
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.874 ms
Execution Time: 0.053 ms
(17 rows)
The planning time even increased :)
Played around with the indexes:
Firstly I dropped all the indexes that contained tenant_id field, except
the one that is used in the execution plan:
DROP INDEX test_db_bench_1_idx_type_16;
DROP INDEX test_db_bench_1_idx_queue_18;
DROP INDEX test_db_bench_1_idx_queue_5;
After that:
Planning Time: 0.889 ms
Execution Time: 0.047 ms
DROP INDEX test_db_bench_1_idx_uuid_0;
Planning Time: 0.841 ms
Execution Time: 0.047 ms
DROP INDEX test_db_bench_1_idx_completion_time_ns_1;
DROP INDEX test_db_bench_1_idx_cti_entity_uuid_2;
DROP INDEX test_db_bench_1_idx_enqueue_time_ns_10;
Planning Time: 0.830 ms
Execution Time: 0.048 ms
DROP INDEX test_db_bench_1_idx_euc_id_4;
DROP INDEX test_db_bench_1_idx_policy_id_12;
DROP INDEX test_db_bench_1_idx_queue_19;
Planning Time: 0.826 ms
Execution Time: 0.044 ms
DROP INDEX test_db_bench_1_idx_queue_6;
DROP INDEX test_db_bench_1_idx_resource_id_11;
DROP INDEX test_db_bench_1_idx_resource_id_14;
Planning Time: 0.821 ms
Execution Time: 0.048 ms
DROP INDEX test_db_bench_1_idx_result_code_13;
DROP INDEX test_db_bench_1_idx_start_time_ns_9;
DROP INDEX test_db_bench_1_idx_state_8;
Planning Time: 0.803 ms
Execution Time: 0.044 ms
DROP INDEX test_db_bench_1_idx_type_15;
DROP INDEX test_db_bench_1_idx_type_17;
DROP INDEX test_db_bench_1_idx_update_time_ns_7;
At that moment only 3 indexes left on the table and a slight improvements
in Planning Time:
Indexes:
"test_db_bench_1_pkey" PRIMARY KEY, btree (id)
"test_db_bench_1_idx_tenant_id_3" btree (tenant_id)
"test_db_bench_1_uuid_key" UNIQUE CONSTRAINT, btree (uuid)
Planning Time: 0.799 ms
Execution Time: 0.044 ms
I.e. the situation is still not good - almost all indexes have been
removed, the planning time has been reduced insignificantly and it still
remains much longer than the query execution time.
As for the stats - default_statistics_target has not been changed, has a
value of 100, and no explicit settings for the columns have been applied
("Stats target" is empty).
Could it be a regression? I'll check it on PG14 when I get a chance.
--
Mikhail
On Mon, 11 Sept 2023 at 09:15, Laurenz Albe
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.0
Fwd: Planning time is time-consuming
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 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
> *Sent:* Sunday, September 10, 2023 6:15:43 PM
> *To:* Mikhail Balayan ;
> [email protected]
> *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
>
>
>
