Re: RFC: Logging plan of the running query - Mailing list pgsql-hackers

On 2022-02-03 17:09, Robert Treat wrote:
> On Wed, Feb 2, 2022 at 7:59 AM torikoshia <torikoshia@oss.nttdata.com> 
> 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"

Thanks! Modified it.


On 2022-02-08 01:13, Fujii Masao wrote:
Thanks for the comments!

> 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.

Removed it.
> 
> 
>> 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.

Agreed.

>> 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());

Agreed.

BTW, since the above example results in calling ExecutorRun() only once, 
the output didn't differ even after ActiveQueryDesc is reset to 
save_ActiveQueryDesc.

The below definition of test() worked as expected.

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

> 
> 
> -CREATE ROLE regress_log_memory;
> +CREATE ROLE regress_log;
> 
> Isn't this name too generic? How about regress_log_function, for 
> example?

Agreed.


On 2022-02-08 17:18, Kyotaro Horiguchi wrote:
> At Tue, 8 Feb 2022 01:13:44 +0900, Fujii Masao
> <masao.fujii@oss.nttdata.com> wrote in
>> 
>> 
>> 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.
> 
> *I* agree to removing the note. And the following error message looks
> as mysterious as the note is, and the DETAIL doesn't help..
> 
>             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);
> 
> We should tell the command can be retried soon, like this?
> 
> "LOG:  ignored request for logging query plan due to lock confilcts"
> "HINT:  You can try again in a moment."

Thanks, it seems better.

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION