Subject: Re: RFC: Logging plan of the running query

From: torikoshia <[email-masked]>
Date: Tue, 24 Oct 2023 21:30:49 +0900

On 2023-10-24 16:12, Étienne BERSAC wrote:
>> Hi,
>> 
>> Yeah, and when we have a situation where we want to run
>> pg_log_query_plan(), we can run it in any environment as long as it
>> is bundled with the core.
> 
> Is it possible to get the plan of a backend programmatically without
> access to the logs?
> 
> Something like pg_get_query_plan(pid, format) which output would be the
> same as EXPLAIN.

Do you imagine a function like below?

   =# select pg_get_query_plan(100, 'plain');
                             QUERY PLAN
   -------------------------------------------------------------------
    Limit  (cost=0.00..0.04 rows=1 width=273)
      ->  Seq Scan on pg_class  (cost=0.00..17.14 rows=414 width=273)

If so, we once tried to implement such function for getting memory 
contexts.
However, this attempt didn't succeed because it could lead dead lock 
situation[1].

I think the same problem can occur when implementing 
pg_get_query_plan().

[1] 
https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com
> Regards,
> Étienne BERSAC
> Dalibo

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

---

From: Étienne BERSAC <[email-masked]>
Date: Fri, 27 Oct 2023 09:06:31 +0200

Hi Torikoshia,

> However, this attempt didn't succeed because it could lead dead lock 

Thanks for the pointer. Why not use client log message to allow client
to get plan without locking backend memory context and without access
to server log ? I missed the rationnal for not sending the plan to
client.

Regards,
Étienne

---

From: torikoshia <[email-masked]>
Date: Fri, 27 Oct 2023 21:30:02 +0900

> to server log ? I missed the rationnal for not sending the plan to

If we use client log message, that message is shown on the target 
process whose pid is specified by the parameter of pg_log_query_plan():

   (pid:1000)=# select pg_sleep(60);
   (pid:1001)=# select pg_log_query_plan(1000);
   (pid:1000)=# LOG:  query plan running on backend with PID 1000 is:
                Query Text: select pg_sleep(1000);
                Result  (cost=0.00..0.01 rows=1 width=4)
                  Output: pg_sleep('1000'::double precision)

I think this is not an expected behavior and we set elevel to 
LOG_SERVER_ONLY.

-- 
Regards,

---

From: Étienne BERSAC <[email-masked]>
Date: Fri, 27 Oct 2023 14:54:48 +0200

> I think this is not an expected behavior and we set elevel to 

Makes sens. Thanks.

---

From: Ashutosh Bapat <[email-masked]>
Date: Fri, 3 Nov 2023 19:31:14 +0530

I have following questions related to the functionality. (Please point
me to the relevant discussion if this has been already discussed.)

1. When a backend is running nested queries, we will see the plan of
the innermost query. That query may not be the actual culprit if the
user query is running slowly. E.g a query being run as part of inner
side nested loop when the nested loop itself is the bottleneck. I
think it will be useful to print plans of all the whole query stack.

2. When a query is running in parallel worker do we want to print that
query? It may or may not be interesting given the situation. If the
overall plan itself is faulty, output of the parallel worker query is
not useful. If the plan is fine but a given worker's leg is running
slowly it may be interesting.

As a side note, you may want to fix the indentation in
ExplainAssembleLogOutput().

-- 
Best Wishes,
Ashutosh Bapat

---

From: Ashutosh Bapat <[email-masked]>
Date: Mon, 6 Nov 2023 12:02:12 +0530

> think it will be useful to print plans of all the whole query stack.

To further explain this point, consider following scenario

-- A completely useless function which executes two SQL statements
which take small amount individually
#create function multstmt() returns int
language sql as $$
select count(*) from pg_class where reltype = 12345;
select count(*) from pg_type limit 10;
$$;

-- force a suboptimal plan
#set enable_hashjoin to false;
#set enable_mergejoin to false;

-- A completely useless but long running query
#select c.oid, t.oid from pg_class c, pg_type t where multstmt(c.oid)
= multstmt(t.oid);

This take a few minutes on my laptop.

In a separate session query pg_stat_activity. We will see the original query
#select pid, query, backend_type from pg_stat_activity where pid = 349330;
  pid   |                                          query
                           |  backend_type
--------+-----------------------------------------------------------------------------------------+----------------
 349330 | select c.oid, t.oid from pg_class c, pg_type t where
multstmt(c.oid) = multstmt(t.oid); | client backend
(1 row)

Run the plan output function a few times
#select pg_log_query_plan(349330);

You will observe different plans based on which of the innermost query
is runnning
LOG:  query plan running on backend with PID 349330 is:
        Query Text:
        select count(*) from pg_class where reltype = typeid;
        select count(*) from pg_type where oid = typeid;

        Query Parameters: $1 = '600'
        Aggregate  (cost=18.18..18.19 rows=1 width=8)
          Output: count(*)
          ->  Seq Scan on pg_catalog.pg_class  (cost=0.00..18.18 rows=2 width=0)
                Output: oid, relname, relnamespace, reltype,
reloftype, relowner, relam, relfilenode, reltablespace, relpages,
reltuples, relallvisible, reltoastrelid, relhasindex, relisshared,
relpersistence, relkind, relnatts, relchecks, relhasrules,
relhastriggers, relhassubclass, relrowsecurity, relforcerowsecurity,
relispopulated, relreplident, relispartition, relrewrite,
relfrozenxid, relminmxid, relacl, reloptions, relpartbound
                Filter: (pg_class.reltype = $1)
        Settings: enable_hashjoin = 'off', enable_mergejoin = 'off'
2023-11-06 11:52:25.610 IST [349330] LOG:  query plan running on
backend with PID 349330 is:
        Query Text:
        select count(*) from pg_class where reltype = typeid;
        select count(*) from pg_type where oid = typeid;

        Query Parameters: $1 = '2203'
        Aggregate  (cost=4.30..4.31 rows=1 width=4)
          Output: count(*)
          ->  Index Only Scan using pg_type_oid_index on
pg_catalog.pg_type  (cost=0.28..4.29 rows=1 width=0)
                Output: oid
                Index Cond: (pg_type.oid = $1)
        Settings: enable_hashjoin = 'off', enable_mergejoin = 'off'

Individual pieces are confusing here since the query run by the
backend is not the one being EXPLAINed. A user may not know that the
queries being EXPLAINed arise from the function call multstmt(). So
they won't be able to stitch the pieces together unless they see plan
of the outermost query with loops and costs. What might help if we
explain each query in the hierarchy.

I think we can start with what auto_explain is doing. Always print the
plan of the outermost query; the query found in pg_stat_activity. In a
later version we might find a way to print plans of all the queries in
the stack and do so in a readable manner.

This makes tracking activeQueryDesc a bit tricky. My guess is that the
outermost query's descriptor will be available through ActivePortal
most of the time. But there are cases when ExecutorRun is called by
passing a queryDesc directly. So may be there are some cases where
that's not true.

-- 
Best Wishes,
Ashutosh Bapat

---

From: torikoshia <[email-masked]>
Date: Thu, 09 Nov 2023 15:33:36 +0900

On 2023-11-06 15:32, Ashutosh Bapat wrote:

Thanks for the suggestion and example.

>> think it will be useful to print plans of all the whole query stack.

This was discussed in previous threads[1] and we thought it'd be useful 
but since it needed some extra works, we stopped widening the scope.

> #select pid, query, backend_type from pg_stat_activity where pid = 

Agreed there are cases printing plan of the outermost query is more 
useful.

> passing a queryDesc directly. So may be there are some cases where

Yeah, actually the original version of the patch got the plan from 
ActivePortal, but it failed logging plan when the query was something 
like this[2]:

      DO $$
      BEGIN
      PERFORM pg_sleep(100);
      END$$;

> slowly it may be interesting.

I think it can be useful.
I'm wondering if we can add this after the first patch for this feature 
is committed.

> ExplainAssembleLogOutput().

Thanks, modified it.
Since the documentation was obsoleted, attached patch also updated it.

-- 
Regards,

From 4fb5d29176ed92b9de3b64e1eadf760d49902a40 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Thu, 9 Nov 2023 15:10:46 +0900
Subject: [PATCH v33] Add function to log the plan of the query

Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.

By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.

On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar,
Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby, Kyotaro
Horiguchi, Robert Treat, Alena Rybakina, Ashutosh Bapat

Co-authored-by: James Coleman <[email-masked]>
---
 contrib/auto_explain/auto_explain.c          |  23 +-
 doc/src/sgml/func.sgml                       |  50 +++++
 src/backend/access/transam/xact.c            |  13 ++
 src/backend/catalog/system_functions.sql     |   2 +
 src/backend/commands/explain.c               | 209 ++++++++++++++++++-
 src/backend/executor/execMain.c              |  14 ++
 src/backend/storage/ipc/procsignal.c         |   4 +
 src/backend/storage/lmgr/lock.c              |   9 +-
 src/backend/tcop/postgres.c                  |   4 +
 src/backend/utils/error/elog.c               |   2 +
 src/backend/utils/init/globals.c             |   2 +
 src/include/catalog/pg_proc.dat              |   6 +
 src/include/commands/explain.h               |   8 +
 src/include/miscadmin.h                      |   1 +
 src/include/storage/lock.h                   |   2 -
 src/include/storage/procsignal.h             |   1 +
 src/include/tcop/pquery.h                    |   2 +-
 src/include/utils/elog.h                     |   1 +
 src/test/regress/expected/misc_functions.out |  54 ++++-
 src/test/regress/sql/misc_functions.sql      |  41 +++-
 20 files changed, 400 insertions(+), 48 deletions(-)

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c3ac27ae99..20a73df8c4 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -399,26 +399,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 			es->format = auto_explain_log_format;
 			es->settings = auto_explain_log_settings;
 
-			ExplainBeginOutput(es);
-			ExplainQueryText(es, queryDesc);
-			ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
-			ExplainPrintPlan(es, queryDesc);
-			if (es->analyze && auto_explain_log_triggers)
-				ExplainPrintTriggers(es, queryDesc);
-			if (es->costs)
-				ExplainPrintJITSummary(es, queryDesc);
-			ExplainEndOutput(es);
-
-			/* Remove last line break */
-			if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
-				es->str->data[--es->str->len] = '\0';
-
-			/* Fix JSON to output an object */
-			if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
-			{
-				es->str->data[0] = '{';
-				es->str->data[es->str->len - 1] = '}';
-			}
+			ExplainAssembleLogOutput(es, queryDesc, auto_explain_log_format,
+									 auto_explain_log_triggers,
+									 auto_explain_log_parameter_max_length);
 
 			/*
 			 * Note: we rely on the existing logging of context or
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index d963f0a0a0..ada715a934 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -26516,6 +26516,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_query_plan</primary>
+        </indexterm>
+        <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the plan of the query currently running on the
+        backend with specified process ID.
+        It will be logged at <literal>LOG</literal> message level and
+        will appear in the server log based on the log
+        configuration set (See <xref linkend="runtime-config-logging"/>
+        for more information), but will not be sent to the client
+        regardless of <xref linkend="guc-client-min-messages"/>.
+        </para></entry>
+      </row>
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>
@@ -26736,6 +26755,37 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
     because it may generate a large number of log messages.
    </para>
 
+   <para>
+    <function>pg_log_query_plan</function> can be used
+    to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG:  query plan running on backend with PID 201116 is:
+        Query Text: SELECT * FROM pgbench_accounts;
+        Seq Scan on public.pgbench_accounts  (cost=0.00..52787.00 rows=2000000 width=97)
+          Output: aid, bid, abalance, filler
+        Settings: work_mem = '1MB'
+        Query Identifier: 8621255546560739680
+</screen>
+    Note that when statements are executed inside a function, only the
+    plan of the most deeply nested query is logged.
+   </para>
+
+   <para>
+    When a subtransaction is aborted, <function>pg_log_query_plan</function>
+    cannot log the query plan after the abort.
+   </para>
+
   </sect2>
 
   <sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 74ce5f9491..de4b0542a9 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -61,6 +61,7 @@
 #include "storage/procarray.h"
 #include "storage/sinvaladt.h"
 #include "storage/smgr.h"
+#include "tcop/pquery.h"
 #include "utils/builtins.h"
 #include "utils/catcache.h"
 #include "utils/combocid.h"
@@ -2750,6 +2751,12 @@ AbortTransaction(void)
 	 */
 	sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
 
+	/*
+	 * When ActiveQueryDesc is referenced after abort, some of its elements
+	 * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+	 */
+	ActiveQueryDesc = NULL;
+
 	/*
 	 * check the current transaction state
 	 */
@@ -5109,6 +5116,12 @@ AbortSubTransaction(void)
 	 */
 	sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
 
+	/*
+	 * When ActiveQueryDesc is referenced after abort, some of its elements
+	 * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+	 */
+	ActiveQueryDesc = NULL;
+
 	/*
 	 * check the current transaction state
 	 */
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 35d738d576..e42db525dc 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -742,6 +742,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
 
 REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
 
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
 --
 -- We also set up some things as accessible to standard roles.
 --
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f1d71bc54e..a3c0a6a3d9 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -21,6 +21,7 @@
 #include "executor/nodeHash.h"
 #include "foreign/fdwapi.h"
 #include "jit/jit.h"
+#include "miscadmin.h"
 #include "nodes/extensible.h"
 #include "nodes/makefuncs.h"
 #include "nodes/nodeFuncs.h"
@@ -28,7 +29,10 @@
 #include "parser/parsetree.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "tcop/pquery.h"
 #include "tcop/tcopprot.h"
+#include "utils/backend_status.h"
 #include "utils/builtins.h"
 #include "utils/guc_tables.h"
 #include "utils/json.h"
@@ -737,6 +741,37 @@ ExplainPrintSettings(ExplainState *es)
 	}
 }
 
+/*
+ * ExplainAssembleLogOutput -
+ *   Assemble es->str for logging according to specified contents and format
+ */
+
+void
+ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc, int logFormat,
+						 bool logTriggers, int logParameterMaxLength)
+{
+	ExplainBeginOutput(es);
+	ExplainQueryText(es, queryDesc);
+	ExplainQueryParameters(es, queryDesc->params, logParameterMaxLength);
+	ExplainPrintPlan(es, queryDesc);
+	if (es->analyze && logTriggers)
+		ExplainPrintTriggers(es, queryDesc);
+	if (es->costs)
+		ExplainPrintJITSummary(es, queryDesc);
+	ExplainEndOutput(es);
+
+	/* Remove last line break */
+	if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+		es->str->data[--es->str->len] = '\0';
+
+	/* Fix JSON to output an object */
+	if (logFormat == EXPLAIN_FORMAT_JSON)
+	{
+		es->str->data[0] = '{';
+		es->str->data[es->str->len - 1] = '}';
+	}
+}
+
 /*
  * ExplainPrintPlan -
  *	  convert a QueryDesc's plan tree to text and append it to es->str
@@ -1647,6 +1682,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	/*
 	 * We have to forcibly clean up the instrumentation state because we
 	 * haven't done ExecutorEnd yet.  This is pretty grotty ...
+	 * This cleanup should not be done when the query has already been
+	 * executed and explain has been called by signal, as the target query
+	 * may use instrumentation and clean itself up.
 	 *
 	 * Note: contrib/auto_explain could cause instrumentation to be set up
 	 * even though we didn't ask for it here.  Be careful not to print any
@@ -1654,7 +1692,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	 * InstrEndLoop call anyway, if possible, to reduce the number of cases
 	 * auto_explain has to contend with.
 	 */
-	if (planstate->instrument)
+	if (planstate->instrument && !es->signaled)
 		InstrEndLoop(planstate->instrument);
 
 	if (es->analyze &&
@@ -5082,3 +5120,172 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogQueryPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the plan of
+ *		the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogQueryPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+bool ProcessLogQueryPlanInterruptActive = false;
+/*
+ * ProcessLogQueryPlanInterrupt
+ * 		Perform logging the plan of the currently running query on this
+ * 		backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange to call
+ * this function if we see LogQueryPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+	ExplainState *es;
+	HASH_SEQ_STATUS status;
+	LOCALLOCK  *locallock;
+	MemoryContext cxt;
+	MemoryContext old_cxt;
+	LogQueryPlanPending = false;
+
+	/* Cannot re-enter. */
+	if (ProcessLogQueryPlanInterruptActive)
+		return;
+
+	ProcessLogQueryPlanInterruptActive = true;
+
+	if (ActiveQueryDesc == NULL)
+	{
+		ereport(LOG_SERVER_ONLY,
+				errmsg("backend with PID %d is not running a query or a subtransaction is aborted",
+					MyProcPid),
+				errhidestmt(true),
+				errhidecontext(true));
+
+		ProcessLogQueryPlanInterruptActive = false;
+		return;
+	}
+
+	/*
+	 * Ensure no page lock is held on this process.
+	 *
+	 * If page lock is held at the time of the interrupt, we can't acquire any
+	 * other heavyweight lock, which might be necessary for explaining the plan
+	 * when retrieving column names.
+	 *
+	 * This may be overkill, but since page locks are held for a short duration
+	 * we check all the LocalLock entries and when finding even one, give up
+	 * logging the plan.
+	 */
+	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 confilcts"),
+				errdetail("You can try again in a moment."));
+			hash_seq_term(&status);
+
+			ProcessLogQueryPlanInterruptActive = false;
+			return;
+		}
+	}
+
+	/*
+	 * Ensure no locks already held on the lockable object.
+	 *
+	 * Otherwise EXPLAIN can be also hold on it.
+	 */
+	if (MyProc->heldLocks)
+	{
+		ereport(LOG_SERVER_ONLY,
+			errmsg("ignored request for logging query plan due to lock confilcts"),
+			errdetail("You can try again in a moment."));
+			return;
+	}
+
+	cxt = AllocSetContextCreate(CurrentMemoryContext,
+								"log_query_plan temporary context",
+								ALLOCSET_DEFAULT_SIZES);
+
+	old_cxt = MemoryContextSwitchTo(cxt);
+
+	es = NewExplainState();
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+	es->verbose = true;
+	es->signaled = true;
+
+	ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1);
+
+	ereport(LOG_SERVER_ONLY,
+			errmsg("query plan running on backend with PID %d is:\n%s",
+					MyProcPid, es->str->data),
+			 errhidestmt(true),
+			 errhidecontext(true));
+
+	MemoryContextSwitchTo(old_cxt);
+	MemoryContextDelete(cxt);
+
+	ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * pg_log_query_plan
+ *		Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+	int			pid = PG_GETARG_INT32(0);
+	PGPROC	   *proc;
+	PgBackendStatus	*be_status;
+
+	proc = BackendPidGetProc(pid);
+
+	if (proc == NULL)
+	{
+		/*
+		 * This is just a warning so a loop-through-resultset will not abort
+		 * if one backend terminated on its own during the run.
+		 */
+		ereport(WARNING,
+				(errmsg("PID %d is not a PostgreSQL backend process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	be_status = pgstat_get_beentry_by_backend_id(proc->backendId);
+	if (be_status->st_backendType != B_BACKEND)
+	{
+		ereport(WARNING,
+				(errmsg("PID %d is not a PostgreSQL client backend process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+	{
+		/* Again, just a warning to allow loops */
+		ereport(WARNING,
+				(errmsg("could not send signal to process %d: %m", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 4c5a7bbf62..4772cb97e7 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -78,6 +78,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
 /* Hook for plugin to get control in ExecCheckPermissions() */
 ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;
 
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
 /* decls for local routines only used within this module */
 static void InitPlan(QueryDesc *queryDesc, int eflags);
 static void CheckValidRowMarkRel(Relation rel, RowMarkType markType);
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
 			ScanDirection direction, uint64 count,
 			bool execute_once)
 {
+	/*
+	 * Update ActiveQueryDesc here to enable retrieval of the currently
+	 * running queryDesc for nested queries.
+	 */
+	QueryDesc *save_ActiveQueryDesc;
+
+	save_ActiveQueryDesc = ActiveQueryDesc;
+	ActiveQueryDesc = queryDesc;
+
 	if (ExecutorRun_hook)
 		(*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
 	else
 		standard_ExecutorRun(queryDesc, direction, count, execute_once);
+
+	ActiveQueryDesc = save_ActiveQueryDesc;
 }
 
 void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index b7427906de..ddaf829917 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -20,6 +20,7 @@
 #include "access/parallel.h"
 #include "port/pg_bitutils.h"
 #include "commands/async.h"
+#include "commands/explain.h"
 #include "miscadmin.h"
 #include "pgstat.h"
 #include "replication/logicalworker.h"
@@ -658,6 +659,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
 	if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
 		HandleLogMemoryContextInterrupt();
 
+	if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN))
+		HandleLogQueryPlanInterrupt();
+
 	if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE))
 		HandleParallelApplyMessageInterrupt();
 
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index b8c57b3e16..1d7a8de4f3 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -602,17 +602,18 @@ LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode)
 	return (locallock && locallock->nLocks > 0);
 }
 
-#ifdef USE_ASSERT_CHECKING
 /*
- * GetLockMethodLocalHash -- return the hash of local locks, for modules that
- *		evaluate assertions based on all locks held.
+ * GetLockMethodLocalHash -- return the hash of local locks, mainly for
+ *		modules that evaluate assertions based on all locks held.
+ *
+ * NOTE: When there are many entries in LockMethodLocalHash, calling this
+ * function and looking into all of them can lead to performance problems.
  */
 HTAB *
 GetLockMethodLocalHash(void)
 {
 	return LockMethodLocalHash;
 }
-#endif
 
 /*
  * LockHasWaiters -- look up 'locktag' and check if releasing this
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 6a070b5d8c..320c0148b4 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -37,6 +37,7 @@
 #include "catalog/pg_type.h"
 #include "commands/async.h"
 #include "commands/event_trigger.h"
+#include "commands/explain.h"
 #include "commands/prepare.h"
 #include "common/pg_prng.h"
 #include "jit/jit.h"
@@ -3457,6 +3458,9 @@ ProcessInterrupts(void)
 	if (LogMemoryContextPending)
 		ProcessLogMemoryContextInterrupt();
 
+	if (LogQueryPlanPending)
+		ProcessLogQueryPlanInterrupt();
+
 	if (ParallelApplyMessagePending)
 		HandleParallelApplyMessages();
 }
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index eeb238331e..63b99dafa5 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -513,6 +513,8 @@ errfinish(const char *filename, int lineno, const char *funcname)
 		 econtext = econtext->previous)
 		econtext->callback(econtext->arg);
 
+	if (elevel >= ERROR)
+		ProcessLogQueryPlanInterruptActive = false;
 	/*
 	 * If ERROR (not more nor less) we pass it off to the current handler.
 	 * Printing it and popping the stack is the responsibility of the handler.
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 60bc1217fb..fee49243a6 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -37,6 +37,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
 volatile sig_atomic_t ProcSignalBarrierPending = false;
 volatile sig_atomic_t LogMemoryContextPending = false;
 volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
 volatile uint32 InterruptHoldoffCount = 0;
 volatile uint32 QueryCancelHoldoffCount = 0;
 volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index f14aed422a..b693b5327e 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8245,6 +8245,12 @@
   prorettype => 'bool', proargtypes => 'int4',
   prosrc => 'pg_log_backend_memory_contexts' },
 
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+  proname => 'pg_log_query_plan',
+  provolatile => 'v', prorettype => 'bool',
+  proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
 # non-persistent series generator
 { oid => '1066', descr => 'non-persistent series generator',
   proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index f9525fb572..2aee08342c 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,7 @@
 #include "lib/stringinfo.h"
 #include "parser/parse_node.h"
 
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
 typedef enum ExplainFormat
 {
 	EXPLAIN_FORMAT_TEXT,
@@ -60,6 +61,7 @@ typedef struct ExplainState
 	bool		hide_workers;	/* set if we find an invisible Gather */
 	/* state related to the current plan node */
 	ExplainWorkersState *workers_state; /* needed if parallel plan */
+	bool		signaled;		/* whether explain is called by signal */
 } ExplainState;
 
 /* Hook for plugins to get control in ExplainOneQuery() */
@@ -94,6 +96,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
 						   const instr_time *planduration,
 						   const BufferUsage *bufusage);
 
+extern void ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc,
+									 int logFormat, bool logTriggers,
+									 int logParameterMaxLength);
+
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
 
@@ -126,4 +132,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);
 
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
 #endif							/* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index f0cc651435..855cdd33cc 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -95,6 +95,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
 extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
 extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
 extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
 
 extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
 extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 590c026b5b..f1b5a5219e 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -569,9 +569,7 @@ extern void LockReleaseSession(LOCKMETHODID lockmethodid);
 extern void LockReleaseCurrentOwner(LOCALLOCK **locallocks, int nlocks);
 extern void LockReassignCurrentOwner(LOCALLOCK **locallocks, int nlocks);
 extern bool LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode);
-#ifdef USE_ASSERT_CHECKING
 extern HTAB *GetLockMethodLocalHash(void);
-#endif
 extern bool LockHasWaiters(const LOCKTAG *locktag,
 						   LOCKMODE lockmode, bool sessionLock);
 extern VirtualTransactionId *GetLockConflicts(const LOCKTAG *locktag,
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index 548519117a..4952523085 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ typedef enum
 	PROCSIG_WALSND_INIT_STOPPING,	/* ask walsenders to prepare for shutdown  */
 	PROCSIG_BARRIER,			/* global barrier interrupt  */
 	PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+	PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current query */
 	PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
 
 	/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index a5e65b98aa..a6ae947a0f 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,7 +21,7 @@ struct PlannedStmt;				/* avoid including plannodes.h here */

 extern PGDLLIMPORT Portal ActivePortal;
-
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
 
 extern PortalStrategy ChoosePortalStrategy(List *stmts);
 
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 0971d5ce33..20f6472998 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
 
 extern bool message_level_is_interesting(int elevel);
 
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
 extern bool errstart(int elevel, const char *domain);
 extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
 extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c669948370..0b98f8a972 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -276,14 +276,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
  ../jkl/mno
 (1 row)
 
+-- Test logging functions
 --
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail, and that the
 -- permissions are set properly.
 --
+-- pg_log_backend_memory_contexts()
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
@@ -297,8 +298,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
  t
 (1 row)
 
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log_function;
+SELECT has_function_privilege('regress_log_function',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
  has_function_privilege 
 ------------------------
@@ -306,15 +307,15 @@ SELECT has_function_privilege('regress_log_memory',
 (1 row)
 
 GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  TO regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+  TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
  has_function_privilege 
 ------------------------
  t
 (1 row)
 
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
@@ -323,8 +324,41 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid());
 
 RESET ROLE;
 REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+  FROM regress_log_function;
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan 
+-------------------
+ t
+(1 row)
+
+SELECT has_function_privilege('regress_log_function',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege 
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege 
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan 
+-------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  FROM regress_log_function;
+DROP ROLE regress_log_function;
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index b57f01f3e9..84327408d8 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
 SELECT test_canonicalize_path('./abc/././def/.');
 SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
 
+-- Test logging functions
 --
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail, and that the
 -- permissions are set properly.
 --
 
+-- pg_log_backend_memory_contexts()
+
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
 
 SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
   WHERE backend_type = 'checkpointer';
 
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
 
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
 
 GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  TO regress_log_memory;
+  TO regress_log_function;
 
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
 
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
 RESET ROLE;
 
 REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  FROM regress_log_memory;
+  FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  FROM regress_log_function;
 
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
 
 --
 -- Test some built-in SRFs

base-commit: cd694f60dc975e9fe41e8643ca6f0629283d102e
-- 
2.39.2

---

From: Ashutosh Bapat <[email-masked]>
Date: Thu, 9 Nov 2023 12:41:49 +0530

> Agreed there are cases printing plan of the outermost query is more

I am fine printing the plan of the outermost query. This will help
many cases. Printing plans of the whole query stack can be added as an
add on later.

> ActivePortal, but it failed logging plan when the query was something

References [1] and [2] are not listed in your email.

Is that because there was no ActivePortal created or the ActivePortal
pointed to DO block instead of PERFORM pg_sleep?

> I'm wondering if we can add this after the first patch for this feature

With the current patches, it will print the query from a parallel
backend. If that's not desirable we should prohibit that case at
least.

-- 
Best Wishes,
Ashutosh Bapat

---

From: torikoshia <[email-masked]>
Date: Thu, 09 Nov 2023 20:26:27 +0900

> References [1] and [2] are not listed in your email.

Oops, sorry. Here are links:

[1] 
https://www.postgresql.org/message-id/64f716c44629e303b66e6c24502147cc%40oss.nttdata.com
[2] 
https://www.postgresql.org/message-id/632e99eb-8090-53e6-1b1a-101601904cbd%40oss.nttdata.com

> pointed to DO block instead of PERFORM pg_sleep?

ActivePortal is created but ActivePortal->queryDesc is null.

> backend. If that's not desirable we should prohibit that case at

Current patch prohibits printing plan if backend type is parallel worker 
as below:

   =# select pg_log_query_plan(pid), backend_type from pg_stat_activity 
where backend_type = 'parallel worker';

    pg_log_query_plan |  backend_type
   -------------------+-----------------
    f                 | parallel worker
    f                 | parallel worker
   (2 rows)

   WARNING:  PID 4618 is not a PostgreSQL client backend process
   WARNING:  PID 4617 is not a PostgreSQL client backend process

Is this the behavior you expect?

-- 
Regards,

---

From: Ashutosh Bapat <[email-masked]>
Date: Thu, 9 Nov 2023 20:28:48 +0530

> ActivePortal is created but ActivePortal->queryDesc is null.

Thanks.

>     pg_log_query_plan |  backend_type

I misread then. Thanks for correcting me. We could consider plans from
parallel workers in v2 of this feature.

-- 
Best Wishes,
Ashutosh Bapat

---

From: Rafael Thofehrn Castro <[email-masked]>
Date: Wed, 6 Dec 2023 20:33:56 -0300

Hello hackers,

Last Saturday I submitted a patch to the pgsql-hackers list with the title
"Proposal: In-flight explain logging" with a patch proposing a feature very
similar to the one being worked on in this thread. I should have done a
better
search in the commitfest before implementing something from scratch.

So, as recommended by Ashutosh, I am sending an incremental patch containing
an additional feature I personally think we should include: logging the plan
with instrumentation details if enabled.

When targeting a query with instrumentation PG should log the complete
EXPLAIN ANALYZE plan with current row count and, if enabled, timing for each
node. This gives the user not only the ability to see what the plan is
but also what was executed so far, which is super useful when
troubleshooting queries that never finish.

Considering that the query is in progress the output will include the
statement (never executed) for nodes that weren't touched yet (or may
never be). This feature is already present in the current ExplainNode
implementation.

I added a new statement (in progress) for nodes currently being executed,
ie,
InstrStartNode was called and clock is ticking there.

Back-reading this thread I saw the discussion about extending
pg_log_query_plan
to parallel workers or not. I added it in my incremental patch as the new
capability of logging instrumentation makes it useful to be able to see
what parallel workers are currently doing.

# DEMONSTRATION:

postgres=# select pid, backend_type,pg_log_query_plan(pid)
postgres=# from pg_stat_activity
postgres=# where (backend_type = 'client backend' and pid !=
pg_backend_pid())
postgres=#    or backend_type = 'parallel worker';
  pid  |  backend_type   | pg_log_query_plan
-------+-----------------+-------------------
 33833 | client backend  | t
 47202 | parallel worker | t
 47203 | parallel worker | t
(3 rows)

2023-12-06 23:14:41.756 UTC [33833] LOG:  query plan running on backend
with PID 33833 is:
Query Text: explain (analyze, buffers) select *
from t2 a
inner join t1 b on a.c1=b.c1
inner join t1 c on a.c1=c.c1
inner join t1 d on a.c1=d.c1
inner join t1 e on a.c1=e.c1;
Gather  (cost=70894.63..202643.27 rows=1000000 width=20) (never executed)
 Output: a.c1, b.c1, c.c1, d.c1, e.c1
 Workers Planned: 2
 Workers Launched: 2
 ->  Parallel Hash Join  (cost=69894.63..101643.27 rows=416667 width=20)
(never executed)
       Output: a.c1, b.c1, c.c1, d.c1, e.c1
       Hash Cond: (a.c1 = e.c1)
       ->  Parallel Hash Join  (cost=54466.62..77218.65 rows=416667
width=16) (never executed)
             Output: a.c1, b.c1, c.c1, d.c1
             Hash Cond: (a.c1 = c.c1)
             ->  Parallel Hash Join  (cost=15428.00..29997.42 rows=416667
width=8) (actual time=2500.914..2625.922 rows=250412 loops=1) (in progress)
                   Output: a.c1, b.c1
                   Inner Unique: true
                   Hash Cond: (b.c1 = a.c1)
                   Buffers: shared hit=755 read=2175, temp read=1473
written=1860
                   ->  Parallel Seq Scan on public.t1 b
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.022..20.904
rows=331492 loops=1)
                         Output: b.c1
                         Buffers: shared hit=602 read=865
                   ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667
width=4) (actual time=1745.107..1745.107 rows=330638 loops=1)
                         Output: a.c1
                         Buffers: shared hit=153 read=1310, temp written=868
                         ->  Parallel Seq Scan on public.t2 a
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.042..27.695
rows=330638 loops=1)
                               Output: a.c1
                               Buffers: shared hit=153 read=1310
             ->  Parallel Hash  (cost=32202.28..32202.28 rows=416667
width=8) (actual time=2450.489..2450.489 rows=407941 loops=1)
                   Output: c.c1, d.c1
                   Buffers: shared hit=1141 read=1833, temp read=1938
written=2836
                   ->  Parallel Hash Join  (cost=15428.00..32202.28
rows=416667 width=8) (actual time=1323.422..1575.245 rows=407941 loops=1)
                         Output: c.c1, d.c1
                         Hash Cond: (c.c1 = d.c1)
                         Buffers: shared hit=1141 read=1833, temp read=1938
written=1864
                         ->  Parallel Seq Scan on public.t1 c
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.026..22.223
rows=336238 loops=1)
                               Output: c.c1
                               Buffers: shared hit=590 read=898
                         ->  Parallel Hash  (cost=8591.67..8591.67
rows=416667 width=4) (actual time=653.306..653.306 rows=335836 loops=1)
                               Output: d.c1
                               Buffers: shared hit=551 read=935, temp
written=872
                               ->  Parallel Seq Scan on public.t1 d
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.022..23.127
rows=335836 loops=1)
                                     Output: d.c1
                                     Buffers: shared hit=551 read=935
       ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667 width=4)
(actual time=590.086..590.086 rows=343696 loops=1)
             Output: e.c1
             Buffers: shared hit=519 read=1002, temp written=896
             ->  Parallel Seq Scan on public.t1 e  (cost=0.00..8591.67
rows=416667 width=4) (actual time=0.066..21.797 rows=343696 loops=1)
                   Output: e.c1
                   Buffers: shared hit=519 read=1002
2023-12-06 23:14:41.757 UTC [47203] LOG:  query plan running on backend
with PID 47203 is:
Query Text: explain (analyze, buffers) select *
from t2 a
inner join t1 b on a.c1=b.c1
inner join t1 c on a.c1=c.c1
inner join t1 d on a.c1=d.c1
inner join t1 e on a.c1=e.c1;
Parallel Hash Join  (cost=69894.63..101643.27 rows=416667 width=20) (never
executed)
 Output: a.c1, b.c1, c.c1, d.c1, e.c1
 Hash Cond: (a.c1 = e.c1)
 ->  Parallel Hash Join  (cost=54466.62..77218.65 rows=416667 width=16)
(never executed)
       Output: a.c1, b.c1, c.c1, d.c1
       Hash Cond: (a.c1 = c.c1)
       ->  Parallel Hash Join  (cost=15428.00..29997.42 rows=416667
width=8) (actual time=2464.367..2628.476 rows=258293 loops=1)
             Output: a.c1, b.c1
             Inner Unique: true
             Hash Cond: (b.c1 = a.c1)
             Buffers: shared hit=704 read=2213, temp read=1497 written=1860
             ->  Parallel Seq Scan on public.t1 b  (cost=0.00..8591.67
rows=416667 width=4) (actual time=0.032..22.247 rows=330412 loops=1)
                   Output: b.c1
                   Buffers: shared hit=594 read=868
             ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667 width=4)
(actual time=1745.093..1745.093 rows=328830 loops=1)
                   Output: a.c1
                   Buffers: shared hit=110 read=1345, temp written=868
                   ->  Parallel Seq Scan on public.t2 a
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=1.141..30.128
rows=328830 loops=1)
                         Output: a.c1
                         Buffers: shared hit=110 read=1345
       ->  Parallel Hash  (cost=32202.28..32202.28 rows=416667 width=8)
(actual time=2449.694..2449.694 rows=295462 loops=1)
             Output: c.c1, d.c1
             Buffers: shared hit=1161 read=1844, temp read=1971 written=2872
             ->  Parallel Hash Join  (cost=15428.00..32202.28 rows=416667
width=8) (actual time=1378.678..1577.182 rows=295462 loops=1)
                   Output: c.c1, d.c1
                   Hash Cond: (c.c1 = d.c1)
                   Buffers: shared hit=1161 read=1844, temp read=1971
written=1856
                   ->  Parallel Seq Scan on public.t1 c
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.031..22.459
rows=336288 loops=1)
                         Output: c.c1
                         Buffers: shared hit=590 read=898
                   ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667
width=4) (actual time=651.048..651.048 rows=328378 loops=1)
                         Output: d.c1
                         Buffers: shared hit=507 read=946, temp written=860
                         ->  Parallel Seq Scan on public.t1 d
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.034..24.462
rows=328378 loops=1)
                               Output: d.c1
                               Buffers: shared hit=507 read=946
 ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667 width=4) (actual
time=575.417..575.417 rows=327926 loops=1)
       Output: e.c1
       Buffers: shared hit=522 read=929, temp written=860
       ->  Parallel Seq Scan on public.t1 e  (cost=0.00..8591.67
rows=416667 width=4) (actual time=0.786..23.114 rows=327926 loops=1)
             Output: e.c1
             Buffers: shared hit=522 read=929
2023-12-06 23:14:41.758 UTC [47202] LOG:  query plan running on backend
with PID 47202 is:
Query Text: explain (analyze, buffers) select *
from t2 a
inner join t1 b on a.c1=b.c1
inner join t1 c on a.c1=c.c1
inner join t1 d on a.c1=d.c1
inner join t1 e on a.c1=e.c1;
Parallel Hash Join  (cost=69894.63..101643.27 rows=416667 width=20) (never
executed)
 Output: a.c1, b.c1, c.c1, d.c1, e.c1
 Hash Cond: (a.c1 = e.c1)
 ->  Parallel Hash Join  (cost=54466.62..77218.65 rows=416667 width=16)
(never executed)
       Output: a.c1, b.c1, c.c1, d.c1
       Hash Cond: (a.c1 = c.c1)
       ->  Parallel Hash Join  (cost=15428.00..29997.42 rows=416667
width=8) (actual time=2500.138..2631.855 rows=254125 loops=1)
             Output: a.c1, b.c1
             Inner Unique: true
             Hash Cond: (b.c1 = a.c1)
             Buffers: shared hit=749 read=2254, temp read=1483 written=1896
             ->  Parallel Seq Scan on public.t1 b  (cost=0.00..8591.67
rows=416667 width=4) (actual time=0.027..22.224 rows=338096 loops=1)
                   Output: b.c1
                   Buffers: shared hit=628 read=868
             ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667 width=4)
(actual time=1744.616..1744.616 rows=340532 loops=1)
                   Output: a.c1
                   Buffers: shared hit=121 read=1386, temp written=892
                   ->  Parallel Seq Scan on public.t2 a
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=1.138..30.003
rows=340532 loops=1)
                         Output: a.c1
                         Buffers: shared hit=121 read=1386
       ->  Parallel Hash  (cost=32202.28..32202.28 rows=416667 width=8)
(actual time=2450.470..2450.470 rows=296597 loops=1)
             Output: c.c1, d.c1
             Buffers: shared hit=1186 read=1813, temp read=1610 written=2872
             ->  Parallel Hash Join  (cost=15428.00..32202.28 rows=416667
width=8) (actual time=1380.286..1561.412 rows=296597 loops=1)
                   Output: c.c1, d.c1
                   Hash Cond: (c.c1 = d.c1)
                   Buffers: shared hit=1186 read=1813, temp read=1610
written=1848
                   ->  Parallel Seq Scan on public.t1 c
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.032..22.170
rows=327474 loops=1)
                         Output: c.c1
                         Buffers: shared hit=548 read=901
                   ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667
width=4) (actual time=653.297..653.297 rows=335786 loops=1)
                         Output: d.c1
                         Buffers: shared hit=574 read=912, temp written=868
                         ->  Parallel Seq Scan on public.t1 d
 (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.023..24.210
rows=335786 loops=1)
                               Output: d.c1
                               Buffers: shared hit=574 read=912
 ->  Parallel Hash  (cost=8591.67..8591.67 rows=416667 width=4) (actual
time=574.553..574.553 rows=328378 loops=1)
       Output: e.c1
       Buffers: shared hit=495 read=958, temp written=864
       ->  Parallel Seq Scan on public.t1 e  (cost=0.00..8591.67
rows=416667 width=4) (actual time=0.717..23.270 rows=328378 loops=1)
             Output: e.c1
             Buffers: shared hit=495 read=958

The thread of my initial patch contains all important implementation
details. Sharing the ones relevant to my incremental patch here:

- Safely printing signaled plans with instrumentation

A plan string is built in function ExplainNode here (
https://github.com/postgres/postgres/blob/REL_16_STABLE/src/backend/commands/explain.c#L1178
)
which is called at the end of a query execution when EXPLAIN is used.
That function performs logic using a PlanState (part of QueryDesc) of
the running query and a ExplainState.

The main challenge there is that ExplainNode calls InstrEndLoop which
changes values in Instrumentation. This is ok for a regular EXPLAIN
where the query is already complete but not ok for the new feature with
signaled plan logging.

So the new code has custom logic to clone Instrumentation instance of
the current node. The cloned object can be safely written.

Function InstrEndLoop has a safety rule here (
https://github.com/postgres/postgres/blob/REL_16_STABLE/src/backend/executor/instrument.c#L148
)
that prevents adjusting instrumentation details in a running node. This
never happens in the current code logic but with the new feature
it will happen very often.

I didn't want to remove this safety rule as InstrEndLoop gets called in
other places too (even in auto_explain) so the solution was to keep
InstrEndLoop and have a new InstrEndLoopForce for the signaled
plan logging with instrumentation. Both InstrEndLoop and InstrEndLoopForce
call a new internal InstrEndLoopInternal to avoid duplicating the code.

- Memory management

Considering that pg_log_query_plan() creates its own memory context before
calling ExplainAssembleLogOutput, the new logic that allocates memory
to clone instrumentation doesn't need to free anything.

# FINAL CONSIDERATIONS

Let me know what you think about this incremental patch. If you think it
is useful but needs adjustments I will be happy to change as needed.

Kind Regards,

Rafael Castro.

---

From: torikoshia <[email-masked]>
Date: Mon, 11 Dec 2023 14:46:23 +0900

On 2023-12-07 08:33, Rafael Thofehrn Castro wrote:
> similar to the one being worked on in this thread. I should have done
> a better

Thanks for the proposal and making the patch!

> troubleshooting queries that never finish.

I think showing the progress of the query execution would be useful.

OTOH it seems to at least need some modifications around Instrumentation 
as your patch.
As a first step, I think it would better to minimize the scope and focus 
on the fundamental function.
For the same reason, getting queries for parallel workers is also 
prohibited in the current patch as discussed here[1].

[1] 
https://www.postgresql.org/message-id/c25ae6015be96a1964eddd964657660b%40oss.nttdata.com

So I think below steps would be better than pushing all the 
functionalities to the 1st commit.

- First, develop function to enable output of query 
progress(v34-0001-Add-function-to-log-the-plan-of-the-query.patch).
- Then enhance the function
   - showing the progress of the query 
execution(v34-0002-Log-plan-along-with-instrumentation-details.patch), 
etc.

> --https://www.postgresql.org/message-id/CAG0ozMp3g3drnkDa6RZxXO_OmnisL2sD9vBrmpu5fOBoYpC-3w%40mail.gmail.com
> - ExplainState customization
> 
> A ExplainState is allocated and customized for the in-flight logging.
> Instrumentation related settings are enabled based on how the target
> query started, which is usually via EXPLAIN ANALYZE or with 
> auto_explain.

Does this mean the progress can be got only when the target query was 
run with EXPLAIN ANALYZE or auto_explain.log_analyze?

If so, there might be limited situations we can get the progress since I 
imagine EXPLAIN ANALYZE is used when user want to get the plan from the 
beginning and auto_explain.log_analyze can give negative impact on 
performance as described in the manual and there may not be many 
environments which enable it.

-- 
Regards,

---

From: torikoshia <[email-masked]>
Date: Mon, 29 Jan 2024 22:02:29 +0900

Hi,

Updated the patch to fix typos and move 
ProcessLogQueryPlanInterruptActive from errfinish() to AbortTransaction.

BTW since the thread is getting long, I list the some points of the 
discussion so far:

# Safety concern
## Catalog access inside CFI
- it seems safe if the CFI call is inside an existing valid 
transaction/query state[1]

- We did some tests, for example calling ProcessLogQueryPlanInterrupt() 
in every single CHECK_FOR_INTERRUPTS()[2]. This test passed on my env 
but was stucked on James's env, so I modified to exit 
ProcessLogQueryPlanInterrupt() when target process is inside of lock 
acquisition code[3]

## Risk of calling EXPLAIN code in CFI
- EXPLAIN is not a simple logic code, and there exists risk calling it 
from CFI. For example, if there is a bug, we may find ourselves in a 
situation where we can't cancel the query

- it's a trade-off that's worth making for the introspection benefits 
this patch would provide?[4]

# Design
- Although some suggested it should be in auto_explain, current patch 
introduces this feature to the core[5]

- When the target query is nested, only the most inner query's plan is 
explained. In future, all the nested queries' plans are expected to 
explained optionally like auto_explain.log_nested_statements[6]

- When the target process is a parallel worker, the plan is not shown[6]

- When the target query is nested and its subtransaction is aborted, 
pg_log_query_plan cannot log the parental query plan after the abort 
even parental query is running[7]

- The output corresponds to EXPLAIN with VERBOSE, COST, SETTINGS and 
FORMAT text. It doesn't do ANALYZE or show the progress of the query 
execution. Future work proposed by Rafael Thofehrn Castro may realize 
this[8]

- To prevent assertion error, this patch ensures no page lock is held by 
checking all the LocalLock entries before running explain code, but 
there is a discussion that ginInsertCleanup() should be modified[9]

It may be not so difficult to improve some of restrictions in "Design", 
but I'd like to limit the scope of the 1st patch to make it simpler.

[1] 
https://www.postgresql.org/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gmail.com
[2] 
https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail.gmail.com
[3] 
https://www.postgresql.org/message-id/0e0e7ca08dff077a625c27a5e0c2ef0a%40oss.nttdata.com
[4] 
https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail.gmail.com
[5] 
https://www.postgresql.org/message-id/CAAaqYe_1EuoTudAz8mr8-qtN5SoNtYRm4JM2J9CqeverpE3B2A%40mail.gmail.com
[6] 
https://www.postgresql.org/message-id/CAExHW5sh4ahrJgmMAGfptWVmESt1JLKCNm148XVxTunRr%2B-6gA%40mail.gmail.com
[7] 
https://www.postgresql.org/message-id/3d121ed5f81cef588bac836b43f5d1f9%40oss.nttdata.com
[8] 
https://www.postgresql.org/message-id/c161b5e7e1888eb9c9eb182a7d9dcf89%40oss.nttdata.com
[9] 
https://www.postgresql.org/message-id/20220201.172757.1480996662235658750.horikyota.ntt%40gmail.com

-- 
Regards,

From 65786ad6c2a9b656c3fd36a45118a39a66da0236 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Mon, 29 Jan 2024 21:40:04 +0900
Subject: [PATCH v35] Add function to log the plan of the query

 src/backend/access/transam/xact.c            |  17 ++
 src/backend/commands/explain.c               | 208 ++++++++++++++++++-
 src/include/commands/explain.h               |   9 +
 19 files changed, 402 insertions(+), 48 deletions(-)

index c7aacd7812..c0f2ca4c18 100644

 			/*
 			 * Note: we rely on the existing logging of context or
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 6788ba8ef4..48e8748fd1 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -26524,6 +26524,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
@@ -27300,6 +27319,37 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
 
+   <para>
 
index 464858117e..d0b5954627 100644
@@ -2750,6 +2751,14 @@ AbortTransaction(void)
 
+	/*
+	 * Reset pg_log_query_plan() related global variables.
+	 * When ActiveQueryDesc is referenced after abort, some of its elements
+	 * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+	 */
+	ActiveQueryDesc = NULL;
+	ProcessLogQueryPlanInterruptActive = false;
+
 	/*
 	 * check the current transaction state
 	 */
@@ -5109,6 +5118,14 @@ AbortSubTransaction(void)
 	 */
 	sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
 
+	/*
+	 * Reset pg_log_query_plan() related global variables.
+	 * When ActiveQueryDesc is referenced after abort, some of its elements
+	 * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+	 */
+	ActiveQueryDesc = NULL;
+	ProcessLogQueryPlanInterruptActive = false;
+
 	/*
 	 * check the current transaction state
 	 */
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 346cfb98a0..c64ca9946e 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -757,6 +757,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;

index 843472e6dd..6d8d2c2f97 100644
@@ -40,6 +44,7 @@
 #include "utils/typcache.h"
 #include "utils/xml.h"

 /* Hook for plugins to get control in ExplainOneQuery() */
 ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
@@ -737,6 +742,37 @@ ExplainPrintSettings(ExplainState *es)
 	}
 }
 
+/*
@@ -1647,6 +1683,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
@@ -1654,7 +1693,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
 	if (es->analyze &&
@@ -5082,3 +5121,170 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+				errmsg("ignored request for logging query plan due to page lock conflicts"),
+	 * Ensure no lock is already held on the lockable object.
+			errmsg("ignored request for logging query plan due to lock conflicts"),
index 13a9b7da83..4c7fe35f8f 100644

 void
index e84619e5a5..69638e64bb 100644

index c70a1adb9a..fed2ea1924 100644

 /*
index 1a34bd3715..07797ef7dd 100644
 
index 88b03e8fa3..063a92a5bc 100644
index 29af4ce65d..26b11d6a12 100644
@@ -8274,6 +8274,12 @@
 
index 1b44d483d6..bbca106e92 100644
@@ -17,6 +17,8 @@
 
@@ -60,6 +62,7 @@ typedef struct ExplainState
 
 /* Hook for plugins to get control in ExplainOneQuery() */
@@ -94,6 +97,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
 						   const instr_time *planduration,
 						   const BufferUsage *bufusage);

@@ -126,4 +133,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);
 
index 0b01c1f093..3914ba9f71 100644
 
index 00679624f7..382930073a 100644
index 52dcb4c2ad..400c527292 100644
 
index 073fb323bc..3dd7edf93c 100644

 
index 761ee2512d..3d5b4b37fd 100644

index 7c15477104..f34f2bcd7b 100644

 

 RESET ROLE;
index 851dad90f4..f472a839bf 100644

 

 

 

base-commit: 6a1ea02c491d16474a6214603dce40b5b122d4d1
-- 
2.39.2

---

From: Ashutosh Bapat <[email-masked]>
Date: Tue, 6 Feb 2024 16:21:58 +0530

Hi Atsushi,

> but I'd like to limit the scope of the 1st patch to make it simpler.

Thanks for the summary. It is helpful. I think patch is also getting better.

I have a few questions and suggestions
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?

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.

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.

-- 
Best Wishes,
Ashutosh Bapat

---

From: torikoshia <[email-masked]>
Date: Wed, 07 Feb 2024 13:08:24 +0900

Hi Ashutosh,

> I have a few questions and suggestions

Thanks for your comments.

> 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.

> 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].)

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)

> especially automated would help.

Thanks for the advice, it seems a good idea.
I'm going to try to add tests using injection point.

[1] 
https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail.gmail.com
[2] 
https://www.postgresql.org/docs/devel/hot-standby.html#HOT-STANDBY-CONFLICT

-- 
Regards,

---

From: Ashutosh Bapat <[email-masked]>
Date: Wed, 7 Feb 2024 10:28:18 +0530

>    +++ b/src/backend/commands/explain.c

What load did you run? I don't think any query in make check would
take say thousands of locks. 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.

> (I imagine 'conflict' here is something like 'hard conflict' in

By conflict, I mean the two features behave weird when used together
e.g give wrong results or crash etc.

> 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.

-- 
Best Wishes,
Ashutosh Bapat

---

From: torikoshia <[email-masked]>
Date: Wed, 07 Feb 2024 19:14:40 +0900

On 2024-02-07 13:58, Ashutosh Bapat wrote:
> 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

OK, I'll try such cases.

> testing might need something like injection points.

It might be so, I will consider whether there are any subtle timing 
issues, etc.

-- 
Regards,

---

From: jian he <[email-masked]>
Date: Mon, 12 Feb 2024 08:00:00 +0800

> > > a lot of time delaying the query execution further?
corner case test:
pgbench  --initialize --partition-method=range --partitions=20000
Somehow my setup, the pg_bench didn't populate the data but there are
20000 partitions there.
(all my other settings are default)

some interesting things happened when a query touch so many partitions like:
select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1;

in another session, if you immediate call SELECT pg_log_query_plan(9482);
then output be
`
LOG:  backend with PID 9482 is not running a query or a subtransaction
is aborted
`
however if you delay a little bit of time (like 1 second), then
LOG will emit the plan with lots of text (not sure the plan is right).

I think the reason is that the `InitPlan` within
standard_ExecutorStart takes more time to finish
when your query touches a lot of partitions.

---

From: jian he <[email-masked]>
Date: Mon, 12 Feb 2024 08:00:00 +0800

+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_query_plan</primary>
+        </indexterm>
+        <function>pg_log_query_plan</function> (
<parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the plan of the query currently running on the
+        backend with specified process ID.
+        It will be logged at <literal>LOG</literal> message level and
+        will appear in the server log based on the log
+        configuration set (See <xref linkend="runtime-config-logging"/>
+        for more information), but will not be sent to the client
+        regardless of <xref linkend="guc-client-min-messages"/>.
+        </para></entry>
+      </row>
it would be better to explain the meaning of return value TRUE/FALSE?

+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the
specified backend',
+  proname => 'pg_log_query_plan',
+  provolatile => 'v', prorettype => 'bool',
you can add
`proargnames => '{pid}'`

+ if (proc == NULL)
+ {
+ /*

I found out that pg_log_query_plan's comments look like
pg_log_backend_memory_contexts.
pg_log_backend_memory_contexts will iterate through many memory contexts.
but pg_log_query_plan for one specific pid will only output one plan?
so I am a little bit confused by the comments.

+ /*
+ * Ensure no page lock is held on this process.
+ *
+ * If page lock is held at the time of the interrupt, we can't acquire any
+ * other heavyweight lock, which might be necessary for explaining the plan
+ * when retrieving column names.
+ *
+ * This may be overkill, but since page locks are held for a short duration
+ * we check all the LocalLock entries and when finding even one, give up
+ * logging the plan.
+ */
+ hash_seq_init(&status, GetLockMethodLocalHash());
+ while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL)
+ {
+ if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE)
maybe not that self evident, the above comments still not explained
why we need to ensure only
PAGE lock was held on this process?

In the commit message, can you add all the discussion links?
My gmail account doesn't have a previous discussion history.
I am not sure this
(https://www.postgresql.org/message-id/flat/d68c3ae31672664876b22d2dcbb526d2%40postgrespro.ru)
is the only discussion link?

I found a bug:
src8=# select *, pg_sleep(10)  from tenk1 for update;
2024-02-11 15:54:17.944 CST [48602] LOG:  query plan running on
backend with PID 48602 is:
        Query Text: select *, pg_sleep(10)  from tenk1 for update;
        LockRows  (cost=0.00..570.00 rows=10000 width=254)
          Output: unique1, unique2, two, four, ten, twenty, hundred,
thousand, twothousand, fivethous, tenthous, odd, even, stringu1,
stringu2, string4, (pg_sleep('10'::double precision)), ctid
          ->  Seq Scan on public.tenk1  (cost=0.00..470.00 rows=10000 width=254)
                Output: unique1, unique2, two, four, ten, twenty,
hundred, thousand, twothousand, fivethous, tenthous, odd, even,
stringu1, stringu2, string4, pg_sleep('10'::double precision), ctid

another session (PID) executes `SELECT pg_log_query_plan(48602);` in
the meantime.
pg_log_query_plan returns true successfully, but PID 48602 was stuck.

I have problem using git apply:
error: patch failed: src/include/commands/explain.h:94
error: src/include/commands/explain.h: patch does not apply

`patch -p1 < /v35-0001-Add-function-to-log-the-plan-of-the-query.patch` works

---

From: Ashutosh Bapat <[email-masked]>
Date: Mon, 12 Feb 2024 10:09:18 +0530

> pg_log_query_plan returns true successfully, but PID 48602 was stuck.

What do you mean by PID 48602 was stuck?

-- 
Best Wishes,
Ashutosh Bapat

---

From: Ashutosh Bapat <[email-masked]>
Date: Mon, 12 Feb 2024 10:12:21 +0530

> when your query touches a lot of partitions.

That's probably expected unless we make the ActiveQueryDesc available
before ExecutorRun.

How much time did it took between issuing SELECT
pg_log_query_plan(9482); and plan getting output to the server error
logs? How does this time compare with say the same time difference for
a simple query and how much of that time can be attributed to Lock
table hash scan, if the difference between time difference is huge.

-- 
Best Wishes,
Ashutosh Bapat

---

From: jian he <[email-masked]>
Date: Mon, 12 Feb 2024 15:08:00 +0800

> That's probably expected unless we make the ActiveQueryDesc available

so the error message should be something like:
errmsg("backend with PID %d is not running a query or a subtransaction
is aborted or the plan is not generated",

> logs?

it either says errmsg("backend with PID %d is not running a query,.....)
or outputs the plan immediately, if i wait one or two seconds to call
pg_log_query_plan.

because of previously mentioned: with lots of partitions, initplan
took longer to finish.
setup: 2 sessions, one runs the query (select abalance, aid from
public.pgbench_accounts,pg_sleep(4) where aid > 1;),
another one calls pg_log_query_plan.

---

From: torikoshia <[email-masked]>
Date: Tue, 13 Feb 2024 09:19:03 +0900

>> thousands of partitions. May be we want to try that scenario.

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,

---

From: torikoshia <[email-masked]>
Date: Tue, 13 Feb 2024 11:30:53 +0900

On 2024-02-12 09:00, jian he wrote:

Thanks for you comments.

> it would be better to explain the meaning of return value TRUE/FALSE?

Yeah, but I've noticed that this should be located in 'Table Server 
Signaling Functions' not 'Table Control Data Functions'.
Since 'Table Server Signaling Functions' describes the return code as 
below, just relocation seems fine.

   Each of these functions returns true if the signal was successfully 
sent and false if sending the signal failed.

> +  provolatile => 'v', prorettype => 'bool',

Hmm, pg_log_query_plan() can take one argument, I'm not sure how much 
sense it makes.
Other functions which take one argument such as pg_cancel_backend() does 
not have proargnames.

> so I am a little bit confused by the comments.

These "loop" mean backend can run pg_log_query_plan() repeatedly even 
when failing sending signals.
pg_signal_backend() also have such comments.

> PAGE lock was held on this process?

This is for preventing assertion error and it seems not necessary 
anymore as described in [1].
I'm going remove them.

> My gmail account doesn't have a previous discussion history.

Sure.

> is the only discussion link?

This is the original one:
https://www.postgresql.org/message-id/cf8501bcd95ba4d727cbba886ba9eea8%40oss.nttdata.com

> pg_log_query_plan returns true successfully, but PID 48602 was stuck.

Hmm, it's not simply sleeping, is it?
I'm concerned a bit this because estimated rows of tenk1 is 10000.
If so, the query will take 10000 * 10 seconds.

> `patch -p1 < /v35-0001-Add-function-to-log-the-plan-of-the-query.patch` 

I'll update the patch including other points such as removing ensuring 
no page lock code.

[1] 
https://www.postgresql.org/message-id/1b2b247530f3ff3afab4ddc2df222e8b%40oss.nttdata.com

-- 
Regards,

---

From: torikoshia <[email-masked]>
Date: Wed, 14 Feb 2024 15:29:35 +0900

> I'll update the patch including other points such as removing ensuring

Updated the patch.

> examine the server log file to see if the plan is indeed output to the

Attached patch uses injection point as below:

- There may be more points to inject, but added an injection point at 
ExecutorRun(), which seems to be the first interruption point where 
plans can be reliably displayed.
- At injection point, it'd be possible to wait for some duration and 
fire pg_log_plan_query() as you suggested. However, I'm not sure how 
long duration is appropriate considering the variety of testing 
environments. Instead, attached patch calls 
HandleLogQueryPlanInterrupt() directly and set InterruptPending.
- Tests both pg_log_plan_query() and auto_explain logs for their output, 
and the logged plans are the same.

-- 
Regards,

From 1dcac4fb4291e3b92733494624cbb090dff7aded Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Wed, 14 Feb 2024 14:41:04 +0900
Subject: [PATCH v36] Add function to log the plan of the query

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar,
Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby, Kyotaro
Horiguchi, Robert Treat, Alena Rybakina, Ashutosh Bapat,
Jian He

Discussion: https://www.postgresql.org/message-id/cf8501bcd95ba4d727cbba886ba9eea8%40oss.nttdata.com
Discussion: https://www.postgresql.org/message-id/flat/d68c3ae31672664876b22d2dcbb526d2%40postgrespro.ru
---
 contrib/auto_explain/Makefile                 |   2 +
 contrib/auto_explain/auto_explain.c           |  23 +--
 contrib/auto_explain/t/001_auto_explain.pl    |  35 ++++
 doc/src/sgml/func.sgml                        |  50 +++++
 src/backend/access/transam/xact.c             |  17 ++
 src/backend/catalog/system_functions.sql      |   2 +
 src/backend/commands/explain.c                | 180 +++++++++++++++++-
 src/backend/executor/execMain.c               |  19 ++
 src/backend/storage/ipc/procsignal.c          |   4 +
 src/backend/storage/lmgr/lock.c               |   9 +-
 src/backend/tcop/postgres.c                   |   4 +
 src/backend/utils/init/globals.c              |   2 +
 src/include/catalog/pg_proc.dat               |   6 +
 src/include/commands/explain.h                |   9 +
 src/include/miscadmin.h                       |   1 +
 src/include/storage/lock.h                    |   2 -
 src/include/storage/procsignal.h              |   1 +
 src/include/tcop/pquery.h                     |   2 +-
 src/include/utils/elog.h                      |   1 +
 .../injection_points/injection_points.c       |  11 ++
 src/test/regress/expected/misc_functions.out  |  54 +++++-
 src/test/regress/sql/misc_functions.sql       |  41 +++-
 22 files changed, 427 insertions(+), 48 deletions(-)

diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
index efd127d3ca..64fe0e0573 100644
--- a/contrib/auto_explain/Makefile
+++ b/contrib/auto_explain/Makefile
@@ -8,6 +8,8 @@ PGFILEDESC = "auto_explain - logging facility for execution plans"
 
 TAP_TESTS = 1
 
+EXTRA_INSTALL = src/test/modules/injection_points
+
 ifdef USE_PGXS
 PG_CONFIG = pg_config
 PGXS := $(shell $(PG_CONFIG) --pgxs)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 677c135f59..e041b10b0e 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -401,26 +401,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 			es->format = auto_explain_log_format;
 			es->settings = auto_explain_log_settings;

 			/*
 			 * Note: we rely on the existing logging of context or
diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 0e5b34afa9..36a787174e 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -35,6 +35,8 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
 $node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
 $node->start;
 
+$node->safe_psql('postgres', 'CREATE EXTENSION injection_points');
+
 # Simple query.
 my $log_contents = query_log($node, "SELECT * FROM pg_class;");
 
@@ -212,4 +214,37 @@ REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1;
 DROP USER regress_user1;
 });
 
+# Check that using both auto_explain and pg_log_query_plan() works fine
+
+$node->safe_psql('postgres', q{SELECT injection_points_attach('executor-run', 'logqueryplan')});
+
+$log_contents = query_log(
+	$node,
+	"SELECT * FROM pg_class;",
+	{
+		"auto_explain.log_verbose" => "on",
+		"auto_explain.log_settings" => "on",
+		"auto_explain.log_analyze" => "off",
+		"compute_query_id" => "on"
+	});
+
+like(
+	$log_contents,
+	qr/query plan running on backend with PID/,
+	"with pg_log_query_plan(), pg_log_query_plan() logged");
+
+like(
+	$log_contents,
+	qr/duration: .+ms  plan:/,
+	"with pg_log_query_plan(), auto_explain logged");
+
+$log_contents =~ /(Query Text:.*Query Identifier: \d+).*(Query Text:.*Query Identifier: \d+)/s;
+my $pg_log_plan_query_output = $1;
+my $auto_explain_output = $2;
+
+cmp_ok(
+	$pg_log_plan_query_output, "eq",
+	$auto_explain_output,
+	"with pg_log_plan_query_log(), logged plans are the same");
+
 done_testing();
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 8f147a2417..61dec0e415 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -27191,6 +27191,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
@@ -27305,6 +27324,37 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
 
+   <para>

+	/*
 
+	/*

index 83d00a4663..a6565c0bab 100644

 /* Hook for plugins to get control in ExplainOneQuery() */
 ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
@@ -784,6 +789,37 @@ ExplainPrintSettings(ExplainState *es)
 	}
 }
 
+/*
@@ -1694,6 +1730,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
@@ -1701,7 +1740,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
 	if (es->analyze &&
@@ -5182,3 +5221,142 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
index 13a9b7da83..4eee998161 100644
 #include "tcop/utility.h"
 #include "utils/acl.h"
 #include "utils/backend_status.h"
+#include "utils/injection_point.h"
 #include "utils/lsyscache.h"
 #include "utils/memutils.h"
 #include "utils/partcache.h"
@@ -78,6 +79,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
 
@@ -303,10 +307,25 @@ ExecutorRun(QueryDesc *queryDesc,
+#ifdef USE_INJECTION_POINTS
+	INJECTION_POINT("executor-run");
+#endif
 
 void

 
 
 /*
 
index 9c120fc2b7..a54bf97c60 100644
 
index 7c0f0b5636..f73f984c37 100644
 
@@ -61,6 +63,7 @@ typedef struct ExplainState
 
 /* Hook for plugins to get control in ExplainOneQuery() */
@@ -96,6 +99,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
 						   const BufferUsage *bufusage,
 						   const MemoryContextCounters *mem_counters);

@@ -128,4 +135,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);

 

 

+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
 extern bool errstart(int elevel, const char *domain);
 extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
 extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/modules/injection_points/injection_points.c b/src/test/modules/injection_points/injection_points.c
index e843e6594f..db0440dd91 100644
--- a/src/test/modules/injection_points/injection_points.c
+++ b/src/test/modules/injection_points/injection_points.c
@@ -17,6 +17,7 @@
 
 #include "postgres.h"
 
+#include "commands/explain.h"
 #include "fmgr.h"
 #include "storage/lwlock.h"
 #include "storage/shmem.h"
@@ -28,6 +29,7 @@ PG_MODULE_MAGIC;
 
 extern PGDLLEXPORT void injection_error(const char *name);
 extern PGDLLEXPORT void injection_notice(const char *name);
+extern PGDLLEXPORT void injection_HandleLogQueryPlanInterrupt(const char *name);

 /* Set of callbacks available to be attached to an injection point. */
@@ -43,6 +45,13 @@ injection_notice(const char *name)
 	elog(NOTICE, "notice triggered for injection point %s", name);
 }
 
+void
+injection_HandleLogQueryPlanInterrupt(const char *name)
+{
+	HandleLogQueryPlanInterrupt();
+	elog(LOG, "triggered injection_HandleLogQueryPlanInterrupt for injection point %s", name);
+}
+
 /*
  * SQL function for creating an injection point.
  */
@@ -58,6 +67,8 @@ injection_points_attach(PG_FUNCTION_ARGS)
 		function = "injection_error";
 	else if (strcmp(action, "notice") == 0)
 		function = "injection_notice";
+	else if (strcmp(action, "logqueryplan") == 0)
+		function = "injection_HandleLogQueryPlanInterrupt";
 	else
 		elog(ERROR, "incorrect action \"%s\" for injection point creation", action);

 

 
 RESET ROLE;

 

 

 

base-commit: ddd5f4f54a026db6a6692876d0d44aef902ab686
-- 
2.39.2

---

From: Robert Haas <[email-masked]>
Date: Thu, 15 Feb 2024 14:42:11 +0530

Hi,

I've just been catching up on this thread.

+ if (MyProc->heldLocks)
+ {

I don't like this for several reasons.

First, I think it's not nice to have a request just get ignored. A
user will expect that if we cannot immediately respond to some
request, we'll respond later at the first time that it's safe to do
so, rather than just ignoring it and telling them to retry.

Second, I don't think that the error message is very good. It talks
about lock conflicts, but we don't know that there is any real
problem. We know that, if we enter this block, the server is in the
middle of trying to acquire some lock, and we also know that we could
attempt to acquire a lock as part of generating the EXPLAIN output,
and maybe that's an issue. But that's not a lock conflict. That's a
re-entrancy problem. I don't know that we want to talk about
re-entrancy problems in an error message, and I don't really think
this error message should exist in the first place, but if we're going
to error out in this case surely we shouldn't do so with an error
message that describes a problem we don't have.

Third, I think that the re-entrancy problems with this patch may
extend well beyond lock acquisition. This is one example of how it can
be unsafe to do something as complicated as EXPLAIN at any arbitrary
CHECK_FOR_INTERRUPTS(). It is not correct to say, as
http://postgr.es/m/[email-masked]
does, that the problems with running EXPLAIN at an arbitrary point are
specific to running this code in an aborted transaction. The existence
of this code shows that there is at least one hazard even if the
current transaction is not aborted, and I see no analysis on this
thread indicating whether there are any more such hazards, or how we
could go about finding them all.

I think the issue is very general. We have lots of subsystems that
both (a) use global variables and (b) contain CHECK_FOR_INTERRUPTS().
If we process an interrupt while that code is in the middle of
manipulating its global variables and then again re-enter that code,
bad things might happen. We could try to rule that out by analyzing
all such subsystems and all places where CHECK_FOR_INTERRUPTS() may
appear, but that's very difficult. Suppose we took the alternative
approach recommended by Andrey Lepikhov in
http://postgr.es/m/[email-masked]
and instead set a flag that gets handled in some suitable place in the
executor code, like ExecProcNode(). If we did that, then we would know
that we're not in the middle of a syscache lookup, a catcache lookup,
a heavyweight lock acquisition, an ereport, or any other low-level
subsystem call that might create problems for the EXPLAIN code.

In that design, the hack shown above would go away, and we could be
much more certain that we don't need any other similar hacks for other
subsystems. The only downside is that we might experience a slightly
longer delay before a requested EXPLAIN plan actually shows up, but
that seems like a pretty small price to pay for being able to reason
about the behavior of the system. I don't *think* there are any cases
where we run in the executor for a particularly long time without a
new call to ExecProcNode().

I think this case is a bit like vacuum_delay_point(). You might think
that vacuum_delay_point() could be moved inside of
CHECK_FOR_INTERRUPTS(), but we've made the opposite decision: every
vacuum_delay_point() calls CHECK_FOR_INTERRUPTS() but not every
CHECK_FOR_INTERRUPTS() calls vacuum_delay_point(). That means that we
can allow vacuum_delay_point() only at cases where we know it's safe,
rather than at every CHECK_FOR_INTERRUPTS(). I think that's a pretty
smart decision, even for vacuum_delay_point(), and AFAICS the code
we're proposing to run here does things that are substantially more
complicated than what vacuum_delay_point() does. That code just does a
bit of reading of shared memory, reports a wait event, and sleeps.
That's really simple compared to code that could try to do relcache
builds, which can trigger syscache lookups, which can both trigger
heavyweight lock acquisition, lightweight lock acquisition, bringing
pages into shared_buffers possibly through physical I/O, processing of
invalidation messages, and a bunch of other stuff.

It's really hard for me to accept that the heavyweight lock problem
for which the patch contains a workaround is the only one that exists.
I can't see any reason why that should be true.

...Robert

---

From: Andres Freund <[email-masked]>
Date: Thu, 15 Feb 2024 10:59:11 -0800

Hi,

On 2024-02-15 14:42:11 +0530, Robert Haas wrote:
> about the behavior of the system.

I am very wary of adding overhead to ExecProcNode() - I'm quite sure that
adding code there would trigger visible overhead for query times.

If we went with something like tht approach, I think we'd have to do something
like redirecting node->ExecProcNode to a wrapper, presumably from within a
CFI. That wrapper could then implement the explain support, without slowing
down the normal execution path.

> I don't *think* there are any cases where we run in the executor for a
> particularly long time without a new call to ExecProcNode().

I guess it depends on what you call a long time. A large sort, for example,
could spend a fair amount of time inside tuplesort, similarly, a gather node
might need to wait for a worker for a while etc.

> I can't see any reason why that should be true.

I suspect you're right.

Greetings,

Andres Freund

---

From: torikoshia <[email-masked]>
Date: Fri, 16 Feb 2024 23:42:36 +0900

> I can't see any reason why that should be true.

Thanks for the review and the very detailed explanation!

I'm convinced that it's unsafe to execute EXPLAIN codes during 
CHECK_FOR_INTERRUPTS() and we need to execute it in other safe place, as 
well as the first and second point.

> down the normal execution path.

Thanks for the idea!
I'm not so sure about the implementation now, i.e. finding the next node 
to be executed from the planstate tree, but I'm going to try this 
approach.

-- 
Regards,

---

From: Robert Haas <[email-masked]>
Date: Tue, 20 Feb 2024 10:23:04 +0530

> down the normal execution path.

That's an annoying complication; maybe there's some better way to
handle this. But I think we need to do something different than what
the patch does currently because...

> > I can't see any reason why that should be true.

...I think the current approach is just plain dead, because of this
issue. We can't take an approach that creates an unbounded number of
unclear reentrancy issues and then insert hacks one by one to cure
them (or hack around them, more to the point) as they're discovered.

The premise has to be that we only allow logging the query plan at
points where we know it's safe, rather than, as at present, allowing
it in places that are unsafe and then trying to compensate with code
elsewhere. That's not likely to ever be as stable as we want
PostgreSQL to be.

-- 
Robert Haas
EDB: http://www.enterprisedb.com