Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1qfVel-00BYN8-9z for pgsql-performance@arkaria.postgresql.org; Mon, 11 Sep 2023 01:24:04 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1qfVek-00CWTG-1G for pgsql-performance@arkaria.postgresql.org; Mon, 11 Sep 2023 01:24:01 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1qfVej-00CWSx-3V for pgsql-performance@lists.postgresql.org; Mon, 11 Sep 2023 01:24:01 +0000 Received: from mail-dm6nam12olkn2104.outbound.protection.outlook.com ([40.92.22.104] helo=NAM12-DM6-obe.outbound.protection.outlook.com) by magus.postgresql.org with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1qfVeZ-004M83-Cd for pgsql-performance@postgresql.org; Mon, 11 Sep 2023 01:24:00 +0000 ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=L/6/f7zikEGcq7EzwxTZ6dM3mJM1T0N1k+fKJO6fTAUFVb5J0zCNN0zu6zNSH1FWYoMxgwwI/Z70l7KPpyQLeo/p6hR+BBnTrDL1igi3iH4/a372QHBjQ1thjpBtktj+wuDwiLwfHzSKGPv+nesjEKR3qG29H8CYeI6NrSd+p9qOlahTrxfSCqvN8LwDr0trTsKGZ4upDvVd1BCDrE9ra9KIXxNJJVdUX0IxA+2ceD9+QrRb0kJ/uVERc3e2kl3V5bohwO8yPpgXFpQizGVfr7N2xjwIWG+0E+OZx2JYvsgeGcQy9yk8DUkrPIuNyVhWnV5Ne3MlDfba5SKlrKvHxQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-AntiSpam-MessageData-ChunkCount:X-MS-Exchange-AntiSpam-MessageData-0:X-MS-Exchange-AntiSpam-MessageData-1; bh=vIYK9nDd58/gFHUqn1fgdQqltAeHEtuSne458REPFLU=; b=FXwT/x+cfTu8HrshHar6YKMmKrpYHQYsB0QhjO7z1eYEf28io+x0BIGSSN0NCsnObWrJWn0xesnCPNTtIY7cenTXigmJr8i/tv3ujO8e/eBozDh+EVieEOG034mcVnHyPsbSiflBE1qeiJaUwueFyPKddWscw8DQpiDoAo5Q9FptOvq/2YGb17NbxZHvOK1xN3vIhSeUzGnTqamFrNkzF3IDB2of98z3Nl9LKeurwhzfzTA5lc093pW5+Kf8RSSKvLeVa/9i+Faj0b2IbUspGusJ2vLZUq34FhuWEiun/d3p9PEiMZCgO3h4lexvnS1SkiLT8CRKVYowe+FKhbgSGg== ARC-Authentication-Results: i=1; mx.microsoft.com 1; spf=none; dmarc=none; dkim=none; arc=none DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=hotmail.com; s=selector1; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=vIYK9nDd58/gFHUqn1fgdQqltAeHEtuSne458REPFLU=; b=rU7Hln45R4qEZJWiOq0jxcdQBipTGu9X2l4xnXaWbgYIZLxGyitlhJ1jrVuQcNANFGLVZfDOss9T9ISpPOVSRoU1DdVyiYIP7ckOPXB/BhPxzhkHGeuzKFJf1PyA8LdFnmMqXyQHQYjKYZuPQSG6dvEiUo+fPIEBkpcObrLgvKyd2Klf8ut4I8uHP8B4gBn3ofui2hb7zY9miiqVOXEypU4zSR9sKhns0vGqNxaNvQk85IjFB0w9rl6NifWtjfQls+WC2LAaU5RkRw5FyIrAweNiPeLf5jTKy9iWFL7YyUln1DVmqxZ/gxW1G5dSuhz1/wU5jSptrvs81EHKl1iO9g== Received: from DM4PR20MB5725.namprd20.prod.outlook.com (2603:10b6:8:107::13) by SJ0PR20MB5184.namprd20.prod.outlook.com (2603:10b6:a03:44c::22) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.6745.34; Mon, 11 Sep 2023 01:23:47 +0000 Received: from DM4PR20MB5725.namprd20.prod.outlook.com ([fe80::fa62:3b1d:a054:7869]) by DM4PR20MB5725.namprd20.prod.outlook.com ([fe80::fa62:3b1d:a054:7869%3]) with mapi id 15.20.6745.034; Mon, 11 Sep 2023 01:23:47 +0000 From: Anupam b To: Laurenz Albe , Mikhail Balayan , "pgsql-performance@postgresql.org" Subject: Re: Planning time is time-consuming Thread-Topic: Planning time is time-consuming Thread-Index: AQHZ5DnsJFFeF1Bj6kKphUVMGTIWprAU0oSAgAAB4HA= Date: Mon, 11 Sep 2023 01:23:46 +0000 Message-ID: References: <5ef3acf5733d5a8584b09eb5dd107e59aa87a075.camel@cybertec.at> In-Reply-To: <5ef3acf5733d5a8584b09eb5dd107e59aa87a075.camel@cybertec.at> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-ms-exchange-messagesentrepresentingtype: 1 x-tmn: [5/tD8MBEWuW0nSXa7eHkWUbe6FP8Ws1L] x-ms-publictraffictype: Email x-ms-traffictypediagnostic: DM4PR20MB5725:EE_|SJ0PR20MB5184:EE_ x-ms-office365-filtering-correlation-id: f6cb9402-0771-47f8-ba56-08dbb265bf10 x-microsoft-antispam: BCL:0; x-microsoft-antispam-message-info: oOGnfYhqhg1fJE+fOrCgEw3pyToj6HzH8gBJJIbawCmwfWFVktM3I0lnkRE/G2wsFjh+pHV+R6K36rCVhNJjPUSDTxNmE5kF6aOFGVXpCN6iQIvcsZxrf995YE2G0k8QnutWGKdlch+gEsQa25NJVqZY7npWFLO3Kn2dsc7nL1Zn7B6bkhlSxXZFtME+kFhDBx/z7TmnYHK0Dc+WOB7qaw+P9pFNc2HI96Yqdmot1xwHuWK5Pv6nsbJWQ2WfYjc7NfTwqdlAWPGMrfPskYyCGq37ZWfFg1x+IK5YK4p8/tw1Aam65qu2SbWykhYtlt80T1oep2qB+JP8d4BpSRY5AARdNI4aq4kNteLIb8w6zqJSwOjMIGy9rl/wd4q8UI9Y7bZ4jRfocWGfp25w1dzMvCxd/NmZkqRba/0pkhZiwoc3hQXcqcVVZZp2C1c/c1/EETtmN7JDauF4/YGNK8t2drh8a3CzhUr1Xmjdnn1a0d88MgUOzFIjGwse6kD1jiE01IrtUhi71SGdlSMN2KW2Y/CaTmfFyMAhayrWeJdidv4Vl1EMZEcNOjSAnJh1zEZmPHUe0LHZd6NXAdEv82ylptru0cYc7oHnQBUBppvLGTk= x-ms-exchange-antispam-messagedata-chunkcount: 1 x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?phZfPsCQBn9TbNAHBlCUtLQAoTc+cNw6rCbTcr4B8C+p+LurrxJXHFuvqrJA?= =?us-ascii?Q?4cJmXjfYPBOrLm19cotwuSbbc3pYIW3/PofT7t9VFOO5vxlFx1Zt8LV9YPB7?= =?us-ascii?Q?jqVk57K8meuisXxbcTcnJRFxr2Vsww3M27J1s5FEz4Dn49kdzRjXfWeHVSUj?= =?us-ascii?Q?ZH54KZi3QH4z3X0zk/CEenXmmZt+hMnbYHADBlad22h6Sy09iT1F2xKfx/2A?= =?us-ascii?Q?sRE6FXVvIXEithvcCfMKHlTRL0GLnqTdAlpKlvwMnow6fojEE05EJUxJcFV3?= =?us-ascii?Q?VXj68i0blvIjfWe5jkjoAFZV/kHoi+KRA2WLNmrqfXI1/Ov8rnly0oWLQWL7?= =?us-ascii?Q?tXhnZK32QtlEvnETOUh7pHKheW+I/kx5fW2WtRg0OqDRF4x9XJIOeW4u1VmD?= =?us-ascii?Q?/7G1cloffarKCZSY3/tPVMRYdiHc8JBRhoPEF1g+G0yr1dfqs9xvmSKhBiUs?= =?us-ascii?Q?EZTpZKjH2/4t0ZYLwnVUkhIgUb/a8L8io4bSQ87ecCQPv32f35x35tdAZ/yn?= =?us-ascii?Q?M6vYg1YUzDN4NfFzRvbofc8zqjNmIGWc58CO8K+xKZ9VXibBDM6c2V/Buc6I?= =?us-ascii?Q?yDI0U81r0ZYjrIL87m21iOqAt9g7h0YN71Zpwm+wqBC/kRMs4TGebikK4otz?= =?us-ascii?Q?JTz0XWAGlFEHqK9WcDa3qpp6u+M+LgeZ9OzfNnzyE02cF/Jti1cdpaCeRwpe?= =?us-ascii?Q?c4aPw7ESEaWPTLTaGm6MYKyX11ZZCw2+0yyuWcowgkU9c8LcksIezg7lxK9I?= =?us-ascii?Q?8qJPSezy7t1/VzwHBc0TA7Kbc5ms3ipgE9CO8XJ+YpdzkeeoUiNLwCUNQRNd?= =?us-ascii?Q?fzTzenSvCRT/Yyw7nYLp6bOVplxBxjR0aqJkrzoXRiu9eNiW/Ggcl2w7rpaR?= =?us-ascii?Q?bPeQG+T1DkHEq97l2oeBvXLb6cGo3RSudotExy8TzOyGMu+eIy/+zYUdj2i1?= =?us-ascii?Q?fmG0ppLurCE/Zvi5+vv5t782olIKBkqLsSP7YUK5uIppueDtYs2xiC/b/NIL?= =?us-ascii?Q?N2ZwJKAp/P8jVKAAwt5DsP2vRDlv0tYpON5kIgN46J6J0OTm+BRUwM4+TG76?= =?us-ascii?Q?vX2PRkpgQjC6EplLI7pON53TjZ7SLX/Lly0PRXQGVRSDO0HsS0mUu6Qt4SOM?= =?us-ascii?Q?iWvrLjBnUXAkjRUOK7RBly9Vk8/PPlkAtzK6Dc8dK73TdnHWeU7LhBjw0JVw?= =?us-ascii?Q?sY21Ow+5LqefIBbn0BBvDrRpFmtfnv292viNr2GdowgSORM8zLkDbwNIZjE?= =?us-ascii?Q?=3D?= Content-Type: multipart/alternative; boundary="_000_DM4PR20MB57256A764C408DE596ECD405BDF2ADM4PR20MB5725namp_" MIME-Version: 1.0 X-OriginatorOrg: sct-15-20-4755-11-msonline-outlook-9803a.templateTenant X-MS-Exchange-CrossTenant-AuthAs: Internal X-MS-Exchange-CrossTenant-AuthSource: DM4PR20MB5725.namprd20.prod.outlook.com X-MS-Exchange-CrossTenant-RMS-PersistedConsumerOrg: 00000000-0000-0000-0000-000000000000 X-MS-Exchange-CrossTenant-Network-Message-Id: f6cb9402-0771-47f8-ba56-08dbb265bf10 X-MS-Exchange-CrossTenant-originalarrivaltime: 11 Sep 2023 01:23:46.9640 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: 84df9e7f-e9f6-40af-b435-aaaaaaaaaaaa X-MS-Exchange-CrossTenant-rms-persistedconsumerorg: 00000000-0000-0000-0000-000000000000 X-MS-Exchange-Transport-CrossTenantHeadersStamped: SJ0PR20MB5184 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --_000_DM4PR20MB57256A764C408DE596ECD405BDF2ADM4PR20MB5725namp_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Also, if you write sql with bind params, planning time should be once for t= he sql. Subsequent sql will use cached stmt. Get Outlook for Android ________________________________ From: Laurenz Albe Sent: Sunday, September 10, 2023 6:15:43 PM To: Mikhail Balayan ; pgsql-performance@postgresql.or= g 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"."u= uid" =3D "test_db_bench_1"."tenant_id") > AND ("tenants_child"."is= _deleted" !=3D true)) > JOIN "test_db_bench_tenant_closure" AS "tenants_closure" ON (("tenants_= closure"."child_id" =3D "tenants_child"."id") > AND ("tenants_c= losure"."barrier" <=3D 0)) > JOIN "test_db_bench_tenants" AS "tenants_parent" ON (("tenants_parent".= "id" =3D "tenants_closure"."parent_id") > AND ("tenants_parent"."= uuid" IN ('4c79c1c5-21ae-45a0-8734-75d67abd0330')) > AND ("tenants_parent"."= is_deleted" !=3D true)) > LIMIT 1 > > > With following execution plan: > > = QUERY PLAN > -------------------------------------------------------------------------= ---------------------------------------------------------------------------= -------------------------------------------------- > --------------- > Limit (cost=3D1.56..1.92 rows=3D1 width=3D44) (actual time=3D0.010..0.0= 11 rows=3D0 loops=3D1) > -> Nested Loop (cost=3D1.56..162.42 rows=3D438 width=3D44) (actual t= ime=3D0.009..0.009 rows=3D0 loops=3D1) > -> Nested Loop (cost=3D1.13..50.27 rows=3D7 width=3D36) (actua= l time=3D0.008..0.009 rows=3D0 loops=3D1) > -> Nested Loop (cost=3D0.84..48.09 rows=3D7 width=3D8) (= actual time=3D0.008..0.009 rows=3D0 loops=3D1) > -> Index Scan using test_db_bench_tenants_uuid on t= est_db_bench_tenants tenants_parent (cost=3D0.41..2.63 rows=3D1 width=3D8)= (actual time=3D0.008..0.008 rows=3D0 loops=3D1) > Index Cond: ((uuid)::text =3D '4c79c1c5-21ae-4= 5a0-8734-75d67abd0330'::text) > Filter: (NOT is_deleted) > -> Index Scan using test_db_bench_tenant_closure_pk= ey on test_db_bench_tenant_closure tenants_closure (cost=3D0.42..45.06 row= s=3D40 width=3D16) (never executed) > Index Cond: (parent_id =3D tenants_parent.id) > Filter: (barrier <=3D 0) > -> Index Scan using test_db_bench_tenants_pkey on test_db= _bench_tenants tenants_child (cost=3D0.29..0.31 rows=3D1 width=3D44) (neve= r executed) > Index Cond: (id =3D 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=3D0.43..14.66 rows=3D136 width=3D44) (never executed) > Index Cond: ((tenant_id)::text =3D (tenants_child.uuid)::t= ext) > 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 understan= d why planning takes so much time. You could try to VACUUM the involved tables; indexes with many entries poin= ting 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 dat= abase, 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 --_000_DM4PR20MB57256A764C408DE596ECD405BDF2ADM4PR20MB5725namp_ Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable
Also, if you write sql with bind params, planning time sh= ould be once for the sql.  Subsequent sql will use cached stmt. <= /div>
From: Laurenz Albe <laur= enz.albe@cybertec.at>
Sent: Sunday, September 10, 2023 6:15:43 PM
To: Mikhail Balayan <mv.balayan@gmail.com>; pgsql-performance@= postgresql.org <pgsql-performance@postgresql.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_be= nch_1"."tenant_id"
>   FROM "test_db_bench_1"
>   JOIN "test_db_bench_tenants" AS "tenants_child&q= uot; ON (("tenants_child"."uuid" =3D "test_db_benc= h_1"."tenant_id")
>                     =                      = ;        AND ("tenants_child"."is_delete= d" !=3D true))
>   JOIN "test_db_bench_tenant_closure" AS "tenants_= closure" ON (("tenants_closure"."child_id" =3D &qu= ot;tenants_child"."id")
>                     =                      = ;                 AND ("tenant= s_closure"."barrier" <=3D 0))
>   JOIN "test_db_bench_tenants" AS "tenants_parent&= quot; ON (("tenants_parent"."id" =3D "tenants_clos= ure"."parent_id")
>                     =                      = ;         AND ("tenants_parent"."uuid&qu= ot; IN ('4c79c1c5-21ae-45a0-8734-75d67abd0330'))
>                     =                      = ;         AND ("tenants_parent"."is_dele= ted" !=3D true))
>  LIMIT 1
>
>
> With following execution plan:
>
>                     =                      = ;                     &nb= sp;                     &= nbsp;                QUERY PLAN
> ----------------------------------------------------------------------= ---------------------------------------------------------------------------= -----------------------------------------------------
> ---------------
>  Limit  (cost=3D1.56..1.92 rows=3D1 width=3D44) (actual time= =3D0.010..0.011 rows=3D0 loops=3D1)
>    ->  Nested Loop  (cost=3D1.56..162.42 rows= =3D438 width=3D44) (actual time=3D0.009..0.009 rows=3D0 loops=3D1)
>          ->  Nested Loop  (cost= =3D1.13..50.27 rows=3D7 width=3D36) (actual time=3D0.008..0.009 rows=3D0 lo= ops=3D1)
>                ->  Nes= ted Loop  (cost=3D0.84..48.09 rows=3D7 width=3D8) (actual time=3D0.008= ..0.009 rows=3D0 loops=3D1)
>                     =  ->  Index Scan using test_db_bench_tenants_uuid on test_db_be= nch_tenants tenants_parent  (cost=3D0.41..2.63 rows=3D1 width=3D8) (ac= tual time=3D0.008..0.008 rows=3D0 loops=3D1)
>                     =        Index Cond: ((uuid)::text =3D '4c79c1c5-21ae-45a= 0-8734-75d67abd0330'::text)
>                     =        Filter: (NOT is_deleted)
>                     =  ->  Index Scan using test_db_bench_tenant_closure_pkey on tes= t_db_bench_tenant_closure tenants_closure  (cost=3D0.42..45.06 rows=3D= 40 width=3D16) (never executed)
>                     =        Index Cond: (parent_id =3D tenants_parent.id) >                     =        Filter: (barrier <=3D 0)
>                ->  Ind= ex Scan using test_db_bench_tenants_pkey on test_db_bench_tenants tenants_c= hild  (cost=3D0.29..0.31 rows=3D1 width=3D44) (never executed)
>                     =  Index Cond: (id =3D 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=3D0.43..14.6= 6 rows=3D136 width=3D44) (never executed)
>                Index Cond: ((t= enant_id)::text =3D (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 magnit= ude more time than the actual execution.
>
> Is there a possibility to reduce this time? And, in general, to unders= tand why planning takes so much time.

You could try to VACUUM the involved tables; indexes with many entries poin= ting 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 va= lue, or if the "Stats target"
for some column in the "\d+ tablename" output is set higher than = 100.

Yours,
Laurenz Albe


--_000_DM4PR20MB57256A764C408DE596ECD405BDF2ADM4PR20MB5725namp_--