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 1rXex8-00Bsgw-P1 for pgsql-hackers@arkaria.postgresql.org; Wed, 07 Feb 2024 10:14:51 +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 1rXex7-009jDj-Rd for pgsql-hackers@arkaria.postgresql.org; Wed, 07 Feb 2024 10:14:49 +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 1rXex7-009jDb-HE for pgsql-hackers@lists.postgresql.org; Wed, 07 Feb 2024 10:14:49 +0000 Received: from oss.nttdata.com ([49.212.34.109]) by magus.postgresql.org with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rXex4-005vOi-9G for pgsql-hackers@lists.postgresql.org; Wed, 07 Feb 2024 10:14:48 +0000 Received: from oss.nttdata.com (localhost [127.0.0.1]) by oss.nttdata.com (Postfix) with ESMTPA id A18AB6093D; Wed, 7 Feb 2024 19:14:40 +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=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Date: Wed, 07 Feb 2024 19:14:40 +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: 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 13:58, Ashutosh Bapat wrote: > On Wed, Feb 7, 2024 at 9:38 AM torikoshia > wrote: >> >> Hi Ashutosh, >> >> On 2024-02-06 19:51, Ashutosh Bapat wrote: >> >> > Thanks for the summary. It is helpful. I think patch is also getting >> > better. >> > >> > I have a few questions and suggestions >> >> Thanks for your comments. >> >> > 1. Prologue of GetLockMethodLocalHash() mentions >> > * NOTE: When there are many entries in LockMethodLocalHash, calling >> > this >> > * function and looking into all of them can lead to performance >> > problems. >> > */ >> > How bad this performance could be. Let's assume that a query is taking >> > time and pg_log_query_plan() is invoked to examine the plan of this >> > query. Is it possible that the looping over all the locks itself takes >> > a lot of time delaying the query execution further? >> >> I think it depends on the number of local locks, but I've measured cpu >> time for this page lock check by adding below codes and >> v27-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch[1], which >> calls ProcessLogQueryPlanInterrupt() in every CFI on my laptop just >> for >> your information: >> >> diff --git a/src/backend/commands/explain.c >> b/src/backend/commands/explain.c >> index 5f7d77d567..65b7cb4925 100644 >> --- a/src/backend/commands/explain.c >> +++ b/src/backend/commands/explain.c >> @@ -44,6 +44,8 @@ >> >> +#include "time.h" >> ... >> @@ -5287,6 +5292,7 @@ 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) >> { >> if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE) >> { >> ereport(LOG_SERVER_ONLY, >> errmsg("ignored request for logging query plan >> due >> to page lock conflicts"), >> errdetail("You can try again in a moment.")); >> hash_seq_term(&status); >> >> ProcessLogQueryPlanInterruptActive = false; >> return; >> } >> } >> + end = clock(); >> + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; >> + >> + ereport(LOG, >> + errmsg("all locallock entry search took: %f", >> cpu_time_used)); >> + >> >> There were about 3 million log lines which recorded the cpu time, and >> the duration was quite short: >> >> =# -- Extracted cpu_time_used from log and loaded it to cpu_time.d. >> =# select max(d), min(d), avg(d) from cpu_time ; >> max | min | avg >> ----------+-----+----------------------- >> 0.000116 | 0 | 4.706274625332238e-07 >> >> I'm not certain that this is valid for actual use cases, but these >> results seem to suggest that it will not take that long. > > What load did you run? I don't think any query in make check would > take say thousands of locks. Sorry, I forgot to write it but ran make check as you imagined. > 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. >> > 2. What happens if auto_explain is enabled in the backend and >> > pg_log_query_plan() is called on the same backend? Will they conflict? >> > I think we should add a test for the same. >> >> Hmm, I think they don't conflict since they just refer QueryDesc and >> don't modify it and don't use same objects for locking. >> (I imagine 'conflict' here is something like 'hard conflict' in >> replication[2].) > > By conflict, I mean the two features behave weird when used together > e.g give wrong results or crash etc. > >> >> Actually using both auto_explain and pg_log_query_plan() output each >> logs separately: >> >> (pid:62835)=# select pg_sleep(10); >> (pid:70000)=# select pg_log_query_plan(62835); >> >> (pid:70000)=# \! cat data/log/postgres.log >> ... >> 2024-02-06 21:44:17.837 JST [62835:4:0] LOG: 00000: query plan >> running on backend with PID 62835 is: >> Query Text: select pg_sleep(10); >> Result (cost=0.00..0.01 rows=1 width=4) >> Output: pg_sleep('10'::double precision) >> Query Identifier: 3506829283127886044 >> 2024-02-06 21:44:17.837 JST [62835:5:0] LOCATION: >> ProcessLogQueryPlanInterrupt, explain.c:5336 >> 2024-02-06 21:44:26.974 JST [62835:6:0] LOG: 00000: duration: >> 10000.868 ms plan: >> Query Text: select pg_sleep(10); >> Result (cost=0.00..0.01 rows=1 width=4) (actual >> time=10000.802..10000.804 rows=1 loops=1) >> >> > Using injection point support we should be able to add tests for >> > testing pg_log_query_plan behaviour when there are page locks held or >> > when auto_explain (with instrumentation) and pg_log_query_plan() work >> > on the same query plan. Use injection point to make the backend >> > running query wait at a suitable point to delay its execution and fire >> > pg_log_query_plan() from other backend. May be the same test could >> > examine the server log file to see if the plan is indeed output to the >> > server log file. >> > >> > Given that the feature will be used when the things have already gone >> > wrong, it should not make things more serious. So more testing and >> > especially automated would help. >> >> Thanks for the advice, it seems a good idea. >> I'm going to try to add tests using injection point. > > Your test with pg_sleep() is a good basic test. But more involved > testing might need something like injection points. It might be so, I will consider whether there are any subtle timing issues, etc. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation