Re: RFC: Logging plan of the running query

On 2021-07-28 20:44, torikoshia wrote:
> On 2021-07-28 03:45, Pavel Stehule wrote:
>> út 27. 7. 2021 v 20:34 odesílatel Fujii Masao
>> <masao(dot)fujii(at)oss(dot)nttdata(dot)com> napsal:
>>
>>> On 2021/07/09 14:05, torikoshia wrote:
>>>> On 2021-07-02 23:21, Bharath Rupireddy wrote:
>>>>> On Tue, Jun 22, 2021 at 8:00 AM torikoshia
>>> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>>>>>> Updated the patch.
>>>>>
>>>>> Thanks for the patch. Here are some comments on the v4 patch:
>>>>
>>>> Thanks for your comments and suggestions!
>>>> I agree with you and updated the patch.
>>>>
>>>> On Thu, Jul 1, 2021 at 3:34 PM Fujii Masao
>>> <masao(dot)fujii(at)oss(dot)nttdata(dot)com> wrote:
>>>>
>>>>> DO $$
>>>>> BEGIN
>>>>> PERFORM pg_sleep(100);
>>>>> END$$;
>>>>>
>>>>> When I called pg_log_current_query_plan() to send the signal to
>>>>> the backend executing the above query, I got the following log
>>> message.
>>>>> I think that this is not expected message. I guess this issue
>>> happened
>>>>> because the information about query text and plan is retrieved
>>>>> from ActivePortal. If this understanding is right, ISTM that we
>>> should
>>>>> implement new mechanism so that we can retrieve those information
>>>>> even while nested query is being executed.
>>>>
>>>> I'm now working on this comment.
>>>
>>> One idea is to define new global pointer, e.g., "QueryDesc
>>> *ActiveQueryDesc;".
>>> This global pointer is set to queryDesc in ExecutorRun()
>>> (also maybe ExecutorStart()). And this is reset to NULL in
>>> ExecutorEnd() and
>>> when an error is thrown. Then ProcessLogCurrentPlanInterrupt() can
>>> get the plan of the currently running query from that global pointer
>>> instead of ActivePortal, and log it. Thought?
>>
>> It cannot work - there can be a lot of nested queries, and at the end
>> you cannot reset to null, but you should return back pointer to outer
>> query.
>
> Thanks for your comment!
>
> I'm wondering if we can avoid this problem by saving one outer level
> QueryDesc in addition to the current one.
> I'm going to try it.

I have updated the patch in this way.

In this patch, getting the plan to the DO statement is as follows.

---------------------------------
(pid:76608)=# DO $$
BEGIN
PERFORM pg_sleep(15);
END$$;

(pid:74482)=# SELECT pg_log_current_query_plan(76608);

LOG: 00000: plan of the query running on backend with PID 76608 is:
Query Text: SELECT pg_sleep(15)
Result (cost=0.00..0.01 rows=1 width=4)
Output: pg_sleep('15'::double precision)

-- pid:76608 finished DO statement:
(pid:74482)=# SELECT pg_log_current_query_plan(76608);

LOG: 00000: backend with PID 76608 is not running a query
---------------------------------

Any thoughts?

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION