Re: RFC: Logging plan of the running query

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

Thanks for your review!

> On Wed, Jun 9, 2021 at 1:14 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>> Updated the patch.
>
> Thanks for the patch. Here are some comments on v3 patch:
>
> 1) We could just say "Requests to log query plan of the presently
> running query of a given backend along with an untruncated query
> string in the server logs."
> Instead of
> + They will be logged at <literal>LOG</literal> message level
> and
> + will appear in the server log based on the log
> + configuration set (See <xref
> linkend="runtime-config-logging"/>

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

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

Agreed.

> 3) Since most of the code looks same in pg_log_backend_memory_contexts
> and pg_log_current_plan, I think we can have a common function
> something like below:

Agreed. I'll do some refactoring.

> bool
> SendProcSignalForLogInfo(ProcSignalReason reason)
> {
> Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT || reason ==
> PROCSIG_LOG_CURRENT_PLAN);
>
> if (!superuser())
> {
> if (reason == PROCSIG_LOG_MEMORY_CONTEXT)
> errmsg("must be a superuser to log memory contexts")
> else if (reason == PROCSIG_LOG_CURRENT_PLAN)
> errmsg("must be a superuser to log plan of the running query")
> }
>
> if (SendProcSignal(pid, reason, proc->backendId) < 0)
> {
> }
> }
> Then we could just do:
> Datum
> pg_log_backend_memory_contexts(PG_FUNCTION_ARGS)
> {
> PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_MEMORY_CONTEXT));
> }
> Datum
> pg_log_current_plan(PG_FUNCTION_ARGS)
> {
> PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_CURRENT_PLAN));
> }
> We can have SendProcSignalForLogInfo function defined in procsignal.c
> and procsignal.h
>
> 4) I think we can have a sample function usage and how it returns true
> value, how the plan looks for a simple query(select 1 or some other
> simple/complex generic query or simply select
> pg_log_current_plan(pg_backend_pid());) in the documentation, much
> like pg_log_backend_memory_contexts.

+1.

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

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

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

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

Agreed.

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

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

+1.

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

+1.

>
> 9) We could just do:
> void
> ProcessLogCurrentPlanInterrupt(void)
> {
> ExplainState *es;
> LogCurrentPlanPending = false;
> if (!ActivePortal || !ActivePortal->queryDesc)
> errmsg("PID %d is not executing queries now");
> es = NewExplainState();
> ExplainQueryText();
> ExplainPrintPlan();
>
> 10) How about renaming the function pg_log_current_plan to
> pg_log_query_plan or pg_log_current_query_plan?

+1.

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

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

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION