Re: RFC: Logging plan of the running query

On 2022-01-27 20:18, Fujii Masao wrote:
> Here are another review comments:

Thanks for reviewing!

> +LOG:  plan of the query running on backend with PID 17793 is:
> 
> This seems not the same as what actually logged.

Modified.

> +        ereport(WARNING,
> +                (errmsg("PID %d is not a PostgreSQL server process", pid)));
> 
> Like commit 7fa945b857 changed, this warning message should be "PID %d
> is not a PostgreSQL backend process"?

Modified.

> +    if (SendProcSignal(pid, PROCSIG_LOG_CURRENT_PLAN, InvalidBackendId) < 
> 0)
> 
> proc->backendId should be specified instead of InvalidBackendId, to
> speed up the processing in SendProcSignal()?

Agreed. Modified.

> +    PROCSIG_LOG_CURRENT_PLAN, /* ask backend to log plan of the current 
> query */
> +volatile sig_atomic_t LogCurrentPlanPending = false;
> +extern void HandleLogCurrentPlanInterrupt(void);
> +extern void ProcessLogCurrentPlanInterrupt(void);
> 
> Isn't it better to use the names that are more consistent with the
> function name, i.e., pg_log_query_plan? For example,
> PROCSIG_LOG_QUERY_PLAN instead of PROCSIG_LOG_CURRENT_PLAN?

Agreed.
I removed 'current' from the variable and function names and used 
'query' instead.

> +        ereport(LOG_SERVER_ONLY,
> +                errmsg("backend with PID %d is not running a query",
> +                    MyProcPid));
> 
> errhidestmt(true) and errhidecontext(true) need to be added, don't
> they? Otherwise, for example, if pg_log_query_plan() is executed after
> debug_query_string is set but before ActiveQueryDesc is set, STATEMENT
> message would be output even though the message saying "not running a
> query" is output. Which seems confusing.

Agreed. Added errhidestmt(true) and errhidecontext(true).

> +    hash_seq_init(&status, GetLockMethodLocalHash());
> +    while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL)
> +    {
> +        if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE)
> 
> Why did you use the search for local lock hash instead of
> IsPageLockHeld flag variable, to check whether a page lock is held or
> not? Because there is the corner case where the interrupt is processed
> after the local lock is registered into the hash but before
> IsPageLockHeld is enabled?

As far as I read CheckAndSetLockHeld(), IsPageLockHeld can be used only 
when USE_ASSERT_CHECKING is enabled.
Since removing USE_ASSERT_CHECKING from CheckAndSetLockHeld() would give 
performance impact on every granting/removing local lock, I used the 
search for local local hash.

> There is the case where the request to log a query plan is skipped
> even while the target backend is running a query. If this happens,
> users can just retry pg_log_query_plan(). These things should be
> documented?

Agreed.
Added following:

   +        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().

|

> +            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?

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION