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.fujii@oss.nttdata.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@oss.nttdata.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.fujii@oss.nttdata.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