On 2022-01-14 15:38, Julien Rouhaud wrote:
Hi,
On Fri, Jan 07, 2022 at 09:54:31PM +0900, Fujii Masao wrote:
I ran the following query every 0.1s by using \watch psql command from
three different sessions while make installcheck test was running.
SELECT pg_log_query_plan(pid) FROM pg_stat_activity;
And then I got the segmentation fault as follows.
2022-01-07 21:40:32 JST [postmaster] LOG: server process (PID 51017)
was terminated by signal 11: Segmentation fault: 11
2022-01-07 21:40:32 JST [postmaster] DETAIL: Failed process was
running: select description, (test_conv(inbytes, 'utf8', 'utf8')).*
from utf8_verification_inputs;
2022-01-07 21:40:32 JST [postmaster] LOG: terminating any other
active server processes
2022-01-07 21:40:32 JST [postmaster] LOG: all server processes
terminated; reinitializing
The backtrace I got from the core file was:
(lldb) target create --core "/cores/core.51017"
Core file '/cores/core.51017' (x86_64) was loaded.
(lldb) bt
* thread #1, stop reason = signal SIGSTOP
* frame #0: 0x00007fff20484552
libsystem_platform.dylib`_platform_strlen + 18
frame #1: 0x000000011076e36c
postgres`dopr(target=0x00007ffedfd1b1d8, format="\n",
args=0x00007ffedfd1b450) at snprintf.c:444:20
frame #2: 0x000000011076e133 postgres`pg_vsnprintf(str="Query
Text:
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x
7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x
7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f"...,
count=1024, fmt="%s: %s\n", args=0x00007ffedfd1b450) at
snprintf.c:195:2
Thanks for testing!
I could reproduce the situation and confirmed almost the same backtrace.
The cause seems that the previous patch didn't do cleanup when the
transactions were aborted. It leaded segmentation faults when
referencing ActiveQueryDesc-> after the transaction were aborted.
The attached patch added cleanups when transactions and subtransactions
are aborted.
BTW, the latest patch for pg_log_backtrace() added a new function for
deduplicating codes for pg_log_*()[1].
It seems better to use it for pg_log_query_plan() after the patch is
merged.
[1]
https://www.postgresql.org/message-id/flat/20211115194251.GP17618%40telsasoft.com#4e681d04c78867b2cce44b3cb1791bf5
duplicate code to a new function
CheckPostgresProcessId which can be used by pg_log_backtrace,
On top of the visibly use-after-pfree memory issue, the patch doesn't
apply
Thanks for letting me know!
As mentioned above, I updated the patch.
Regards,
--
Atsushi Torikoshi
NTT DATA CORPORATION
From bb0c50aecf07975873e9b2dfb380156df7c4aa94 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Mon, 24 Jan 2022 09:05:57 +0900
Subject: [PATCH v17] 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
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.
By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.
On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.
Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar, Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby
---
doc/src/sgml/func.sgml | 45 ++++++
src/backend/access/transam/xact.c | 13 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 139 ++++++++++++++++++-
src/backend/executor/execMain.c | 11 ++
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/storage/lmgr/lock.c | 9 +-
src/backend/tcop/postgres.c | 7 +
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/lock.h | 2 -
src/include/storage/procsignal.h | 1 +
src/include/tcop/pquery.h | 1 +
src/test/regress/expected/misc_functions.out | 53 +++++--
src/test/regress/sql/misc_functions.sql | 40 ++++--
17 files changed, 312 insertions(+), 26 deletions(-)
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 034fecc3a1..b714b804c7 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -25424,6 +25424,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_query_plan</primary>
+ </indexterm>
+ <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+ <returnvalue>boolean</returnvalue>
+ </para>
+ <para>
+ Requests to log the plan of the query currently running on the
+ backend with specified process ID along with the untruncated
+ query string.
+ 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"/>.
+ </para></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -25537,6 +25557,31 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: 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>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index c9516e03fa..9fb72df963 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -59,6 +59,7 @@
#include "storage/procarray.h"
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
+#include "tcop/pquery.h"
#include "utils/builtins.h"
#include "utils/catcache.h"
#include "utils/combocid.h"
@@ -2723,6 +2724,12 @@ AbortTransaction(void)
*/
PG_SETMASK(&UnBlockSig);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
@@ -5048,6 +5055,12 @@ AbortSubTransaction(void)
*/
PG_SETMASK(&UnBlockSig);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index fd1421788e..b90a8a0537 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -711,6 +711,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index b970997c34..abd840a0a8 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"
@@ -40,7 +43,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 +1596,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 +1606,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 &&
@@ -4925,3 +4930,133 @@ 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 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("query plan running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true),
+ errhidecontext(true));
+}
+
+/*
+ * pg_log_query_plan
+ * Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+ int pid = PG_GETARG_INT32(0);
+ PGPROC *proc;
+
+ proc = BackendPidGetProc(pid);
+
+ if (proc == NULL)
+ {
+ /*
+ * This is just a warning so a loop-through-resultset will not abort
+ * if one backend terminated on its own during the run.
+ */
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL server process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ if (SendProcSignal(pid, PROCSIG_LOG_CURRENT_PLAN, InvalidBackendId) < 0)
+ {
+ /* Again, just a warning to allow loops */
+ ereport(WARNING,
+ (errmsg("could not send signal to process %d: %m", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 549d9eb696..376a8d670b 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
@@ -440,6 +450,7 @@ standard_ExecutorFinish(QueryDesc *queryDesc)
MemoryContextSwitchTo(oldcontext);
+ ActiveQueryDesc = NULL;
estate->es_finished = true;
}
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index f1c8ff8f9e..3bd58cd4c2 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/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 5f5803f681..9beb456f78 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
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index fda2e9360e..95e26d1c0e 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 "common/pg_prng.h"
#include "executor/spi.h"
@@ -3367,6 +3368,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+
+ if (LogCurrentPlanPending)
+ ProcessLogCurrentPlanInterrupt();
}
@@ -4290,6 +4294,9 @@ PostgresMain(const char *dbname, const char *username)
/* 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/init/globals.c b/src/backend/utils/init/globals.c
index c26a1a73df..6b6f0b6d4f 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 0859dc81ca..bb555e5642 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8042,6 +8042,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '4550', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 666977fb1f..6887925a0d 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);
+extern void HandleLogCurrentPlanInterrupt(void);
+extern void ProcessLogCurrentPlanInterrupt(void);
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 02276d3edd..39d58d6873 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/lock.h b/src/include/storage/lock.h
index dc537e20f2..6a4150a3cf 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -561,9 +561,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 a121e65066..104f95949b 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/include/tcop/pquery.h b/src/include/tcop/pquery.h
index f9a6882ecb..d04de1f556 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);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index e2c77d0ac8..7af28cea2d 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -134,13 +134,15 @@ 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()
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -154,8 +156,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
t
(1 row)
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log;
+SELECT has_function_privilege('regress_log',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
has_function_privilege
------------------------
@@ -163,15 +165,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
--------------------------------
@@ -180,8 +182,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_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 1159f6b585..4a006ad911 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -31,38 +31,60 @@ 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.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log;
-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_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;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log;
--
-- Test some built-in SRFs
base-commit: 7b65862e2280eafca00566ee44af2c1bbb143e9d
--
2.27.0
