Subject: RFC: Logging plan of the running query

From: "a.rybakina" <[email-masked]>
Date: Fri, 16 Sep 2022 21:51:01 +0300

Hi,

I liked this idea and after reviewing code I noticed some moments and 
I'd rather ask you some questions.

Firstly, I suggest some editing in the comment of commit. I think, it is 
turned out the more laconic and the same clear. I wrote it below since I 
can't think of any other way to add it.

```
Currently, we have to wait for finishing of the query execution to check 
its plan.
This is not so convenient in investigation long-running queries on 
production
environments where we cannot use debuggers.

To improve this situation there is proposed the patch containing the 
pg_log_query_plan()
function which request to log plan of the specified backend process.

By default, only superusers are allowed to request log of the plan 
otherwise
allowing any users to issue this request could create cause lots of log 
messages
and it can lead to denial of service.

At the next requesting CHECK_FOR_INTERRUPTS(), the target backend logs 
its plan at
LOG_SERVER_ONLY level and therefore this plan will appear in the server 
log only,
not to be sent to the client.
```

Secondly, I have question about deleting USE_ASSERT_CHECKING in lock.h?
It supposed to have been checked in another placed of the code by 
matching values. I am worry about skipping errors due to untesting with 
assert option in the places where it (GetLockMethodLocalHash) 
participates and we won't able to get core file in segfault cases. I 
might not understand something, then can you please explain to me?

Thirdly, I have incomprehension of the point why save_ActiveQueryDesc is 
declared in the pquery.h? I am seemed to save_ActiveQueryDesc to be used 
in an once time in the ExecutorRun function and  its declaration 
superfluous. I added it in the attached patch.

Fourthly, it seems to me there are not enough explanatory comments in 
the code. I also added them in the attached patch.

Lastly, I have incomprehension about handling signals since have been 
unused it before. Could another signal disabled calling this signal to 
log query plan? I noticed this signal to be checked the latest in 
procsignal_sigusr1_handler function.

Regards,

--
Alena Rybakina
Postgres Professional
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index a82ac87457e..65b692b0ddf 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -306,6 +306,12 @@ ExecutorRun(QueryDesc *queryDesc,
 {
 	QueryDesc *save_ActiveQueryDesc;
 
+	/*
+	 * Save value of ActiveQueryDesc before having called
+	 * ExecutorRun_hook function due to having reset by
+	 * AbortSubTransaction.
+	 */
+
 	save_ActiveQueryDesc = ActiveQueryDesc;
 	ActiveQueryDesc = queryDesc;
 
@@ -314,6 +320,7 @@ ExecutorRun(QueryDesc *queryDesc,
 	else
 		standard_ExecutorRun(queryDesc, direction, count, execute_once);
 
+	/* We set the actual value of ActiveQueryDesc */
 	ActiveQueryDesc = save_ActiveQueryDesc;
 }
 
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index fc9f9f8e3f0..8e7ce3c976f 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -126,6 +126,7 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);
 
+/* Function to handle the signal to output the query plan. */
 extern void HandleLogQueryPlanInterrupt(void);
 extern void ProcessLogQueryPlanInterrupt(void);
 #endif							/* EXPLAIN_H */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index 227d24b9d60..d04de1f5566 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -22,7 +22,6 @@ struct PlannedStmt;				/* avoid including plannodes.h here */
 
 extern PGDLLIMPORT Portal ActivePortal;
 extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
-extern PGDLLIMPORT QueryDesc *save_ActiveQueryDesc;

 extern PortalStrategy ChoosePortalStrategy(List *stmts);

---

From: "a.rybakina" <[email-masked]>
Date: Mon, 19 Sep 2022 13:42:24 +0300

Hi,

I'm sorry,if this message is duplicated previous this one, but the 
previous message is sent incorrectly. I sent it from email address 
[email-masked].

```

Regards,

-- 
Alena Rybakina
Postgres Professional
> 19.09.2022, 11:01, "torikoshia" <[email-masked]>:
>
>     On 2022-05-16 17:02, torikoshia wrote:
>
>          On 2022-03-09 19:04, torikoshia wrote:
>
>              On 2022-02-08 01:13, Fujii Masao wrote:
>
>                  AbortSubTransaction() should reset ActiveQueryDesc to
>                  save_ActiveQueryDesc that ExecutorRun() set, instead
>                 of NULL?
>                  Otherwise ActiveQueryDesc of top-level statement will
>                 be unavailable
>                  after subtransaction is aborted in the nested statements.
>
>
>              I once agreed above suggestion and made v20 patch making
>              save_ActiveQueryDesc a global variable, but it caused
>             segfault when
>              calling pg_log_query_plan() after FreeQueryDesc().
>
>              OTOH, doing some kind of reset of ActiveQueryDesc seems
>             necessary
>              since it also caused segfault when running
>             pg_log_query_plan() during
>              installcheck.
>
>              There may be a better way, but resetting ActiveQueryDesc
>             to NULL seems
>              safe and simple.
>              Of course it makes pg_log_query_plan() useless after a
>             subtransaction
>              is aborted.
>              However, if it does not often happen that people want to
>             know the
>              running query's plan whose subtransaction is aborted,
>             resetting
>              ActiveQueryDesc to NULL would be acceptable.
>
>              Attached is a patch that sets ActiveQueryDesc to NULL when a
>              subtransaction is aborted.
>
>              How do you think?
>
>     Attached new patch to fix patch apply failures again.
>
>     --
>     Regards,
>
>     --
>     Atsushi Torikoshi
>     NTT DATA CORPORATION
>

+	/*

---

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,

--
Atsushi Torikoshi
NTT DATA Group Corporation

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

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            |  17 ++
 src/backend/catalog/system_functions.sql     |   2 +
 src/backend/commands/explain.c               | 208 ++++++++++++++++++-
 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/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 +
 src/test/regress/expected/misc_functions.out |  54 ++++-
 src/test/regress/sql/misc_functions.sql      |  41 +++-
 19 files changed, 402 insertions(+), 48 deletions(-)

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c7aacd7812..c0f2ca4c18 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 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>
+       <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>
@@ -27300,6 +27319,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 464858117e..d0b5954627 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,14 @@ AbortTransaction(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
 	 */
@@ -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;
 
 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 843472e6dd..6d8d2c2f97 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"
@@ -40,6 +44,7 @@
 #include "utils/typcache.h"
 #include "utils/xml.h"
 
+bool ProcessLogQueryPlanInterruptActive = false;
 
 /* Hook for plugins to get control in ExplainOneQuery() */
 ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
@@ -737,6 +742,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 +1683,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 +1693,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 +5121,170 @@ 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 */
+}
+
+/*
+ * 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 conflicts"),
+				errdetail("You can try again in a moment."));
+			hash_seq_term(&status);
+
+			ProcessLogQueryPlanInterruptActive = false;
+			return;
+		}
+	}
+
+	/*
+	 * Ensure no lock is 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 conflicts"),
+			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 13a9b7da83..4c7fe35f8f 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 e84619e5a5..69638e64bb 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 c70a1adb9a..fed2ea1924 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 1a34bd3715..07797ef7dd 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/init/globals.c b/src/backend/utils/init/globals.c
index 88b03e8fa3..063a92a5bc 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 29af4ce65d..26b11d6a12 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8274,6 +8274,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 1b44d483d6..bbca106e92 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,8 @@
 #include "lib/stringinfo.h"
 #include "parser/parse_node.h"
 
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
+
 typedef enum ExplainFormat
 {
 	EXPLAIN_FORMAT_TEXT,
@@ -60,6 +62,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 +97,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 +133,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 0b01c1f093..3914ba9f71 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 00679624f7..382930073a 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 52dcb4c2ad..400c527292 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 073fb323bc..3dd7edf93c 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;

diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 761ee2512d..3d5b4b37fd 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 7c15477104..f34f2bcd7b 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 851dad90f4..f472a839bf 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: 6a1ea02c491d16474a6214603dce40b5b122d4d1
-- 
2.39.2