On 2021-06-16 20:36, torikoshia 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
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.
+1. I'm going to proceed in this direction.
Updated the patch.
On Thu, Jun 10, 2021 at 11:09 AM torikoshia <torikos...@oss.nttdata.com>
wrote:
On 2021-06-09 23:04, Fujii Masao wrote:
> 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.
+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 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 <torikos...@oss.nttdata.com>
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.
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.
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(-)
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 6388385edc..dad2d34a04 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_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();
+ 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 8cea10c901..ac8ea67e81 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"
@@ -3366,6 +3367,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+
+ if (LogCurrentPlanPending)
+ ProcessLogCurrentPlanInterrupt();
}
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));
}
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 fde251fa4f..629d393828 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -7970,6 +7970,12 @@
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',
+ 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..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 4dc343cbc5..355e3db622 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -94,6 +94,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..92290c2ed9 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 */
/* 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());
--
-- Test some built-in SRFs
base-commit: bafad2c5b261a1449bed60ebac9e7918ebcc42b4
--
2.27.0
