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 1rZgW1-005reH-28 for pgsql-hackers@arkaria.postgresql.org; Tue, 13 Feb 2024 00:19:13 +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 1rZgW0-00ESWY-2w for pgsql-hackers@arkaria.postgresql.org; Tue, 13 Feb 2024 00:19:12 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rZgVz-00ESWP-PK for pgsql-hackers@lists.postgresql.org; Tue, 13 Feb 2024 00:19:11 +0000 Received: from oss.nttdata.com ([49.212.34.109]) by makus.postgresql.org with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rZgVw-006Rwp-4R for pgsql-hackers@lists.postgresql.org; Tue, 13 Feb 2024 00:19:10 +0000 Received: from oss.nttdata.com (localhost [127.0.0.1]) by oss.nttdata.com (Postfix) with ESMTPA id E6CE560998; Tue, 13 Feb 2024 09:19:03 +0900 (JST) X-Virus-Status: Clean X-Virus-Scanned: clamav-milter 0.103.11 at oss.nttdata.com MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII; format=flowed Content-Transfer-Encoding: 7bit Date: Tue, 13 Feb 2024 09:19:03 +0900 From: torikoshia To: Ashutosh Bapat Cc: pgsql-hackers@lists.postgresql.org, =?UTF-8?Q?=C3=89tienne_BERSAC?= , Andres Freund , jtc331@gmail.com, rafaelthca@gmail.com Subject: Re: RFC: Logging plan of the running query In-Reply-To: References: <4e1e4e5d022964953e84468fe4e511b0@oss.nttdata.com> <4af7712833d4ce989cf5e658106e42da@oss.nttdata.com> <7ab57ab0ba3416e2dbf54927752bc310@oss.nttdata.com> <20231006155850.kjjb2vwbkawj7moq@alap3.anarazel.de> <0e0e7ca08dff077a625c27a5e0c2ef0a@oss.nttdata.com> <2d6d7846b6b794c0e727c431852a113c@oss.nttdata.com> <0eb66e8c72f23695957466db5c76c69c@oss.nttdata.com> <9c36599db62ef7466a297843fe812fc60e827cd2.camel@dalibo.com> <66d29d2c10ca9181c7e183eeeb4525f8@oss.nttdata.com> <7bc1cc1bcc3289e9354ebb00ac1c8440c01b736c.camel@dalibo.com> <0eafbfbe8dc39e80bce358b48a258510@oss.nttdata.com> <6d13f7485091f51ad7d11cb7c65f75038c10d747.camel@dalibo.com> <61b4add9a01f21011789b6ee04085751@oss.nttdata.com> User-Agent: Roundcube Webmail/1.4.11 Message-ID: <1b2b247530f3ff3afab4ddc2df222e8b@oss.nttdata.com> X-Sender: torikoshia@oss.nttdata.com List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On 2024-02-07 19:14, torikoshia wrote: > On 2024-02-07 13:58, Ashutosh Bapat wrote: >> The prologue refers to a very populated >> lock hash table. I think that will happen if thousands of tables are >> queried in a single query OR a query runs on a partitioned table with >> thousands of partitions. May be we want to try that scenario. > > OK, I'll try such cases. I measured this using partitioned pgbench_accounts with some modification to v36[1]. The results[2] show that CPU time increases in proportion to the number of partitions, and the increase is not that large. However I've noticed that these ensuring no page lock logic would not be necessary anymore since cc32ec24fdf3b98 removed the assertion which caused an error[1]. $ git show cc32ec24fdf3b98 .. diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c index 0a692ee0a6..f595bce31b 100644 --- a/src/backend/storage/lmgr/lock.c +++ b/src/backend/storage/lmgr/lock.c @@ -186,18 +186,6 @@ static int FastPathLocalUseCount = 0; */ static bool IsRelationExtensionLockHeld PG_USED_FOR_ASSERTS_ONLY = false; - /* - * We don't acquire any other heavyweight lock while holding the page lock - * except for relation extension. - */ - Assert(!IsPageLockHeld || - (locktag->locktag_type == LOCKTAG_RELATION_EXTEND)); I'm going to remove ensuring no page lock logic after some testings. [1] $ git diff _submission/log_running_query-v36 +#include "time.h" + bool ProcessLogQueryPlanInterruptActive = false; /* Hook for plugins to get control in ExplainOneQuery() */ @@ -5258,6 +5260,10 @@ ProcessLogQueryPlanInterrupt(void) MemoryContext old_cxt; LogQueryPlanPending = false; + clock_t start, end; + double cpu_time_used; + int num_hash_entry = 0; + /* Cannot re-enter. */ if (ProcessLogQueryPlanInterruptActive) return; @@ -5287,9 +5293,11 @@ ProcessLogQueryPlanInterrupt(void) * we check all the LocalLock entries and when finding even one, give up * logging the plan. */ + start = clock(); hash_seq_init(&status, GetLockMethodLocalHash()); while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL) { + num_hash_entry++; if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE) { ereport(LOG_SERVER_ONLY, @@ -5301,6 +5309,12 @@ ProcessLogQueryPlanInterrupt(void) return; } } + end = clock(); + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; + + ereport(LOG, + errmsg("locallock entry search took: %f for %d entries", cpu_time_used, num_hash_entry)); [2] # partition number: 512 locallock entry search took: 0.000029 for 1026 entries locallock entry search took: 0.000030 for 1026 entries locallock entry search took: 0.000036 for 1026 entries # partition number: 1024 locallock entry search took: 0.000070 for 2050 entries locallock entry search took: 0.000059 for 2050 entries locallock entry search took: 0.000049 for 2050 entries # partition number: 2048 locallock entry search took: 0.000100 for 4098 entries locallock entry search took: 0.000103 for 4098 entries locallock entry search took: 0.000101 for 4098 entries # partition number: 4096 locallock entry search took: 0.000197 for 8194 entries locallock entry search took: 0.000193 for 8194 entries locallock entry search took: 0.000192 for 8194 entries [3] https://www.postgresql.org/message-id/0642712f-1298-960a-a3ba-e256d56040ac%40oss.nttdata.com -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation