public inbox for [email protected]  
help / color / mirror / Atom feed
Re: RFC: Logging plan of the running query
6+ messages / 5 participants
[nested] [flat]

* Re: RFC: Logging plan of the running query
@ 2022-02-02 07:49  Kyotaro Horiguchi <[email protected]>
  0 siblings, 1 reply; 6+ messages in thread

From: Kyotaro Horiguchi @ 2022-02-02 07:49 UTC (permalink / raw)
  To: [email protected]; +Cc: [email protected]; [email protected]

At Tue, 1 Feb 2022 23:11:03 +0900, Fujii Masao <[email protected]> wrote in 
> >> One thing that really bothers me about commit e2c79e14 is that
> >> LockPage() is called, not LockBuffer(). GIN had no LockPage() calls
> >> before that commit, and is now the only code in the entire system that
> >> calls LockPage()/ConditionalLockPage() (the hash am no longer uses
> >> page heavyweight locks following recent work there).
> > I agree to the discussion.  Can't we use other mechanism here to get
> > rid of the Lockpage()?
> 
> I have no good idea for that yet, but I agree it's better to get rid
> of page level lock.

It's my turn?

The page lock is used to hold-off simultaneous cleanups on the same
index.  ShareUpdateExclusive lock on the index relation works that
way. In that path it seems like we are always holding a RowExclusive
lock, so it seems to me we can use ShareUpdateExclusive for our
purpose.

There might be a false blocking case when another backend is holding a
conflicting lock on the index.  They are, Share, ShareRowExclusive,
Exclusive and AccessExclusive.  The last three cases don't seem worth
discussion.  I'm not sure about Share and Share Row cases. AFAICS
Share lock is taken on an index in ATExecReplicaIdentity, and there no
use of ShareRowExclusive lock on an index. It's no use discussing about
explicit locking.

So aren't we able to use ShareUpdateExclusive lock for that?

In the attached patch, ginInsertCleanup has an extra check for such
stronger locks not being held.  At least "make check" doesn't cause
the extra assertion to fire.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

diff --git a/src/backend/access/gin/ginfast.c b/src/backend/access/gin/ginfast.c
index 7409fdc165..1af9a69abb 100644
--- a/src/backend/access/gin/ginfast.c
+++ b/src/backend/access/gin/ginfast.c
@@ -791,20 +791,29 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 	bool		fsm_vac = false;
 	Size		workMemory;
 
-	/*
+	/*r
 	 * We would like to prevent concurrent cleanup process. For that we will
 	 * lock metapage in exclusive mode using LockPage() call. Nobody other
 	 * will use that lock for metapage, so we keep possibility of concurrent
 	 * insertion into pending list
 	 */
 
+	/*
+	 * we use ShareUpdateExclusive lock on this relation to hold-off concurrent
+	 * cleanup
+	 */
+	Assert(!CheckRelationLockedByMe(index, ShareUpdateExclusiveLock, false));
+
+	/* tentative debug-purpose assertion for stronger locks */
+	Assert(!CheckRelationLockedByMe(index, ShareLock, true));
+	
 	if (forceCleanup)
 	{
 		/*
 		 * We are called from [auto]vacuum/analyze or gin_clean_pending_list()
 		 * and we would like to wait concurrent cleanup to finish.
 		 */
-		LockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+		LockRelation(index, ShareUpdateExclusiveLock);
 		workMemory =
 			(IsAutoVacuumWorkerProcess() && autovacuum_work_mem != -1) ?
 			autovacuum_work_mem : maintenance_work_mem;
@@ -816,7 +825,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 		 * just exit in hope that concurrent process will clean up pending
 		 * list.
 		 */
-		if (!ConditionalLockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock))
+		if (!ConditionalLockRelation(index, ShareUpdateExclusiveLock))
 			return;
 		workMemory = work_mem;
 	}
@@ -830,7 +839,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 	{
 		/* Nothing to do */
 		UnlockReleaseBuffer(metabuffer);
-		UnlockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+		UnlockRelation(index, ShareUpdateExclusiveLock);
 		return;
 	}
 
@@ -1002,7 +1011,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 		page = BufferGetPage(buffer);
 	}
 
-	UnlockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+	UnlockRelation(index, ShareUpdateExclusiveLock);
 	ReleaseBuffer(metabuffer);
 
 	/*


Attachments:

  [text/plain] PoC_get_rid_of_PageLock_from_ginInsertCleanup.txt (2.1K, ../../[email protected]/2-PoC_get_rid_of_PageLock_from_ginInsertCleanup.txt)
  download | inline diff:
diff --git a/src/backend/access/gin/ginfast.c b/src/backend/access/gin/ginfast.c
index 7409fdc165..1af9a69abb 100644
--- a/src/backend/access/gin/ginfast.c
+++ b/src/backend/access/gin/ginfast.c
@@ -791,20 +791,29 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 	bool		fsm_vac = false;
 	Size		workMemory;
 
-	/*
+	/*r
 	 * We would like to prevent concurrent cleanup process. For that we will
 	 * lock metapage in exclusive mode using LockPage() call. Nobody other
 	 * will use that lock for metapage, so we keep possibility of concurrent
 	 * insertion into pending list
 	 */
 
+	/*
+	 * we use ShareUpdateExclusive lock on this relation to hold-off concurrent
+	 * cleanup
+	 */
+	Assert(!CheckRelationLockedByMe(index, ShareUpdateExclusiveLock, false));
+
+	/* tentative debug-purpose assertion for stronger locks */
+	Assert(!CheckRelationLockedByMe(index, ShareLock, true));
+	
 	if (forceCleanup)
 	{
 		/*
 		 * We are called from [auto]vacuum/analyze or gin_clean_pending_list()
 		 * and we would like to wait concurrent cleanup to finish.
 		 */
-		LockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+		LockRelation(index, ShareUpdateExclusiveLock);
 		workMemory =
 			(IsAutoVacuumWorkerProcess() && autovacuum_work_mem != -1) ?
 			autovacuum_work_mem : maintenance_work_mem;
@@ -816,7 +825,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 		 * just exit in hope that concurrent process will clean up pending
 		 * list.
 		 */
-		if (!ConditionalLockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock))
+		if (!ConditionalLockRelation(index, ShareUpdateExclusiveLock))
 			return;
 		workMemory = work_mem;
 	}
@@ -830,7 +839,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 	{
 		/* Nothing to do */
 		UnlockReleaseBuffer(metabuffer);
-		UnlockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+		UnlockRelation(index, ShareUpdateExclusiveLock);
 		return;
 	}
 
@@ -1002,7 +1011,7 @@ ginInsertCleanup(GinState *ginstate, bool full_clean,
 		page = BufferGetPage(buffer);
 	}
 
-	UnlockPage(index, GIN_METAPAGE_BLKNO, ExclusiveLock);
+	UnlockRelation(index, ShareUpdateExclusiveLock);
 	ReleaseBuffer(metabuffer);
 
 	/*


^ permalink  raw  reply  [nested|flat] 6+ messages in thread

* Re: RFC: Logging plan of the running query
@ 2022-02-02 08:04  Kyotaro Horiguchi <[email protected]>
  parent: Kyotaro Horiguchi <[email protected]>
  0 siblings, 1 reply; 6+ messages in thread

From: Kyotaro Horiguchi @ 2022-02-02 08:04 UTC (permalink / raw)
  To: [email protected]; +Cc: [email protected]; [email protected]

At Wed, 02 Feb 2022 16:49:57 +0900 (JST), Kyotaro Horiguchi <[email protected]> wrote in 
> So aren't we able to use ShareUpdateExclusive lock for that?
> 
> In the attached patch, ginInsertCleanup has an extra check for such
> stronger locks not being held.  At least "make check" doesn't cause
> the extra assertion to fire.

Actually, the discussion is a bit dubious. What we need really to
check is wheter such locks are not held on an index *elsewhere*.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center






^ permalink  raw  reply  [nested|flat] 6+ messages in thread

* Re: RFC: Logging plan of the running query
@ 2022-02-02 12:59  torikoshia <[email protected]>
  parent: Kyotaro Horiguchi <[email protected]>
  0 siblings, 2 replies; 6+ messages in thread

From: torikoshia @ 2022-02-02 12:59 UTC (permalink / raw)
  To: Kyotaro Horiguchi <[email protected]>; [email protected]; +Cc: [email protected]

2022-02-01 01:51, Fujii Masao wrote:
Thanks for reviewing and suggestions!

>>    +        Note that there is the case where the request to log a 
>> query
>>    +        plan is skipped even while the target backend is running a
>>    +        query due to lock conflict avoidance.
>>    +        If this happens, users can just retry pg_log_query_plan().
> 
> This may cause users to misunderstand that pg_log_query_plan() fails
> while the target backend is holding *any* locks? Isn't it better to
> mention "page-level locks", instead? So how about the following?
> 
> --------------------------
> Note that the request to log the query plan will be ignored if it's
> received during a short period while the target backend is holding a
> page-level lock.
> --------------------------

Agreed.

>>> +            ereport(LOG_SERVER_ONLY,
>>> +                errmsg("backend with PID %d is holding a page lock. 
>>> Try again",
>>> +                    MyProcPid));
>>> 
>>> It seems more proper to output this message in DETAIL or HINT,
>>> instead. So how about something like the following messages?
>>> 
>>> LOG: could not log the query plan
>>> DETAIL: query plan cannot be logged while page level lock is being 
>>> held
>>> HINT: Try pg_log_query_plan() after a few ....
>> 
>> Agreed.
>> I felt the HINT message 'after a few ...' is difficult to describe, 
>> and wrote as below.
>> 
>> | HINT: Retrying pg_log_query_plan() might succeed since the lock 
>> duration of page level locks are usually short
>> 
>> How do you think?
> 
> Or we don't need HINT message?

Removed the HINT message.

> +                             errmsg("could not log the query plan"),
> +                             errdetail("query plan cannot be logged 
> while page level lock is
> being held"),
> 
> In detail message, the first word of sentences should be capitalized.
> How about "Cannot log the query plan while holding page-level lock.",
> instead?

Agreed.

> Thanks for updating the patch! Here are some review comments.
> 
> +      <row>
> +       <entry role="func_table_entry"><para role="func_signature">
> +        <indexterm>
> +         <primary>pg_log_query_plan</primary>
> +        </indexterm>
> 
> This entry is placed before one for pg_log_backend_memory_contexts().
> But it should be *after* that since those entries seem to be placed in
> alphabetical order in the table?

Modified it.

> +        Requests to log the plan of the query currently running on the
> +        backend with specified process ID along with the untruncated
> +        query string.
> 
> Other descriptions about logging of query string seem not to mention
> something like "untruncated query string". For example, auto_explain,
> log_statement, etc. Why do we need to mention "along with the
> untruncated query string" specially for pg_log_query_plan()?

Modified it as below:

              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
     +        backend with specified process ID.
     +        It will be logged at <literal>LOG</literal> message level 
and

> +    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.
> 
> Now the plan of even nested statement can be logged. So this
> description needs to be updated?

Modified it as below:

     -    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.
     +    Note that when the statements are executed inside a function, 
only the
     +    plan of the most deeply nested query is logged.

> @@ -440,6 +450,7 @@ standard_ExecutorFinish(QueryDesc *queryDesc)
>       MemoryContextSwitchTo(oldcontext);
>  +    ActiveQueryDesc = NULL;
> 
> ActiveQueryDesc seems unnecessary. Why does ActiveQueryDesc need to be
> reset to NULL in standard_ExecutorFinish()?

ActiveQueryDesc should not be reset in standard_ExecutorFinish().
Removed it.

> Currently even during ProcessLogQueryPlanInterrupt(),
> pg_log_query_plan() can be call and another
> ProcessLogQueryPlanInterrupt() can be executed. So repeatable
> re-entrances to ProcessLogQueryPlanInterrupt() could cause "stack
> depth limit exceeded" error. To avoid this, shouldn't we make
> ProcessLogQueryPlanInterrupt() do nothing and return immediately, if
> it's called during another ProcessLogQueryPlanInterrupt()?
> 
> pg_log_backend_memory_contexts() also might have the same issue.

As you pointed out offlist, the issue could occur even when both 
pg_log_backend_memory_contexts and pg_log_query_plan are called and it 
may be better to make another patch.


You also pointed out offlist that it would be necessary to call 
LockErrorCleanup() if ProcessLogQueryPlanInterrupt() can incur ERROR.
AFAICS it can call ereport(ERROR), i.e., palloc0() in NewExplainState(), 
so I added PG_TRY/CATCH and make it call LockErrorCleanup() when ERROR 
occurs.



On 2022-02-01 17:27, Kyotaro Horiguchi wrote:

Thanks for reviewing Horiguchi-san!

> By the way, I'm anxious about the following part and I'd like to
> remove it.

I also think it would be nice if it's possible.
> 
> +        * Ensure no page lock is held on this process.
> 
> It seems to me what is wrong is ginInsertCleanup(), not this feature.

> Actually, the discussion is a bit dubious. What we need really to
check is wheter such locks are not held on an index *elsewhere*.

Since I'm not sure how long it will take to discuss this point, the 
attached patch is based on the current HEAD at this time.
I also think it may be better to discuss it on another thread.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Attachments:

  [text/x-diff] v19-0001-log-running-query-plan.patch (24.9K, ../../[email protected]/2-v19-0001-log-running-query-plan.patch)
  download | inline diff:
From 048a9afb9922acc8f0ccea67710e1a510f83be49 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi<[email protected]>
Date: Web, 2 Feb 2022 21:20:50 +0900
Subject: [PATCH v19] Add function to log the plan of the query
 currently running on the backend.

Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.

By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.

On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.

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

---
 doc/src/sgml/func.sgml                       |  49 +++++++
 src/backend/access/transam/xact.c            |  13 ++
 src/backend/catalog/system_functions.sql     |   2 +
 src/backend/commands/explain.c               | 140 ++++++++++++++++++-
 src/backend/executor/execMain.c              |  10 ++
 src/backend/storage/ipc/procsignal.c         |   4 +
 src/backend/storage/lmgr/lock.c              |   9 +-
 src/backend/tcop/postgres.c                  |  13 ++
 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 |  54 +++++--
 src/test/regress/sql/misc_functions.sql      |  41 ++++--
 17 files changed, 322 insertions(+), 28 deletions(-)

diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 8754f2f89b..1bbad70ec8 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -25461,6 +25461,30 @@ SELECT collation for ('foo' COLLATE "de_DE");
        </para></entry>
       </row>
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_query_plan</primary>
+        </indexterm>
+        <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the plan of the query currently running on the
+        backend with specified process ID.
+        It will be logged at <literal>LOG</literal> message level and
+        will appear in the server log based on the log
+        configuration set (See <xref linkend="runtime-config-logging"/>
+        for more information), but will not be sent to the client
+        regardless of <xref linkend="guc-client-min-messages"/>.
+        </para>
+        <para>
+        Note that the request to log the query plan will be ignored
+        if it's received during a short period while the target
+        backend is holding a page-level lock.
+        </para></entry>
+      </row>
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>
@@ -25574,6 +25598,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:  query plan running on backend with PID 201116 is:
+        Query Text: SELECT * FROM pgbench_accounts;
+        Seq Scan on public.pgbench_accounts  (cost=0.00..52787.00 rows=2000000 width=97)
+          Output: aid, bid, abalance, filler
+        Settings: work_mem = '1MB'
+</screen>
+    Note that when the statements are executed inside a function, 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..f875f6ffaf 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,134 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+/*
+ * HandleLogQueryPlanInterrupt
+ *		Handle receipt of an interrupt indicating logging the plan of
+ *		the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+	InterruptPending = true;
+	LogQueryPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * ProcessLogQueryPlanInterrupt
+ * 		Perform logging the plan of the currently running query on this
+ * 		backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange to call
+ * this function if we see LogQueryPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+	ExplainState *es;
+	HASH_SEQ_STATUS status;
+	LOCALLOCK  *locallock;
+	LogQueryPlanPending = false;
+
+	if (ActiveQueryDesc == NULL)
+	{
+		ereport(LOG_SERVER_ONLY,
+				errmsg("backend with PID %d is not running a query",
+					MyProcPid),
+				errhidestmt(true),
+				errhidecontext(true));
+		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("could not log the query plan"),
+				errdetail("Cannot log the query plan while holding page-level lock."));
+			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);
+	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 backend process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+	{
+		/* Again, just a warning to allow loops */
+		ereport(WARNING,
+				(errmsg("could not send signal to process %d: %m", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 549d9eb696..fe9b6a9229 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/procsignal.c b/src/backend/storage/ipc/procsignal.c
index f1c8ff8f9e..82691193b1 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_QUERY_PLAN))
+		HandleLogQueryPlanInterrupt();
+
 	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..40781ae1de 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,18 @@ ProcessInterrupts(void)
 
 	if (LogMemoryContextPending)
 		ProcessLogMemoryContextInterrupt();
+
+	if (LogQueryPlanPending)
+		PG_TRY();
+		{
+			ProcessLogQueryPlanInterrupt();
+		}
+		PG_CATCH();
+		{
+			LockErrorCleanup();
+			PG_RE_THROW();
+		}
+		PG_END_TRY();
 }
 
 
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index c26a1a73df..116cd69699 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 LogQueryPlanPending = false;
 volatile uint32 InterruptHoldoffCount = 0;
 volatile uint32 QueryCancelHoldoffCount = 0;
 volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 7024dbe10a..bb4e12ef62 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8047,6 +8047,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..21c749f026 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 HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
 #endif							/* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 02276d3edd..e8427b9655 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 LogQueryPlanPending;
 
 extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
 extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 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..00fe169035 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ typedef enum
 	PROCSIG_WALSND_INIT_STOPPING,	/* ask walsenders to prepare for shutdown  */
 	PROCSIG_BARRIER,			/* global barrier interrupt  */
 	PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+	PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current query */
 
 	/* 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 6cf39c6bd2..5c7cedfc3b 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -268,14 +268,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
  ../jkl/mno
 (1 row)
 
+-- Test logging functions
 --
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail, and that the
 -- permissions are set properly.
 --
+-- pg_log_backend_memory_contexts()
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
  pg_log_backend_memory_contexts 
 --------------------------------
@@ -289,8 +290,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 
 ------------------------
@@ -298,15 +299,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 
 --------------------------------
@@ -315,8 +316,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 cfaba456e1..d068a2fb5d 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -57,39 +57,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
 SELECT test_canonicalize_path('./abc/././def/.');
 SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
 
+-- Test logging functions
 --
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
 -- Furthermore, their contents can vary depending on the timing. However,
 -- we can at least verify that the code doesn't fail, and that the
 -- permissions are set properly.
 --
 
+-- pg_log_backend_memory_contexts()
+
 SELECT pg_log_backend_memory_contexts(pg_backend_pid());
 
 SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
   WHERE backend_type = 'checkpointer';
 
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log;
 
-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: 87669de72c2249e6aec84b8c27fdc3ffb7284e13
-- 
2.27.0



^ permalink  raw  reply  [nested|flat] 6+ messages in thread

* Re: RFC: Logging plan of the running query
@ 2022-02-03 08:09  Robert Treat <[email protected]>
  parent: torikoshia <[email protected]>
  1 sibling, 0 replies; 6+ messages in thread

From: Robert Treat @ 2022-02-03 08:09 UTC (permalink / raw)
  To: torikoshia <[email protected]>; +Cc: Kyotaro Horiguchi <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>

On Wed, Feb 2, 2022 at 7:59 AM torikoshia <[email protected]> wrote:
>
> 2022-02-01 01:51, Fujii Masao wrote:
<snip>
> > +    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.
> >
> > Now the plan of even nested statement can be logged. So this
> > description needs to be updated?
>
> Modified it as below:
>
>      -    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.
>      +    Note that when the statements are executed inside a function,
> only the
>      +    plan of the most deeply nested query is logged.
>

Minor nit, but I think the "the" is superfluous.. ie.

"Note that when statements are executed inside a function,
only the plan of the most deeply nested query is logged"

<snip>
> On 2022-02-01 17:27, Kyotaro Horiguchi wrote:
>
> Thanks for reviewing Horiguchi-san!
>
> > By the way, I'm anxious about the following part and I'd like to
> > remove it.
>
> I also think it would be nice if it's possible.
> >
> > +        * Ensure no page lock is held on this process.
> >
> > It seems to me what is wrong is ginInsertCleanup(), not this feature.
>
> > Actually, the discussion is a bit dubious. What we need really to
> check is wheter such locks are not held on an index *elsewhere*.
>
> Since I'm not sure how long it will take to discuss this point, the
> attached patch is based on the current HEAD at this time.
> I also think it may be better to discuss it on another thread.
>

While I agree on the above points, IMHO I don't believe it should be a
show-stopper for adding this functionality to v15, but we have a few
more commitments before we get to that point.


Robert Treat
https://xzilla.net






^ permalink  raw  reply  [nested|flat] 6+ messages in thread

* Re: RFC: Logging plan of the running query
@ 2022-02-07 16:13  Fujii Masao <[email protected]>
  parent: torikoshia <[email protected]>
  1 sibling, 0 replies; 6+ messages in thread

From: Fujii Masao @ 2022-02-07 16:13 UTC (permalink / raw)
  To: torikoshia <[email protected]>; Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]



On 2022/02/02 21:59, torikoshia wrote:
>> This may cause users to misunderstand that pg_log_query_plan() fails
>> while the target backend is holding *any* locks? Isn't it better to
>> mention "page-level locks", instead? So how about the following?
>>
>> --------------------------
>> Note that the request to log the query plan will be ignored if it's
>> received during a short period while the target backend is holding a
>> page-level lock.
>> --------------------------
> 
> Agreed.

On second thought, this note is confusing rather than helpful? Because the users don't know when and what operation needs page-level lock. So now I'm thinking it's better to remove this note.


> As you pointed out offlist, the issue could occur even when both pg_log_backend_memory_contexts and pg_log_query_plan are called and it may be better to make another patch.

OK.


> You also pointed out offlist that it would be necessary to call LockErrorCleanup() if ProcessLogQueryPlanInterrupt() can incur ERROR.
> AFAICS it can call ereport(ERROR), i.e., palloc0() in NewExplainState(), so I added PG_TRY/CATCH and make it call LockErrorCleanup() when ERROR occurs.

As we discussed off-list, this treatment might not be necessary. Because when ERROR or FATAL error happens, AbortTransaction() is called and LockErrorCleanup() is also called inside there.


> Since I'm not sure how long it will take to discuss this point, the attached patch is based on the current HEAD at this time.

Thanks for updating the patch!

@@ -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;

AbortSubTransaction() should reset ActiveQueryDesc to save_ActiveQueryDesc that ExecutorRun() set, instead of NULL? Otherwise ActiveQueryDesc of top-level statement will be unavailable after subtransaction is aborted in the nested statements.

For example, no plan is logged while the following "select pg_sleep(test())" is running, because the exception inside test() function aborts the subtransaction and resets ActiveQueryDesc to NULL.

create or replace function test () returns int as $$
begin
     perform 1/0;
exception when others then
     return 30;
end;
$$ language plpgsql;

select pg_sleep(test());


-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log;

Isn't this name too generic? How about regress_log_function, for example?

Regards,

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






^ permalink  raw  reply  [nested|flat] 6+ messages in thread

* [PATCH 3/3] Distinguish properly when database-specific transaction list should be used.
@ 2026-05-06 07:38  Antonin Houska <[email protected]>
  0 siblings, 0 replies; 6+ messages in thread

From: Antonin Houska @ 2026-05-06 07:38 UTC (permalink / raw)

Currently, decoding session that relies on database-specific xl_running_xacts
WAL records can also use some information of cluster-wide records and vice
versa. Although this approach might reduce the total number of
xl_running_xacts records, it's simply not correct.

SnapBuildProcessRunningXacts() now decides at the very beginning whether
particular record can be used or not.
---
 src/backend/replication/logical/snapbuild.c | 55 +++++++++++++--------
 1 file changed, 34 insertions(+), 21 deletions(-)

diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index c8309b96ed4..b9661b7d70a 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1157,6 +1157,39 @@ SnapBuildProcessRunningXacts(SnapBuild *builder, XLogRecPtr lsn, xl_running_xact
 	ReorderBufferTXN *txn;
 	TransactionId xmin;
 
+	/*
+	 * Each decoding session should use either cluster-wide snapshots or
+	 * database-specific ones, but not both. Since the latter can have more
+	 * recent value of oldestRunningXid, builder->xmin could go backwards if
+	 * it was followed by cluster-wide snapshot - see the ->xmin adjustment
+	 * below.
+	 */
+	if (!db_specific && OidIsValid(running->dbid))
+		return;
+
+	if (db_specific)
+	{
+		/*
+		 * Make sure that we have the snapshots needed for startup, as well as
+		 * those for regular cleanup: each time the cluster-wide snapshot is
+		 * created (typically on slot creation or by checkpointer), the
+		 * database-specific snapshot is requested here if the current session
+		 * needs it.
+		 */
+		if (!OidIsValid(running->dbid))
+		{
+			LogStandbySnapshot(MyDatabaseId);
+
+			return;
+		}
+		/*
+		 * Snapshots issued for other databases do not contain the information
+		 * about transactions in our database.
+		 */
+		else if (running->dbid != MyDatabaseId)
+			return;
+	}
+
 	/*
 	 * If we're not consistent yet, inspect the record to see whether it
 	 * allows to get closer to being consistent. If we are consistent, dump
@@ -1171,17 +1204,7 @@ SnapBuildProcessRunningXacts(SnapBuild *builder, XLogRecPtr lsn, xl_running_xact
 		 */
 		if (db_specific)
 		{
-			/*
-			 * If we must only keep track of transactions running in the
-			 * current database, we need transaction info from exactly that
-			 * database.
-			 */
-			if (running->dbid != MyDatabaseId)
-			{
-				LogStandbySnapshot(MyDatabaseId);
-
-				return;
-			}
+			Assert(running->dbid == MyDatabaseId);
 
 			/*
 			 * We'd better be able to check during scan if the plugin does not
@@ -1198,16 +1221,6 @@ SnapBuildProcessRunningXacts(SnapBuild *builder, XLogRecPtr lsn, xl_running_xact
 	else
 		SnapBuildSerialize(builder, lsn);
 
-	/*
-	 * Database specific transaction info may exist to reach CONSISTENT state
-	 * faster, however the code below makes no use of it. Moreover, such
-	 * record might cause problems because the following normal (cluster-wide)
-	 * record can have lower value of oldestRunningXid. In that case, let's
-	 * wait with the cleanup for the next regular cluster-wide record.
-	 */
-	if (OidIsValid(running->dbid))
-		return;
-
 	/*
 	 * Update range of interesting xids based on the running xacts
 	 * information. We don't increase ->xmax using it, because once we are in
-- 
2.47.3


--tbdehtstrqwksfdh--





^ permalink  raw  reply  [nested|flat] 6+ messages in thread


end of thread, other threads:[~2026-05-06 07:38 UTC | newest]

Thread overview: 6+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-02-02 07:49 Re: RFC: Logging plan of the running query Kyotaro Horiguchi <[email protected]>
2022-02-02 08:04 ` Kyotaro Horiguchi <[email protected]>
2022-02-02 12:59   ` torikoshia <[email protected]>
2022-02-03 08:09     ` Robert Treat <[email protected]>
2022-02-07 16:13     ` Fujii Masao <[email protected]>
2026-05-06 07:38 [PATCH 3/3] Distinguish properly when database-specific transaction list should be used. Antonin Houska <[email protected]>

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox