On 2021-05-28 15:51, torikoshia wrote:
On 2021-05-13 21:57, Dilip Kumar wrote:
On Thu, May 13, 2021 at 5:18 PM Dilip Kumar <dilipbal...@gmail.com>
wrote:
On Thu, May 13, 2021 at 5:15 PM Bharath Rupireddy
<bharath.rupireddyforpostg...@gmail.com> wrote:
>
> On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbal...@gmail.com> wrote:
> >
> > On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
> > <bharath.rupireddyforpostg...@gmail.com> wrote:
> > >
> > > 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.
> > >
> > > /* 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)));
> > >
> >
> > Yes, that was my exact point, that in this particular code log with
> > LOG_SERVER_ONLY.
> >
> > Like this.
> > /* Log immediately if dictated by log_statement */
> > if (check_log_statement(parsetree_list))
> > {
> > ereport(LOG_SERVER_ONLY,
>
> 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.
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.
Updated the patch.
- reordered superuser check which was pointed out in another thread[1]
- added a regression test
[1] https://postgr.es/m/ylxw1uvgiap5u...@paquier.xyz
Regards,
--
Atsushi Torikoshi
NTT DATA CORPORATION
From 7ad9a280b6f74e4718293863716046c02b0a3835 Mon Sep 17 00:00:00 2001
From: atorik <torikos...@oss.nttdata.com>
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.
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 | 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(-)
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..1cea557764 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 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;
+
+ /* 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")));
+
+ 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);
+ }
+
+ 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();
+ 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/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 acbcae4607..a6be1ab0b5 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -7975,6 +7975,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_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 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..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 */
/* 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
