Re: RFC: Logging plan of the running query

On 2022-02-03 17:09, Robert Treat wrote:
> On Wed, Feb 2, 2022 at 7:59 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)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(dot)fujii(at)oss(dot)nttdata(dot)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