Subject: RFC: Logging plan of the running query

From: torikoshia <[email-masked]>
Date: Wed, 12 May 2021 20:24:04 +0900

Hi,

During the discussion about memory contexts dumping[1], there
was a comment that exposing not only memory contexts but also
query plans and untruncated query string would be useful.

I also feel that it would be nice when thinking about situations
such as troubleshooting a long-running query on production
environments where we cannot use debuggers.

At that point of the above comment, I was considering exposing
such information on the shared memory.
However, since memory contexts are now exposed on the log by
pg_log_backend_memory_contexts(PID), I'm thinking about
defining a function that logs the plan of a running query and
untruncated query string on the specified PID in the same way
as below.

   postgres=# SELECT * FROM pg_log_current_plan(2155192);
    pg_log_current_plan
   ---------------------
    t
   (1 row)

   $ tail -f data/log/postgresql-2021-05-12.log

   2021-05-12 17:37:19.481 JST [2155192] LOG:  logging the plan of 
running query on PID 2155192
           Query Text: SELECT a.filler FROM pgbench_accounts a JOIN 
pgbench_accounts b ON a.aid = b.aid;
           Merge Join  (cost=0.85..83357.85 rows=1000000 width=85)
             Merge Cond: (a.aid = b.aid)
             ->  Index Scan using pgbench_accounts_pkey on 
pgbench_accounts a  (cost=0.42..42377.43 rows=1000000 width=89)
             ->  Index Only Scan using pgbench_accounts_pkey on 
pgbench_accounts b  (cost=0.42..25980.42 rows=1000000 width=4)

Attached a PoC patch.

Any thoughts?

[1] 
https://www.postgresql.org/message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 4d1f1794ca..5959bbfddc 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -24939,6 +24939,26 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_current_plan</primary>
+        </indexterm>
+        <function>pg_log_current_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the untruncated query string and its plan of the
+        backend with the specified process ID.
+        They 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"/>.
+        Only superusers can request to log the plan of running query.
+       </para></entry>
+      </row>
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 9867da83bc..edbe1c6829 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,6 +29,8 @@
 #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/builtins.h"
 #include "utils/guc_tables.h"
@@ -4928,3 +4931,116 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogCurrentPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the
+ *		plan of a running query.
+ *
+ * All the actual work is deferred to ProcessLogExplainInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogCurrentPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogCurrentPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogCurrentPlanInterrupt
+ * 		Perform logging the plan of running query on this
+ * 		backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange
+ * to call this function if we see LogCurrentPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because
+ * the target process for logging the plan of running query.
+ */
+void
+ProcessLogCurrentPlanInterrupt(void)
+{
+	ExplainState *es = NewExplainState();
+
+	LogCurrentPlanPending = false;
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->summary = true;
+
+	if (ActivePortal && ActivePortal->queryDesc != NULL)
+	{
+		ExplainQueryText(es, ActivePortal->queryDesc);
+		ExplainPrintPlan(es, ActivePortal->queryDesc);
+
+		/* Remove last line break */
+		if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+			es->str->data[--es->str->len] = '\0';
+
+		ereport(LOG,
+				(errmsg("logging the plan of running query on PID %d\n%s",
+					MyProcPid,
+					es->str->data),
+				 errhidestmt(true)));
+	}
+	else
+		ereport(LOG,
+				(errmsg("PID %d is not running a query now",
+					MyProcPid)));
+}
+
+/*
+ * pg_log_current_plan
+ *		Signal a backend process to log the plan of running
+ *		query.
+ *
+ * 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.
+ *
+ * On receipt of this signal, a backend sets the flag in the signal
+ * handler, which causes the next CHECK_FOR_INTERRUPTS() to log the
+ * plan.
+ */
+Datum
+pg_log_current_plan(PG_FUNCTION_ARGS)
+{
+	int			pid = PG_GETARG_INT32(0);
+	PGPROC	   *proc = BackendPidGetProc(pid);
+
+	/*
+	 * BackendPidGetProc returns NULL if the pid isn't valid; but by the time
+	 * we reach kill(), a process for which we get a valid proc here might
+	 * have terminated on its own.  There's no way to acquire a lock on an
+	 * arbitrary process to prevent that. But since this mechanism is usually
+	 * used to look into the plan of long running query, that it might end on
+	 * its own first and its plan is not logged is not a problem.
+	 */
+	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 server process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	/* Only allow superusers to log the plan of running query. */
+	if (!superuser())
+		ereport(ERROR,
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("must be a superuser to log the plan of running query")));
+
+	if (SendProcSignal(pid, PROCSIG_LOG_CURRENT_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/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index eac6895141..3aaf4b4818 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/walsender.h"
@@ -661,6 +662,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
 	if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
 		HandleLogMemoryContextInterrupt();
 
+	if (CheckProcSignal(PROCSIG_LOG_CURRENT_PLAN))
+		HandleLogCurrentPlanInterrupt();
+
 	if (CheckProcSignal(PROCSIG_RECOVERY_CONFLICT_DATABASE))
 		RecoveryConflictInterrupt(PROCSIG_RECOVERY_CONFLICT_DATABASE);
 
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 2d6d145ecc..f456f0b7d5 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -41,6 +41,7 @@
 #include "access/xact.h"
 #include "catalog/pg_type.h"
 #include "commands/async.h"
+#include "commands/explain.h"
 #include "commands/prepare.h"
 #include "executor/spi.h"
 #include "jit/jit.h"
@@ -3356,6 +3357,9 @@ ProcessInterrupts(void)
 
 	if (LogMemoryContextPending)
 		ProcessLogMemoryContextInterrupt();
+
+	if (LogCurrentPlanPending)
+		ProcessLogCurrentPlanInterrupt();
 }

diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 381d9e548d..126ed10362 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -36,6 +36,7 @@ volatile sig_atomic_t IdleInTransactionSessionTimeoutPending = false;
 volatile sig_atomic_t IdleSessionTimeoutPending = false;
 volatile sig_atomic_t ProcSignalBarrierPending = false;
 volatile sig_atomic_t LogMemoryContextPending = false;
+volatile sig_atomic_t LogCurrentPlanPending = 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 26c3fc0f6b..461c1efe91 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -7975,6 +7975,12 @@
   provolatile => 'v', prorettype => 'bool',
   proargtypes => 'int4', prosrc => 'pg_log_backend_memory_contexts' },
 
+# logging the plan of running query on the specified backend
+{ oid => '4544', descr => 'log the plan of running query on the specified backend',
+  proname => 'pg_log_current_plan',
+  provolatile => 'v', prorettype => 'bool',
+  proargtypes => 'int4', prosrc => 'pg_log_current_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 e94d9e49cf..fa81beb553 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -124,4 +124,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 HandleLogCurrentPlanInterrupt(void);
+extern void ProcessLogCurrentPlanInterrupt(void);
 #endif							/* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 95202d37af..8c03a515fd 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -85,6 +85,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleInTransactionSessionTimeoutPending;
 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 LogCurrentPlanPending;
 
 extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
 extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index eec186be2e..a80e7999e8 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_CURRENT_PLAN, /* ask backend to log the plan of current query */
 
 	/* Recovery conflict reasons */
 	PROCSIG_RECOVERY_CONFLICT_DATABASE,

---

From: Pavel Stehule <[email-masked]>
Date: Wed, 12 May 2021 14:07:44 +0200

>    postgres=# SELECT * FROM pg_log_current_plan(2155192);

+1

Pavel

---

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 12 May 2021 18:03:29 +0530

>    postgres=# SELECT * FROM pg_log_current_plan(2155192);

+1 for the idea. It looks like pg_log_current_plan is allowed to run
by superusers. Since it also shows up the full query text and the plan
in the server log as plain text, there are chances that the sensitive
information might be logged into the server log which is a risky thing
from security standpoint. There's another thread (see [1] below) which
discusses this issue by having a separate role for all debugging
purposes. Note that final consensus is not reached yet. We may want to
use the same role for this patch as well.

[1] - https://www.postgresql.org/message-id/CA%2BTgmoZz%3DK1bQRp0Ug%3D6uMGFWg-6kaxdHe6VSWaxq0U-YkppYQ%40mail.gmail.com

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

---

From: Matthias van de Meent <[email-masked]>
Date: Wed, 12 May 2021 14:55:14 +0200

>    postgres=# SELECT * FROM pg_log_current_plan(2155192);

Great idea. One feature I'd suggest would be adding a 'format' option
as well, if such feature would be feasable.

With regards,

Matthias van de Meent

---

From: Julien Rouhaud <[email-masked]>
Date: Wed, 12 May 2021 22:40:46 +0800

On Wed, May 12, 2021 at 08:24:04PM +0900, torikoshia wrote:
>   2021-05-12 17:37:19.481 JST [2155192] LOG:  logging the plan of running
> query on PID 2155192
>             ->  Index Scan using pgbench_accounts_pkey on pgbench_accounts a
> (cost=0.42..42377.43 rows=1000000 width=89)

I didn't read the POC patch yet, but +1 for having that feature.

---

From: Laurenz Albe <[email-masked]>
Date: Wed, 12 May 2021 18:08:07 +0200

> >    postgres=# SELECT * FROM pg_log_current_plan(2155192);

I love the idea, but I didn't look at the patch.

> Since it also shows up the full query text and the plan
> from security standpoint.

I think that is irrelevant.

A superuser can already set "log_statement = 'all'" to get this.
There is no protection from superusers, and it is pointless to require that.

Yours,
Laurenz Albe

---

From: torikoshia <[email-masked]>
Date: Thu, 13 May 2021 17:23:33 +0900

Thank you all for your positive comments.

> as well, if such feature would be feasable.

Thanks for the comment!

During the development of pg_log_backend_memory_contexts(), I tried to
make the number of contexts to record configurable by making it GUC
variable or putting it on the shared memory, but the former seemed an
overkill and the latter introduced some ugly behaviors, so we decided
to make it a static number[1].
I think we face the same difficulty here.

Allowing to select the format would be better as auto_explain does by
auto_explain.log_format, but I'm a bit doubtful that it is worth the
costs.

[1] 
https://www.postgresql.org/message-id/flat/6738f309-a41b-cbe6-bb57-a1c58ce9f05a%40oss.nttdata.com#e687d583080c96563b2fa2e32dbf3fb6

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Thu, 13 May 2021 17:26:20 +0900

>> from security standpoint.

Thanks for the notification!

> There is no protection from superusers, and it is pointless to require 

AFAIU, since that discussion is whether or not users other than 
superusers
should be given the privilege to execute the backtrace printing 
function,
I think it might be applicable to pg_log_current_plan().

Since restricting privilege to superusers is stricter, I'm going to 
proceed
as it is for now, but depending on the above discussion, it may be 
better to
change it.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 13 May 2021 14:43:56 +0530

>    postgres=# SELECT * FROM pg_log_current_plan(2155192);

+1 for the idea.  I did not read the complete patch but while reading
through the patch, I noticed that you using elevel as LOG for printing
the stack trace.  But I think the backend whose pid you have passed,
the connected client to that backend might not have superuser
privileges and if you use elevel LOG then that message will be sent to
that connected client as well and I don't think that is secure.  So
can we use LOG_SERVER_ONLY so that we can prevent
it from sending to the client.

-- 
Regards,
Dilip Kumar

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 May 2021 14:57:56 +0530

> it from sending to the client.

True, we should use LOG_SERVER_ONLY and not send any logs to the client.

With Regards,
Bharath Rupireddy.

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 May 2021 15:06:41 +0530

> True, we should use LOG_SERVER_ONLY and not send any logs to the client.

I further tend to think that, is it correct to log queries with LOG
level when log_statement GUC is set? Or should it also be
LOG_SERVER_ONLY?

    /* Log immediately if dictated by log_statement */
    if (check_log_statement(parsetree_list))
    {
        ereport(LOG,
                (errmsg("statement: %s", query_string),
                 errhidestmt(true),
                 errdetail_execute(parsetree_list)));

With Regards,
Bharath Rupireddy.

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 May 2021 15:08:50 +0530

> as it is for now, but depending on the above discussion, it may be

Yeah, we can keep it as superuser-only for now.

Might be unrelated, but just for info - there's another thread
"Granting control of SUSET gucs to non-superusers" at [1] discussing
the new roles.

[1] - https://www.postgresql.org/message-id/F9408A5A-B20B-42D2-9E7F-49CD3D1547BC%40enterprisedb.com

With Regards,
Bharath Rupireddy.

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 13 May 2021 15:19:48 +0530

>                  errdetail_execute(parsetree_list)));

What is your argument behind logging it with LOG? I mean we are
sending the signal to all the backend and some backend might have the
client who is not connected as a superuser so sending the plan to
those clients is not a good idea from a security perspective.
Anyways, LOG_SERVER_ONLY is not an exposed logging level it is used
for an internal purpose.  So IMHO it should be logged with
LOG_SERVER_ONLY level.

---

From: torikoshia <[email-masked]>
Date: Thu, 13 May 2021 19:12:39 +0900

>> True, we should use LOG_SERVER_ONLY and not send any logs to the 

Thanks, agree with changing it to LOG_SERVER_ONLY.

> level when log_statement GUC is set? Or should it also be

I feel it's OK to log with LOG_SERVER_ONLY since the log from
log_statement GUC would be printed already and independently.
ISTM people don't expect to log_statement GUC works even on
pg_log_current_plan(), do they?

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 May 2021 16:16:39 +0530

> for an internal purpose.  So IMHO it should be logged with

I'm saying that -  currently, queries are logged with LOG level when
the log_statement GUC is set. The queries might be sent to the
non-superuser clients. So, your point of "sending the plan to those
clients is not a good idea from a security perspective" gets violated
right? Should the log level be changed(in the below code) from "LOG"
to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
to sidetrack the main feature.

With Regards,
Bharath Rupireddy.

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 13 May 2021 17:13:47 +0530

>                  errdetail_execute(parsetree_list)));

Yes, that was my exact point, that in this particular code log with
LOG_SERVER_ONLY.

Like this.
         ereport(LOG_SERVER_ONLY,
.....

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 May 2021 17:15:12 +0530

>      if (check_log_statement(parsetree_list))

Agree, but let's discuss that in a separate thread.

With Regards,
Bharath Rupireddy.

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 13 May 2021 17:18:52 +0530

> Agree, but let's discuss that in a separate thread.

Did not understand why separate thread? this is part of this thread
no? but anyways now everyone agreed that we will log with
LOG_SERVER_ONLY.

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 13 May 2021 18:27:32 +0530

> no? but anyways now everyone agreed that we will log with

Bharat offlist pointed to me that here he was talking about another
log that is logging the query and not specific to this patch, so let's
not discuss this point here.

---

From: torikoshia <[email-masked]>
Date: Fri, 28 May 2021 15:51:37 +0900

>> no? but anyways now everyone agreed that we will log with

Modified elevel from LOG to LOG_SERVER_ONLY.

I also modified the patch to log JIT Summary and GUC settings 
information.
If there is other useful information to log, I would appreciate it if 
you could point it out.

> not discuss this point here.

Thanks for sharing the situation!

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 02297b02bb305d2b8b67f86979fb9252ef5e1264 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Fri, 28 May 2021 13:06:06 +0900
Subject: [PATCH v2] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Currently, we have to wait for the query execution to finish
before we 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_current_plan() function that requests to log the plan
of the specified backend process.

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.
---
 doc/src/sgml/func.sgml               |  21 +++++
 src/backend/commands/explain.c       | 114 +++++++++++++++++++++++++++
 src/backend/storage/ipc/procsignal.c |   4 +
 src/backend/tcop/postgres.c          |   4 +
 src/backend/utils/init/globals.c     |   1 +
 src/include/catalog/pg_proc.dat      |   6 ++
 src/include/commands/explain.h       |   2 +
 src/include/miscadmin.h              |   1 +
 src/include/storage/procsignal.h     |   1 +
 9 files changed, 154 insertions(+)

diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 08b07f561e..399fa12aa2 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -24940,6 +24940,27 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_current_plan</primary>
+        </indexterm>
+        <function>pg_log_current_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the untruncated query string and its plan for
+        the query currently running on the backend with the specified
+        process ID.
+        They 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"/>.
+        Only superusers can request to log plan of the running query.
+       </para></entry>
+      </row>
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 9a60865d19..9d934f28a8 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,6 +29,8 @@
 #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/builtins.h"
 #include "utils/guc_tables.h"
@@ -4928,3 +4931,114 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogCurrentPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the
+ *		plan of a currently running query.
+ *
+ * All the actual work is deferred to ProcessLogExplainInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogCurrentPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogCurrentPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogCurrentPlanInterrupt
+ * 		Perform logging 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 LogCurrentPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogCurrentPlanInterrupt(void)
+{
+	ExplainState *es = NewExplainState();
+
+	LogCurrentPlanPending = false;
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+
+	if (ActivePortal && ActivePortal->queryDesc != NULL)
+	{
+		ExplainQueryText(es, ActivePortal->queryDesc);
+		ExplainPrintPlan(es, ActivePortal->queryDesc);
+		ExplainPrintJITSummary(es, ActivePortal->queryDesc);
+
+		/* Remove last line break */
+		if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+			es->str->data[--es->str->len] = '\0';
+
+		ereport(LOG_SERVER_ONLY,
+				(errmsg("logging plan of the running query on PID %d\n%s",
+					MyProcPid,
+					es->str->data),
+				 errhidestmt(true)));
+	}
+	else
+		ereport(LOG_SERVER_ONLY,
+				(errmsg("PID %d is not executing queries now",
+					MyProcPid)));
+}
+
+/*
+ * pg_log_current_plan
+ *		Signal a backend process to log plan the of running query.
+ *
+ * Only superusers are allowed to signal to log plan because 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 this signal, a backend sets the flag in the signal handler,
+ * which causes the next CHECK_FOR_INTERRUPTS() to log plan.
+ */
+Datum
+pg_log_current_plan(PG_FUNCTION_ARGS)
+{
+	int			pid = PG_GETARG_INT32(0);
+	PGPROC	   *proc = BackendPidGetProc(pid);
+
+	/*
+	 * BackendPidGetProc returns NULL if the pid isn't valid; but by the time
+	 * we reach kill(), a process for which we get a valid proc here might
+	 * have terminated on its own.  There's no way to acquire a lock on an
+	 * arbitrary process to prevent that. But since this mechanism is usually
+	 * used to look into plans of long running queries, that it might end its
+	 * own first and its plan is not logged is not a problem.
+	 */
+	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 server process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	/* Only allow superusers to log plan of the running queries. */
+	if (!superuser())
+		ereport(ERROR,
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("must be a superuser to log plan of the running query")));
+
+	if (SendProcSignal(pid, PROCSIG_LOG_CURRENT_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/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index defb75aa26..9b9653544a 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/walsender.h"
@@ -661,6 +662,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
 	if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
 		HandleLogMemoryContextInterrupt();

index 8cea10c901..ac8ea67e81 100644
@@ -3366,6 +3367,9 @@ ProcessInterrupts(void)

index acbcae4607..a6be1ab0b5 100644
   prorettype => 'bool', proargtypes => 'int4',
   prosrc => 'pg_log_backend_memory_contexts' },
 
+# logging plan of the running query on the specified backend
+{ oid => '4544', descr => 'log plan of the running query on the specified backend',
 
index 4dc343cbc5..355e3db622 100644
@@ -94,6 +94,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleInTransactionSessionTimeoutPending;
 
index eec186be2e..c1a7218d69 100644
+	PROCSIG_LOG_CURRENT_PLAN, /* ask backend to log plan of the current query */

base-commit: 9afdea982420f9672b88e5c17d1ee8eec64105fc
-- 
2.18.1

---

From: torikoshia <[email-masked]>
Date: Wed, 09 Jun 2021 16:44:55 +0900

> If there is other useful information to log, I would appreciate it if

Updated the patch.

- reordered superuser check which was pointed out in another thread[1]
- added a regression test

[1] https://postgr.es/m/[email-masked]

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 7ad9a280b6f74e4718293863716046c02b0a3835 Mon Sep 17 00:00:00 2001
From: atorik <[email-masked]>
Date: Wed, 9 Jun 2021 15:03:39 +0900
Subject: [PATCH v3] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

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.
---
 doc/src/sgml/func.sgml                       |  21 ++++
 src/backend/commands/explain.c               | 116 +++++++++++++++++++
 src/backend/storage/ipc/procsignal.c         |   4 +
 src/backend/tcop/postgres.c                  |   4 +
 src/backend/utils/init/globals.c             |   1 +
 src/include/catalog/pg_proc.dat              |   6 +
 src/include/commands/explain.h               |   2 +
 src/include/miscadmin.h                      |   1 +
 src/include/storage/procsignal.h             |   1 +
 src/test/regress/expected/misc_functions.out |  10 +-
 src/test/regress/sql/misc_functions.sql      |   6 +-
 11 files changed, 167 insertions(+), 5 deletions(-)

+      <row>
index 9a60865d19..1cea557764 100644
+	PGPROC	   *proc;
+	proc = BackendPidGetProc(pid);

 

 

 	/* Recovery conflict reasons */
 	PROCSIG_RECOVERY_CONFLICT_DATABASE,
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index e845042d38..4c6159a11c 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -134,9 +134,9 @@ LINE 1: SELECT num_nulls();
                ^
 HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail.
 --
@@ -146,6 +146,12 @@ SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
  t
 (1 row)
 
+SELECT * FROM pg_log_current_plan(pg_backend_pid());
+ pg_log_current_plan 
+---------------------
+ t
+(1 row)
+
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index a398349afc..7aed52f437 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -29,15 +29,15 @@ SELECT num_nulls(VARIADIC '{}'::int[]);
 -- should fail, one or more arguments is required
 SELECT num_nonnulls();
 SELECT num_nulls();
-
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail.
 --
 SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT * FROM pg_log_current_plan(pg_backend_pid());
 
 --
 -- Test some built-in SRFs

base-commit: be90098907475f3cfff7dc6d590641b9c2dae081
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Wed, 9 Jun 2021 23:04:22 +0900

> Updated the patch.

Thanks for updating the patch!

auto_explain can log the plan of even nested statement
if auto_explain.log_nested_statements is enabled.
But ISTM that pg_log_current_plan() cannot log that plan.
Is this intentional?
I think that it's better to make pg_log_current_plan() log
the plan of even nested statement.

Since pg_log_current_plan() is usually used to investigate and
trouble-shoot the long running queries, IMO it's better to
enable es->verbose by default and get additional information
about the queries. Thought?

+ * pg_log_current_plan

"plan the of" is typo?

"because any users" should be "because allowing any users"
like the comment for pg_log_backend_memory_contexts()?

"ProcessLogExplainInterrupt()" should be "ProcessLogCurrentPlanInterrupt()"?

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Thu, 10 Jun 2021 11:09:22 +0900

On 2021-06-09 23:04, Fujii Masao wrote:

Thanks for your review!

> the plan of even nested statement.

+1. It would be better.
But currently plan information is got from ActivePortal and ISTM there 
are no easy way to retrieve plan information of nested statements from 
ActivePortal.
Anyway I'll do some more research.

I think you are right about the following comments.
I'll fix them.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 10 Jun 2021 21:50:48 +0530

> Updated the patch.

Thanks for the patch. Here are some comments on v3 patch:

1) We could just say "Requests to log query plan of the presently
running query of a given backend along with an untruncated query
string in the server logs."
Instead of
+        They 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"/>

2) It's better to do below, for reference see how pg_backend_pid,
pg_terminate_backend, pg_relpages and so on are used in the tests.
+SELECT pg_log_current_plan(pg_backend_pid());
rather than using the function in the FROM clause.
+SELECT * FROM pg_log_current_plan(pg_backend_pid());
If okay, also change it for pg_log_backend_memory_contexts.

3) Since most of the code looks same in pg_log_backend_memory_contexts
and pg_log_current_plan, I think we can have a common function
something like below:
bool
SendProcSignalForLogInfo(ProcSignalReason reason)
{
Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT || reason ==
PROCSIG_LOG_CURRENT_PLAN);

if (!superuser())
{
if (reason == PROCSIG_LOG_MEMORY_CONTEXT)
errmsg("must be a superuser to log memory contexts")
else if (reason == PROCSIG_LOG_CURRENT_PLAN)
errmsg("must be a superuser to log plan of the running query")
}

if (SendProcSignal(pid, reason, proc->backendId) < 0)
{
}
}
Then we could just do:
Datum
pg_log_backend_memory_contexts(PG_FUNCTION_ARGS)
{
PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_MEMORY_CONTEXT));
}
Datum
pg_log_current_plan(PG_FUNCTION_ARGS)
{
PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_CURRENT_PLAN));
}
We can have SendProcSignalForLogInfo function defined in procsignal.c
and procsignal.h

4) I think we can have a sample function usage and how it returns true
value, how the plan looks for a simple query(select 1 or some other
simple/complex generic query or simply select
pg_log_current_plan(pg_backend_pid());) in the documentation, much
like pg_log_backend_memory_contexts.

5) Instead of just showing the true return value of the function
pg_log_current_plan in the sql test, which just shows that the signal
is sent, but it doesn't mean that the backend has processed that
signal and logged the plan. I think we can add the test using TAP
framework, one

6) Do we unnecessarily need to signal the processes such as autovacuum
launcher/workers, logical replication launcher/workers, wal senders,
wal receivers and so on. only to emit a "PID %d is not executing
queries now" message? Moreover, those processes will be waiting in
loops for timeouts to occur, then as soon as they wake up do they need
to process this extra uninformative signal?
We could choose to not signal those processes at all which might or
might not be possible.
Otherwise, we could just emit messages like "XXXX process cannot run a
query" in ProcessInterrupts.

7)Instead of
(errmsg("logging plan of the running query on PID %d\n%s",
how about below?
(errmsg("plan of the query running on backend with PID %d is:\n%s",

8) Instead of
errmsg("PID %d is not executing queries now")
how about below?
errmsg("Backend with PID %d is not running a query")

9) We could just do:
void
ProcessLogCurrentPlanInterrupt(void)
{
ExplainState *es;
LogCurrentPlanPending = false;
if (!ActivePortal || !ActivePortal->queryDesc)
errmsg("PID %d is not executing queries now");
es = NewExplainState();
ExplainQueryText();
ExplainPrintPlan();

10) How about renaming the function pg_log_current_plan to
pg_log_query_plan or pg_log_current_query_plan?

11) What happens if pg_log_current_plan is called for a parallel worker?

With Regards,
Bharath Rupireddy.

---

From: torikoshia <[email-masked]>
Date: Mon, 14 Jun 2021 21:18:51 +0900

On 2021-06-11 01:20, Bharath Rupireddy wrote:

Thanks for your review!

> linkend="runtime-config-logging"/>

Actually this explanation is almost the same as that of
pg_log_backend_memory_contexts().
Do you think we should change both of them?
I think it may be too detailed but accurate.

> If okay, also change it for pg_log_backend_memory_contexts.

Agreed.

> and pg_log_current_plan, I think we can have a common function

Agreed. I'll do some refactoring.

> like pg_log_backend_memory_contexts.

+1.

> signal and logged the plan. I think we can add the test using TAP

I once made a tap test for pg_log_backend_memory_contexts(), but it
seemed an overkill and we agreed that it was appropriate just ensuring
the function working as below discussion.

https://www.postgresql.org/message-id/bbecd722d4f8e261b350186ac4bf68a7%40oss.nttdata.com

> query" in ProcessInterrupts.

Agreed.

However it needs to distinguish backends which can execute queries and
other processes such as autovacuum launcher, I don't come up with
easy ways to do so.
I'm going to think about it.

> (errmsg("plan of the query running on backend with PID %d is:\n%s",

+1.

> errmsg("Backend with PID %d is not running a query")

+1.

> pg_log_query_plan or pg_log_current_query_plan?

+1.

> 11) What happens if pg_log_current_plan is called for a parallel 

AFAIU Parallel worker doesn't have ActivePortal, so it would always
emit the message 'PID %d is not executing queries now'.
As 6), it would be better to distinguish the parallel worker and normal
backend.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 15 Jun 2021 09:57:02 +0530

> I think it may be too detailed but accurate.

I withdraw my comment. We can keep the explanation similar to
pg_log_backend_memory_contexts as it was agreed upon and committed
text. If the wordings are similar, then it will be easier for users to
understand the documentation.

> https://www.postgresql.org/message-id/bbecd722d4f8e261b350186ac4bf68a7%40oss.nttdata.com

Okay. I withdraw my comment.

> I'm going to think about it.

I'm not sure if there is any information in the shared memory
accessible to all the backends/sessions that can say a PID is
autovacuum launcher/worker, logical replication launcher/worker or any
other background or parallel worker. If we were to invent a new
mechanism just for addressing the above comment, I would rather choose
to not do that as it seems like an overkill. We can leave it up to the
user whether or not to unnecessarily signal those processes which are
bound to print "PID XXX is not executing queries now" message.

> As 6), it would be better to distinguish the parallel worker and normal

As I said, above, I think it will be a bit tough to do. If done, it
seems like an overkill.

With Regards,
Bharath Rupireddy.

---

From: torikoshia <[email-masked]>
Date: Wed, 16 Jun 2021 20:36:08 +0900

On 2021-06-15 13:27, Bharath Rupireddy wrote:
> other background or parallel worker.

As far as I looked around, there seems no easy ways to do so.

> If we were to invent a new

+1. I'm going to proceed in this direction.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Tue, 22 Jun 2021 11:30:31 +0900

Updated the patch.

> Anyway I'll do some more research.

I haven't found a proper way yet but it seems necessary to use something 
other than ActivePortal and I'm now thinking this could be a separate 
patch in the future.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 7ad9a280b6f74e4718293863716046c02b0a3835 Mon Sep 17 00:00:00 2001
From: atorik <[email-masked]>
Date: Tue, 22 Jun 2021 10:03:39 +0900
Subject: [PATCH v4] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Currently, we have to wait for the query execution to finish
before we 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_current_query_plan() function that requests to log the
plan of the specified backend process.

Since some codes and comments of pg_log_current_query_plan() 
are the same with pg_log_backend_memory_contexts(), this
patch also refactors them to make them common.

Reviewd-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar
---
 doc/src/sgml/func.sgml                       | 44 ++++++++++++
 src/backend/commands/explain.c               | 75 ++++++++++++++++++++
 src/backend/storage/ipc/procsignal.c         | 66 +++++++++++++++++
 src/backend/tcop/postgres.c                  |  4 ++
 src/backend/utils/adt/mcxtfuncs.c            | 51 +------------
 src/backend/utils/init/globals.c             |  1 +
 src/include/catalog/pg_proc.dat              |  6 ++
 src/include/commands/explain.h               |  2 +
 src/include/miscadmin.h                      |  1 +
 src/include/storage/procsignal.h             |  3 +
 src/test/regress/expected/misc_functions.out | 12 +++-
 src/test/regress/sql/misc_functions.sql      |  8 +--
 12 files changed, 217 insertions(+), 56 deletions(-)

index 6388385edc..dad2d34a04 100644
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_current_query_plan</primary>
+        </indexterm>
+        <function>pg_log_current_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the untruncated query string and its plan for
+        the query currently running on the backend with the specified
+        process ID.
+        They 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"/>.
+        Only superusers can request to log plan of the running query.
+       </para></entry>
+      </row>
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>
@@ -25053,6 +25074,29 @@ 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_current_query_plan</function> can be used
+    to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_current_query_plan(201116);
+ pg_log_current_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>FORMAT TEXT</literal>
+and <literal>VEBOSE</literal> are used in the <command>EXPLAIN</command> command.
+For example:
+<screen>
+LOG:  plan of the query running on backend with PID 201116 is:
+        Query Text: SELECT * FROM pgbench_accounts;
+        Seq Scan on public.pgbench_accounts  (cost=0.00..26394.00 rows=1000000 width=97)
+          Output: aid, bid, abalance, filler
+</screen>
+    Note that nested statements (statements executed inside a function) is not
+    considered for logging. Only top-level query plans are logged.
+   </para>
+
   </sect2>
 
   <sect2 id="functions-admin-backup">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index e81b990092..c568a2e234 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,6 +29,8 @@
 #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/builtins.h"
 #include "utils/guc_tables.h"
@@ -4922,3 +4925,75 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogCurrentPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the plan of
+ *		the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogCurrentPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogCurrentPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogCurrentPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogCurrentPlanInterrupt
+ * 		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 LogCurrentPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogCurrentPlanInterrupt(void)
+{
+	ExplainState *es = NewExplainState();
+
+	LogCurrentPlanPending = false;
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+	es->verbose = true;
+
+	if (!ActivePortal || !ActivePortal->queryDesc)
+	{
+		ereport(LOG_SERVER_ONLY,
+				(errmsg("backend with PID %d is not running a query",
+					MyProcPid)));
+		return;
+	}
+
+	ExplainQueryText(es, ActivePortal->queryDesc);
+	ExplainPrintPlan(es, ActivePortal->queryDesc);
+	ExplainPrintJITSummary(es, ActivePortal->queryDesc);
+
+	/* Remove last line break */
+	if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+		es->str->data[--es->str->len] = '\0';
+
+	ereport(LOG_SERVER_ONLY,
+			(errmsg("plan of the query running on backend with PID %d is:\n%s",
+				MyProcPid,
+				es->str->data),
+			 errhidestmt(true)));
+}
+
+/*
+ * pg_log_current_query_plan
+ *		Signal a backend process to log the query plan of the running query.
+ */
+Datum
+pg_log_current_query_plan(PG_FUNCTION_ARGS)
+{
+	pid_t			pid = PG_GETARG_INT32(0);
+
+	PG_RETURN_BOOL(SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN));
+}
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index defb75aa26..fe9ea90222 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/walsender.h"
@@ -27,6 +28,7 @@
 #include "storage/ipc.h"
 #include "storage/latch.h"
 #include "storage/proc.h"
+#include "storage/procarray.h"
 #include "storage/shmem.h"
 #include "storage/sinval.h"
 #include "tcop/tcopprot.h"
@@ -312,6 +314,67 @@ SendProcSignal(pid_t pid, ProcSignalReason reason, BackendId backendId)
 	return -1;
 }
 
+/*
+ * SendProcSignalForLogInfo
+ *		Signal a backend process to log its information.
+ *
+ * Only superusers are allowed to signal to log information 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 this signal, a backend sets the flag in the signal
+ * handler, which causes the next CHECK_FOR_INTERRUPTS() to log the
+ * information.
+ */
+bool
+SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason)
+{
+	PGPROC	   *proc;
+
+	Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT ||
+			reason == PROCSIG_LOG_CURRENT_PLAN);
+
+	/* Only allow superusers to log information. */
+	if (!superuser())
+		ereport(ERROR,
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("must be a superuser to log information about specified process")));
+
+	proc = BackendPidGetProc(pid);
+
+	/*
+	 * BackendPidGetProc returns NULL if the pid isn't valid; but by the time
+	 * we reach kill(), a process for which we get a valid proc here might
+	 * have terminated on its own.  There's no way to acquire a lock on an
+	 * arbitrary process to prevent that. But since this mechanism is usually
+	 * used to below purposes, it might end its own first and the information
+	 * is not logged is not a problem.
+	 * - debug a backend running and consuming lots of memory
+	 * - look into the plan of the long running query
+	 */
+	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 server process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	if (SendProcSignal(pid, reason, 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);
+}
+
 /*
  * EmitProcSignalBarrier
  *		Send a signal to every Postgres process
@@ -661,6 +724,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
 	if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
 		HandleLogMemoryContextInterrupt();

 

diff --git a/src/backend/utils/adt/mcxtfuncs.c b/src/backend/utils/adt/mcxtfuncs.c
index 0d52613bc3..efb9942c5f 100644
--- a/src/backend/utils/adt/mcxtfuncs.c
+++ b/src/backend/utils/adt/mcxtfuncs.c
@@ -18,7 +18,6 @@
 #include "funcapi.h"
 #include "miscadmin.h"
 #include "mb/pg_wchar.h"
-#include "storage/proc.h"
 #include "storage/procarray.h"
 #include "utils/builtins.h"
 
@@ -161,57 +160,11 @@ pg_get_backend_memory_contexts(PG_FUNCTION_ARGS)
 /*
  * pg_log_backend_memory_contexts
  *		Signal a backend process to log its memory contexts.
- *
- * Only superusers are allowed to signal to log the memory contexts
- * 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 this signal, a backend sets the flag in the signal
- * handler, which causes the next CHECK_FOR_INTERRUPTS() to log the
- * memory contexts.
  */
 Datum
 pg_log_backend_memory_contexts(PG_FUNCTION_ARGS)
 {
-	int			pid = PG_GETARG_INT32(0);
-	PGPROC	   *proc;
-
-	/* Only allow superusers to log memory contexts. */
-	if (!superuser())
-		ereport(ERROR,
-				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
-				 errmsg("must be a superuser to log memory contexts")));
-
-	proc = BackendPidGetProc(pid);
-
-	/*
-	 * BackendPidGetProc returns NULL if the pid isn't valid; but by the time
-	 * we reach kill(), a process for which we get a valid proc here might
-	 * have terminated on its own.  There's no way to acquire a lock on an
-	 * arbitrary process to prevent that. But since this mechanism is usually
-	 * used to debug a backend running and consuming lots of memory, that it
-	 * might end on its own first and its memory contexts are not logged is
-	 * not a problem.
-	 */
-	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 server process", pid)));
-		PG_RETURN_BOOL(false);
-	}
-
-	if (SendProcSignal(pid, PROCSIG_LOG_MEMORY_CONTEXT, 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);
-	}
+	pid_t			pid = PG_GETARG_INT32(0);
 
-	PG_RETURN_BOOL(true);
+	PG_RETURN_BOOL(SendProcSignalForLogInfo(pid, PROCSIG_LOG_MEMORY_CONTEXT));
 }
index fde251fa4f..629d393828 100644
@@ -7970,6 +7970,12 @@
 
+  proname => 'pg_log_current_query_plan',
+  proargtypes => 'int4', prosrc => 'pg_log_current_query_plan' },

index eec186be2e..92290c2ed9 100644
 
 	/* Recovery conflict reasons */
 	PROCSIG_RECOVERY_CONFLICT_DATABASE,
@@ -66,6 +67,8 @@ extern void ProcSignalShmemInit(void);
 extern void ProcSignalInit(int pss_idx);
 extern int	SendProcSignal(pid_t pid, ProcSignalReason reason,
 						   BackendId backendId);
+extern bool	SendProcSignalForLogInfo(pid_t pid,
+						   ProcSignalReason reason);
 
 extern uint64 EmitProcSignalBarrier(ProcSignalBarrierType type);
 extern void WaitForProcSignalBarrier(uint64 generation);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index e845042d38..5e9c3cbd8f 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -134,18 +134,24 @@ LINE 1: SELECT num_nulls();
                ^
 HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail.
 --
-SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
  t
 (1 row)
 
+SELECT pg_log_current_query_plan(pg_backend_pid());
+ pg_log_current_query_plan 
+---------------------------
+ t
+(1 row)
+
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index a398349afc..a3be66ab11 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -29,15 +29,15 @@ SELECT num_nulls(VARIADIC '{}'::int[]);
 -- should fail, one or more arguments is required
 SELECT num_nonnulls();
 SELECT num_nulls();
-
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail.
 --
-SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_current_query_plan(pg_backend_pid());

base-commit: bafad2c5b261a1449bed60ebac9e7918ebcc42b4
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Thu, 1 Jul 2021 15:34:26 +0900

On 2021/06/22 11:30, torikoshia wrote:
> On Thu, Jun 10, 2021 at 11:09 AM torikoshia <[email-masked]> wrote:
> I haven't found a proper way yet but it seems necessary to use something other than ActivePortal and I'm now thinking this could be a separate patch in the future. 

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

When I called pg_log_current_query_plan() to send the signal to
the backend executing the above query, I got the following log message.
I think that this is not expected message. I guess this issue happened
because the information about query text and plan is retrieved
from ActivePortal. If this understanding is right, ISTM that we should
implement new mechanism so that we can retrieve those information
even while nested query is being executed.

     LOG:  backend with PID 42449 is not running a query

Regards,

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 2 Jul 2021 19:51:38 +0530

> Updated the patch.

Thanks for the patch. Here are some comments on the v4 patch:

1) Can we do + ExplainState *es = NewExplainState(); and es
assignments after if (!ActivePortal || !ActivePortal->queryDesc), just
to avoid unnecessary call in case of error hit? Also note that, we can
easily hit the error case.

2) It looks like there's an improper indentation. MyProcPid and
es->str->data, should start from the ".
+ ereport(LOG_SERVER_ONLY,
+ (errmsg("backend with PID %d is not running a query",
+ MyProcPid)));

+ ereport(LOG_SERVER_ONLY,
+ (errmsg("plan of the query running on backend with PID %d is:\n%s",
+ MyProcPid,
+ es->str->data),
For reference see errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",

3)I prefer to do this so that any new piece of code can be introduced
in between easily and it will be more readable as well.
+Datum
+pg_log_current_query_plan(PG_FUNCTION_ARGS)
+{
+ pid_t pid;
+ bool result;
+
+ pid = PG_GETARG_INT32(0);
+ result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN);
+
+ PG_RETURN_BOOL(result);
+}
If okay, please also change for the pg_log_backend_memory_contexts.

4) Extra whitespace before the second line i.e. 2nd line reason should
be aligned with the 1st line reason.
+ Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT ||
+ reason == PROCSIG_LOG_CURRENT_PLAN);

5) How about "Requests to log the plan of the query currently running
on the backend with specified process ID along with the untruncated
query string"?
+        Requests to log the untruncated query string and its plan for
+        the query currently running on the backend with the specified
+        process ID.

6) A typo: it is "nested statements (..) are not"
+    Note that nested statements (statements executed inside a function) is not

7) I'm not sure what you mean by "Some functions output what you want
to the log."
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
Instead, can we say "These functions return true if the specified
backend is successfully signaled, otherwise false. Upon receiving the
signal, the backend will log the information to the server log."

Regards,
Bharath Rupireddy.

---

From: torikoshia <[email-masked]>
Date: Fri, 09 Jul 2021 14:05:16 +0900

> Thanks for the patch. Here are some comments on the v4 patch:

Thanks for your comments and suggestions!
I agree with you and updated the patch.

> even while nested query is being executed.

I'm now working on this comment.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 7ad9a280b6f74e4718293863716046c02b0a3835 Mon Sep 17 00:00:00 2001
From: atorik <[email-masked]>
Date: Fri, 9 Jul 2021 13:33:02 +0900
Subject: [PATCH v5] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Reviewd-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar
---
 doc/src/sgml/func.sgml                       | 44 +++++++++++
 src/backend/commands/explain.c               | 79 ++++++++++++++++++++
 src/backend/storage/ipc/procsignal.c         | 66 ++++++++++++++++
 src/backend/tcop/postgres.c                  |  4 +
 src/backend/utils/adt/mcxtfuncs.c            | 53 ++-----------
 src/backend/utils/init/globals.c             |  1 +
 src/include/catalog/pg_proc.dat              |  6 ++
 src/include/commands/explain.h               |  2 +
 src/include/miscadmin.h                      |  1 +
 src/include/storage/procsignal.h             |  3 +
 src/test/regress/expected/misc_functions.out | 16 +++-
 src/test/regress/sql/misc_functions.sql      | 12 +--
 12 files changed, 230 insertions(+), 57 deletions(-)

index 6388385edc..950e32a290 100644
 
+      <row>
+        Requests to log the plan of the query currently running on the
+        backend with specified process ID along with the untruncated
+        query string.
 
+   <para>
+    Note that nested statements (statements executed inside a function) are not
 
index e81b990092..e1cd88e201 100644
@@ -4922,3 +4925,79 @@ escape_yaml(StringInfo buf, const char *str)
+	ExplainState *es;
+	es = NewExplainState();
+					MyProcPid, es->str->data),
index defb75aa26..b89e9a98a5 100644
 
+/*

 

index 0d52613bc3..25c621e776 100644
 
@@ -161,57 +160,15 @@ pg_get_backend_memory_contexts(PG_FUNCTION_ARGS)
 /*
 
+	result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_MEMORY_CONTEXT);
 
-	PG_RETURN_BOOL(true);

 

 extern uint64 EmitProcSignalBarrier(ProcSignalBarrierType type);
 extern void WaitForProcSignalBarrier(uint64 generation);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index e845042d38..98017f83a9 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -134,18 +134,26 @@ LINE 1: SELECT num_nulls();
                ^
 HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
--- Furthermore, their contents can vary depending on the timing. However,
+-- These functions return true if the specified backend is successfully
+-- signaled, otherwise false. Upon receiving the signal, the backend
+-- will log the information to the server log.
+-- Although their contents can vary depending on the timing,
 -- we can at least verify that the code doesn't fail.
 --
-SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
  t
 (1 row)
 
+SELECT pg_log_current_query_plan(pg_backend_pid());
+ pg_log_current_query_plan 
+---------------------------
+ t
+(1 row)
+
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index a398349afc..979a418e8e 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -29,15 +29,17 @@ SELECT num_nulls(VARIADIC '{}'::int[]);
 -- should fail, one or more arguments is required
 SELECT num_nonnulls();
 SELECT num_nulls();
-
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- Memory contexts are logged and they are not returned to the function.
--- Furthermore, their contents can vary depending on the timing. However,
+-- These functions return true if the specified backend is successfully
+-- signaled, otherwise false. Upon receiving the signal, the backend
+-- will log the information to the server log.
+-- Although their contents can vary depending on the timing,
 -- we can at least verify that the code doesn't fail.
 --
-SELECT * FROM pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_backend_memory_contexts(pg_backend_pid());
+SELECT pg_log_current_query_plan(pg_backend_pid());

base-commit: 387925893edf2a3a30a8ddf2c6474d8a7eb056a5
-- 
2.27.0

---

From: Masahiro Ikeda <[email-masked]>
Date: Tue, 13 Jul 2021 23:11:37 +0900

> Updated the patch.

Hi, torikoshi-san

Thanks for your great work! I'd like to use this feature in v15.
I confirmed that it works with queries I tried and make check-world has 
no error.

When I tried this feature, I realized two things. So, I share them.

(1) About output contents

> The format of the query plan is the same as when <literal>FORMAT 
> TEXT</literal>
> and <literal>VEBOSE</literal> are used in the 
> <command>EXPLAIN</command> command.
> For example:

I think the above needs to add COSTS and SETTINGS options too, and it's 
better to use an
example which the SETTINGS option works like the following.

```
2021-07-13 21:59:56 JST 69757 [client backend] LOG:  plan of the query 
running on backend with PID 69757 is:
         Query Text: PREPARE query2 AS SELECT COUNT(*) FROM 
pgbench_accounts t1, pgbench_accounts t2;
         Aggregate  (cost=3750027242.84..3750027242.86 rows=1 width=8)
           Output: count(*)
           ->  Nested Loop  (cost=0.84..3125027242.84 rows=250000000000 
width=0)
                 ->  Index Only Scan using pgbench_accounts_pkey on 
public.pgbench_accounts t1  (cost=0.42..12996.42 rows=500000 width=0)
                       Output: t1.aid
                 ->  Materialize  (cost=0.42..15496.42 rows=500000 
width=0)
                       ->  Index Only Scan using pgbench_accounts_pkey on 
public.pgbench_accounts t2  (cost=0.42..12996.42 rows=500000 width=0)
         Settings: effective_cache_size = '8GB', work_mem = '16MB'
```

(2) About EXPLAIN "BUFFER" option

When I checked EXPLAIN option, I found there is another option "BUFFER" 
which can be
used without the "ANALYZE" option.

I'm not sure it's useful because your target use-case is analyzing a 
long-running query,
not its planning phase. If so, the planning buffer usage is not so much 
useful. But, since
the overhead to output buffer usages is not high and it's used for 
debugging use cases,
I wonder it's not a bad idea to output buffer usages too. Thought?

Regards,
-- 
Masahiro Ikeda
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Mon, 19 Jul 2021 11:28:40 +0900

Thanks for your review!

> example which the SETTINGS option works like the following.

Agreed. Updated the patch.

> I wonder it's not a bad idea to output buffer usages too. Thought?

As you pointed out, I also think it would be useful when queries are 
taking a long time in the planning phase.
However, as far as I read ExplainOneQuery(), the buffer usages in the 
planner phase are not retrieved by default. They are retrieved only when 
BUFFERS is specified in the EXPLAIN.

If we change it to always get the buffer usages and expose them as a 
global variable, we can get them through pg_log_current_plan(), but I 
think it doesn't pay.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 7ad9a280b6f74e4718293863716046c02b0a3835 Mon Sep 17 00:00:00 2001
From: atorik <[email-masked]>
Date: Mon, 19 Jul 2021 10:33:02 +0900
Subject: [PATCH v6] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda
---
 doc/src/sgml/func.sgml                       | 46 ++++++++++++
 src/backend/commands/explain.c               | 79 ++++++++++++++++++++
 src/backend/storage/ipc/procsignal.c         | 66 ++++++++++++++++
 src/backend/tcop/postgres.c                  |  4 +
 src/backend/utils/adt/mcxtfuncs.c            | 53 ++-----------
 src/backend/utils/init/globals.c             |  1 +
 src/include/catalog/pg_proc.dat              |  6 ++
 src/include/commands/explain.h               |  2 +
 src/include/miscadmin.h                      |  1 +
 src/include/storage/procsignal.h             |  3 +
 src/test/regress/expected/misc_functions.out | 16 +++-
 src/test/regress/sql/misc_functions.sql      | 12 +--
 12 files changed, 232 insertions(+), 57 deletions(-)

index ac6347a971..21cd8c9fbb 100644
 
+      <row>
@@ -25053,6 +25074,31 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
 
+   <para>
+    <function>pg_log_current_query_plan</function> can be used
+    to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_current_query_plan(17793);
+ pg_log_current_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:  plan of the query running on backend with PID 17793 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'
+</screen>
+    Note that nested statements (statements executed inside a function) are not
+    considered for logging. Only top-level query plans are logged.
+   </para>
+
   </sect2>
 
index 340db2bac4..cb3ed273f4 100644
@@ -4921,3 +4924,79 @@ escape_yaml(StringInfo buf, const char *str)
 
+/*

 

 
 
-	PG_RETURN_BOOL(true);
index 8bf9d704b7..ed22a17bd2 100644
@@ -7974,6 +7974,12 @@

 

 

base-commit: f0e21f2f61675f4e56ae53d32ea54d587a7c2257
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Mon, 19 Jul 2021 15:07:48 +0900

+bool

I don't think that procsignal.c is proper place to check the permission and
check whether the specified PID indicates a PostgreSQL server process, etc
because procsignal.c just provides fundamental routines for interprocess
signaling. Isn't it better to move the function to signalfuncs.c or elsewhere?

When text format is used, ExplainBeginOutput() and ExplainEndOutput()
do nothing. So (I guess) you thought that they don't need to be called and
implemented the code in that way. But IMO it's better to comment
why they don't need to be called, or to just call both of them
even if they do nothing in text format.

It's better to check es->costs before calling this function,
like explain_ExecutorEnd() and ExplainOnePlan() do?

Currently SendProcSignalForLogInfo() calls PG_RETURN_BOOL() in some cases,
but instead it should just return true/false because pg_log_current_query_plan()
expects that?

Regards,

---

From: Fujii Masao <[email-masked]>
Date: Wed, 28 Jul 2021 03:34:44 +0900

On 2021/07/09 14:05, torikoshia wrote:
> On Thu, Jul 1, 2021 at 3:34 PM Fujii Masao <[email-masked]> wrote:
> 
>>      DO $$
>>      BEGIN
>>      PERFORM pg_sleep(100);
>>      END$$;
>>

One idea is to define new global pointer, e.g., "QueryDesc *ActiveQueryDesc;".
This global pointer is set to queryDesc in ExecutorRun()
(also maybe ExecutorStart()). And this is reset to NULL in ExecutorEnd() and
when an error is thrown. Then ProcessLogCurrentPlanInterrupt() can
get the plan of the currently running query from that global pointer
instead of ActivePortal, and log it. Thought?

Regards,

---

From: Pavel Stehule <[email-masked]>
Date: Tue, 27 Jul 2021 20:45:34 +0200

> instead of ActivePortal, and log it. Thought?

It cannot work - there can be a lot of nested queries, and at the end you
cannot reset to null, but you should return back pointer to outer query.

Regards

Pavel

---

From: torikoshia <[email-masked]>
Date: Wed, 28 Jul 2021 20:44:00 +0900

On 2021-07-28 03:45, Pavel Stehule wrote:
> út 27. 7. 2021 v 20:34 odesílatel Fujii Masao
> <[email-masked]> napsal:
> 
> It cannot work - there can be a lot of nested queries, and at the end
> you cannot reset to null, but you should return back pointer to outer
> query.

Thanks for your comment!

I'm wondering if we can avoid this problem by saving one outer level 
QueryDesc in addition to the current one.
I'm going to try it.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Tue, 10 Aug 2021 21:22:49 +0900

> QueryDesc in addition to the current one.

I have updated the patch in this way.

In this patch, getting the plan to the DO statement is as follows.

---------------------------------
   (pid:76608)=# DO $$
    BEGIN
    PERFORM pg_sleep(15);
    END$$;

   (pid:74482)=# SELECT pg_log_current_query_plan(76608);

   LOG: 00000: plan of the query running on backend with PID 76608 is:
         Query Text: SELECT pg_sleep(15)
         Result  (cost=0.00..0.01 rows=1 width=4)
           Output: pg_sleep('15'::double precision)

    -- pid:76608 finished DO statement:
   (pid:74482)=# SELECT pg_log_current_query_plan(76608);

   LOG:  00000: backend with PID 76608 is not running a query
---------------------------------

Any thoughts?

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 74b6cdd70de2c6ed0f4c8370af892584ad9d9a4f Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Tue, 10 Aug 2021 15:38:57 +0900

Subject: [PATCH v7] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Since some codes, tests and comments of
pg_log_current_query_plan() are the same with
pg_log_backend_memory_contexts(), this patch also refactors
them to make them common.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda
---
 doc/src/sgml/func.sgml                       | 46 +++++++++++
 src/backend/commands/explain.c               | 83 ++++++++++++++++++++
 src/backend/executor/execMain.c              | 10 +++
 src/backend/storage/ipc/procsignal.c         |  4 +
 src/backend/storage/ipc/signalfuncs.c        | 61 ++++++++++++++
 src/backend/tcop/postgres.c                  |  7 ++
 src/backend/utils/adt/mcxtfuncs.c            | 54 ++-----------
 src/backend/utils/init/globals.c             |  1 +
 src/include/catalog/pg_proc.dat              |  6 ++
 src/include/commands/explain.h               |  2 +
 src/include/miscadmin.h                      |  1 +
 src/include/storage/procsignal.h             |  1 +
 src/include/storage/signalfuncs.h            | 22 ++++++
 src/include/tcop/pquery.h                    |  1 +
 src/test/regress/expected/misc_functions.out | 16 +++-
 src/test/regress/sql/misc_functions.sql      | 12 +--
 16 files changed, 270 insertions(+), 57 deletions(-)
 create mode 100644 src/include/storage/signalfuncs.h

diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 78812b2dbe..13b44b42cb 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -25281,6 +25281,27 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
@@ -25394,6 +25415,31 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
 
+   <para>
+    considered for logging. Only the deepest nesting query's plan is logged.
+   </para>
+
   </sect2>
 
   <sect2 id="functions-admin-backup">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 10644dfac4..71538c1b6b 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,6 +29,9 @@
 #include "parser/parsetree.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "storage/signalfuncs.h"
+#include "tcop/pquery.h"
 #include "tcop/tcopprot.h"
 #include "utils/builtins.h"
 #include "utils/guc_tables.h"
@@ -4922,3 +4926,82 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogCurrentPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the plan of
+ *		the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogCurrentPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogCurrentPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogCurrentPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogCurrentPlanInterrupt
+ * 		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 LogCurrentPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogCurrentPlanInterrupt(void)
+{
+	ExplainState *es;
+	LogCurrentPlanPending = false;
+
+	if (ActiveQueryDesc == NULL)
+	{
+		ereport(LOG_SERVER_ONLY,
+				(errmsg("backend with PID %d is not running a query",
+					MyProcPid)));
+		return;
+	}
+
+	es = NewExplainState();
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+	es->verbose = true;
+
+	ExplainBeginOutput(es);
+	ExplainQueryText(es, ActiveQueryDesc);
+	ExplainPrintPlan(es, ActiveQueryDesc);
+	if (es->costs)
+		ExplainPrintJITSummary(es, ActiveQueryDesc);
+	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';
+
+	ereport(LOG_SERVER_ONLY,
+			(errmsg("plan of the query running on backend with PID %d is:\n%s",
+					MyProcPid, es->str->data),
+			 errhidestmt(true)));
+}
+
+/*
+ * pg_log_current_query_plan
+ *		Signal a backend process to log the query plan of the running query.
+ */
+Datum
+pg_log_current_query_plan(PG_FUNCTION_ARGS)
+{
+	pid_t		pid;
+	bool		result;
+
+	pid = PG_GETARG_INT32(0);
+	result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN);
+
+	PG_RETURN_BOOL(result);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index b3ce4bae53..c74aa1d04e 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -76,6 +76,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
 /* Hook for plugin to get control in ExecCheckRTPerms() */
 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);
@@ -299,10 +302,17 @@ ExecutorRun(QueryDesc *queryDesc,
 			ScanDirection direction, uint64 count,
 			bool execute_once)
 {
+	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/signalfuncs.c b/src/backend/storage/ipc/signalfuncs.c
index de69d60e79..1aad120791 100644
--- a/src/backend/storage/ipc/signalfuncs.c
+++ b/src/backend/storage/ipc/signalfuncs.c
@@ -23,6 +23,7 @@
 #include "storage/pmsignal.h"
 #include "storage/proc.h"
 #include "storage/procarray.h"
+#include "storage/signalfuncs.h"
 #include "utils/acl.h"
 #include "utils/builtins.h"
 
@@ -298,3 +299,63 @@ pg_rotate_logfile_v2(PG_FUNCTION_ARGS)
 	SendPostmasterSignal(PMSIGNAL_ROTATE_LOGFILE);
 	PG_RETURN_BOOL(true);
 }
+
+/*
+		return false;
+		return false;
+	return true;
index 58b5960e27..8b8808db8f 100644

@@ -4278,6 +4282,9 @@ PostgresMain(int argc, char *argv[],
 		/* We don't have a transaction command open anymore */
 		xact_started = false;
 
+		/* We have no running query */
+		ActiveQueryDesc = NULL;
+
 		/*
 		 * If an error occurred while we were reading a message from the
 		 * client, we have potentially lost track of where the previous
diff --git a/src/backend/utils/adt/mcxtfuncs.c b/src/backend/utils/adt/mcxtfuncs.c
index 0d52613bc3..304f36bda0 100644
--- a/src/backend/utils/adt/mcxtfuncs.c
+++ b/src/backend/utils/adt/mcxtfuncs.c
@@ -18,8 +18,8 @@
 #include "funcapi.h"
 #include "miscadmin.h"
 #include "mb/pg_wchar.h"
-#include "storage/proc.h"
 #include "storage/procarray.h"
+#include "storage/signalfuncs.h"
 #include "utils/builtins.h"
 
 /* ----------
@@ -161,57 +161,15 @@ pg_get_backend_memory_contexts(PG_FUNCTION_ARGS)
 /*

-	PG_RETURN_BOOL(true);
index b603700ed9..0321726227 100644
@@ -8038,6 +8038,12 @@

index 2e2e9a364a..097ebaa96d 100644

 	/* Recovery conflict reasons */
 	PROCSIG_RECOVERY_CONFLICT_DATABASE,
diff --git a/src/include/storage/signalfuncs.h b/src/include/storage/signalfuncs.h
new file mode 100644
index 0000000000..5f6b124372
--- /dev/null
+++ b/src/include/storage/signalfuncs.h
@@ -0,0 +1,22 @@
+/*-------------------------------------------------------------------------
+ *
+ * signalfuncs.h
+ *	  Functions for signaling backends
+ *
+ *
+ * Portions Copyright (c) 1996-2021, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994, Regents of the University of California
+ *
+ * src/include/storage/signalfuncs.h
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifndef PROCSIGNALFUNC_H
+#define PROCSIGNALFUNC_H
+
+/*
+ * prototypes for functions in signalfuncs.c
+ */
+extern bool SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason);
+
+#endif							/* PROCSIGNALFUNC_H */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index 2318f04ff0..d37a5eb837 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,6 +21,7 @@ struct PlannedStmt;				/* avoid including plannodes.h here */

 extern PGDLLIMPORT Portal ActivePortal;
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;

 extern PortalStrategy ChoosePortalStrategy(List *stmts);

base-commit: 152c2e0ae1a8d0ed810b2e833b536e64b91da0a6
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Wed, 11 Aug 2021 00:21:11 +0900

> In this patch, getting the plan to the DO statement is as follows.

Looks good to me.

Shouldn't we hide context information by calling errhidecontext(true)?

While "make installcheck" regression test was running, I repeated
executing pg_log_current_query_plan() and got the failure of join_hash test
with the following diff. This means that pg_log_current_query_plan() could
cause the query that should be completed successfully to fail with the error.
Isn't this a bug?

I *guess* that the cause of this issue is that ExplainNode() can call
InstrEndLoop() more than once unexpectedly.

  ------------------------------------------------------------------------------
  $$
    select count(*) from simple r join simple s using (id);
  $$);
- initially_multibatch | increased_batches
-----------------------+-------------------
- f                    | f
-(1 row)
-
+ERROR:  InstrEndLoop called on running node
+CONTEXT:  PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE statement
  rollback to settings;
  -- parallel with parallel-oblivious hash join
  savepoint settings;
@@ -687,11 +684,9 @@
      left join (select b1.id, b1.t from join_bar b1 join join_bar b2 using (id)) ss
      on join_foo.id < ss.id + 1 and join_foo.id > ss.id - 1;
  $$);
- multibatch
-------------
- t
-(1 row)
-
+ERROR:  InstrEndLoop called on running node
+CONTEXT:  parallel worker
+PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE statement
  rollback to settings;
  -- single-batch with rescan, parallel-aware
  savepoint settings;
  ------------------------------------------------------------------------------

Regards,

---

From: torikoshia <[email-masked]>
Date: Wed, 11 Aug 2021 21:14:05 +0900

Agreed.

> cause the query that should be completed successfully to fail with the 

Thanks for finding the bug.
I also reproduced it.

> InstrEndLoop() more than once unexpectedly.

As far as I looked into, pg_log_current_plan() can call InstrEndLoop() 
through ExplainNode().
I added a flag to ExplainState to avoid calling InstrEndLoop() when 
ExplainNode() is called from pg_log_current_plan().

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 26356efb094ac25b11fe65df93f11c64ad136723 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Wed, 11 Aug 2021 20:17:42 +0900
Subject: [PATCH v8] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda
---
 doc/src/sgml/func.sgml                       | 46 ++++++++++
 src/backend/commands/explain.c               | 90 +++++++++++++++++++-
 src/backend/executor/execMain.c              | 10 +++
 src/backend/storage/ipc/procsignal.c         |  4 +
 src/backend/storage/ipc/signalfuncs.c        | 61 +++++++++++++
 src/backend/tcop/postgres.c                  |  7 ++
 src/backend/utils/adt/mcxtfuncs.c            | 54 ++----------
 src/backend/utils/init/globals.c             |  1 +
 src/include/catalog/pg_proc.dat              |  6 ++
 src/include/commands/explain.h               |  3 +
 src/include/miscadmin.h                      |  1 +
 src/include/storage/procsignal.h             |  1 +
 src/include/storage/signalfuncs.h            | 22 +++++
 src/include/tcop/pquery.h                    |  1 +
 src/test/regress/expected/misc_functions.out | 16 +++-
 src/test/regress/sql/misc_functions.sql      | 12 +--
 16 files changed, 277 insertions(+), 58 deletions(-)
 create mode 100644 src/include/storage/signalfuncs.h

+      <row>
 
+   <para>
 
   <sect2 id="functions-admin-backup">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 10644dfac4..75524eb1b8 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,6 +29,9 @@
 #include "parser/parsetree.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "storage/signalfuncs.h"
+#include "tcop/pquery.h"
 #include "tcop/tcopprot.h"
 #include "utils/builtins.h"
 #include "utils/guc_tables.h"
@@ -1594,6 +1598,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, 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
@@ -1601,7 +1608,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->running)
 		InstrEndLoop(planstate->instrument);
 
 	if (es->analyze &&
@@ -4922,3 +4929,84 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+	es->running = true;
+			 errhidestmt(true),
+			 errhidecontext(true)));

 void

 

 
 
 /* ----------

-	PG_RETURN_BOOL(true);
 
+# logging plan of the running query on the specified backend
+{ oid => '4544', descr => 'log plan of the running query on the specified backend',
+  proname => 'pg_log_current_query_plan',
+  provolatile => 'v', prorettype => 'bool',
+  proargtypes => 'int4', prosrc => 'pg_log_current_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 e94d9e49cf..7c2dce7cdf 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -59,6 +59,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		running;		/* whether target query is already running */
 } ExplainState;
 
 /* Hook for plugins to get control in ExplainOneQuery() */
@@ -124,4 +125,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);

 

 

base-commit: a6bd28beb0639d4cf424e961862a65c466ca65bf
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Fri, 20 Aug 2021 01:12:11 +0900

On 2021/08/11 21:14, torikoshia wrote:
> As far as I looked into, pg_log_current_plan() can call InstrEndLoop() through ExplainNode().
> I added a flag to ExplainState to avoid calling InstrEndLoop() when ExplainNode() is called from pg_log_current_plan().

Thanks for updating the patch!
I tried to test the patch again and encountered two issues.

(1)
The following WITH RECURSIVE query failed with the error
"ERROR:  failed to find plan for CTE sg" when I ran
pg_log_current_query_plan() against the backend executing that query.
Is this a bug?

     create table graph0( f int, t int, label text );
     insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 -> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');

     with recursive search_graph(f, t, label, i) as (
         select *, 1||pg_sleep(1)::text from graph0 g
         union distinct
         select g.*,1||pg_sleep(1)::text
         from graph0 g, search_graph sg
        where g.f = sg.t
     ) search breadth first by f, t set seq
     select * from search_graph order by seq;

(2)
When I ran pg_log_current_query_plan() while "make installcheck" test
was running, I got the following assertion failure.

TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type == LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)

0   postgres                            0x000000010ec23557 ExceptionalCondition + 231
1   postgres                            0x000000010e9eff15 LockAcquireExtended + 1461
2   postgres                            0x000000010e9ed14d LockRelationOid + 61
3   postgres                            0x000000010e41251b relation_open + 91
4   postgres                            0x000000010e509679 table_open + 25
5   postgres                            0x000000010ebf9462 SearchCatCacheMiss + 274
6   postgres                            0x000000010ebf5979 SearchCatCacheInternal + 761
7   postgres                            0x000000010ebf566c SearchCatCache + 60
8   postgres                            0x000000010ec1a9e0 SearchSysCache + 144
9   postgres                            0x000000010ec1ae03 SearchSysCacheExists + 51
10  postgres                            0x000000010e58ce35 TypeIsVisible + 437
11  postgres                            0x000000010ea98e4c format_type_extended + 1964
12  postgres                            0x000000010ea9900e format_type_with_typemod + 30
13  postgres                            0x000000010eb78d76 get_const_expr + 742
14  postgres                            0x000000010eb79bc8 get_rule_expr + 232
15  postgres                            0x000000010eb8140f get_func_expr + 1247
16  postgres                            0x000000010eb79dcd get_rule_expr + 749
17  postgres                            0x000000010eb81688 get_rule_expr_paren + 136
18  postgres                            0x000000010eb7bf38 get_rule_expr + 9304
19  postgres                            0x000000010eb72ad5 deparse_expression_pretty + 149
20  postgres                            0x000000010eb73463 deparse_expression + 83
21  postgres                            0x000000010e68eaf1 show_plan_tlist + 353
22  postgres                            0x000000010e68adaf ExplainNode + 4991
23  postgres                            0x000000010e688b4b ExplainPrintPlan + 283
24  postgres                            0x000000010e68e1aa ProcessLogCurrentPlanInterrupt + 266
25  postgres                            0x000000010ea133bb ProcessInterrupts + 3435
26  postgres                            0x000000010e738c97 vacuum_delay_point + 55
27  postgres                            0x000000010e42bb4b ginInsertCleanup + 1531
28  postgres                            0x000000010e42d418 gin_clean_pending_list + 776
29  postgres                            0x000000010e74955a ExecInterpExpr + 2522
30  postgres                            0x000000010e7487e2 ExecInterpExprStillValid + 82
31  postgres                            0x000000010e7ae83b ExecEvalExprSwitchContext + 59
32  postgres                            0x000000010e7ae7be ExecProject + 78
33  postgres                            0x000000010e7ae4e9 ExecResult + 345
34  postgres                            0x000000010e764e42 ExecProcNodeFirst + 82
35  postgres                            0x000000010e75ccb2 ExecProcNode + 50
36  postgres                            0x000000010e758301 ExecutePlan + 193
37  postgres                            0x000000010e7581d1 standard_ExecutorRun + 609
38  auto_explain.so                     0x000000010f1df3a7 explain_ExecutorRun + 247
39  postgres                            0x000000010e757f3b ExecutorRun + 91
40  postgres                            0x000000010ea1cb49 PortalRunSelect + 313
41  postgres                            0x000000010ea1c4dd PortalRun + 861
42  postgres                            0x000000010ea17474 exec_simple_query + 1540
43  postgres                            0x000000010ea164d4 PostgresMain + 2580
44  postgres                            0x000000010e91d159 BackendRun + 89
45  postgres                            0x000000010e91c6a5 BackendStartup + 565
46  postgres                            0x000000010e91b3fe ServerLoop + 638
47  postgres                            0x000000010e918b9d PostmasterMain + 6717
48  postgres                            0x000000010e7efd43 main + 819
49  libdyld.dylib                       0x00007fff6a46e3d5 start + 1
50  ???                                 0x0000000000000003 0x0 + 3

LOG:  server process (PID 61512) was terminated by signal 6: Abort trap: 6
DETAIL:  Failed process was running: select gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;

Regards,

---

From: torikoshia <[email-masked]>
Date: Tue, 07 Sep 2021 12:39:46 +0900

> I tried to test the patch again and encountered two issues.

Thanks for finding these issues!

>     insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 ->
> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');
> 

This ERROR occurred without applying the patch and just calling 
EXPLAIN(VERBOSE) to CTE with SEARCH BREADTH FIRST.

I'm going to make another thread to discuss it.

> TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type ==
> LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)
> 
> DETAIL:  Failed process was running: select
> gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;

As far as I understand, since explaining plans can acquire heavyweight 
lock for example to get column names, when page lock is held at the time 
of the interrupt, this assertion error occurs.

The attached patch tries to avoid this by checking each LocalLock entry 
and when finding even one, giving up logging the plan.

Thoughts?

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Date: Mon, 6 Sep 2021 14:18:51 +0900

---
 doc/src/sgml/func.sgml                       |  46 ++++++++
 src/backend/commands/explain.c               | 117 ++++++++++++++++++-
 src/backend/executor/execMain.c              |  10 ++
 src/backend/storage/ipc/procsignal.c         |   4 +
 src/backend/storage/ipc/signalfuncs.c        |  61 ++++++++++
 src/backend/tcop/postgres.c                  |   7 ++
 src/backend/utils/adt/mcxtfuncs.c            |  54 +--------
 src/backend/utils/init/globals.c             |   1 +
 src/include/catalog/pg_proc.dat              |   6 +
 src/include/commands/explain.h               |   3 +
 src/include/miscadmin.h                      |   1 +
 src/include/storage/procsignal.h             |   1 +
 src/include/storage/signalfuncs.h            |  22 ++++
 src/include/tcop/pquery.h                    |   1 +
 src/test/regress/expected/misc_functions.out |  16 ++-
 src/test/regress/sql/misc_functions.sql      |  12 +-
 16 files changed, 303 insertions(+), 59 deletions(-)
 create mode 100644 src/include/storage/signalfuncs.h

+      <row>
 
+   <para>
 
index 10644dfac4..f528301cc5 100644
@@ -40,7 +44,6 @@
 #include "utils/typcache.h"
 #include "utils/xml.h"
 
-
 /* Hook for plugins to get control in ExplainOneQuery() */
 ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 
@@ -1594,6 +1597,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	/*
@@ -1601,7 +1607,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
 	if (es->analyze &&
@@ -4922,3 +4928,110 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogCurrentPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the plan of
+ *		the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogCurrentPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogCurrentPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogCurrentPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogCurrentPlanInterrupt
+ * 		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 LogCurrentPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogCurrentPlanInterrupt(void)
+{
+	ExplainState *es;
+	HASH_SEQ_STATUS status;
+	LOCALLOCK  *locallock;
+	LogCurrentPlanPending = false;
+
+	if (ActiveQueryDesc == NULL)
+	{
+		ereport(LOG_SERVER_ONLY,
+				(errmsg("backend with PID %d is not running a query",
+					MyProcPid)));
+		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("backend with PID %d is now holding a page lock. Try again",
+					MyProcPid)));
+			hash_seq_term(&status);
+			return;
+		}
+	}
+
+	es = NewExplainState();
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+	es->verbose = true;
+	es->running = true;
+
+	ExplainBeginOutput(es);
+	ExplainQueryText(es, ActiveQueryDesc);
+	ExplainPrintPlan(es, ActiveQueryDesc);
+	if (es->costs)
+		ExplainPrintJITSummary(es, ActiveQueryDesc);
+	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';
+
+	ereport(LOG_SERVER_ONLY,
+			(errmsg("plan of the query running on backend with PID %d is:\n%s",
+					MyProcPid, es->str->data),
+			 errhidestmt(true),
+			 errhidecontext(true)));
+}
+
+/*
+ * pg_log_current_query_plan
+ *		Signal a backend process to log the query plan of the running query.
+ */
+Datum
+pg_log_current_query_plan(PG_FUNCTION_ARGS)
+{
+	pid_t		pid;
+	bool		result;
+
+	pid = PG_GETARG_INT32(0);
+	result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN);
+
+	PG_RETURN_BOOL(result);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index b3ce4bae53..c74aa1d04e 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -76,6 +76,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
 /* Hook for plugin to get control in ExecCheckRTPerms() */
 ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;

 void

 

 
 
 /* ----------

-	PG_RETURN_BOOL(true);
index c07b2c6a55..6b4ef16d81 100644

 

 

base-commit: 0bd305ee1d427ef29f5fa4fa20567e3b3f5ff792
-- 
2.27.0

---

From: torikoshia <[email-masked]>
Date: Wed, 08 Sep 2021 21:06:26 +0900

On 2021-09-07 12:39, torikoshia wrote:
> lock for example to get column names, when page lock is held at the
> time of the interrupt, this assertion error occurs.
> 
> The attached patch tries to avoid this by checking each LocalLock
> entry and when finding even one, giving up logging the plan.
> 
> Thoughts?

Regression tests failed on windows.
Updated patch attached.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Date: Wed, 8 Sep 2021 20:40:21 +0900

---
 src/backend/storage/lmgr/lock.c              |   9 +-
 17 files changed, 308 insertions(+), 63 deletions(-)

+      <row>
 
+   <para>

-

 	if (es->analyze &&

 void

 
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 364654e106..6d1a5add17 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -614,17 +614,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

 
 
 /* ----------

-	PG_RETURN_BOOL(true);
index d068d6532e..3a81e86493 100644

 

 

base-commit: a3d2b1bbe904b0ca8d9fdde20f25295ff3e21f79
-- 
2.27.0

---

From: Ekaterina Sokolova <[email-masked]>
Date: Wed, 13 Oct 2021 17:28:30 +0300

Hi, hackers!

• The last version of patch is correct applied. It changes 8 files from 
/src/backend, and 9 other files.

• I have 1 error and 1 warning during compilation on Mac.

explain.c:4985:25: error: implicit declaration of function 
'GetLockMethodLocalHash' is invalid in C99 
[-Werror,-Wimplicit-function-declaration]
         hash_seq_init(&status, GetLockMethodLocalHash());
explain.c:4985:25: warning: incompatible integer to pointer conversion 
passing 'int' to parameter of type 'HTAB *' (aka 'struct HTAB *') 
[-Wint-conversion]
         hash_seq_init(&status, GetLockMethodLocalHash());

This error doesn't appear at my second machine with Ubuntu.

I found the reason. You delete #ifdef USE_ASSERT_CHECKING from 
implementation of function GetLockMethodLocalHash(void), but this ifdef 
exists around function declaration. There may be a situation, when 
implementation exists without declaration, so files with using of 
function produce errors. I create new version of patch with fix of this 
problem.

I'm agree that seeing the details of a query is a useful feature, but I 
have several doubts:

1) There are lots of changes of core's code. But not all users need this 
functionality. So adding this functionality like extension seemed more 
reasonable.

2) There are many tools available to monitor the status of a query. How 
much do we need another one? For example:
     • pg_stat_progress_* is set of views with current status of ANALYZE, 
CREATE INDEX, VACUUM, CLUSTER, COPY, Base Backup. You can find it in 
PostgreSQL documentation [1].
     • pg_query_state is contrib with 2 patches for core (I hope someday 
Community will support adding this patches to PostgreSQL). It contains 
function with printing table with pid, full query text, plan and current 
progress of every node like momentary EXPLAIN ANALYSE for SELECT, 
UPDATE, INSERT, DELETE. So it supports every flags and formats of 
EXPLAIN. You can find current version of pg_query_state on github [2]. 
Also I found old discussion about first version of it in Community [3].

3) Have you measured the overload of your feature? It would be really 
interesting to know the changes in speed and performance.

Thank you for working on this issue. I would be glad to continue to 
follow the development of this issue.

Links above:
[1] https://www.postgresql.org/docs/current/progress-reporting.html
[2] https://github.com/postgrespro/pg_query_state
[3] 
https://www.postgresql.org/message-id/[email-masked]

-- 
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda, Ekaterina Sokolova

---
 src/include/storage/lock.h                   |   2 -
 18 files changed, 308 insertions(+), 65 deletions(-)

+      <row>
 
+   <para>

-

 	if (es->analyze &&

 void

 

 /*

 
 
 /* ----------

-	PG_RETURN_BOOL(true);

 
 
 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 9b2a421c32c..5efac88b130 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -560,9 +560,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 eec186be2e..c1a7218d69 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_CURRENT_PLAN, /* ask backend to log plan of the current query */

---

From: torikoshia <[email-masked]>
Date: Fri, 15 Oct 2021 15:17:22 +0900

On 2021-10-13 23:28, Ekaterina Sokolova wrote:
> Hi, hackers!
> 
> • The last version of patch is correct applied. It changes 8 files
> from /src/backend, and 9 other files.
> 
> implementation of function GetLockMethodLocalHash(void), but this
> ifdef exists around function declaration. There may be a situation,
> when implementation exists without declaration, so files with using of
> function produce errors. I create new version of patch with fix of
> this problem.

Thanks for fixing that!

> I'm agree that seeing the details of a query is a useful feature, but
> I have several doubts:
> 
> 1) There are lots of changes of core's code. But not all users need
> this functionality. So adding this functionality like extension seemed
> more reasonable.

It would be good if we can implement this feature in an extension, but 
as pg_query_state extension needs applying patches to PostgreSQL, I 
think this kind of feature needs PostgreSQL core modification.
IMHO extensions which need core modification are not easy to use in 
production environments..

> 2) There are many tools available to monitor the status of a query.
> How much do we need another one? For example:
>     • pg_stat_progress_* is set of views with current status of
> ANALYZE, CREATE INDEX, VACUUM, CLUSTER, COPY, Base Backup. You can
> find it in PostgreSQL documentation [1].
>     • pg_query_state is contrib with 2 patches for core (I hope
> someday Community will support adding this patches to PostgreSQL). It
> contains function with printing table with pid, full query text, plan
> and current progress of every node like momentary EXPLAIN ANALYSE for
> SELECT, UPDATE, INSERT, DELETE. So it supports every flags and formats
> of EXPLAIN. You can find current version of pg_query_state on github
> [2]. Also I found old discussion about first version of it in
> Community [3].

Thanks for introducing the extension!

I only took a quick look at pg_query_state, I have some questions.

pg_query_state seems using shm_mq to expose the plan information, but 
there was a discussion that this kind of architecture would be tricky to 
do properly [1].
Does pg_query_state handle difficulties listed on the discussion?

It seems the caller of the pg_query_state() has to wait until the target 
process pushes the plan information into shared memory, can it lead to 
deadlock situations?
I came up with this question because when trying to make a view for 
memory contexts of other backends, we encountered deadlock situations. 
After all, we gave up view design and adopted sending signal and 
logging.

Some of the comments of [3] seem useful for my patch, I'm going to 
consider them. Thanks!

> interesting to know the changes in speed and performance.

I haven't measured it yet, but I believe that the overhead for backends 
which are not called pg_log_current_plan() would be slight since the 
patch just adds the logic for saving QueryDesc on ExecutorRun().
The overhead for backends which is called pg_log_current_plan() might 
not slight, but since the target process are assumed dealing with 
long-running query and the user want to know its plan, its overhead 
would be worth the cost.

> follow the development of this issue.

Thanks for your help!

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: torikoshia <[email-masked]>
Date: Fri, 15 Oct 2021 19:12:26 +0900

On 2021-10-15 15:17, torikoshia wrote:
> there was a discussion that this kind of architecture would be tricky
> to do properly [1].

Sorry, I forgot to add the URL.
[1] 
https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

> It seems the caller of the pg_query_state() has to wait until the
> target process pushes the plan information into shared memory, can it
> lead to deadlock situations?

Discussion at the following URL.
https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

---

From: Justin Pryzby <[email-masked]>
Date: Fri, 12 Nov 2021 12:37:09 -0600

> Community will support adding this patches to PostgreSQL). It contains

I reviewed this version of the patch - I have some language fixes.

I didn't know about pg_query_state, thanks.

> plan of the specified backend process.

To me, "current plan" seems to mean "plan of *this* backend" (which makes no
sense to log).  I think the user-facing function could be called
pg_log_query_plan().  It's true that the implementation is a request to another
backend to log its *own* query plan - but users shouldn't need to know about
the implementation.

> +        Only superusers can request to log plan of the running query.

.. log the plan of a running query.

> +    considered for logging. Only the deepest nesting query's plan is logged.

Only the plan of the most deeply nested query is logged.

> +				(errmsg("backend with PID %d is not running a query",

The extra parens around errmsg() are not needed since e3a87b499.

> +				(errmsg("backend with PID %d is now holding a page lock. Try again",

remove "now"

> +					MyProcPid, es->str->data),

Maybe this should say "query plan running on backend with PID 17793 is:"

> + * would cause lots of log messages and which can lead to denial of

remove "and"

> +				 errmsg("must be a superuser to log information about specified process")));

I think it should say not say "specified", since that sounds like the user
might have access to log information about some other processes:
| must be a superuser to log information about processes

> +	 * used to below purposes, it might end its own first and the information

used for below purposes,

-- 
Justin

---

From: Bharath Rupireddy <[email-masked]>
Date: Sat, 13 Nov 2021 18:59:59 +0530

> follow the development of this issue.

Thanks for the patch. I'm not sure if v11 is the latest patch, if yes,
I have the following comments:

1) Firstly, v11 patch isn't getting applied on the master -
http://cfbot.cputube.org/patch_35_3142.log.

2) I think we are moving away from if (!superuser()) checks, see the
commit [1]. The goal is to let the GRANT-REVOKE system deal with who
is supposed to run these system functions. Since
pg_log_current_query_plan also writes the info to server logs, I think
it should do the same thing as commit [1] did for
pg_log_backend_memory_contexts.

With v11, you are re-introducing the superuser() check in the
pg_log_backend_memory_contexts which is wrong.

3) I think SendProcSignalForLogInfo can be more generic, meaning, it
can also send signal to auxiliary processes if asked to do this will
simplify the things for pg_log_backend_memory_contexts and other
patches like pg_print_backtrace. I would imagine it to be "bool
SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason, bool
signal_aux_proc);".

[1] commit f0b051e322d530a340e62f2ae16d99acdbcb3d05
Author: Jeff Davis <[email-masked]>
Date:   Tue Oct 26 13:13:52 2021 -0700

    Allow GRANT on pg_log_backend_memory_contexts().

    Remove superuser check, allowing any user granted permissions on
    pg_log_backend_memory_contexts() to log the memory contexts of any
    backend.

    Note that this could allow a privileged non-superuser to log the
    memory contexts of a superuser backend, but as discussed, that does
    not seem to be a problem.

    Reviewed-by: Nathan Bossart, Bharath Rupireddy, Michael Paquier,
Kyotaro Horiguchi, Andres Freund
    Discussion:
https://postgr.es/m/[email-masked]

Regards,
Bharath Rupireddy.

---

From: torikoshia <[email-masked]>
Date: Mon, 15 Nov 2021 21:59:15 +0900

On 2021-11-13 22:29, Bharath Rupireddy wrote:
Thanks for your review!

Updated the patch.

> pg_log_backend_memory_contexts which is wrong.

Yeah, I removed superuser() check and make it possible to be executed by 
non-superusers when users are granted to do so.
> SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason, bool

I agree with your idea.
Since sending signals to auxiliary processes to dump memory contexts and 
pg_print_backtrace is still under discussion, IMHO it would be better to 
refactor SendProcSignalForLogInfo after these patches are commited.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From 5499167a7ecc6f040d5fec817cf36a7ba0b5cbff Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Mon, 15 Nov 2021 21:20:43 +0900
Subject: [PATCH v12] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

to check its plan. This is not so convenient when

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.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda, Ekaterina Sokolova
---
 doc/src/sgml/func.sgml                       |  45 +++++++
 src/backend/catalog/system_functions.sql     |   2 +
 src/backend/commands/explain.c               | 117 ++++++++++++++++++-
 src/backend/executor/execMain.c              |  10 ++
 src/backend/storage/ipc/procsignal.c         |   4 +
 src/backend/storage/ipc/signalfuncs.c        |  55 +++++++++
 src/backend/storage/lmgr/lock.c              |   9 +-
 src/backend/tcop/postgres.c                  |   7 ++
 src/backend/utils/adt/mcxtfuncs.c            |  36 +-----
 src/backend/utils/init/globals.c             |   1 +
 src/include/catalog/pg_proc.dat              |   6 +
 src/include/commands/explain.h               |   3 +
 src/include/miscadmin.h                      |   1 +
 src/include/storage/procsignal.h             |   1 +
 src/include/tcop/pquery.h                    |   1 +
 src/test/regress/expected/misc_functions.out |  54 +++++++--
 src/test/regress/sql/misc_functions.sql      |  42 +++++--
 17 files changed, 333 insertions(+), 61 deletions(-)

diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 24447c0017..e12e1feeca 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -25345,6 +25345,26 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
@@ -25458,6 +25478,31 @@ LOG:  Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
 
+   <para>
 
   <sect2 id="functions-admin-backup">
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 54c93b16c4..039c15d581 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -701,6 +701,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_dir(text,boolean,boolean) FROM public;
 
 REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) FROM PUBLIC;
 
+REVOKE EXECUTE ON FUNCTION pg_log_current_query_plan(integer) FROM PUBLIC;
+
 --
 -- We also set up some things as accessible to standard roles.
index 10644dfac4..30493b6fa2 100644
 
-

 	if (es->analyze &&
+ * 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.

 void
index 6e69398cdd..6ea63e0c53 100644

index de69d60e79..97e18ee4cb 100644
 
@@ -298,3 +299,57 @@ pg_rotate_logfile_v2(PG_FUNCTION_ARGS)
+ * By default, only superusers are allowed to signal to log information
+ * 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.
index c25af7fe09..8a70a6d94e 100644

 /*
index 0775abe35d..774dadb87a 100644

@@ -4289,6 +4293,9 @@ PostgresMain(const char *dbname, const char *username)
 		/* We don't have a transaction command open anymore */
 		xact_started = false;
 
index 6ddbf70b30..2db662282f 100644
 
 /* ----------
@@ -175,37 +175,5 @@ Datum
 	int			pid = PG_GETARG_INT32(0);
index d068d6532e..5763b45f23 100644
 
+{ oid => '4545', descr => 'log plan of the running query on the specified backend',

index 90a3016065..0fb0da77e2 100644

 extern PortalStrategy ChoosePortalStrategy(List *stmts);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index 71d316cad3..918460ee35 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -134,21 +134,22 @@ LINE 1: SELECT num_nulls();
                ^
 HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- 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()
+CREATE ROLE regress_log;
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
  t
 (1 row)
 
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
  has_function_privilege 
 ------------------------
@@ -156,15 +157,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;
+SELECT has_function_privilege('regress_log',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
  has_function_privilege 
 ------------------------
  t
 (1 row)
 
-SET ROLE regress_log_memory;
+SET ROLE regress_log;
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
@@ -173,8 +174,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;
+-- pg_log_current_query_plan()
+SELECT pg_log_current_query_plan(pg_backend_pid());
+ pg_log_current_query_plan 
+---------------------------
+ t
+(1 row)
+
+SELECT has_function_privilege('regress_log',
+  'pg_log_current_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege 
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_current_query_plan(integer)
+  TO regress_log;
+SELECT has_function_privilege('regress_log',
+  'pg_log_current_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege 
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log;
+SELECT pg_log_current_query_plan(pg_backend_pid());
+ pg_log_current_query_plan 
+---------------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_current_query_plan(integer)
+  FROM regress_log;
+DROP ROLE regress_log;
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index 8c23874b3f..462b66a770 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -31,35 +31,55 @@ SELECT num_nonnulls();
 SELECT num_nulls();
 
 --
--- pg_log_backend_memory_contexts()
+-- Test logging functions
 --
--- 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.
---
 
-SELECT pg_log_backend_memory_contexts(pg_backend_pid());
+-- pg_log_backend_memory_contexts()
+CREATE ROLE regress_log;
 
-CREATE ROLE regress_log_memory;
+SELECT pg_log_backend_memory_contexts(pg_backend_pid());
 
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log',
   '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;
 
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log',
   'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
 
-SET ROLE regress_log_memory;
+SET ROLE regress_log;
 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;
+
+-- pg_log_current_query_plan()
+SELECT pg_log_current_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log',
+  'pg_log_current_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_current_query_plan(integer)
+  TO regress_log;
+
+SELECT has_function_privilege('regress_log',
+  'pg_log_current_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log;
+SELECT pg_log_current_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_current_query_plan(integer)
+  FROM regress_log;
 
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log;

base-commit: b0f7425ec2445678f32381de8bd3174d3cc2167e
-- 
2.27.0

---

From: torikoshia <[email-masked]>
Date: Mon, 15 Nov 2021 23:00:12 +0900

> I reviewed this version of the patch - I have some language fixes.

Thanks for your review!
Attached patch that reflects your comments.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

From b8367e22d7a9898e4b85627ba8c203be273fc22f Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email-masked]>
Date: Mon, 15 Nov 2021 22:31:00 +0900
Subject: [PATCH v13] Add function to log the untruncated query string and its
 plan for the query currently running on the backend with the specified
 process ID.

pg_log_query_plan() function that requests to log the

Since some codes, tests and comments of
pg_log_query_plan() are the same with
pg_log_backend_memory_contexts(), this patch also refactors
them to make them common.

Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby

---
 18 files changed, 355 insertions(+), 61 deletions(-)

index 24447c0017..7ffaa9a55d 100644
 
+      <row>
+         <primary>pg_log_query_plan</primary>
+        <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
 
+   <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:  plan of the query running on backend with PID 17793 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'
+</screen>
+    Note that nested statements (statements executed inside a function) are not
+    considered for logging. Only the plan of the most deeply nested query is logged.
+   </para>
+
   </sect2>
 
index 54c93b16c4..d7f0010e47 100644

+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
index 10644dfac4..d930200987 100644
 
-

 	if (es->analyze &&
+				errmsg("backend with PID %d is not running a query",
+					MyProcPid));
+				errmsg("backend with PID %d is holding a page lock. Try again",
+					MyProcPid));
+			errmsg("query plan running on backend with PID %d is:\n%s",
+			 errhidecontext(true));
+ * pg_log_query_plan
+pg_log_query_plan(PG_FUNCTION_ARGS)

 void

index de69d60e79..7aeec69ea5 100644
 
+ * rate would cause lots of log messages which can lead to denial of
+	 * used for below purposes, it might end its own first and the information
+				errmsg("PID %d is not a PostgreSQL server process", pid));
+				errmsg("could not send signal to process %d: %m", pid));

 /*

 
 
 /* ----------
index d068d6532e..0b96cf61b2 100644
 
+  proname => 'pg_log_query_plan',
+  proargtypes => 'int4', prosrc => 'pg_log_query_plan' },

 

index 71d316cad3..1b6bc7a89d 100644

 
 
 RESET ROLE;
 REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+  FROM regress_log;
+-- 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',
+  '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;
+SELECT has_function_privilege('regress_log',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege 
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log;
+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;
+DROP ROLE regress_log;
 --
 -- Test some built-in SRFs
 --
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index 8c23874b3f..5cb2a64aad 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -31,35 +31,55 @@ SELECT num_nonnulls();
 SELECT num_nulls();

 

 

 REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
-  FROM regress_log_memory;
+  FROM regress_log;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  TO regress_log;
+
+SELECT has_function_privilege('regress_log',
+  'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+  FROM regress_log;

---

From: Bharath Rupireddy <[email-masked]>
Date: Mon, 15 Nov 2021 19:45:49 +0530

+1.

I have another comment: isn't it a good idea that an overloaded
version of the new function pg_log_query_plan can take the available
explain command options as a text argument? I'm not sure if it is
possible to get the stats like buffers, costs etc of a running query,
if yes, something like pg_log_query_plan(pid, 'buffers',
'costs'....);? It looks to be an overkill at first sight, but these
can be useful to know more detailed plan of the query.

Thoughts?

Regards,
Bharath Rupireddy.

---

From: torikoshia <[email-masked]>
Date: Tue, 16 Nov 2021 20:48:27 +0900

> can be useful to know more detailed plan of the query.

I also think the overloaded version would be useful.
However as discussed in [1], it seems to introduce other difficulties.
I think it would be enough that the first version of pg_log_query_plan 
doesn't take any parameters.

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

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION