Re: RFC: Logging plan of the running query

Hi!

I'm here to answer your questions about contrib/pg_query_state.
>> I only took a quick look at pg_query_state, I have some questions.

>> pg_query_state seems using shm_mq to expose the plan information, but
>> there was a discussion that this kind of architecture would be tricky
>> to do properly [1].
>> Does pg_query_state handle difficulties listed on the discussion?
> [1]
> /message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

I doubt that it was the right link.
But on the topic I will say that extension really use shared memory,
interaction is implemented by sending / receiving messages. This
architecture provides the required reliability and convenience.

>> It seems the caller of the pg_query_state() has to wait until the
>> target process pushes the plan information into shared memory, can it
>> lead to deadlock situations?
>> I came up with this question because when trying to make a view for
>> memory contexts of other backends, we encountered deadlock situations.
>> After all, we gave up view design and adopted sending signal and
>> logging.
>
> Discussion at the following URL.
> /message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

Before extracting information about side process we check its state.
Information will only be retrieved for a process willing to provide it.
Otherwise, we will receive an error message about impossibility of
getting query execution statistics + process status. Also checking fact
of extracting your own status exists. This is even verified in tests.

Thanks for your attention.
Just in case, I am ready to discuss this topic in more detail.

About overhead:
> I haven't measured it yet, but I believe that the overhead for backends
> which are not called pg_log_current_plan() would be slight since the
> patch just adds the logic for saving QueryDesc on ExecutorRun().
> The overhead for backends which is called pg_log_current_plan() might
> not slight, but since the target process are assumed dealing with
> long-running query and the user want to know its plan, its overhead
> would be worth the cost.
I think it would be useful for us to have couple of examples with a
different number of rows compared to using without this functionality.

Hope this helps.

--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

This patch no longer applies on top of HEAD, please submit a rebased version.

--
Daniel Gustafsson https://vmware.com/

On 2021-11-02 20:32, Ekaterina Sokolova wrote:
Thanks for your response!

> Hi!
>
> I'm here to answer your questions about contrib/pg_query_state.
>>> I only took a quick look at pg_query_state, I have some questions.
>
>>> pg_query_state seems using shm_mq to expose the plan information, but
>>> there was a discussion that this kind of architecture would be tricky
>>> to do properly [1].
>>> Does pg_query_state handle difficulties listed on the discussion?
>> [1]
>> /message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com
>
> I doubt that it was the right link.

Sorry for make you confused, here is the link.

/message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com

> But on the topic I will say that extension really use shared memory,
> interaction is implemented by sending / receiving messages. This
> architecture provides the required reliability and convenience.

As described in the link, using shared memory for this kind of work
would need DSM and It'd be also necessary to exchange information
between requestor and responder.

For example, when I looked at a little bit of pg_query_state code, it
looks like the size of the queue is fixed at QUEUE_SIZE, and I wonder
how plans that exceed QUEUE_SIZE are handled.

>>> It seems the caller of the pg_query_state() has to wait until the
>>> target process pushes the plan information into shared memory, can it
>>> lead to deadlock situations?
>>> I came up with this question because when trying to make a view for
>>> memory contexts of other backends, we encountered deadlock
>>> situations.
>>> After all, we gave up view design and adopted sending signal and
>>> logging.
>>
>> Discussion at the following URL.
>> /message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com
>
> Before extracting information about side process we check its state.
> Information will only be retrieved for a process willing to provide
> it. Otherwise, we will receive an error message about impossibility of
> getting query execution statistics + process status. Also checking
> fact of extracting your own status exists. This is even verified in
> tests.
>
> Thanks for your attention.
> Just in case, I am ready to discuss this topic in more detail.

I imagined the following procedure.
Does it cause dead lock in pg_query_state?

- session1
BEGIN; TRUNCATE t;

- session2
BEGIN; TRUNCATE t; -- wait

- session1
SELECT * FROM pg_query_state(<pid of session>); -- wait and dead locked?

> About overhead:
>> I haven't measured it yet, but I believe that the overhead for
>> backends
>> which are not called pg_log_current_plan() would be slight since the
>> patch just adds the logic for saving QueryDesc on ExecutorRun().
>> The overhead for backends which is called pg_log_current_plan() might
>> not slight, but since the target process are assumed dealing with
>> long-running query and the user want to know its plan, its overhead
>> would be worth the cost.
> I think it would be useful for us to have couple of examples with a
> different number of rows compared to using without this functionality.

Do you have any expectaion that the number of rows would affect the
performance of this functionality?
This patch adds some codes to ExecutorRun(), but I thought the number of
rows would not give impact on the performance.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Hi!

You forgot my last fix to build correctly on Mac. I have added it.

About our discussion of pg_query_state:

torikoshia писал 2021-11-04 15:49:
>> I doubt that it was the right link.
> Sorry for make you confused, here is the link.
> /message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com

Thank you. I'll see it soon.

> I imagined the following procedure.
> Does it cause dead lock in pg_query_state?
>
> - session1
> BEGIN; TRUNCATE t;
>
> - session2
> BEGIN; TRUNCATE t; -- wait
>
> - session1
> SELECT * FROM pg_query_state(<pid of session>); -- wait and dead
> locked?

As I know, pg_query_state use non-blocking read and write. I have wrote
few tests trying to deadlock it (on 14 version), but all finished
correctly.

Have a nice day. Please feel free to contact me if you need any further
information.

--
Ekaterina Sokolova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On 2021-11-17 22:44, Ekaterina Sokolova wrote:
> Hi!
>
> You forgot my last fix to build correctly on Mac. I have added it.

Thanks for the notification!
Since the patch could not be applied to the HEAD anymore, I also updated
it.

>
> About our discussion of pg_query_state:
>
> torikoshia писал 2021-11-04 15:49:
>>> I doubt that it was the right link.
>> Sorry for make you confused, here is the link.
>> /message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com
>
> Thank you. I'll see it soon.
>
>> I imagined the following procedure.
>> Does it cause dead lock in pg_query_state?
>>
>> - session1
>> BEGIN; TRUNCATE t;
>>
>> - session2
>> BEGIN; TRUNCATE t; -- wait
>>
>> - session1
>> SELECT * FROM pg_query_state(<pid of session>); -- wait and dead
>> locked?
>
> As I know, pg_query_state use non-blocking read and write. I have
> wrote few tests trying to deadlock it (on 14 version), but all
> finished correctly.
>
> Have a nice day. Please feel free to contact me if you need any
> further information.

Thanks for your information and help!

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-11-26 12:39, torikoshia wrote:
> Since the patch could not be applied to the HEAD anymore, I also
> updated it.

Updated the patch for fixing compiler warning about the format on
windows.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2022-01-07 14:30, torikoshia wrote:

> Updated the patch for fixing compiler warning about the format on
> windows.

I got another compiler warning, updated the patch again.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2022/01/07 20:58, torikoshia wrote:
> On 2022-01-07 14:30, torikoshia wrote:
>
>> Updated the patch for fixing compiler warning about the format on windows.
>
> I got another compiler warning, updated the patch again.

Thanks for updating the patch!

I ran the following query every 0.1s by using \watch psql command from three different sessions while make installcheck test was running.

SELECT pg_log_query_plan(pid) FROM pg_stat_activity;

And then I got the segmentation fault as follows.

2022-01-07 21:40:32 JST [postmaster] LOG: server process (PID 51017) was terminated by signal 11: Segmentation fault: 11
2022-01-07 21:40:32 JST [postmaster] DETAIL: Failed process was running: select description, (test_conv(inbytes, 'utf8', 'utf8')).* from utf8_verification_inputs;
2022-01-07 21:40:32 JST [postmaster] LOG: terminating any other active server processes
2022-01-07 21:40:32 JST [postmaster] LOG: all server processes terminated; reinitializing

The backtrace I got from the core file was:

(lldb) target create --core "/cores/core.51017"
Core file '/cores/core.51017' (x86_64) was loaded.
(lldb) bt
* thread #1, stop reason = signal SIGSTOP
* frame #0: 0x00007fff20484552 libsystem_platform.dylib`_platform_strlen + 18
frame #1: 0x000000011076e36c postgres`dopr(target=0x00007ffedfd1b1d8, format="\n", args=0x00007ffedfd1b450) at snprintf.c:444:20
frame #2: 0x000000011076e133 postgres`pg_vsnprintf(str="Query Text: \x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f"..., count=1024, fmt="%s: %s\n", args=0x00007ffedfd1b450) at snprintf.c:195:2
frame #3: 0x000000011075e51d postgres`pvsnprintf(buf="Query Text: \x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f"..., len=1024, fmt="%s: %s\n", args=0x00007ffedfd1b450) at psprintf.c:110:13
frame #4: 0x000000011076052d postgres`appendStringInfoVA(str=0x00007fe56804bec0, fmt="%s: %s\n", args=0x00007ffedfd1b450) at stringinfo.c:149:13
frame #5: 0x0000000110760449 postgres`appendStringInfo(str=0x00007fe56804bec0, fmt="%s: %s\n") at stringinfo.c:103:12
frame #6: 0x000000011016f6cf postgres`ExplainProperty(qlabel="Query Text", unit=0x0000000000000000, value="", numeric=false, es=0x00007fe56804be28) at explain.c:4390:5
frame #7: 0x000000011016eace postgres`ExplainPropertyText(qlabel="Query Text", value="", es=0x00007fe56804be28) at explain.c:4435:2
frame #8: 0x000000011016ea97 postgres`ExplainQueryText(es=0x00007fe56804be28, queryDesc=0x00007fe568022320) at explain.c:969:3
frame #9: 0x000000011016faeb postgres`ProcessLogCurrentPlanInterrupt at explain.c:5009:2
frame #10: 0x00000001104dda84 postgres`ProcessInterrupts at postgres.c:3373:3
frame #11: 0x0000000110c81c57 plpgsql.so`exec_stmts(estate=0x00007ffedfd1bab8, stmts=0x00007fe568050e00) at pl_exec.c:1994:3
frame #12: 0x0000000110c80a78 plpgsql.so`exec_stmt_block(estate=0x00007ffedfd1bab8, block=0x00007fe56801c570) at pl_exec.c:1777:9
frame #13: 0x0000000110c81c91 plpgsql.so`exec_stmts(estate=0x00007ffedfd1bab8, stmts=0x00007fe56801c5c8) at pl_exec.c:1999:10
frame #14: 0x0000000110c80f21 plpgsql.so`exec_stmt_block(estate=0x00007ffedfd1bab8, block=0x00007fe56801c678) at pl_exec.c:1926:8
frame #15: 0x0000000110c7ed92 plpgsql.so`exec_toplevel_block(estate=0x00007ffedfd1bab8, block=0x00007fe56801c678) at pl_exec.c:1617:7
frame #16: 0x0000000110c7d3e4 plpgsql.so`plpgsql_exec_function(func=0x00007fe56a00aa20, fcinfo=0x00007fe56803c888, simple_eval_estate=0x0000000000000000, simple_eval_resowner=0x0000000000000000, procedure_resowner=0x0000000000000000, atomic=true) at pl_exec.c:611:7
frame #17: 0x0000000110c9bf12 plpgsql.so`plpgsql_call_handler(fcinfo=0x00007fe56803c888) at pl_handler.c:277:13
frame #18: 0x0000000110228b06 postgres`ExecInterpExpr(state=0x00007fe56803bf88, econtext=0x00007fe56803ba70, isnull=0x00007ffedfd1bf7f) at execExprInterp.c:725:8
frame #19: 0x000000011024858b postgres`ExecEvalExprSwitchContext(state=0x00007fe56803bf88, econtext=0x00007fe56803ba70, isNull=0x00007ffedfd1bf7f) at executor.h:339:13
frame #20: 0x00000001102482aa postgres`ExecProject(projInfo=0x00007fe56803bf80) at executor.h:373:9
frame #21: 0x0000000110247e2f postgres`ExecScan(node=0x00007fe56803b958, accessMtd=(postgres`SeqNext at nodeSeqscan.c:51), recheckMtd=(postgres`SeqRecheck at nodeSeqscan.c:90)) at execScan.c:238:12
frame #22: 0x000000011028c575 postgres`ExecSeqScan(pstate=0x00007fe56803b958) at nodeSeqscan.c:112:9
frame #23: 0x000000011023bbe2 postgres`ExecProcNode(node=0x00007fe56803b958) at executor.h:257:9
frame #24: 0x0000000110237471 postgres`ExecutePlan(estate=0x00007fe56803b720, planstate=0x00007fe56803b958, use_parallel_mode=false, operation=CMD_SELECT, sendTuples=true, numberTuples=0, direction=ForwardScanDirection, dest=0x00007fe568046ac8, execute_once=true) at execMain.c:1561:10
frame #25: 0x0000000110237320 postgres`standard_ExecutorRun(queryDesc=0x00007fe568037320, direction=ForwardScanDirection, count=0, execute_once=true) at execMain.c:371:3
frame #26: 0x00000001102370b8 postgres`ExecutorRun(queryDesc=0x00007fe568037320, direction=ForwardScanDirection, count=0, execute_once=true) at execMain.c:313:3
frame #27: 0x00000001104e6bdb postgres`PortalRunSelect(portal=0x00007fe567825920, forward=true, count=0, dest=0x00007fe568046ac8) at pquery.c:921:4
frame #28: 0x00000001104e65ba postgres`PortalRun(portal=0x00007fe567825920, count=9223372036854775807, isTopLevel=true, run_once=true, dest=0x00007fe568046ac8, altdest=0x00007fe568046ac8, qc=0x00007ffedfd1c350) at pquery.c:765:18
frame #29: 0x00000001104e1861 postgres`exec_simple_query(query_string="select description, (test_conv(inbytes, 'utf8', 'utf8')).* from utf8_verification_inputs;") at postgres.c:1216:10
frame #30: 0x00000001104e099c postgres`PostgresMain(dbname="regression", username="postgres") at postgres.c:4505:7
frame #31: 0x00000001103ee2a2 postgres`BackendRun(port=0x00007fe567704080) at postmaster.c:4594:2
frame #32: 0x00000001103ed868 postgres`BackendStartup(port=0x00007fe567704080) at postmaster.c:4322:3
frame #33: 0x00000001103ec64c postgres`ServerLoop at postmaster.c:1802:7
frame #34: 0x00000001103e9e29 postgres`PostmasterMain(argc=3, argv=0x00007fe567405e70) at postmaster.c:1474:11
frame #35: 0x00000001102c8b69 postgres`main(argc=3, argv=0x00007fe567405e70) at main.c:198:3
frame #36: 0x00007fff2045cf3d libdyld.dylib`start + 1

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

Hi,

On Fri, Jan 07, 2022 at 09:54:31PM +0900, Fujii Masao wrote:
>
> On 2022/01/07 20:58, torikoshia wrote:
> > On 2022-01-07 14:30, torikoshia wrote:
> >
> > > Updated the patch for fixing compiler warning about the format on windows.
> >
> > I got another compiler warning, updated the patch again.
>
> Thanks for updating the patch!
>
> I ran the following query every 0.1s by using \watch psql command from three different sessions while make installcheck test was running.
>
> SELECT pg_log_query_plan(pid) FROM pg_stat_activity;
>
>
> And then I got the segmentation fault as follows.
>
> 2022-01-07 21:40:32 JST [postmaster] LOG: server process (PID 51017) was terminated by signal 11: Segmentation fault: 11
> 2022-01-07 21:40:32 JST [postmaster] DETAIL: Failed process was running: select description, (test_conv(inbytes, 'utf8', 'utf8')).* from utf8_verification_inputs;
> 2022-01-07 21:40:32 JST [postmaster] LOG: terminating any other active server processes
> 2022-01-07 21:40:32 JST [postmaster] LOG: all server processes terminated; reinitializing
>
>
> The backtrace I got from the core file was:
>
> (lldb) target create --core "/cores/core.51017"
> Core file '/cores/core.51017' (x86_64) was loaded.
> (lldb) bt
> * thread #1, stop reason = signal SIGSTOP
> * frame #0: 0x00007fff20484552 libsystem_platform.dylib`_platform_strlen + 18
> frame #1: 0x000000011076e36c postgres`dopr(target=0x00007ffedfd1b1d8, format="\n", args=0x00007ffedfd1b450) at snprintf.c:444:20
> frame #2: 0x000000011076e133 postgres`pg_vsnprintf(str="Query Text: \x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f"..., count=1024, fmt="%s: %s\n", args=0x00007ffedfd1b450) at snprintf.c:195:2

On top of the visibly use-after-pfree memory issue, the patch doesn't apply
anymore:

http://cfbot.cputube.org/patch_36_3142.log
=== Applying patches on top of PostgreSQL commit ID a18b6d2dc288dfa6e7905ede1d4462edd6a8af47 ===
=== applying patch ./v16-0001-log-running-query-plan.patch
[...]
patching file src/test/regress/expected/misc_functions.out
Hunk #1 FAILED at 134.
Hunk #2 succeeded at 163 (offset 7 lines).
Hunk #3 succeeded at 180 (offset 7 lines).
1 out of 3 hunks FAILED -- saving rejects to file src/test/regress/expected/misc_functions.out.rej
patching file src/test/regress/sql/misc_functions.sql
Hunk #1 FAILED at 31.
1 out of 1 hunk FAILED -- saving rejects to file src/test/regress/sql/misc_functions.sql.rej

I'm switching the patch to Waiting on Author.

On 2022-01-14 15:38, Julien Rouhaud wrote:
> Hi,
>
> On Fri, Jan 07, 2022 at 09:54:31PM +0900, Fujii Masao wrote:

>> I ran the following query every 0.1s by using \watch psql command from
>> three different sessions while make installcheck test was running.
>>
>> SELECT pg_log_query_plan(pid) FROM pg_stat_activity;
>>
>>
>> And then I got the segmentation fault as follows.
>>
>> 2022-01-07 21:40:32 JST [postmaster] LOG: server process (PID 51017)
>> was terminated by signal 11: Segmentation fault: 11
>> 2022-01-07 21:40:32 JST [postmaster] DETAIL: Failed process was
>> running: select description, (test_conv(inbytes, 'utf8', 'utf8')).*
>> from utf8_verification_inputs;
>> 2022-01-07 21:40:32 JST [postmaster] LOG: terminating any other
>> active server processes
>> 2022-01-07 21:40:32 JST [postmaster] LOG: all server processes
>> terminated; reinitializing
>>
>>
>> The backtrace I got from the core file was:
>>
>> (lldb) target create --core "/cores/core.51017"
>> Core file '/cores/core.51017' (x86_64) was loaded.
>> (lldb) bt
>> * thread #1, stop reason = signal SIGSTOP
>> * frame #0: 0x00007fff20484552
>> libsystem_platform.dylib`_platform_strlen + 18
>> frame #1: 0x000000011076e36c
>> postgres`dopr(target=0x00007ffedfd1b1d8, format="\n",
>> args=0x00007ffedfd1b450) at snprintf.c:444:20
>> frame #2: 0x000000011076e133 postgres`pg_vsnprintf(str="Query
>> Text:
>>
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x
7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x
7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f
\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f\x7f"...,
>> count=1024, fmt="%s: %s\n", args=0x00007ffedfd1b450) at
>> snprintf.c:195:2

Thanks for testing!
I could reproduce the situation and confirmed almost the same backtrace.

The cause seems that the previous patch didn't do cleanup when the
transactions were aborted. It leaded segmentation faults when
referencing ActiveQueryDesc-> after the transaction were aborted.

The attached patch added cleanups when transactions and subtransactions
are aborted.

BTW, the latest patch for pg_log_backtrace() added a new function for
deduplicating codes for pg_log_*()[1].
It seems better to use it for pg_log_query_plan() after the patch is
merged.

[1]
/message-id/flat/20211115194251.GP17618%40telsasoft.com#4e681d04c78867b2cce44b3cb1791bf5
duplicate code to a new function
CheckPostgresProcessId which can be used by pg_log_backtrace,

> On top of the visibly use-after-pfree memory issue, the patch doesn't
> apply

Thanks for letting me know!
As mentioned above, I updated the patch.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2022/01/24 14:33, torikoshia wrote:
> As mentioned above, I updated the patch.

Thanks for updating the patch!

Here are another review comments:

+LOG: plan of the query running on backend with PID 17793 is:

This seems not the same as what actually logged.

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

+ if (SendProcSignal(pid, PROCSIG_LOG_CURRENT_PLAN, InvalidBackendId) < 0)

proc->backendId should be specified instead of InvalidBackendId, to speed up the processing in SendProcSignal()?

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

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

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

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?

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

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

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

On 2022/01/28 17:45, torikoshia wrote:
>> 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().

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

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

Or we don't need HINT message?

+ errmsg("could not log the query plan"),
+ errdetail("query plan cannot be logged while page level lock is being held"),

In detail message, the first word of sentences should be capitalized. How about "Cannot log the query plan while holding page-level lock.", instead?

Thanks for updating the patch! Here are some review comments.

+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>pg_log_query_plan</primary>
+ </indexterm>

This entry is placed before one for pg_log_backend_memory_contexts(). But it should be *after* that since those entries seem to be placed in alphabetical order in the table?

+ Requests to log the plan of the query currently running on the
+ backend with specified process ID along with the untruncated
+ query string.

Other descriptions about logging of query string seem not to mention something like "untruncated query string". For example, auto_explain, log_statement, etc. Why do we need to mention "along with the untruncated query string" specially for pg_log_query_plan()?

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

@@ -440,6 +450,7 @@ standard_ExecutorFinish(QueryDesc *queryDesc)

MemoryContextSwitchTo(oldcontext);

+ ActiveQueryDesc = NULL;

ActiveQueryDesc seems unnecessary. Why does ActiveQueryDesc need to be reset to NULL in standard_ExecutorFinish()?

Currently even during ProcessLogQueryPlanInterrupt(), pg_log_query_plan() can be call and another ProcessLogQueryPlanInterrupt() can be executed. So repeatable re-entrances to ProcessLogQueryPlanInterrupt() could cause "stack depth limit exceeded" error. To avoid this, shouldn't we make ProcessLogQueryPlanInterrupt() do nothing and return immediately, if it's called during another ProcessLogQueryPlanInterrupt()?

pg_log_backend_memory_contexts() also might have the same issue.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

At Tue, 1 Feb 2022 01:51:11 +0900, Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com> wrote in
>
>
> On 2022/01/28 17:45, torikoshia wrote:
> >> 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().
>
> 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.
> --------------------------
>
>
> >> +            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?
>
> Or we don't need HINT message?
>
>
> + errmsg("could not log the query plan"),
> + errdetail("query plan cannot be logged while page level lock is
> being held"),
>
> In detail message, the first word of sentences should be
> capitalized. How about "Cannot log the query plan while holding
> page-level lock.", instead?
>
>
> Thanks for updating the patch! Here are some review comments.
>
> + <row>
> + <entry role="func_table_entry"><para role="func_signature">
> + <indexterm>
> + <primary>pg_log_query_plan</primary>
> + </indexterm>
>
> This entry is placed before one for
> pg_log_backend_memory_contexts(). But it should be *after* that since
> those entries seem to be placed in alphabetical order in the table?
>
>
> + Requests to log the plan of the query currently running on the
> + backend with specified process ID along with the untruncated
> + query string.
>
> Other descriptions about logging of query string seem not to mention
> something like "untruncated query string". For example, auto_explain,
> log_statement, etc. Why do we need to mention "along with the
> untruncated query string" specially for pg_log_query_plan()?
>
>
> + 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?
>
>
> @@ -440,6 +450,7 @@ standard_ExecutorFinish(QueryDesc *queryDesc)
> MemoryContextSwitchTo(oldcontext);
> + ActiveQueryDesc = NULL;
>
> ActiveQueryDesc seems unnecessary. Why does ActiveQueryDesc need to be
> reset to NULL in standard_ExecutorFinish()?
>
>
> Currently even during ProcessLogQueryPlanInterrupt(),
> pg_log_query_plan() can be call and another
> ProcessLogQueryPlanInterrupt() can be executed. So repeatable
> re-entrances to ProcessLogQueryPlanInterrupt() could cause "stack
> depth limit exceeded" error. To avoid this, shouldn't we make
> ProcessLogQueryPlanInterrupt() do nothing and return immediately, if
> it's called during another ProcessLogQueryPlanInterrupt()?
>
> pg_log_backend_memory_contexts() also might have the same issue.

Good catch.

By the way, I'm anxious about the following part and I'd like to
remove it.

+ * Ensure no page lock is held on this process.

It seems to me what is wrong is ginInsertCleanup(), not this feature.
As I read the comment for the assertion, I don't believe we want to
allow CFI while holding a page lock. And AFAICS the function is the
only point where doing that. (It is the alone user of LockPage()...)

This is the assertion.

lock.c: 902
> /*
> * We don't acquire any other heavyweight lock while holding the page lock
> * except for relation extension.
> */
> Assert(!IsPageLockHeld ||
> (locktag->locktag_type == LOCKTAG_RELATION_EXTEND));

It is added by a recent commit 72e78d831ab5550c39f2dcc7cc5d44c406ec3dc2.

> * Similar to relation extension, page locks are also held for a short
> * duration, so imposing such a restriction won't hurt.

I don't believe a path involving vacuum_delay_point() calls is
short-duration'ed.

/message-id/CAH2-WznzCPUKnOV%2Bre30_rHLCkqQWm2JTSVjTCAei9LySTc2pw%40mail.gmail.com

> One thing that really bothers me about commit e2c79e14 is that
> LockPage() is called, not LockBuffer(). GIN had no LockPage() calls
> before that commit, and is now the only code in the entire system that
> calls LockPage()/ConditionalLockPage() (the hash am no longer uses
> page heavyweight locks following recent work there).

I agree to the discussion. Can't we use other mechanism here to get
rid of the Lockpage()?

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On 2022/02/01 17:27, Kyotaro Horiguchi wrote:
>> * Similar to relation extension, page locks are also held for a short
>> * duration, so imposing such a restriction won't hurt.
>
> I don't believe a path involving vacuum_delay_point() calls is
> short-duration'ed.

Yes.

>> One thing that really bothers me about commit e2c79e14 is that
>> LockPage() is called, not LockBuffer(). GIN had no LockPage() calls
>> before that commit, and is now the only code in the entire system that
>> calls LockPage()/ConditionalLockPage() (the hash am no longer uses
>> page heavyweight locks following recent work there).
>
> I agree to the discussion. Can't we use other mechanism here to get
> rid of the Lockpage()?

I have no good idea for that yet, but I agree it's better to get rid of page level lock.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

At Tue, 1 Feb 2022 23:11:03 +0900, Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com> wrote in
> >> One thing that really bothers me about commit e2c79e14 is that
> >> LockPage() is called, not LockBuffer(). GIN had no LockPage() calls
> >> before that commit, and is now the only code in the entire system that
> >> calls LockPage()/ConditionalLockPage() (the hash am no longer uses
> >> page heavyweight locks following recent work there).
> > I agree to the discussion. Can't we use other mechanism here to get
> > rid of the Lockpage()?
>
> I have no good idea for that yet, but I agree it's better to get rid
> of page level lock.

It's my turn?

The page lock is used to hold-off simultaneous cleanups on the same
index. ShareUpdateExclusive lock on the index relation works that
way. In that path it seems like we are always holding a RowExclusive
lock, so it seems to me we can use ShareUpdateExclusive for our
purpose.

There might be a false blocking case when another backend is holding a
conflicting lock on the index. They are, Share, ShareRowExclusive,
Exclusive and AccessExclusive. The last three cases don't seem worth
discussion. I'm not sure about Share and Share Row cases. AFAICS
Share lock is taken on an index in ATExecReplicaIdentity, and there no
use of ShareRowExclusive lock on an index. It's no use discussing about
explicit locking.

So aren't we able to use ShareUpdateExclusive lock for that?

In the attached patch, ginInsertCleanup has an extra check for such
stronger locks not being held. At least "make check" doesn't cause
the extra assertion to fire.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

At Wed, 02 Feb 2022 16:49:57 +0900 (JST), Kyotaro Horiguchi <horikyota(dot)ntt(at)gmail(dot)com> wrote in
> So aren't we able to use ShareUpdateExclusive lock for that?
>
> In the attached patch, ginInsertCleanup has an extra check for such
> stronger locks not being held. At least "make check" doesn't cause
> the extra assertion to fire.

Actually, the discussion is a bit dubious. What we need really to
check is wheter such locks are not held on an index *elsewhere*.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

2022-02-01 01:51, Fujii Masao wrote:
Thanks for reviewing and suggestions!

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

>>> +            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?
>
> Or we don't need HINT message?

Removed the HINT message.

> + errmsg("could not log the query plan"),
> + errdetail("query plan cannot be logged
> while page level lock is
> being held"),
>
> In detail message, the first word of sentences should be capitalized.
> How about "Cannot log the query plan while holding page-level lock.",
> instead?

Agreed.

> Thanks for updating the patch! Here are some review comments.
>
> + <row>
> + <entry role="func_table_entry"><para role="func_signature">
> + <indexterm>
> + <primary>pg_log_query_plan</primary>
> + </indexterm>
>
> This entry is placed before one for pg_log_backend_memory_contexts().
> But it should be *after* that since those entries seem to be placed in
> alphabetical order in the table?

Modified it.

> + Requests to log the plan of the query currently running on the
> + backend with specified process ID along with the untruncated
> + query string.
>
> Other descriptions about logging of query string seem not to mention
> something like "untruncated query string". For example, auto_explain,
> log_statement, etc. Why do we need to mention "along with the
> untruncated query string" specially for pg_log_query_plan()?

Modified it as below:

Requests to log the plan of the query currently running on
the
- backend with specified process ID along with the
untruncated
- query string.
- They will be logged at <literal>LOG</literal> message level
and
+ backend with specified process ID.
+ It will be logged at <literal>LOG</literal> message level
and

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

> @@ -440,6 +450,7 @@ standard_ExecutorFinish(QueryDesc *queryDesc)
> MemoryContextSwitchTo(oldcontext);
> + ActiveQueryDesc = NULL;
>
> ActiveQueryDesc seems unnecessary. Why does ActiveQueryDesc need to be
> reset to NULL in standard_ExecutorFinish()?

ActiveQueryDesc should not be reset in standard_ExecutorFinish().
Removed it.

> Currently even during ProcessLogQueryPlanInterrupt(),
> pg_log_query_plan() can be call and another
> ProcessLogQueryPlanInterrupt() can be executed. So repeatable
> re-entrances to ProcessLogQueryPlanInterrupt() could cause "stack
> depth limit exceeded" error. To avoid this, shouldn't we make
> ProcessLogQueryPlanInterrupt() do nothing and return immediately, if
> it's called during another ProcessLogQueryPlanInterrupt()?
>
> pg_log_backend_memory_contexts() also might have the same issue.

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.

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.

On 2022-02-01 17:27, Kyotaro Horiguchi wrote:

Thanks for reviewing Horiguchi-san!

> By the way, I'm anxious about the following part and I'd like to
> remove it.

I also think it would be nice if it's possible.
>
> + * Ensure no page lock is held on this process.
>
> It seems to me what is wrong is ginInsertCleanup(), not this feature.

> Actually, the discussion is a bit dubious. What we need really to
check is wheter such locks are not held on an index *elsewhere*.

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.
I also think it may be better to discuss it on another thread.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

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"

<snip>
> On 2022-02-01 17:27, Kyotaro Horiguchi wrote:
>
> Thanks for reviewing Horiguchi-san!
>
> > By the way, I'm anxious about the following part and I'd like to
> > remove it.
>
> I also think it would be nice if it's possible.
> >
> > + * Ensure no page lock is held on this process.
> >
> > It seems to me what is wrong is ginInsertCleanup(), not this feature.
>
> > Actually, the discussion is a bit dubious. What we need really to
> check is wheter such locks are not held on an index *elsewhere*.
>
> 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.
> I also think it may be better to discuss it on another thread.
>

While I agree on the above points, IMHO I don't believe it should be a
show-stopper for adding this functionality to v15, but we have a few
more commitments before we get to that point.

Robert Treat
https://xzilla.net

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.

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

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

-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log;

Isn't this name too generic? How about regress_log_function, for example?

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

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

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

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

On 2022/02/09 0:12, torikoshia wrote:
> 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;
So in this case ActiveQueryDesc set by ExecutorRun() called only once is still valid even when AbortSubTransaction() is called. That is, that ActiveQueryDesc should NOT be reset to save_ActiveQueryDesc in this case, should it?

OTOH, in your example, ActiveQueryDesc set by the second call to ExecutorRun() should be reset in AbortSubTransaction(). Then ActiveQueryDesc set by the first call should be valid.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On 2022-02-08 01:13, Fujii Masao wrote:
> 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.

I once agreed above suggestion and made v20 patch making
save_ActiveQueryDesc a global variable, but it caused segfault when
calling pg_log_query_plan() after FreeQueryDesc().

OTOH, doing some kind of reset of ActiveQueryDesc seems necessary since
it also caused segfault when running pg_log_query_plan() during
installcheck.

There may be a better way, but resetting ActiveQueryDesc to NULL seems
safe and simple.
Of course it makes pg_log_query_plan() useless after a subtransaction is
aborted.
However, if it does not often happen that people want to know the
running query's plan whose subtransaction is aborted, resetting
ActiveQueryDesc to NULL would be acceptable.

Attached is a patch that sets ActiveQueryDesc to NULL when a
subtransaction is aborted.

How do you think?

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2022-03-09 19:04, torikoshia wrote:
> On 2022-02-08 01:13, Fujii Masao wrote:
>> 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.
>
> I once agreed above suggestion and made v20 patch making
> save_ActiveQueryDesc a global variable, but it caused segfault when
> calling pg_log_query_plan() after FreeQueryDesc().
>
> OTOH, doing some kind of reset of ActiveQueryDesc seems necessary
> since it also caused segfault when running pg_log_query_plan() during
> installcheck.
>
> There may be a better way, but resetting ActiveQueryDesc to NULL seems
> safe and simple.
> Of course it makes pg_log_query_plan() useless after a subtransaction
> is aborted.
> However, if it does not often happen that people want to know the
> running query's plan whose subtransaction is aborted, resetting
> ActiveQueryDesc to NULL would be acceptable.
>
> Attached is a patch that sets ActiveQueryDesc to NULL when a
> subtransaction is aborted.
>
> How do you think?

Attached new patch to fix patch apply failures.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2022-05-16 17:02, torikoshia wrote:
> On 2022-03-09 19:04, torikoshia wrote:
>> On 2022-02-08 01:13, Fujii Masao wrote:
>>> 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.
>>
>> I once agreed above suggestion and made v20 patch making
>> save_ActiveQueryDesc a global variable, but it caused segfault when
>> calling pg_log_query_plan() after FreeQueryDesc().
>>
>> OTOH, doing some kind of reset of ActiveQueryDesc seems necessary
>> since it also caused segfault when running pg_log_query_plan() during
>> installcheck.
>>
>> There may be a better way, but resetting ActiveQueryDesc to NULL seems
>> safe and simple.
>> Of course it makes pg_log_query_plan() useless after a subtransaction
>> is aborted.
>> However, if it does not often happen that people want to know the
>> running query's plan whose subtransaction is aborted, resetting
>> ActiveQueryDesc to NULL would be acceptable.
>>
>> Attached is a patch that sets ActiveQueryDesc to NULL when a
>> subtransaction is aborted.
>>
>> How do you think?
Attached new patch to fix patch apply failures again.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

<div><div>Hi,</div><div><div>I'm sorry,if this message is duplicated previous this one, but I'm not sure that the previous message is sent correctly. I sent it from email address <a href="mailto:a(dot)rybakina(at)postgrespro(dot)ru" rel="noopener noreferrer">a(dot)rybakina(at)postgrespro(dot)ru</a> and I couldn't send this one email from those address.</div><div>I like idea to create patch for logging query plan. After reviewing this code and notice some moments and I'd rather ask you some questions.</div></div><div><br />Firstly, I suggest some editing in the comment of commit. I think, it is turned out the more laconic and the same clear. I wrote it below since I can't think of any other way to add it.<br /><br />```<br />Currently, we have to wait for finishing of the query execution to check its plan.<br />This is not so convenient in investigation long-running queries on production<br />environments where we cannot use debuggers.<br /><br />To improve this situation there is proposed the patch containing the pg_log_query_plan()<br />function which request to log plan of the specified backend process.<br /><br />By default, only superusers are allowed to request log of the plan otherwise<br />allowing any users to issue this request could create cause lots of log messages<br />and it can lead to denial of service.<br /><br />At the next requesting CHECK_FOR_INTERRUPTS(), the target backend logs its plan at<br />LOG_SERVER_ONLY level and therefore this plan will appear in the server log only,<br />not to be sent to the client.<br />```<br /><br />Secondly, I have question about deleting USE_ASSERT_CHECKING in lock.h?<br />It supposed to have been checked in another placed of the code by matching values. I am worry about skipping errors due to untesting with assert option in the places where it (GetLockMethodLocalHash) participates and we won't able to get core file in segfault cases. I might not understand something, then can you please explain to me?<br /><br />Thirdly, I have incomprehension of the point why save_ActiveQueryDesc is declared in the pquery.h? I am seemed to save_ActiveQueryDesc to be used in an once time in the ExecutorRun function and  its declaration superfluous. I added it in the attached patch.<br /><br />Fourthly, it seems to me there are not enough explanatory comments in the code. I also added them in the attached patch.<br /><br />Lastly, I have incomprehension about handling signals since have been unused it before. Could another signal disabled calling this signal to log query plan? I noticed this signal to be checked the latest in procsignal_sigusr1_handler function.</div></div><div> </div><div> </div><div>-- </div><div>Regards,</div><div>Alena Rybakina<br />Postgres Professional</div><div> </div><div> </div><div> </div><div>19.09.2022, 11:01, "torikoshia" &lt;torikoshia(at)oss(dot)nttdata(dot)com&gt;:</div><blockquote><p>On 2022-05-16 17:02, torikoshia wrote:</p><blockquote> On 2022-03-09 19:04, torikoshia wrote:<blockquote> On 2022-02-08 01:13, Fujii Masao wrote:<blockquote> AbortSubTransaction() should reset ActiveQueryDesc to<br /> save_ActiveQueryDesc that ExecutorRun() set, instead of NULL?<br /> Otherwise ActiveQueryDesc of top-level statement will be unavailable<br /> after subtransaction is aborted in the nested statements.</blockquote> <br /> I once agreed above suggestion and made v20 patch making<br /> save_ActiveQueryDesc a global variable, but it caused segfault when<br /> calling pg_log_query_plan() after FreeQueryDesc().<br /> <br /> OTOH, doing some kind of reset of ActiveQueryDesc seems necessary<br /> since it also caused segfault when running pg_log_query_plan() during<br /> installcheck.<br /> <br /> There may be a better way, but resetting ActiveQueryDesc to NULL seems<br /> safe and simple.<br /> Of course it makes pg_log_query_plan() useless after a subtransaction<br /> is aborted.<br /> However, if it does not often happen that people want to know the<br /> running query's plan whose subtransaction is aborted, resetting<br /> ActiveQueryDesc to NULL would be acceptable.<br /> <br /> Attached is a patch that sets ActiveQueryDesc to NULL when a<br /> subtransaction is aborted.<br /> <br /> How do you think?</blockquote></blockquote><p>Attached new patch to fix patch apply failures again.<br /> </p>--<br />Regards,<br /><br />--<br />Atsushi Torikoshi<br />NTT DATA CORPORATION</blockquote>

On 2022-09-19 17:47, Алена Рыбакина wrote:
Thanks for your review and comments!

> Hi,
>
> I'm sorry,if this message is duplicated previous this one, but I'm not
> sure that the previous message is sent correctly. I sent it from email
> address a(dot)rybakina(at)postgrespro(dot)ru and I couldn't send this one email
> from those address.

I've successfully received your mail from both a(dot)rybakina(at)postgrespro(dot)ru
and lena(dot)ribackina(at)yandex(dot)ru(dot)

> I like idea to create patch for logging query plan. After reviewing
> this code and notice some moments and I'd rather ask you some
> questions.
>
> Firstly, I suggest some editing in the comment of commit. I think, it
> is
> turned out the more laconic and the same clear. I wrote it below since
> I
> can't think of any other way to add it.

> ```
> Currently, we have to wait for finishing of the query execution to
> check
> its plan.
> This is not so convenient in investigation long-running queries on
> production
> environments where we cannot use debuggers.

> To improve this situation there is proposed the patch containing the
> pg_log_query_plan()
> function which request to log plan of the specified backend process.

> By default, only superusers are allowed to request log of the plan
> otherwise
> allowing any users to issue this request could create cause lots of log
> messages
> and it can lead to denial of service.
>
> At the next requesting CHECK_FOR_INTERRUPTS(), the target backend logs
> its plan at
> LOG_SERVER_ONLY level and therefore this plan will appear in the server
> log only,
> not to be sent to the client.
Thanks, I have incorporated your comments.
Since the latter part of the original message comes from the commit
message of pg_log_backend_memory_contexts(43620e328617c), so I left it
as it was for consistency.

> Secondly, I have question about deleting USE_ASSERT_CHECKING in lock.h?
> It supposed to have been checked in another placed of the code by
> matching values. I am worry about skipping errors due to untesting with
> assert option in the places where it (GetLockMethodLocalHash)
> participates and we won't able to get core file in segfault cases. I
> might not understand something, then can you please explain to me?
Since GetLockMethodLocalHash() is only used for assertions, this is only
defined when USE_ASSERT_CHECKING is enabled.
This patch uses GetLockMethodLocalHash() not only for the assertion
purpose, so I removed "ifdef USE_ASSERT_CHECKING" for this function.
I belive it does not lead to skip errors.

> Thirdly, I have incomprehension of the point why save_ActiveQueryDesc
> is
> declared in the pquery.h? I am seemed to save_ActiveQueryDesc to be
> used
> in an once time in the ExecutorRun function and its declaration
> superfluous. I added it in the attached patch.
Exactly.

> Fourthly, it seems to me there are not enough explanatory comments in
> the code. I also added them in the attached patch.
Thanks!

| + /*
| + * Save value of ActiveQueryDesc before having called
| + * ExecutorRun_hook function due to having reset by
| + * AbortSubTransaction.
| + */
| +
| save_ActiveQueryDesc = ActiveQueryDesc;
| ActiveQueryDesc = queryDesc;
|
| @@ -314,6 +320,7 @@ ExecutorRun(QueryDesc *queryDesc,
| else
| standard_ExecutorRun(queryDesc, direction, count,
execute_once);
|
| + /* We set the actual value of ActiveQueryDesc */
| ActiveQueryDesc = save_ActiveQueryDesc;

Since these processes are needed for nested queries, not only for
AbortSubTransaction[1], added comments on it.

| +/* Function to handle the signal to output the query plan. */
| extern void HandleLogQueryPlanInterrupt(void);

I feel this comment is unnecessary since the explanation of
HandleLogQueryPlanInterrupt() is written in explain.c and no functions
in explain.h have comments in it.

> Lastly, I have incomprehension about handling signals since have been
> unused it before. Could another signal disabled calling this signal to
> log query plan? I noticed this signal to be checked the latest in
> procsignal_sigusr1_handler function.
Are you concerned that one signal will not be processed when multiple
signals are sent in succession?
AFAIU both of them are processed since SendProcSignal flags
ps_signalFlags for each signal.

```
SendProcSignal(pid_t pid, ProcSignalReason reason, BackendId backendId)
{
volatile ProcSignalSlot *slot;
...(snip)...
278 if (slot->pss_pid == pid)
279 {
280 /* Atomically set the proper flag */
281 slot->pss_signalFlags[reason] = true;
282 /* Send signal */
283 return kill(pid, SIGUSR1);
```

Comments of ProcSignalReason also say 'We can cope with concurrent
signals for different reasons'.

```C
/*
* Reasons for signaling a Postgres child process (a backend or an
auxiliary
* process, like checkpointer). We can cope with concurrent signals
for different
* reasons. However, if the same reason is signaled multiple times in
quick
* succession, the process is likely to observe only one notification
of it.
* This is okay for the present uses.
...
typedef enum
{
PROCSIG_CATCHUP_INTERRUPT, /* sinval catchup interrupt */
PROCSIG_NOTIFY_INTERRUPT, /* listen/notify interrupt */
PROCSIG_PARALLEL_MESSAGE, /* message from cooperating parallel
backend */
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for
shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory
contexts */
PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
query */
...
} ProcSignalReason;
```

[1]
/message-id/8b53b32f-26cc-0531-4ac0-27310e0bef4b%40oss.nttdata.com

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

 Ok, I get it.

> Since GetLockMethodLocalHash() is only used for assertions, this is
> only defined when USE_ASSERT_CHECKING is enabled. This patch uses
> GetLockMethodLocalHash() not only for the assertion purpose, so I
> removed "ifdef USE_ASSERT_CHECKING" for this function. I belive it
> does not lead to skip errors.
Agree.
> Since these processes are needed for nested queries, not only for
> AbortSubTransaction[1], added comments on it.

I also noticed it. However I also discovered that above function
declarations to be aplied for explain command and used to be printed
details of the executed query.

We have a similar task to print the plan of an interrupted process
making a request for a specific pid.

In short, I think, this task is different and for separating these parts
I added this comment.

> I feel this comment is unnecessary since the explanation of
> HandleLogQueryPlanInterrupt() is written in explain.c and no functions
> in explain.h have comments in it.

Yes, I was worried about it. I understood it, thank for explaining.

>
> AFAIU both of them are processed since SendProcSignal flags
> ps_signalFlags for each signal.
>
> ```
> SendProcSignal(pid_t pid, ProcSignalReason reason, BackendId backendId)
> {
> volatile ProcSignalSlot *slot;
> ...(snip)...
> 278 if (slot->pss_pid == pid)
> 279 {
> 280 /* Atomically set the proper flag */
> 281 slot->pss_signalFlags[reason] = true;
> 282 /* Send signal */
> 283 return kill(pid, SIGUSR1);
> ```
>
> Comments of ProcSignalReason also say 'We can cope with concurrent
> signals for different reasons'.
>
> ```C
> /*
> * Reasons for signaling a Postgres child process (a backend or an
> auxiliary
> * process, like checkpointer). We can cope with concurrent signals for
> different
> * reasons. However, if the same reason is signaled multiple times in
> quick
> * succession, the process is likely to observe only one notification
> of it.
> * This is okay for the present uses.
> ...
> typedef enum
> {
> PROCSIG_CATCHUP_INTERRUPT, /* sinval catchup interrupt */
> PROCSIG_NOTIFY_INTERRUPT, /* listen/notify interrupt */
> PROCSIG_PARALLEL_MESSAGE, /* message from cooperating parallel backend */
> PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for
> shutdown */
> PROCSIG_BARRIER, /* global barrier interrupt */
> PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
> PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
> query */
> ...
> } ProcSignalReason;
> ```
>
>
> [1]
> /message-id/8b53b32f-26cc-0531-4ac0-27310e0bef4b%40oss.nttdata.com

On 2022-09-21 17:30, Alena Rybakina wrote:

Thanks for your reply!

> I also noticed it. However I also discovered that above function
> declarations to be aplied for explain command and used to be printed
> details of the executed query.
>
> We have a similar task to print the plan of an interrupted process
> making a request for a specific pid.
>
> In short, I think, this task is different and for separating these
> parts I added this comment.

I'm not sure I understand your comment correctly, do you mean
HandleLogQueryPlanInterrupt() should not be placed in explain.c?

It may be so.
However, given that ProcesLogMemoryContextInterrupt(), which similarly
handles interrupts for pg_log_backend_memory_contexts(), is located in
mcxt.c, I also think current location might be acceptable.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Sorry, I wrote confusingly at that time.

No, I suggested adding comment about the explanation of
HandleLogQueryPlanInterrupt() only in the explain.h and not removing
from the explain.c.

I seemed to be necessary separating declaration function for 'explaining
feature' of executed query from our logging plan of the running query
interrupts function. But now, I doubt it.

> I'm not sure I understand your comment correctly, do you mean
> HandleLogQueryPlanInterrupt() should not be placed in explain.c?

Thank you for having reminded about this function and I looked at
ProcessLogMemoryContextInterrupt() declaration. I'm noticed comments in
the memutils.h are missed tooю

Description of this function is written only in mcxt.c.
> However, given that ProcesLogMemoryContextInterrupt(), which similarly
> handles interrupts for pg_log_backend_memory_contexts(), is located in
> mcxt.c, I also think current location might be acceptable.

So I think you are right and the comment about the explanation of
HandleLogQueryPlanInterrupt() written in explain.h is redundant.

> I feel this comment is unnecessary since the explanation of
> HandleLogQueryPlanInterrupt() is written in explain.c and no functions
> in explain.h have comments in it.

Regards,

--
Alena Rybakina
Postgres Professional

Hi,

This patch does not currently build, due to a conflicting oid:

https://cirrus-ci.com/task/4638460594618368?logs=build#L108
[17:26:44.602] /usr/bin/perl ../src/include/catalog/../../backend/catalog/genbki.pl --include-path=../src/include --set-version=16 --output=src/include/catalog ../src/include/catalog/pg_proc.h ../src/include/catalog/pg_type.h ../src/include/catalog/pg_attribute.h ../src/include/catalog/pg_class.h ../src/include/catalog/pg_attrdef.h ../src/include/catalog/pg_constraint.h ../src/include/catalog/pg_inherits.h ../src/include/catalog/pg_index.h ../src/include/catalog/pg_operator.h ../src/include/catalog/pg_opfamily.h ../src/include/catalog/pg_opclass.h ../src/include/catalog/pg_am.h ../src/include/catalog/pg_amop.h ../src/include/catalog/pg_amproc.h ../src/include/catalog/pg_language.h ../src/include/catalog/pg_largeobject_metadata.h ../src/include/catalog/pg_largeobject.h ../src/include/catalog/pg_aggregate.h ../src/include/catalog/pg_statistic.h ../src/include/catalog/pg_statistic_ext.h ../src/include/catalog/pg_statistic_ext_data.h ../src/include/catalog/pg_rewrite.h ../src/include/catalog/pg_trigger.h ../src/include/catalog/pg_event_trigger.h ../src/include/catalog/pg_description.h ../src/include/catalog/pg_cast.h ../src/include/catalog/pg_enum.h ../src/include/catalog/pg_namespace.h ../src/include/catalog/pg_conversion.h ../src/include/catalog/pg_depend.h ../src/include/catalog/pg_database.h ../src/include/catalog/pg_db_role_setting.h ../src/include/catalog/pg_tablespace.h ../src/include/catalog/pg_authid.h ../src/include/catalog/pg_auth_members.h ../src/include/catalog/pg_shdepend.h ../src/include/catalog/pg_shdescription.h ../src/include/catalog/pg_ts_config.h ../src/include/catalog/pg_ts_config_map.h ../src/include/catalog/pg_ts_dict.h ../src/include/catalog/pg_ts_parser.h ../src/include/catalog/pg_ts_template.h ../src/include/catalog/pg_extension.h ../src/include/catalog/pg_foreign_data_wrapper.h ../src/include/catalog/pg_foreign_server.h ../src/include/catalog/pg_user_mapping.h ../src/include/catalog/pg_foreign_table.h ../src/include/catalog/pg_policy.h ../src/include/catalog/pg_replication_origin.h ../src/include/catalog/pg_default_acl.h ../src/include/catalog/pg_init_privs.h ../src/include/catalog/pg_seclabel.h ../src/include/catalog/pg_shseclabel.h ../src/include/catalog/pg_collation.h ../src/include/catalog/pg_parameter_acl.h ../src/include/catalog/pg_partitioned_table.h ../src/include/catalog/pg_range.h ../src/include/catalog/pg_transform.h ../src/include/catalog/pg_sequence.h ../src/include/catalog/pg_publication.h ../src/include/catalog/pg_publication_namespace.h ../src/include/catalog/pg_publication_rel.h ../src/include/catalog/pg_subscription.h ../src/include/catalog/pg_subscription_rel.h
[17:26:44.602] Duplicate OIDs detected:
[17:26:44.602] 4550
[17:26:44.602] found 1 duplicate OID(s) in catalog data

I suggest you choose a random oid out of the "development purposes" range:

* OIDs 1-9999 are reserved for manual assignment (see .dat files in
* src/include/catalog/). Of these, 8000-9999 are reserved for
* development purposes (such as in-progress patches and forks);
* they should not appear in released versions.

Greetings,

Andres Freund

On 2022-12-07 03:41, Andres Freund wrote:
> Hi,
>
> This patch does not currently build, due to a conflicting oid:
>
> I suggest you choose a random oid out of the "development purposes"
> range:

Thanks for your advice!
Attached updated patch.

BTW, since this patch depends on ProcessInterrupts() and EXPLAIN codes
which is used in auto_explain, I'm feeling that the following discussion
also applies to this patch.

> --
> /message-id/CA%2BTgmoYW_rSOW4JMQ9_0Df9PKQ%3DsQDOKUGA4Gc9D8w4wui8fSA%40mail.gmail.com
>
> explaining a query is a pretty
> complicated operation that involves catalog lookups and lots of
> complicated stuff, and I don't think that it would be safe to do all
> of that at any arbitrary point in the code where ProcessInterrupts()
> happened to fire.

If I can't come up with some workaround during the next Commitfest, I'm
going to withdraw this proposal.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Hello,

Thanks for working on this patch!

On Thu, Dec 8, 2022 at 12:10 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> BTW, since this patch depends on ProcessInterrupts() and EXPLAIN codes
> which is used in auto_explain, I'm feeling that the following discussion
> also applies to this patch.
>
> > --
> > /message-id/CA%2BTgmoYW_rSOW4JMQ9_0Df9PKQ%3DsQDOKUGA4Gc9D8w4wui8fSA%40mail.gmail.com
> >
> > explaining a query is a pretty
> > complicated operation that involves catalog lookups and lots of
> > complicated stuff, and I don't think that it would be safe to do all
> > of that at any arbitrary point in the code where ProcessInterrupts()
> > happened to fire.
>
> If I can't come up with some workaround during the next Commitfest, I'm
> going to withdraw this proposal.

While at PGCon this week I'd brought up this idea with a few people
without realizing you'd already worked on it previously, and then
after I discovered this thread several of us (Greg, Ronan, David,
Heikki, and myself -- all cc'd) discussed the safety concerns over
dinner last night.

Our conclusion was that all of the concerns we could come up with (for
example, walking though the code for ExplainTargetRel() and discussing
the relevant catalog and syscache accesses) all applied specifically
to Robert's concerns about running explain inside an aborted
transaction. After all, I'd originally started that thread to ask
about running auto-explain after a query timeout.

To put it positively: we believe that, for example, catalog accesses
inside CHECK_FOR_INTERRUPTS() -- assuming that the CFI call is inside
an existing valid transaction/query state, as it would be for this
patch -- are safe. If there were problems, then those problems are
likely bugs we already have in other CFI cases.

Another concern Robert raised may apply here: what if a person tries
to cancel a query when we're explaining? I believe that's a reasonable
question to ask, but I believe it's a trade-off that's worth making
for the (significant) introspection benefits this patch would provide.

On to the patch itself: overall I think it looks like it's in pretty
good shape. I also noticed we don't have any tests (I assume it'd have
to be TAP tests) of the actual output happening, and I think it would
be worth adding that.

Are you interested in re-opening this patch? I'd be happy to provide
further review and help to try to push this along.

I've rebased the patch and attached as v26.

Thanks,
James Coleman

On 2023-06-03 02:51, James Coleman wrote:
> Hello,
>
> Thanks for working on this patch!
>
> On Thu, Dec 8, 2022 at 12:10 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> BTW, since this patch depends on ProcessInterrupts() and EXPLAIN codes
>> which is used in auto_explain, I'm feeling that the following
>> discussion
>> also applies to this patch.
>>
>> > --
>> > /message-id/CA%2BTgmoYW_rSOW4JMQ9_0Df9PKQ%3DsQDOKUGA4Gc9D8w4wui8fSA%40mail.gmail.com
>> >
>> > explaining a query is a pretty
>> > complicated operation that involves catalog lookups and lots of
>> > complicated stuff, and I don't think that it would be safe to do all
>> > of that at any arbitrary point in the code where ProcessInterrupts()
>> > happened to fire.
>>
>> If I can't come up with some workaround during the next Commitfest,
>> I'm
>> going to withdraw this proposal.
>
> While at PGCon this week I'd brought up this idea with a few people
> without realizing you'd already worked on it previously, and then
> after I discovered this thread several of us (Greg, Ronan, David,
> Heikki, and myself -- all cc'd) discussed the safety concerns over
> dinner last night.
>
> Our conclusion was that all of the concerns we could come up with (for
> example, walking though the code for ExplainTargetRel() and discussing
> the relevant catalog and syscache accesses) all applied specifically
> to Robert's concerns about running explain inside an aborted
> transaction. After all, I'd originally started that thread to ask
> about running auto-explain after a query timeout.
>
> To put it positively: we believe that, for example, catalog accesses
> inside CHECK_FOR_INTERRUPTS() -- assuming that the CFI call is inside
> an existing valid transaction/query state, as it would be for this
> patch -- are safe. If there were problems, then those problems are
> likely bugs we already have in other CFI cases.

Thanks a lot for the discussion and sharing it!
I really appreciate it.

BTW I'm not sure whether all the CFI are called in valid transaction,
do you think we should check each of them?

> Another concern Robert raised may apply here: what if a person tries
> to cancel a query when we're explaining? I believe that's a reasonable
> question to ask, but I believe it's a trade-off that's worth making
> for the (significant) introspection benefits this patch would provide.

Is the concern here limited to the case where explain code goes crazy
as Robert pointed out?
If so, this may be a trade-off worth doing.
I am a little concerned about whether there will be cases where the
explain code is not problematic but just takes long time.

> On to the patch itself: overall I think it looks like it's in pretty
> good shape. I also noticed we don't have any tests (I assume it'd have
> to be TAP tests) of the actual output happening, and I think it would
> be worth adding that.

Checking the log output may be better, but I didn't add it since there
is only a little content that can be checked, and similar function
pg_log_backend_memory_contexts() does not do such type of tests.

> Are you interested in re-opening this patch? I'd be happy to provide
> further review and help to try to push this along.
Sure, I'm going to re-open this.

> I've rebased the patch and attached as v26.
Thanks again for your work!

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Mon, Jun 5, 2023 at 4:30 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-06-03 02:51, James Coleman wrote:
> > Hello,
> >
> > Thanks for working on this patch!

Sure thing! I'm *very interested* in seeing this available, and I
think it paves the way for some additional features later on...

> > On Thu, Dec 8, 2022 at 12:10 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> ...
> > To put it positively: we believe that, for example, catalog accesses
> > inside CHECK_FOR_INTERRUPTS() -- assuming that the CFI call is inside
> > an existing valid transaction/query state, as it would be for this
> > patch -- are safe. If there were problems, then those problems are
> > likely bugs we already have in other CFI cases.
>
> Thanks a lot for the discussion and sharing it!
> I really appreciate it.
>
> BTW I'm not sure whether all the CFI are called in valid transaction,
> do you think we should check each of them?

I kicked off the regressions tests with a call to
ProcessLogQueryPlanInterrupt() in every single CHECK_FOR_INTERRUPTS()
call. Several hours and 52 GB of logs later I have confirmed that
(with the attached revision) at the very least the regression test
suite can't trigger any kind of failures regardless of when we trigger
this. The existing code in the patch for only running the explain when
there's an active query handling that.

> > Another concern Robert raised may apply here: what if a person tries
> > to cancel a query when we're explaining? I believe that's a reasonable
> > question to ask, but I believe it's a trade-off that's worth making
> > for the (significant) introspection benefits this patch would provide.
>
> Is the concern here limited to the case where explain code goes crazy
> as Robert pointed out?
> If so, this may be a trade-off worth doing.
> I am a little concerned about whether there will be cases where the
> explain code is not problematic but just takes long time.

The explain code could take a long time in some rare cases (e.g., we
discovered a bug a few years back with the planning code that actually
descends an index to find the max value), but I think the trade-off is
worth it.

> > On to the patch itself: overall I think it looks like it's in pretty
> > good shape. I also noticed we don't have any tests (I assume it'd have
> > to be TAP tests) of the actual output happening, and I think it would
> > be worth adding that.
>
> Checking the log output may be better, but I didn't add it since there
> is only a little content that can be checked, and similar function
> pg_log_backend_memory_contexts() does not do such type of tests.

Fair enough. I still think that would be an improvement here, but
others could also weigh in.

> > Are you interested in re-opening this patch? I'd be happy to provide
> > further review and help to try to push this along.
> Sure, I'm going to re-open this.

I've attached v27. The important change here in 0001 is that it
guarantees the interrupt handler is re-entrant, since that was a bug
exposed by my testing. I've also included 0002 which is only meant for
testing (it attempts to log in the plan in every
CHECK_FOR_INTERRUPTS() call).

Regards,
James

On 2023-06-06 03:26, James Coleman wrote:
> On Mon, Jun 5, 2023 at 4:30 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-06-03 02:51, James Coleman wrote:
>> > Hello,
>> >
>> > Thanks for working on this patch!
>
> Sure thing! I'm *very interested* in seeing this available, and I
> think it paves the way for some additional features later on...
>
>> > On Thu, Dec 8, 2022 at 12:10 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
>> ...
>> > To put it positively: we believe that, for example, catalog accesses
>> > inside CHECK_FOR_INTERRUPTS() -- assuming that the CFI call is inside
>> > an existing valid transaction/query state, as it would be for this
>> > patch -- are safe. If there were problems, then those problems are
>> > likely bugs we already have in other CFI cases.
>>
>> Thanks a lot for the discussion and sharing it!
>> I really appreciate it.
>>
>> BTW I'm not sure whether all the CFI are called in valid transaction,
>> do you think we should check each of them?
>
> I kicked off the regressions tests with a call to
> ProcessLogQueryPlanInterrupt() in every single CHECK_FOR_INTERRUPTS()
> call. Several hours and 52 GB of logs later I have confirmed that
> (with the attached revision) at the very least the regression test
> suite can't trigger any kind of failures regardless of when we trigger
> this. The existing code in the patch for only running the explain when
> there's an active query handling that.

Thanks for the testing!

> I've attached v27. The important change here in 0001 is that it
> guarantees the interrupt handler is re-entrant, since that was a bug
> exposed by my testing. I've also included 0002 which is only meant for
> testing (it attempts to log in the plan in every
> CHECK_FOR_INTERRUPTS() call).

When SIGINT is sent during ProcessLogQueryPlanInterrupt(),
ProcessLogQueryPlanInterruptActive can remain true.
After that, pg_log_query_plan() does nothing but just returns.

AFAIU, v26 logs plan for each pg_log_query_plan() even when another
pg_log_query_plan() is running, but it doesn't cause errors or critical
problem.

Considering the problem solved and introduced by v27, I think v26 might
be fine.
How do you think?

>
> Regards,
> James

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Sun, Jun 11, 2023 at 11:07 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-06-06 03:26, James Coleman wrote:
> > On Mon, Jun 5, 2023 at 4:30 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> > wrote:
> >>
> >> On 2023-06-03 02:51, James Coleman wrote:
> >> > Hello,
> >> >
> >> > Thanks for working on this patch!
> >
> > Sure thing! I'm *very interested* in seeing this available, and I
> > think it paves the way for some additional features later on...
> >
> >> > On Thu, Dec 8, 2022 at 12:10 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> >> ...
> >> > To put it positively: we believe that, for example, catalog accesses
> >> > inside CHECK_FOR_INTERRUPTS() -- assuming that the CFI call is inside
> >> > an existing valid transaction/query state, as it would be for this
> >> > patch -- are safe. If there were problems, then those problems are
> >> > likely bugs we already have in other CFI cases.
> >>
> >> Thanks a lot for the discussion and sharing it!
> >> I really appreciate it.
> >>
> >> BTW I'm not sure whether all the CFI are called in valid transaction,
> >> do you think we should check each of them?
> >
> > I kicked off the regressions tests with a call to
> > ProcessLogQueryPlanInterrupt() in every single CHECK_FOR_INTERRUPTS()
> > call. Several hours and 52 GB of logs later I have confirmed that
> > (with the attached revision) at the very least the regression test
> > suite can't trigger any kind of failures regardless of when we trigger
> > this. The existing code in the patch for only running the explain when
> > there's an active query handling that.
>
> Thanks for the testing!
>
> > I've attached v27. The important change here in 0001 is that it
> > guarantees the interrupt handler is re-entrant, since that was a bug
> > exposed by my testing. I've also included 0002 which is only meant for
> > testing (it attempts to log in the plan in every
> > CHECK_FOR_INTERRUPTS() call).
>
> When SIGINT is sent during ProcessLogQueryPlanInterrupt(),
> ProcessLogQueryPlanInterruptActive can remain true.
> After that, pg_log_query_plan() does nothing but just returns.
>
> AFAIU, v26 logs plan for each pg_log_query_plan() even when another
> pg_log_query_plan() is running, but it doesn't cause errors or critical
> problem.
>
> Considering the problem solved and introduced by v27, I think v26 might
> be fine.
> How do you think?

The testing I did with calling this during every CFI is what uncovered
the re-entrancy problem. IIRC (without running that test again) the
problem was a stack overflow. Now, to be sure this is a particularly
degenerate case because in real-world usage it'd be impossible in
practice, I think, to trigger that many calls to this function (and by
extension the interrupt handler).

If SIGINT is the only concern we could reset
ProcessLogQueryPlanInterruptActive in error handling code. I admit
that part of my thought process here is thinking ahead to an
additional patch I'd like to see on top of this, which is logging a
query plan before cleaning up when statement timeout occurs. The
re-entrancy issue becomes more interesting then, I think, since we
would then have automated calling of the logging code. BTW: I'd
thought that would make a nice follow-up patch for this, but if you'd
prefer I could add it as another patch in the series here.

What do you think about resetting the flag versus just not having it?

Regards,
James Coleman

On 2023-06-13 00:52, James Coleman wrote:
>>
>> > I've attached v27. The important change here in 0001 is that it
>> > guarantees the interrupt handler is re-entrant, since that was a bug
>> > exposed by my testing. I've also included 0002 which is only meant for
>> > testing (it attempts to log in the plan in every
>> > CHECK_FOR_INTERRUPTS() call).
>>
>> When SIGINT is sent during ProcessLogQueryPlanInterrupt(),
>> ProcessLogQueryPlanInterruptActive can remain true.
>> After that, pg_log_query_plan() does nothing but just returns.
>>
>> AFAIU, v26 logs plan for each pg_log_query_plan() even when another
>> pg_log_query_plan() is running, but it doesn't cause errors or
>> critical
>> problem.
>>
>> Considering the problem solved and introduced by v27, I think v26
>> might
>> be fine.
>> How do you think?
>
> The testing I did with calling this during every CFI is what uncovered
> the re-entrancy problem. IIRC (without running that test again) the
> problem was a stack overflow. Now, to be sure this is a particularly
> degenerate case because in real-world usage it'd be impossible in
> practice, I think, to trigger that many calls to this function (and by
> extension the interrupt handler).

Yeah.In addition, currently only superusers are allowed to execute
pg_log_query_plan(), I think we don't need to think about cases
where users are malicious.

> If SIGINT is the only concern we could reset
> ProcessLogQueryPlanInterruptActive in error handling code. I admit
> that part of my thought process here is thinking ahead to an
> additional patch I'd like to see on top of this, which is logging a
> query plan before cleaning up when statement timeout occurs.

I remember this is what you wanted do.[1]

> The
> re-entrancy issue becomes more interesting then, I think, since we
> would then have automated calling of the logging code. BTW: I'd
> thought that would make a nice follow-up patch for this, but if you'd
> prefer I could add it as another patch in the series here.
>
> What do you think about resetting the flag versus just not having it?

If I understand you correctly, adding the flag is not necessary for this
proposal.
To keep the patch simple, I prefer not having it.

[1]
/message-id/flat/CA%2BTgmoYW_rSOW4JMQ9_0Df9PKQ%3DsQDOKUGA4Gc9D8w4wui8fSA%40mail.gmail.com#b57432077f8045be8588049269f7a8dd

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Tue, Jun 13, 2023 at 11:22 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-06-13 00:52, James Coleman wrote:
> >>
> >> > I've attached v27. The important change here in 0001 is that it
> >> > guarantees the interrupt handler is re-entrant, since that was a bug
> >> > exposed by my testing. I've also included 0002 which is only meant for
> >> > testing (it attempts to log in the plan in every
> >> > CHECK_FOR_INTERRUPTS() call).
> >>
> >> When SIGINT is sent during ProcessLogQueryPlanInterrupt(),
> >> ProcessLogQueryPlanInterruptActive can remain true.
> >> After that, pg_log_query_plan() does nothing but just returns.
> >>
> >> AFAIU, v26 logs plan for each pg_log_query_plan() even when another
> >> pg_log_query_plan() is running, but it doesn't cause errors or
> >> critical
> >> problem.
> >>
> >> Considering the problem solved and introduced by v27, I think v26
> >> might
> >> be fine.
> >> How do you think?
> >
> > The testing I did with calling this during every CFI is what uncovered
> > the re-entrancy problem. IIRC (without running that test again) the
> > problem was a stack overflow. Now, to be sure this is a particularly
> > degenerate case because in real-world usage it'd be impossible in
> > practice, I think, to trigger that many calls to this function (and by
> > extension the interrupt handler).
>
> Yeah.In addition, currently only superusers are allowed to execute
> pg_log_query_plan(), I think we don't need to think about cases
> where users are malicious.
>
> > If SIGINT is the only concern we could reset
> > ProcessLogQueryPlanInterruptActive in error handling code. I admit
> > that part of my thought process here is thinking ahead to an
> > additional patch I'd like to see on top of this, which is logging a
> > query plan before cleaning up when statement timeout occurs.
>
> I remember this is what you wanted do.[1]
>
> > The
> > re-entrancy issue becomes more interesting then, I think, since we
> > would then have automated calling of the logging code. BTW: I'd
> > thought that would make a nice follow-up patch for this, but if you'd
> > prefer I could add it as another patch in the series here.
> >
> > What do you think about resetting the flag versus just not having it?
>
> If I understand you correctly, adding the flag is not necessary for this
> proposal.
> To keep the patch simple, I prefer not having it.
>

I'm going to re-run tests with my patch version + resetting the flag
on SIGINT (and any other error condition) to be certain that the issue
you uncovered (where backends get stuck after a SIGINT not responding
to the requested plan logging) wasn't masking any other issues.

As long as that run is clean also then I believe the patch is safe
as-is even without the re-entrancy guard.

I'll report back with the results of that testing.

Regards,
James Coleman

On Tue, Jun 13, 2023 at 11:53 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
>
> ...
> I'm going to re-run tests with my patch version + resetting the flag
> on SIGINT (and any other error condition) to be certain that the issue
> you uncovered (where backends get stuck after a SIGINT not responding
> to the requested plan logging) wasn't masking any other issues.
>
> As long as that run is clean also then I believe the patch is safe
> as-is even without the re-entrancy guard.
>
> I'll report back with the results of that testing.

The tests have been running since last night, but have been apparently
hung now for many hours. I haven't been able to fully look into it,
but so far I know the hung (100% CPU) backend last logged this:

2023-06-14 02:00:30.045 UTC client backend[84461]
pg_regress/updatable_views LOG: query plan running on backend with
PID 84461 is:
Query Text: SELECT table_name, column_name, is_updatable
FROM information_schema.columns
WHERE table_name LIKE E'r_\\_view%'
ORDER BY table_name, ordinal_position;

The last output from the regression test harness was:

# parallel group (5 tests): index_including create_view
index_including_gist create_index create_index_spgist
ok 66 + create_index 36508 ms
ok 67 + create_index_spgist 38588 ms
ok 68 + create_view 1394 ms
ok 69 + index_including 654 ms
ok 70 + index_including_gist 1701 ms
# parallel group (16 tests): errors create_cast drop_if_exists
create_aggregate roleattributes constraints hash_func typed_table
infinite_recurse

Attaching gdb to the hung backend shows this:

#0 0x00005601ab1f9529 in ProcLockWakeup
(lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
<default_lockmethod>, lock=lock(at)entry=0x7f5325c913f0) at proc.c:1655
#1 0x00005601ab1e99dc in CleanUpLock (lock=lock(at)entry=0x7f5325c913f0,
proclock=proclock(at)entry=0x7f5325d40d60,
lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
<default_lockmethod>,
hashcode=hashcode(at)entry=573498161, wakeupNeeded=<optimized out>)
at lock.c:1673
#2 0x00005601ab1e9e21 in LockRefindAndRelease
(lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
<default_lockmethod>, proc=<optimized out>,
locktag=locktag(at)entry=0x5601ac3d7998, lockmode=lockmode(at)entry=1,
decrement_strong_lock_count=decrement_strong_lock_count(at)entry=false)
at lock.c:3150
#3 0x00005601ab1edb27 in LockReleaseAll
(lockmethodid=lockmethodid(at)entry=1, allLocks=false) at lock.c:2295
#4 0x00005601ab1f8599 in ProcReleaseLocks
(isCommit=isCommit(at)entry=true) at proc.c:781
#5 0x00005601ab37f1f4 in ResourceOwnerReleaseInternal
(owner=<optimized out>, phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
resowner.c:618
#6 0x00005601ab37f7b7 in ResourceOwnerRelease (owner=<optimized out>,
phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
resowner.c:494
#7 0x00005601aaec1d84 in CommitTransaction () at xact.c:2334
#8 0x00005601aaec2b22 in CommitTransactionCommand () at xact.c:3067
#9 0x00005601ab200a66 in finish_xact_command () at postgres.c:2783
#10 0x00005601ab20338f in exec_simple_query (
query_string=query_string(at)entry=0x5601ac3b0858 "SELECT table_name,
column_name, is_updatable\n FROM information_schema.columns\n WHERE
table_name LIKE E'r_\\\\_view%'\n ORDER BY table_name,
ordinal_position;") at postgres.c:1300

I am unable to connect to the regression test Postgres instance --
psql just hangs, so the lock seems to have affected the postmaster
also.

I'm wondering if this might represent a bug in the current patch.

Regards,
James Coleman

On 2023-06-15 01:48, James Coleman wrote:
> On Tue, Jun 13, 2023 at 11:53 AM James Coleman <jtc331(at)gmail(dot)com>
> wrote:
>>
>> ...
>> I'm going to re-run tests with my patch version + resetting the flag
>> on SIGINT (and any other error condition) to be certain that the issue
>> you uncovered (where backends get stuck after a SIGINT not responding
>> to the requested plan logging) wasn't masking any other issues.
>>
>> As long as that run is clean also then I believe the patch is safe
>> as-is even without the re-entrancy guard.
>>
>> I'll report back with the results of that testing.
>
> The tests have been running since last night, but have been apparently
> hung now for many hours. I haven't been able to fully look into it,
> but so far I know the hung (100% CPU) backend last logged this:
>
> 2023-06-14 02:00:30.045 UTC client backend[84461]
> pg_regress/updatable_views LOG: query plan running on backend with
> PID 84461 is:
> Query Text: SELECT table_name, column_name, is_updatable
> FROM information_schema.columns
> WHERE table_name LIKE E'r_\\_view%'
> ORDER BY table_name, ordinal_position;
>
> The last output from the regression test harness was:
>
> # parallel group (5 tests): index_including create_view
> index_including_gist create_index create_index_spgist
> ok 66 + create_index 36508 ms
> ok 67 + create_index_spgist 38588 ms
> ok 68 + create_view 1394 ms
> ok 69 + index_including 654 ms
> ok 70 + index_including_gist 1701 ms
> # parallel group (16 tests): errors create_cast drop_if_exists
> create_aggregate roleattributes constraints hash_func typed_table
> infinite_recurse
>
> Attaching gdb to the hung backend shows this:
>
> #0 0x00005601ab1f9529 in ProcLockWakeup
> (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> <default_lockmethod>, lock=lock(at)entry=0x7f5325c913f0) at proc.c:1655
> #1 0x00005601ab1e99dc in CleanUpLock (lock=lock(at)entry=0x7f5325c913f0,
> proclock=proclock(at)entry=0x7f5325d40d60,
> lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> <default_lockmethod>,
> hashcode=hashcode(at)entry=573498161, wakeupNeeded=<optimized out>)
> at lock.c:1673
> #2 0x00005601ab1e9e21 in LockRefindAndRelease
> (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> <default_lockmethod>, proc=<optimized out>,
> locktag=locktag(at)entry=0x5601ac3d7998, lockmode=lockmode(at)entry=1,
>
> decrement_strong_lock_count=decrement_strong_lock_count(at)entry=false)
> at lock.c:3150
> #3 0x00005601ab1edb27 in LockReleaseAll
> (lockmethodid=lockmethodid(at)entry=1, allLocks=false) at lock.c:2295
> #4 0x00005601ab1f8599 in ProcReleaseLocks
> (isCommit=isCommit(at)entry=true) at proc.c:781
> #5 0x00005601ab37f1f4 in ResourceOwnerReleaseInternal
> (owner=<optimized out>, phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
> isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
> resowner.c:618
> #6 0x00005601ab37f7b7 in ResourceOwnerRelease (owner=<optimized out>,
> phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
> isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
> resowner.c:494
> #7 0x00005601aaec1d84 in CommitTransaction () at xact.c:2334
> #8 0x00005601aaec2b22 in CommitTransactionCommand () at xact.c:3067
> #9 0x00005601ab200a66 in finish_xact_command () at postgres.c:2783
> #10 0x00005601ab20338f in exec_simple_query (
> query_string=query_string(at)entry=0x5601ac3b0858 "SELECT table_name,
> column_name, is_updatable\n FROM information_schema.columns\n WHERE
> table_name LIKE E'r_\\\\_view%'\n ORDER BY table_name,
> ordinal_position;") at postgres.c:1300
>
> I am unable to connect to the regression test Postgres instance --
> psql just hangs, so the lock seems to have affected the postmaster
> also.
>
> I'm wondering if this might represent a bug in the current patch.

Thanks for running and analyzing the test!

Could you share me how you are running the test?

I imagined something like below, but currently couldn't reproduce it.
- apply both v26-0001 and v27-0002 and build
- run PostgreSQL with default GUCssaaa
- make installcheck-world
- run 'SELECT pg_log_query_plan(pid) FROM pg_stat_activity \watch 0.1'
during make installcheck-world

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Thu, Jun 15, 2023 at 9:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-06-15 01:48, James Coleman wrote:
> > On Tue, Jun 13, 2023 at 11:53 AM James Coleman <jtc331(at)gmail(dot)com>
> > wrote:
> >>
> >> ...
> >> I'm going to re-run tests with my patch version + resetting the flag
> >> on SIGINT (and any other error condition) to be certain that the issue
> >> you uncovered (where backends get stuck after a SIGINT not responding
> >> to the requested plan logging) wasn't masking any other issues.
> >>
> >> As long as that run is clean also then I believe the patch is safe
> >> as-is even without the re-entrancy guard.
> >>
> >> I'll report back with the results of that testing.
> >
> > The tests have been running since last night, but have been apparently
> > hung now for many hours. I haven't been able to fully look into it,
> > but so far I know the hung (100% CPU) backend last logged this:
> >
> > 2023-06-14 02:00:30.045 UTC client backend[84461]
> > pg_regress/updatable_views LOG: query plan running on backend with
> > PID 84461 is:
> > Query Text: SELECT table_name, column_name, is_updatable
> > FROM information_schema.columns
> > WHERE table_name LIKE E'r_\\_view%'
> > ORDER BY table_name, ordinal_position;
> >
> > The last output from the regression test harness was:
> >
> > # parallel group (5 tests): index_including create_view
> > index_including_gist create_index create_index_spgist
> > ok 66 + create_index 36508 ms
> > ok 67 + create_index_spgist 38588 ms
> > ok 68 + create_view 1394 ms
> > ok 69 + index_including 654 ms
> > ok 70 + index_including_gist 1701 ms
> > # parallel group (16 tests): errors create_cast drop_if_exists
> > create_aggregate roleattributes constraints hash_func typed_table
> > infinite_recurse
> >
> > Attaching gdb to the hung backend shows this:
> >
> > #0 0x00005601ab1f9529 in ProcLockWakeup
> > (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> > <default_lockmethod>, lock=lock(at)entry=0x7f5325c913f0) at proc.c:1655
> > #1 0x00005601ab1e99dc in CleanUpLock (lock=lock(at)entry=0x7f5325c913f0,
> > proclock=proclock(at)entry=0x7f5325d40d60,
> > lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> > <default_lockmethod>,
> > hashcode=hashcode(at)entry=573498161, wakeupNeeded=<optimized out>)
> > at lock.c:1673
> > #2 0x00005601ab1e9e21 in LockRefindAndRelease
> > (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
> > <default_lockmethod>, proc=<optimized out>,
> > locktag=locktag(at)entry=0x5601ac3d7998, lockmode=lockmode(at)entry=1,
> >
> > decrement_strong_lock_count=decrement_strong_lock_count(at)entry=false)
> > at lock.c:3150
> > #3 0x00005601ab1edb27 in LockReleaseAll
> > (lockmethodid=lockmethodid(at)entry=1, allLocks=false) at lock.c:2295
> > #4 0x00005601ab1f8599 in ProcReleaseLocks
> > (isCommit=isCommit(at)entry=true) at proc.c:781
> > #5 0x00005601ab37f1f4 in ResourceOwnerReleaseInternal
> > (owner=<optimized out>, phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
> > isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
> > resowner.c:618
> > #6 0x00005601ab37f7b7 in ResourceOwnerRelease (owner=<optimized out>,
> > phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
> > isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
> > resowner.c:494
> > #7 0x00005601aaec1d84 in CommitTransaction () at xact.c:2334
> > #8 0x00005601aaec2b22 in CommitTransactionCommand () at xact.c:3067
> > #9 0x00005601ab200a66 in finish_xact_command () at postgres.c:2783
> > #10 0x00005601ab20338f in exec_simple_query (
> > query_string=query_string(at)entry=0x5601ac3b0858 "SELECT table_name,
> > column_name, is_updatable\n FROM information_schema.columns\n WHERE
> > table_name LIKE E'r_\\\\_view%'\n ORDER BY table_name,
> > ordinal_position;") at postgres.c:1300
> >
> > I am unable to connect to the regression test Postgres instance --
> > psql just hangs, so the lock seems to have affected the postmaster
> > also.
> >
> > I'm wondering if this might represent a bug in the current patch.
>
> Thanks for running and analyzing the test!

Sure thing!

> Could you share me how you are running the test?
>
> I imagined something like below, but currently couldn't reproduce it.
> - apply both v26-0001 and v27-0002 and build
> - run PostgreSQL with default GUCssaaa
> - make installcheck-world
> - run 'SELECT pg_log_query_plan(pid) FROM pg_stat_activity \watch 0.1'
> during make installcheck-world

Apologies, I should have attached my updated patch (with the fix for
the bug you'd reporting with the re-entrancy guard). Attached is v28
which sets ProcessLogQueryPlanInterruptActive to false in errfinish
when necessary. Once built with those two patches I'm simply running
`make check`.

Regards,
James Coleman

On 2023-06-16 01:34, James Coleman wrote:
> On Thu, Jun 15, 2023 at 9:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-06-15 01:48, James Coleman wrote:
>> > On Tue, Jun 13, 2023 at 11:53 AM James Coleman <jtc331(at)gmail(dot)com>
>> > wrote:
>> >>
>> >> ...
>> >> I'm going to re-run tests with my patch version + resetting the flag
>> >> on SIGINT (and any other error condition) to be certain that the issue
>> >> you uncovered (where backends get stuck after a SIGINT not responding
>> >> to the requested plan logging) wasn't masking any other issues.
>> >>
>> >> As long as that run is clean also then I believe the patch is safe
>> >> as-is even without the re-entrancy guard.
>> >>
>> >> I'll report back with the results of that testing.
>> >
>> > The tests have been running since last night, but have been apparently
>> > hung now for many hours. I haven't been able to fully look into it,
>> > but so far I know the hung (100% CPU) backend last logged this:
>> >
>> > 2023-06-14 02:00:30.045 UTC client backend[84461]
>> > pg_regress/updatable_views LOG: query plan running on backend with
>> > PID 84461 is:
>> > Query Text: SELECT table_name, column_name, is_updatable
>> > FROM information_schema.columns
>> > WHERE table_name LIKE E'r_\\_view%'
>> > ORDER BY table_name, ordinal_position;
>> >
>> > The last output from the regression test harness was:
>> >
>> > # parallel group (5 tests): index_including create_view
>> > index_including_gist create_index create_index_spgist
>> > ok 66 + create_index 36508 ms
>> > ok 67 + create_index_spgist 38588 ms
>> > ok 68 + create_view 1394 ms
>> > ok 69 + index_including 654 ms
>> > ok 70 + index_including_gist 1701 ms
>> > # parallel group (16 tests): errors create_cast drop_if_exists
>> > create_aggregate roleattributes constraints hash_func typed_table
>> > infinite_recurse
>> >
>> > Attaching gdb to the hung backend shows this:
>> >
>> > #0 0x00005601ab1f9529 in ProcLockWakeup
>> > (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
>> > <default_lockmethod>, lock=lock(at)entry=0x7f5325c913f0) at proc.c:1655
>> > #1 0x00005601ab1e99dc in CleanUpLock (lock=lock(at)entry=0x7f5325c913f0,
>> > proclock=proclock(at)entry=0x7f5325d40d60,
>> > lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
>> > <default_lockmethod>,
>> > hashcode=hashcode(at)entry=573498161, wakeupNeeded=<optimized out>)
>> > at lock.c:1673
>> > #2 0x00005601ab1e9e21 in LockRefindAndRelease
>> > (lockMethodTable=lockMethodTable(at)entry=0x5601ab6484e0
>> > <default_lockmethod>, proc=<optimized out>,
>> > locktag=locktag(at)entry=0x5601ac3d7998, lockmode=lockmode(at)entry=1,
>> >
>> > decrement_strong_lock_count=decrement_strong_lock_count(at)entry=false)
>> > at lock.c:3150
>> > #3 0x00005601ab1edb27 in LockReleaseAll
>> > (lockmethodid=lockmethodid(at)entry=1, allLocks=false) at lock.c:2295
>> > #4 0x00005601ab1f8599 in ProcReleaseLocks
>> > (isCommit=isCommit(at)entry=true) at proc.c:781
>> > #5 0x00005601ab37f1f4 in ResourceOwnerReleaseInternal
>> > (owner=<optimized out>, phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
>> > isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
>> > resowner.c:618
>> > #6 0x00005601ab37f7b7 in ResourceOwnerRelease (owner=<optimized out>,
>> > phase=phase(at)entry=RESOURCE_RELEASE_LOCKS,
>> > isCommit=isCommit(at)entry=true, isTopLevel=isTopLevel(at)entry=true) at
>> > resowner.c:494
>> > #7 0x00005601aaec1d84 in CommitTransaction () at xact.c:2334
>> > #8 0x00005601aaec2b22 in CommitTransactionCommand () at xact.c:3067
>> > #9 0x00005601ab200a66 in finish_xact_command () at postgres.c:2783
>> > #10 0x00005601ab20338f in exec_simple_query (
>> > query_string=query_string(at)entry=0x5601ac3b0858 "SELECT table_name,
>> > column_name, is_updatable\n FROM information_schema.columns\n WHERE
>> > table_name LIKE E'r_\\\\_view%'\n ORDER BY table_name,
>> > ordinal_position;") at postgres.c:1300
>> >
>> > I am unable to connect to the regression test Postgres instance --
>> > psql just hangs, so the lock seems to have affected the postmaster
>> > also.
>> >
>> > I'm wondering if this might represent a bug in the current patch.
>>
>> Thanks for running and analyzing the test!
>
> Sure thing!
>
>> Could you share me how you are running the test?
>>
>> I imagined something like below, but currently couldn't reproduce it.
>> - apply both v26-0001 and v27-0002 and build
>> - run PostgreSQL with default GUCssaaa
>> - make installcheck-world
>> - run 'SELECT pg_log_query_plan(pid) FROM pg_stat_activity \watch 0.1'
>> during make installcheck-world
>
> Apologies, I should have attached my updated patch (with the fix for
> the bug you'd reporting with the re-entrancy guard). Attached is v28
> which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> when necessary. Once built with those two patches I'm simply running
> `make check`.

Thanks!

However, I haven't succeeded in reproducing the problem as below:

> The tests have been running since last night, but have been apparently
> hung now for many hours. I haven't been able to fully look into it,
> but so far I know the hung (100% CPU) backend last logged this:

Did you do something like this?

$ ./configure --prefix=/home/ubuntu/pgsql/master --enable-cassert
$ git apply
../patch/v28-0001-Add-function-to-log-the-plan-of-the-query.patch
../patch/v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
$ make
$ make check

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2023-06-16 01:34, James Coleman wrote:
> Attached is v28
> which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> when necessary. Once built with those two patches I'm simply running
> `make check`.

With v28-0001 and v28-0002 patch, I confirmed backend processes consume
huge
amount of memory and under some environments they were terminated by OOM
killer.

This was because memory was allocated from existing memory contexts and
they
were not freed after ProcessLogQueryPlanInterrupt().
Updated the patch to use dedicated memory context for
ProcessLogQueryPlanInterrupt().

Applying attached patch and v28-0002 patch, `make check` successfully
completed after 20min and 50GB of logs on my environment.

>>> On 2023-06-15 01:48, James Coleman wrote:
>>> > The tests have been running since last night, but have been apparently
>>> > hung now for many hours.

I don't know if this has anything to do with the hung you faced, but I
thought
it might be possible that the large amount of memory usage resulted in
swapping, which caused a significant delay in processing.

If possible, I would be very grateful if you could try to reproduce this
with
the v29 patch.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Thu, Aug 17, 2023 at 10:02 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-06-16 01:34, James Coleman wrote:
> > Attached is v28
> > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> > when necessary. Once built with those two patches I'm simply running
> > `make check`.
>
> With v28-0001 and v28-0002 patch, I confirmed backend processes consume
> huge
> amount of memory and under some environments they were terminated by OOM
> killer.
>
> This was because memory was allocated from existing memory contexts and
> they
> were not freed after ProcessLogQueryPlanInterrupt().
> Updated the patch to use dedicated memory context for
> ProcessLogQueryPlanInterrupt().
>
> Applying attached patch and v28-0002 patch, `make check` successfully
> completed after 20min and 50GB of logs on my environment.
>
> >>> On 2023-06-15 01:48, James Coleman wrote:
> >>> > The tests have been running since last night, but have been apparently
> >>> > hung now for many hours.
>
> I don't know if this has anything to do with the hung you faced, but I
> thought
> it might be possible that the large amount of memory usage resulted in
> swapping, which caused a significant delay in processing.

Ah, yes, I think that could be a possible explanation. I was delaying
on this thread because I wasn't comfortable with having caused an
issue once (even if I couldn't easily reproduce) without at least some
theory as to the cause (and a fix).

> If possible, I would be very grateful if you could try to reproduce this
> with
> the v29 patch.

I'll kick off some testing.

Thanks,
James Coleman

On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
>
> On Thu, Aug 17, 2023 at 10:02 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> >
> > On 2023-06-16 01:34, James Coleman wrote:
> > > Attached is v28
> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> > > when necessary. Once built with those two patches I'm simply running
> > > `make check`.
> >
> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
> > huge
> > amount of memory and under some environments they were terminated by OOM
> > killer.
> >
> > This was because memory was allocated from existing memory contexts and
> > they
> > were not freed after ProcessLogQueryPlanInterrupt().
> > Updated the patch to use dedicated memory context for
> > ProcessLogQueryPlanInterrupt().
> >
> > Applying attached patch and v28-0002 patch, `make check` successfully
> > completed after 20min and 50GB of logs on my environment.
> >
> > >>> On 2023-06-15 01:48, James Coleman wrote:
> > >>> > The tests have been running since last night, but have been apparently
> > >>> > hung now for many hours.
> >
> > I don't know if this has anything to do with the hung you faced, but I
> > thought
> > it might be possible that the large amount of memory usage resulted in
> > swapping, which caused a significant delay in processing.
>
> Ah, yes, I think that could be a possible explanation. I was delaying
> on this thread because I wasn't comfortable with having caused an
> issue once (even if I couldn't easily reproduce) without at least some
> theory as to the cause (and a fix).
>
> > If possible, I would be very grateful if you could try to reproduce this
> > with
> > the v29 patch.
>
> I'll kick off some testing.
>

I don't have time to investigate what's happening here, but 24 hours
later the first "make check" is still running, and at first glance it
seems to have the same behavior I'd seen that first time. The test
output is to this point:

# parallel group (5 tests): index_including create_view
index_including_gist create_index create_index_spgist
ok 66 + create_index 26365 ms
ok 67 + create_index_spgist 27675 ms
ok 68 + create_view 1235 ms
ok 69 + index_including 1102 ms
ok 70 + index_including_gist 1633 ms
# parallel group (16 tests): create_aggregate create_cast errors
roleattributes drop_if_exists hash_func typed_table create_am
infinite_recurse

and it hasn't progressed past that point since at least ~16 hours ago
(the first several hours of the run I wasn't monitoring it).

I haven't connected up gdb yet, and won't be able to until maybe
tomorrow, but here's the ps output for postgres processes that are
running:

admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
/home/admin/postgresql-test/bin/postgres -D
/home/admin/postgresql-test-data
admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
postgres: checkpointer
admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
postgres: background writer
admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
postgres: walwriter
admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
postgres: autovacuum launcher
admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
postgres: logical replication launcher
admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
/bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
../../../src/test/regress/pg_regress --temp-instance=./tmp_check
--inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
--schedule=./parallel_schedule
admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
listen_addresses= -k /tmp/pg_regress-7mmGUa
admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
postgres: checkpointer
admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
postgres: background writer
admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
postgres: walwriter
admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
postgres: autovacuum launcher
admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
postgres: logical replication launcher
admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
postgres: admin regression [local] SELECT waiting
admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
postgres: admin regression [local] SELECT waiting
admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
postgres: admin regression [local] VACUUM
admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
postgres: admin regression [local] SELECT waiting
admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
postgres: admin regression [local] DELETE waiting
admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
postgres: admin regression [local] ALTER TABLE waiting
admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
postgres: admin regression [local] ANALYZE waiting
admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
postgres: autovacuum worker
admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
postgres: autovacuum worker
admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
postgres: autovacuum worker

As you can see there are a bunch of backends presumably waiting, and
also the VACUUM process has been pegging a single CPU core for at
least since that ~16 hour ago mark.

I hope to be able to do more investigation later, but I wanted to at
least give you this information now.

James Coleman

On 2023-08-26 21:03, James Coleman wrote:
> On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
>>
>> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
>> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>> >
>> > On 2023-06-16 01:34, James Coleman wrote:
>> > > Attached is v28
>> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
>> > > when necessary. Once built with those two patches I'm simply running
>> > > `make check`.
>> >
>> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
>> > huge
>> > amount of memory and under some environments they were terminated by OOM
>> > killer.
>> >
>> > This was because memory was allocated from existing memory contexts and
>> > they
>> > were not freed after ProcessLogQueryPlanInterrupt().
>> > Updated the patch to use dedicated memory context for
>> > ProcessLogQueryPlanInterrupt().
>> >
>> > Applying attached patch and v28-0002 patch, `make check` successfully
>> > completed after 20min and 50GB of logs on my environment.
>> >
>> > >>> On 2023-06-15 01:48, James Coleman wrote:
>> > >>> > The tests have been running since last night, but have been apparently
>> > >>> > hung now for many hours.
>> >
>> > I don't know if this has anything to do with the hung you faced, but I
>> > thought
>> > it might be possible that the large amount of memory usage resulted in
>> > swapping, which caused a significant delay in processing.
>>
>> Ah, yes, I think that could be a possible explanation. I was delaying
>> on this thread because I wasn't comfortable with having caused an
>> issue once (even if I couldn't easily reproduce) without at least some
>> theory as to the cause (and a fix).
>>
>> > If possible, I would be very grateful if you could try to reproduce this
>> > with
>> > the v29 patch.
>>
>> I'll kick off some testing.
>>
>
> I don't have time to investigate what's happening here, but 24 hours
> later the first "make check" is still running, and at first glance it
> seems to have the same behavior I'd seen that first time. The test
> output is to this point:
>
> # parallel group (5 tests): index_including create_view
> index_including_gist create_index create_index_spgist
> ok 66 + create_index 26365 ms
> ok 67 + create_index_spgist 27675 ms
> ok 68 + create_view 1235 ms
> ok 69 + index_including 1102 ms
> ok 70 + index_including_gist 1633 ms
> # parallel group (16 tests): create_aggregate create_cast errors
> roleattributes drop_if_exists hash_func typed_table create_am
> infinite_recurse
>
> and it hasn't progressed past that point since at least ~16 hours ago
> (the first several hours of the run I wasn't monitoring it).
>
> I haven't connected up gdb yet, and won't be able to until maybe
> tomorrow, but here's the ps output for postgres processes that are
> running:
>
> admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
> /home/admin/postgresql-test/bin/postgres -D
> /home/admin/postgresql-test-data
> admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
> postgres: checkpointer
> admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
> postgres: background writer
> admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
> postgres: walwriter
> admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
> postgres: autovacuum launcher
> admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
> postgres: logical replication launcher
> admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
> /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
> PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
> LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
> INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
> ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
> --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
> --schedule=./parallel_schedule
> admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
> postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
> listen_addresses= -k /tmp/pg_regress-7mmGUa
> admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
> postgres: checkpointer
> admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
> postgres: background writer
> admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
> postgres: walwriter
> admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
> postgres: autovacuum launcher
> admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
> postgres: logical replication launcher
> admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
> postgres: admin regression [local] SELECT waiting
> admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
> postgres: admin regression [local] SELECT waiting
> admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
> postgres: admin regression [local] VACUUM
> admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
> postgres: admin regression [local] SELECT waiting
> admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
> postgres: admin regression [local] DELETE waiting
> admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
> postgres: admin regression [local] ALTER TABLE waiting
> admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
> postgres: admin regression [local] ANALYZE waiting
> admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
> postgres: autovacuum worker
> admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
> postgres: autovacuum worker
> admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
> postgres: autovacuum worker
>
> As you can see there are a bunch of backends presumably waiting, and
> also the VACUUM process has been pegging a single CPU core for at
> least since that ~16 hour ago mark.
>
> I hope to be able to do more investigation later, but I wanted to at
> least give you this information now.

Thanks a lot for testing the patch!
I really appreciate your cooperation.

Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
22.04 and macOS, but unfortunately(fortunately?) they succeeded as
below:

```
$ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
$ git apply v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
$ ./configure --enable-debug --enable-cassert
$ make
$ make check

...(snip)...

# parallel group (5 tests): index_including index_including_gist
create_view create_index create_index_spgist
ok 66 + create_index 25033 ms
ok 67 + create_index_spgist 26144 ms
ok 68 + create_view 3061 ms
ok 69 + index_including 976 ms
ok 70 + index_including_gist 2998 ms
# parallel group (16 tests): create_cast errors create_aggregate
roleattributes drop_if_exists hash_func typed_table
create_am select constraints updatable_views inherit triggers vacuum
create_function_sql infinite_recurse
ok 71 + create_aggregate 225 ms
ok 72 + create_function_sql 18874 ms
ok 73 + create_cast 168 ms

...(snip)...

# All 215 tests passed.
```

If you notice any difference, I would be grateful if you could let me
know.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Mon, Aug 28, 2023 at 3:01 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-08-26 21:03, James Coleman wrote:
> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
> >>
> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
> >> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> >> >
> >> > On 2023-06-16 01:34, James Coleman wrote:
> >> > > Attached is v28
> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> >> > > when necessary. Once built with those two patches I'm simply running
> >> > > `make check`.
> >> >
> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
> >> > huge
> >> > amount of memory and under some environments they were terminated by OOM
> >> > killer.
> >> >
> >> > This was because memory was allocated from existing memory contexts and
> >> > they
> >> > were not freed after ProcessLogQueryPlanInterrupt().
> >> > Updated the patch to use dedicated memory context for
> >> > ProcessLogQueryPlanInterrupt().
> >> >
> >> > Applying attached patch and v28-0002 patch, `make check` successfully
> >> > completed after 20min and 50GB of logs on my environment.
> >> >
> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
> >> > >>> > The tests have been running since last night, but have been apparently
> >> > >>> > hung now for many hours.
> >> >
> >> > I don't know if this has anything to do with the hung you faced, but I
> >> > thought
> >> > it might be possible that the large amount of memory usage resulted in
> >> > swapping, which caused a significant delay in processing.
> >>
> >> Ah, yes, I think that could be a possible explanation. I was delaying
> >> on this thread because I wasn't comfortable with having caused an
> >> issue once (even if I couldn't easily reproduce) without at least some
> >> theory as to the cause (and a fix).
> >>
> >> > If possible, I would be very grateful if you could try to reproduce this
> >> > with
> >> > the v29 patch.
> >>
> >> I'll kick off some testing.
> >>
> >
> > I don't have time to investigate what's happening here, but 24 hours
> > later the first "make check" is still running, and at first glance it
> > seems to have the same behavior I'd seen that first time. The test
> > output is to this point:
> >
> > # parallel group (5 tests): index_including create_view
> > index_including_gist create_index create_index_spgist
> > ok 66 + create_index 26365 ms
> > ok 67 + create_index_spgist 27675 ms
> > ok 68 + create_view 1235 ms
> > ok 69 + index_including 1102 ms
> > ok 70 + index_including_gist 1633 ms
> > # parallel group (16 tests): create_aggregate create_cast errors
> > roleattributes drop_if_exists hash_func typed_table create_am
> > infinite_recurse
> >
> > and it hasn't progressed past that point since at least ~16 hours ago
> > (the first several hours of the run I wasn't monitoring it).
> >
> > I haven't connected up gdb yet, and won't be able to until maybe
> > tomorrow, but here's the ps output for postgres processes that are
> > running:
> >
> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
> > /home/admin/postgresql-test/bin/postgres -D
> > /home/admin/postgresql-test-data
> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
> > postgres: checkpointer
> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
> > postgres: background writer
> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
> > postgres: walwriter
> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
> > postgres: autovacuum launcher
> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
> > postgres: logical replication launcher
> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
> > --schedule=./parallel_schedule
> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
> > listen_addresses= -k /tmp/pg_regress-7mmGUa
> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
> > postgres: checkpointer
> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
> > postgres: background writer
> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
> > postgres: walwriter
> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
> > postgres: autovacuum launcher
> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
> > postgres: logical replication launcher
> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
> > postgres: admin regression [local] SELECT waiting
> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
> > postgres: admin regression [local] SELECT waiting
> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
> > postgres: admin regression [local] VACUUM
> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
> > postgres: admin regression [local] SELECT waiting
> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
> > postgres: admin regression [local] DELETE waiting
> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
> > postgres: admin regression [local] ALTER TABLE waiting
> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
> > postgres: admin regression [local] ANALYZE waiting
> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
> > postgres: autovacuum worker
> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
> > postgres: autovacuum worker
> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
> > postgres: autovacuum worker
> >
> > As you can see there are a bunch of backends presumably waiting, and
> > also the VACUUM process has been pegging a single CPU core for at
> > least since that ~16 hour ago mark.
> >
> > I hope to be able to do more investigation later, but I wanted to at
> > least give you this information now.
>
> Thanks a lot for testing the patch!
> I really appreciate your cooperation.
>
> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
> below:
>
> ```
> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
> $ git apply v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
> $ ./configure --enable-debug --enable-cassert
> $ make
> $ make check
>
> ...(snip)...
>
> # parallel group (5 tests): index_including index_including_gist
> create_view create_index create_index_spgist
> ok 66 + create_index 25033 ms
> ok 67 + create_index_spgist 26144 ms
> ok 68 + create_view 3061 ms
> ok 69 + index_including 976 ms
> ok 70 + index_including_gist 2998 ms
> # parallel group (16 tests): create_cast errors create_aggregate
> roleattributes drop_if_exists hash_func typed_table
> create_am select constraints updatable_views inherit triggers vacuum
> create_function_sql infinite_recurse
> ok 71 + create_aggregate 225 ms
> ok 72 + create_function_sql 18874 ms
> ok 73 + create_cast 168 ms
>
> ...(snip)...
>
> # All 215 tests passed.
> ```
>
> If you notice any difference, I would be grateful if you could let me
> know.

I've never been able to reproduce it (haven't tested the new version,
but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
(first buster and now bullseye).

I'm attaching several stacktraces in the hope that they provide some
clues. These all match the ps output I sent earlier, though note in
that output there is both the regress instance and my test instance
(pid 3213249) running (different ports, of course, and they are from
the exact same compilation run). I've attached ps output for the
postgres processes under the make check process to simplify cross
referencing.

A few interesting things:
- There's definitely a lock on a relation that seems to be what's
blocking the processes.
- When I try to connect with psql the process forks but then hangs
(see the ps output with task names stuck in "authentication"). I've
also included a trace from one of these.

If you think a core file for any of these processes would be helpful
for debugging I'd be happy to try to figure out a way to get that to
you.

Regards,
James Coleman

On 2023-08-28 22:47, James Coleman wrote:
> On Mon, Aug 28, 2023 at 3:01 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-08-26 21:03, James Coleman wrote:
>> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
>> >>
>> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
>> >> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>> >> >
>> >> > On 2023-06-16 01:34, James Coleman wrote:
>> >> > > Attached is v28
>> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
>> >> > > when necessary. Once built with those two patches I'm simply running
>> >> > > `make check`.
>> >> >
>> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
>> >> > huge
>> >> > amount of memory and under some environments they were terminated by OOM
>> >> > killer.
>> >> >
>> >> > This was because memory was allocated from existing memory contexts and
>> >> > they
>> >> > were not freed after ProcessLogQueryPlanInterrupt().
>> >> > Updated the patch to use dedicated memory context for
>> >> > ProcessLogQueryPlanInterrupt().
>> >> >
>> >> > Applying attached patch and v28-0002 patch, `make check` successfully
>> >> > completed after 20min and 50GB of logs on my environment.
>> >> >
>> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
>> >> > >>> > The tests have been running since last night, but have been apparently
>> >> > >>> > hung now for many hours.
>> >> >
>> >> > I don't know if this has anything to do with the hung you faced, but I
>> >> > thought
>> >> > it might be possible that the large amount of memory usage resulted in
>> >> > swapping, which caused a significant delay in processing.
>> >>
>> >> Ah, yes, I think that could be a possible explanation. I was delaying
>> >> on this thread because I wasn't comfortable with having caused an
>> >> issue once (even if I couldn't easily reproduce) without at least some
>> >> theory as to the cause (and a fix).
>> >>
>> >> > If possible, I would be very grateful if you could try to reproduce this
>> >> > with
>> >> > the v29 patch.
>> >>
>> >> I'll kick off some testing.
>> >>
>> >
>> > I don't have time to investigate what's happening here, but 24 hours
>> > later the first "make check" is still running, and at first glance it
>> > seems to have the same behavior I'd seen that first time. The test
>> > output is to this point:
>> >
>> > # parallel group (5 tests): index_including create_view
>> > index_including_gist create_index create_index_spgist
>> > ok 66 + create_index 26365 ms
>> > ok 67 + create_index_spgist 27675 ms
>> > ok 68 + create_view 1235 ms
>> > ok 69 + index_including 1102 ms
>> > ok 70 + index_including_gist 1633 ms
>> > # parallel group (16 tests): create_aggregate create_cast errors
>> > roleattributes drop_if_exists hash_func typed_table create_am
>> > infinite_recurse
>> >
>> > and it hasn't progressed past that point since at least ~16 hours ago
>> > (the first several hours of the run I wasn't monitoring it).
>> >
>> > I haven't connected up gdb yet, and won't be able to until maybe
>> > tomorrow, but here's the ps output for postgres processes that are
>> > running:
>> >
>> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
>> > /home/admin/postgresql-test/bin/postgres -D
>> > /home/admin/postgresql-test-data
>> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
>> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
>> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
>> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
>> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
>> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
>> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
>> > --schedule=./parallel_schedule
>> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
>> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
>> > listen_addresses= -k /tmp/pg_regress-7mmGUa
>> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
>> > postgres: admin regression [local] VACUUM
>> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
>> > postgres: admin regression [local] DELETE waiting
>> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ALTER TABLE waiting
>> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ANALYZE waiting
>> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> >
>> > As you can see there are a bunch of backends presumably waiting, and
>> > also the VACUUM process has been pegging a single CPU core for at
>> > least since that ~16 hour ago mark.
>> >
>> > I hope to be able to do more investigation later, but I wanted to at
>> > least give you this information now.
>>
>> Thanks a lot for testing the patch!
>> I really appreciate your cooperation.
>>
>> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
>> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
>> below:
>>
>> ```
>> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
>> $ git apply
>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
>> $ ./configure --enable-debug --enable-cassert
>> $ make
>> $ make check
>>
>> ...(snip)...
>>
>> # parallel group (5 tests): index_including index_including_gist
>> create_view create_index create_index_spgist
>> ok 66 + create_index 25033 ms
>> ok 67 + create_index_spgist 26144 ms
>> ok 68 + create_view 3061 ms
>> ok 69 + index_including 976 ms
>> ok 70 + index_including_gist 2998 ms
>> # parallel group (16 tests): create_cast errors create_aggregate
>> roleattributes drop_if_exists hash_func typed_table
>> create_am select constraints updatable_views inherit triggers vacuum
>> create_function_sql infinite_recurse
>> ok 71 + create_aggregate 225 ms
>> ok 72 + create_function_sql 18874 ms
>> ok 73 + create_cast 168 ms
>>
>> ...(snip)...
>>
>> # All 215 tests passed.
>> ```
>>
>> If you notice any difference, I would be grateful if you could let me
>> know.
>
> I've never been able to reproduce it (haven't tested the new version,
> but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> (first buster and now bullseye).
>
> I'm attaching several stacktraces in the hope that they provide some
> clues. These all match the ps output I sent earlier, though note in
> that output there is both the regress instance and my test instance
> (pid 3213249) running (different ports, of course, and they are from
> the exact same compilation run). I've attached ps output for the
> postgres processes under the make check process to simplify cross
> referencing.
>
> A few interesting things:
> - There's definitely a lock on a relation that seems to be what's
> blocking the processes.
> - When I try to connect with psql the process forks but then hangs
> (see the ps output with task names stuck in "authentication"). I've
> also included a trace from one of these.

Thanks for sharing them!

Many processes are waiting to acquire the LW lock, including the process
trying to output the plan(select1.trace).

I suspect that this is due to a lock that was acquired prior to being
interrupted by ProcessLogQueryPlanInterrupt(), but have not been able to
reproduce the same situation..

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Tue, Sep 5, 2023 at 9:59 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-08-28 22:47, James Coleman wrote:
> > On Mon, Aug 28, 2023 at 3:01 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> > wrote:
> >>
> >> On 2023-08-26 21:03, James Coleman wrote:
> >> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <jtc331(at)gmail(dot)com> wrote:
> >> >>
> >> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
> >> >> <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> >> >> >
> >> >> > On 2023-06-16 01:34, James Coleman wrote:
> >> >> > > Attached is v28
> >> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> >> >> > > when necessary. Once built with those two patches I'm simply running
> >> >> > > `make check`.
> >> >> >
> >> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
> >> >> > huge
> >> >> > amount of memory and under some environments they were terminated by OOM
> >> >> > killer.
> >> >> >
> >> >> > This was because memory was allocated from existing memory contexts and
> >> >> > they
> >> >> > were not freed after ProcessLogQueryPlanInterrupt().
> >> >> > Updated the patch to use dedicated memory context for
> >> >> > ProcessLogQueryPlanInterrupt().
> >> >> >
> >> >> > Applying attached patch and v28-0002 patch, `make check` successfully
> >> >> > completed after 20min and 50GB of logs on my environment.
> >> >> >
> >> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
> >> >> > >>> > The tests have been running since last night, but have been apparently
> >> >> > >>> > hung now for many hours.
> >> >> >
> >> >> > I don't know if this has anything to do with the hung you faced, but I
> >> >> > thought
> >> >> > it might be possible that the large amount of memory usage resulted in
> >> >> > swapping, which caused a significant delay in processing.
> >> >>
> >> >> Ah, yes, I think that could be a possible explanation. I was delaying
> >> >> on this thread because I wasn't comfortable with having caused an
> >> >> issue once (even if I couldn't easily reproduce) without at least some
> >> >> theory as to the cause (and a fix).
> >> >>
> >> >> > If possible, I would be very grateful if you could try to reproduce this
> >> >> > with
> >> >> > the v29 patch.
> >> >>
> >> >> I'll kick off some testing.
> >> >>
> >> >
> >> > I don't have time to investigate what's happening here, but 24 hours
> >> > later the first "make check" is still running, and at first glance it
> >> > seems to have the same behavior I'd seen that first time. The test
> >> > output is to this point:
> >> >
> >> > # parallel group (5 tests): index_including create_view
> >> > index_including_gist create_index create_index_spgist
> >> > ok 66 + create_index 26365 ms
> >> > ok 67 + create_index_spgist 27675 ms
> >> > ok 68 + create_view 1235 ms
> >> > ok 69 + index_including 1102 ms
> >> > ok 70 + index_including_gist 1633 ms
> >> > # parallel group (16 tests): create_aggregate create_cast errors
> >> > roleattributes drop_if_exists hash_func typed_table create_am
> >> > infinite_recurse
> >> >
> >> > and it hasn't progressed past that point since at least ~16 hours ago
> >> > (the first several hours of the run I wasn't monitoring it).
> >> >
> >> > I haven't connected up gdb yet, and won't be able to until maybe
> >> > tomorrow, but here's the ps output for postgres processes that are
> >> > running:
> >> >
> >> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
> >> > /home/admin/postgresql-test/bin/postgres -D
> >> > /home/admin/postgresql-test-data
> >> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
> >> > postgres: checkpointer
> >> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
> >> > postgres: background writer
> >> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
> >> > postgres: walwriter
> >> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
> >> > postgres: autovacuum launcher
> >> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
> >> > postgres: logical replication launcher
> >> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
> >> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
> >> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
> >> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
> >> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
> >> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
> >> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
> >> > --schedule=./parallel_schedule
> >> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
> >> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
> >> > listen_addresses= -k /tmp/pg_regress-7mmGUa
> >> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
> >> > postgres: checkpointer
> >> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
> >> > postgres: background writer
> >> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
> >> > postgres: walwriter
> >> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
> >> > postgres: autovacuum launcher
> >> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
> >> > postgres: logical replication launcher
> >> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
> >> > postgres: admin regression [local] VACUUM
> >> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] DELETE waiting
> >> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] ALTER TABLE waiting
> >> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] ANALYZE waiting
> >> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> >
> >> > As you can see there are a bunch of backends presumably waiting, and
> >> > also the VACUUM process has been pegging a single CPU core for at
> >> > least since that ~16 hour ago mark.
> >> >
> >> > I hope to be able to do more investigation later, but I wanted to at
> >> > least give you this information now.
> >>
> >> Thanks a lot for testing the patch!
> >> I really appreciate your cooperation.
> >>
> >> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
> >> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
> >> below:
> >>
> >> ```
> >> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
> >> $ git apply
> >> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
> >> $ ./configure --enable-debug --enable-cassert
> >> $ make
> >> $ make check
> >>
> >> ...(snip)...
> >>
> >> # parallel group (5 tests): index_including index_including_gist
> >> create_view create_index create_index_spgist
> >> ok 66 + create_index 25033 ms
> >> ok 67 + create_index_spgist 26144 ms
> >> ok 68 + create_view 3061 ms
> >> ok 69 + index_including 976 ms
> >> ok 70 + index_including_gist 2998 ms
> >> # parallel group (16 tests): create_cast errors create_aggregate
> >> roleattributes drop_if_exists hash_func typed_table
> >> create_am select constraints updatable_views inherit triggers vacuum
> >> create_function_sql infinite_recurse
> >> ok 71 + create_aggregate 225 ms
> >> ok 72 + create_function_sql 18874 ms
> >> ok 73 + create_cast 168 ms
> >>
> >> ...(snip)...
> >>
> >> # All 215 tests passed.
> >> ```
> >>
> >> If you notice any difference, I would be grateful if you could let me
> >> know.
> >
> > I've never been able to reproduce it (haven't tested the new version,
> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> > (first buster and now bullseye).
> >
> > I'm attaching several stacktraces in the hope that they provide some
> > clues. These all match the ps output I sent earlier, though note in
> > that output there is both the regress instance and my test instance
> > (pid 3213249) running (different ports, of course, and they are from
> > the exact same compilation run). I've attached ps output for the
> > postgres processes under the make check process to simplify cross
> > referencing.
> >
> > A few interesting things:
> > - There's definitely a lock on a relation that seems to be what's
> > blocking the processes.
> > - When I try to connect with psql the process forks but then hangs
> > (see the ps output with task names stuck in "authentication"). I've
> > also included a trace from one of these.
>
> Thanks for sharing them!
>
> Many processes are waiting to acquire the LW lock, including the process
> trying to output the plan(select1.trace).
>
> I suspect that this is due to a lock that was acquired prior to being
> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able to
> reproduce the same situation..
>

I don't have time immediately to dig into this, but perhaps loading up
the core dumps would allow us to see what query is running in each
backend process (if it hasn't already been discarded by that point)
and thereby determine what point in each test process led to the error
condition?

Alternatively we might be able to apply the same trick to the test
client instead...

BTW, for my own easy reference in this thread: relid 1259 is pg_class
if I'm not mistaken.

Thoughts?
James Coleman

On 2023-09-06 11:17, James Coleman wrote:

>> > I've never been able to reproduce it (haven't tested the new version,
>> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
>> > (first buster and now bullseye).
>> >
>> > I'm attaching several stacktraces in the hope that they provide some
>> > clues. These all match the ps output I sent earlier, though note in
>> > that output there is both the regress instance and my test instance
>> > (pid 3213249) running (different ports, of course, and they are from
>> > the exact same compilation run). I've attached ps output for the
>> > postgres processes under the make check process to simplify cross
>> > referencing.
>> >
>> > A few interesting things:
>> > - There's definitely a lock on a relation that seems to be what's
>> > blocking the processes.
>> > - When I try to connect with psql the process forks but then hangs
>> > (see the ps output with task names stuck in "authentication"). I've
>> > also included a trace from one of these.
>>
>> Thanks for sharing them!
>>
>> Many processes are waiting to acquire the LW lock, including the
>> process
>> trying to output the plan(select1.trace).
>>
>> I suspect that this is due to a lock that was acquired prior to being
>> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
>> to
>> reproduce the same situation..
>>
>
> I don't have time immediately to dig into this, but perhaps loading up
> the core dumps would allow us to see what query is running in each
> backend process (if it hasn't already been discarded by that point)
> and thereby determine what point in each test process led to the error
> condition?

Thanks for the suggestion.
I am concerned that core dumps may not be readable on different
operating systems or other environments. (Unfortunately, I do not have
Debian on hand)

It seems that we can know what queries were running from the stack
traces you shared.
As described above, I suspect a lock which was acquired prior to
ProcessLogQueryPlanInterrupt() caused the issue.
I will try a little more to see if I can devise a way to create the same
situation.

> Alternatively we might be able to apply the same trick to the test
> client instead...
>
> BTW, for my own easy reference in this thread: relid 1259 is pg_class
> if I'm not mistaken.

Yeah, and I think it's strange that the lock to 1259 appears twice and
must be avoided.

#10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
lmgr.c:117
..
#49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
explain.c:5158
..
#53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
lmgr.c:117

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
> On 2023-09-06 11:17, James Coleman wrote:
> It seems that we can know what queries were running from the stack
> traces you shared.
> As described above, I suspect a lock which was acquired prior to
> ProcessLogQueryPlanInterrupt() caused the issue.
> I will try a little more to see if I can devise a way to create the same
> situation.
Hi,
I have explored this patch and, by and large, agree with the code. But some questions I want to discuss:
1. Maybe add a hook to give a chance for extensions, like pg_query_state, to do their job?
2. In this implementation, ProcessInterrupts does a lot of work during the explain creation: memory allocations, pass through the plan, systables locks, syscache access, etc. I guess it can change the semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be called - I can imagine a SELECT query, which would call a stored procedure, which executes some DDL and acquires row exclusive lock at the time of interruption. So, in my mind, it is too unpredictable to make the explain in the place of interruption processing. Maybe it is better to think about some hook at the end of ExecProcNode, where a pending explain could be created?

Also, I suggest minor code change with the diff in attachment.

--
Regards,
Andrei Lepikhov

On 2023-09-15 15:21, Lepikhov Andrei wrote:
> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>> On 2023-09-06 11:17, James Coleman wrote:
>> It seems that we can know what queries were running from the stack
>> traces you shared.
>> As described above, I suspect a lock which was acquired prior to
>> ProcessLogQueryPlanInterrupt() caused the issue.
>> I will try a little more to see if I can devise a way to create the
>> same
>> situation.
> Hi,
> I have explored this patch and, by and large, agree with the code. But
> some questions I want to discuss:
> 1. Maybe add a hook to give a chance for extensions, like
> pg_query_state, to do their job?

Do you imagine adding a hook which enables adding custom interrupt codes
like below?

https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch

If so, that would be possible, but this patch doesn't require the
functionality and I feel it'd be better doing in independent patch.

> 2. In this implementation, ProcessInterrupts does a lot of work during
> the explain creation: memory allocations, pass through the plan,
> systables locks, syscache access, etc. I guess it can change the
> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
> called - I can imagine a SELECT query, which would call a stored
> procedure, which executes some DDL and acquires row exclusive lock at
> the time of interruption. So, in my mind, it is too unpredictable to
> make the explain in the place of interruption processing. Maybe it is
> better to think about some hook at the end of ExecProcNode, where a
> pending explain could be created?

Yeah, I withdrew this patch once for that reason, but we are resuming
development in response to the results of a discussion by James and
others at this year's pgcon about the safety of this process in CFI:

/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gmail.com

BTW it seems pg_query_state also enables users to get running query
plans using CFI.
Does pg_query_state do something for this safety concern?

> Also, I suggest minor code change with the diff in attachment.

Thanks!

This might be biased opinion and objections are welcomed, but I feel the
original patch is easier to read since PG_RETURN_BOOL(true/false) is
located in near place to each cases.
Also the existing function pg_log_backend_memory_contexts(), which does
the same thing, has the same form as the original patch.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Tue, Sep 19, 2023, at 8:39 PM, torikoshia wrote:
> On 2023-09-15 15:21, Lepikhov Andrei wrote:
>> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>> I have explored this patch and, by and large, agree with the code. But
>> some questions I want to discuss:
>> 1. Maybe add a hook to give a chance for extensions, like
>> pg_query_state, to do their job?
>
> Do you imagine adding a hook which enables adding custom interrupt codes
> like below?
>
> https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch

No, I think around the hook, which would allow us to rewrite the pg_query_state extension without additional patches by using the functionality provided by your patch. I mean, an extension could provide console UI, not only server logging. And obtain from target backend so much information in the explain as the instrumentation level of the current query can give.
It may make pg_query_state shorter and more stable.

>> 2. In this implementation, ProcessInterrupts does a lot of work during
>> the explain creation: memory allocations, pass through the plan,
>> systables locks, syscache access, etc. I guess it can change the
>> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
>> called - I can imagine a SELECT query, which would call a stored
>> procedure, which executes some DDL and acquires row exclusive lock at
>> the time of interruption. So, in my mind, it is too unpredictable to
>> make the explain in the place of interruption processing. Maybe it is
>> better to think about some hook at the end of ExecProcNode, where a
>> pending explain could be created?
>
> Yeah, I withdrew this patch once for that reason, but we are resuming
> development in response to the results of a discussion by James and
> others at this year's pgcon about the safety of this process in CFI:
>
> /message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gmail.com

I can't track the logic path of the decision provided at this conference. But my anxiety related to specific place, where ActiveQueryDesc points top-level query and interruption comes during DDL, wrapped up in stored procedure. For example:
CREATE TABLE test();
CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
BEGIN
EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
...
END; $$ LANGUAGE plpgsql VOLATILE;
SELECT ddl(), ... FROM ...;

> BTW it seems pg_query_state also enables users to get running query
> plans using CFI.
> Does pg_query_state do something for this safety concern?

No, and I'm looking for the solution, which could help to rewrite pg_query_state as a clean extension, without patches.

>> Also, I suggest minor code change with the diff in attachment.
>
> Thanks!
>
> This might be biased opinion and objections are welcomed, but I feel the
> original patch is easier to read since PG_RETURN_BOOL(true/false) is
> located in near place to each cases.
> Also the existing function pg_log_backend_memory_contexts(), which does
> the same thing, has the same form as the original patch.
I got it, thank you.

--
Regards,
Andrei Lepikhov

On 2023-09-20 14:39, Lepikhov Andrei wrote:
Thanks for your reply.

> On Tue, Sep 19, 2023, at 8:39 PM, torikoshia wrote:
>> On 2023-09-15 15:21, Lepikhov Andrei wrote:
>>> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>>> I have explored this patch and, by and large, agree with the code.
>>> But
>>> some questions I want to discuss:
>>> 1. Maybe add a hook to give a chance for extensions, like
>>> pg_query_state, to do their job?
>>
>> Do you imagine adding a hook which enables adding custom interrupt
>> codes
>> like below?
>>
>> https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch
>
> No, I think around the hook, which would allow us to rewrite the
> pg_query_state extension without additional patches by using the
> functionality provided by your patch. I mean, an extension could
> provide console UI, not only server logging. And obtain from target
> backend so much information in the explain as the instrumentation
> level of the current query can give.
> It may make pg_query_state shorter and more stable.
>
>>> 2. In this implementation, ProcessInterrupts does a lot of work
>>> during
>>> the explain creation: memory allocations, pass through the plan,
>>> systables locks, syscache access, etc. I guess it can change the
>>> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
>>> called - I can imagine a SELECT query, which would call a stored
>>> procedure, which executes some DDL and acquires row exclusive lock at
>>> the time of interruption. So, in my mind, it is too unpredictable to
>>> make the explain in the place of interruption processing. Maybe it is
>>> better to think about some hook at the end of ExecProcNode, where a
>>> pending explain could be created?
>>
>> Yeah, I withdrew this patch once for that reason, but we are resuming
>> development in response to the results of a discussion by James and
>> others at this year's pgcon about the safety of this process in CFI:
>>
>> /message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gmail.com
>
> I can't track the logic path of the decision provided at this
> conference. But my anxiety related to specific place, where
> ActiveQueryDesc points top-level query and interruption comes during
> DDL, wrapped up in stored procedure. For example:
> CREATE TABLE test();
> CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
> BEGIN
> EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
> ...
> END; $$ LANGUAGE plpgsql VOLATILE;
> SELECT ddl(), ... FROM ...;

Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
all CFI using
v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
ran the following query but did not cause any problems.

```
=# CREATE TABLE test();
=# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
BEGIN
EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
PERFORM pg_sleep(5);
END; $$ LANGUAGE plpgsql VOLATILE;
=# SELECT ddl();
```

Is this the case you're worrying about?

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On 25/9/2023 14:21, torikoshia wrote:
> On 2023-09-20 14:39, Lepikhov Andrei wrote:
> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
> all CFI using
> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
> ran the following query but did not cause any problems.
>
> ```
> =# CREATE TABLE test();
> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
> BEGIN
>   EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
>   PERFORM pg_sleep(5);
> END; $$ LANGUAGE plpgsql VOLATILE;
> =# SELECT ddl();
> ```
>
> Is this the case you're worrying about?

I didn't find a problem either. I just feel uncomfortable if, at the
moment of interruption, we have a descriptor of another query than the
query have been executing and holding resources.

--
regards,
Andrey Lepikhov
Postgres Professional

On 2023-09-25 18:49, Andrey Lepikhov wrote:
> On 25/9/2023 14:21, torikoshia wrote:
>> On 2023-09-20 14:39, Lepikhov Andrei wrote:
>> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
>> all CFI using
>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
>> ran the following query but did not cause any problems.
>>
>> ```
>> =# CREATE TABLE test();
>> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
>> BEGIN
>>   EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
>>   PERFORM pg_sleep(5);
>> END; $$ LANGUAGE plpgsql VOLATILE;
>> =# SELECT ddl();
>> ```
>>
>> Is this the case you're worrying about?
>
> I didn't find a problem either. I just feel uncomfortable if, at the
> moment of interruption, we have a descriptor of another query than the
> query have been executing and holding resources.

I think that "descriptor" here refers to ActiveQueryDesc, in which case
it is updated at the beginning of ExecutorRun(), so I am wondering if
the situation you're worried about would not occur.

---------
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
---------
--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On 28/9/2023 09:04, torikoshia wrote:
> On 2023-09-25 18:49, Andrey Lepikhov wrote:
>> On 25/9/2023 14:21, torikoshia wrote:
>>> On 2023-09-20 14:39, Lepikhov Andrei wrote:
>>> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
>>> all CFI using
>>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and
>>> then ran the following query but did not cause any problems.
>>>
>>> ```
>>> =# CREATE TABLE test();
>>> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
>>> BEGIN
>>>    EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
>>>    PERFORM pg_sleep(5);
>>> END; $$ LANGUAGE plpgsql VOLATILE;
>>> =# SELECT ddl();
>>> ```
>>>
>>> Is this the case you're worrying about?
>>
>> I didn't find a problem either. I just feel uncomfortable if, at the
>> moment of interruption, we have a descriptor of another query than the
>> query have been executing and holding resources.
>
> I think that "descriptor" here refers to ActiveQueryDesc, in which case
> it is updated at the beginning of ExecutorRun(), so I am wondering if
> the situation you're worried about would not occur.
As you can see, in my example we have the only DDL and no queries with
plans. In this case postgres doesn't call ExecutorRun() just because it
doesn't have a plan. But locks will be obtained.

--
regards,
Andrey Lepikhov
Postgres Professional

On Thu, Sep 7, 2023 at 2:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-09-06 11:17, James Coleman wrote:
>
> >> > I've never been able to reproduce it (haven't tested the new version,
> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> >> > (first buster and now bullseye).
> >> >
> >> > I'm attaching several stacktraces in the hope that they provide some
> >> > clues. These all match the ps output I sent earlier, though note in
> >> > that output there is both the regress instance and my test instance
> >> > (pid 3213249) running (different ports, of course, and they are from
> >> > the exact same compilation run). I've attached ps output for the
> >> > postgres processes under the make check process to simplify cross
> >> > referencing.
> >> >
> >> > A few interesting things:
> >> > - There's definitely a lock on a relation that seems to be what's
> >> > blocking the processes.
> >> > - When I try to connect with psql the process forks but then hangs
> >> > (see the ps output with task names stuck in "authentication"). I've
> >> > also included a trace from one of these.
> >>
> >> Thanks for sharing them!
> >>
> >> Many processes are waiting to acquire the LW lock, including the
> >> process
> >> trying to output the plan(select1.trace).
> >>
> >> I suspect that this is due to a lock that was acquired prior to being
> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
> >> to
> >> reproduce the same situation..
> >>
> >
> > I don't have time immediately to dig into this, but perhaps loading up
> > the core dumps would allow us to see what query is running in each
> > backend process (if it hasn't already been discarded by that point)
> > and thereby determine what point in each test process led to the error
> > condition?
>
> Thanks for the suggestion.
> I am concerned that core dumps may not be readable on different
> operating systems or other environments. (Unfortunately, I do not have
> Debian on hand)
>
> It seems that we can know what queries were running from the stack
> traces you shared.
> As described above, I suspect a lock which was acquired prior to
> ProcessLogQueryPlanInterrupt() caused the issue.
> I will try a little more to see if I can devise a way to create the same
> situation.
>
> > Alternatively we might be able to apply the same trick to the test
> > client instead...
> >
> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
> > if I'm not mistaken.
>
> Yeah, and I think it's strange that the lock to 1259 appears twice and
> must be avoided.
>
> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
> lmgr.c:117
> ..
> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
> explain.c:5158
> ..
> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
> lmgr.c:117

I chatted with Andres and David about this at PGConf.NYC, and I think
what we need to do is explicitly disallow running this code any time
we are inside of lock acquisition code.

Regards,
James Coleman

On 2023-10-04 03:00, James Coleman wrote:
> On Thu, Sep 7, 2023 at 2:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-09-06 11:17, James Coleman wrote:
>>
>> >> > I've never been able to reproduce it (haven't tested the new version,
>> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
>> >> > (first buster and now bullseye).
>> >> >
>> >> > I'm attaching several stacktraces in the hope that they provide some
>> >> > clues. These all match the ps output I sent earlier, though note in
>> >> > that output there is both the regress instance and my test instance
>> >> > (pid 3213249) running (different ports, of course, and they are from
>> >> > the exact same compilation run). I've attached ps output for the
>> >> > postgres processes under the make check process to simplify cross
>> >> > referencing.
>> >> >
>> >> > A few interesting things:
>> >> > - There's definitely a lock on a relation that seems to be what's
>> >> > blocking the processes.
>> >> > - When I try to connect with psql the process forks but then hangs
>> >> > (see the ps output with task names stuck in "authentication"). I've
>> >> > also included a trace from one of these.
>> >>
>> >> Thanks for sharing them!
>> >>
>> >> Many processes are waiting to acquire the LW lock, including the
>> >> process
>> >> trying to output the plan(select1.trace).
>> >>
>> >> I suspect that this is due to a lock that was acquired prior to being
>> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
>> >> to
>> >> reproduce the same situation..
>> >>
>> >
>> > I don't have time immediately to dig into this, but perhaps loading up
>> > the core dumps would allow us to see what query is running in each
>> > backend process (if it hasn't already been discarded by that point)
>> > and thereby determine what point in each test process led to the error
>> > condition?
>>
>> Thanks for the suggestion.
>> I am concerned that core dumps may not be readable on different
>> operating systems or other environments. (Unfortunately, I do not have
>> Debian on hand)
>>
>> It seems that we can know what queries were running from the stack
>> traces you shared.
>> As described above, I suspect a lock which was acquired prior to
>> ProcessLogQueryPlanInterrupt() caused the issue.
>> I will try a little more to see if I can devise a way to create the
>> same
>> situation.
>>
>> > Alternatively we might be able to apply the same trick to the test
>> > client instead...
>> >
>> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
>> > if I'm not mistaken.
>>
>> Yeah, and I think it's strange that the lock to 1259 appears twice and
>> must be avoided.
>>
>> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
>> at
>> lmgr.c:117
>> ..
>> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
>> explain.c:5158
>> ..
>> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
>> at
>> lmgr.c:117
>
> I chatted with Andres and David about this at PGConf.NYC,
Thanks again for the discussion with hackers!

> and I think
> what we need to do is explicitly disallow running this code any time
> we are inside of lock acquisition code.

Yeah, I think it's a straightforward workaround.
And I'm also concerned that the condition of being in the process
of acquiring some kind of lock is too strict and will make it almost
impossible to output a running plan.

Anyway I'm going to implement it and run pg_log_query_plan()
while the regression test is running to see how successful the plan
output is.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Fri, Oct 6, 2023 at 8:58 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-10-04 03:00, James Coleman wrote:
> > On Thu, Sep 7, 2023 at 2:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> > wrote:
> >>
> >> On 2023-09-06 11:17, James Coleman wrote:
> >>
> >> >> > I've never been able to reproduce it (haven't tested the new version,
> >> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> >> >> > (first buster and now bullseye).
> >> >> >
> >> >> > I'm attaching several stacktraces in the hope that they provide some
> >> >> > clues. These all match the ps output I sent earlier, though note in
> >> >> > that output there is both the regress instance and my test instance
> >> >> > (pid 3213249) running (different ports, of course, and they are from
> >> >> > the exact same compilation run). I've attached ps output for the
> >> >> > postgres processes under the make check process to simplify cross
> >> >> > referencing.
> >> >> >
> >> >> > A few interesting things:
> >> >> > - There's definitely a lock on a relation that seems to be what's
> >> >> > blocking the processes.
> >> >> > - When I try to connect with psql the process forks but then hangs
> >> >> > (see the ps output with task names stuck in "authentication"). I've
> >> >> > also included a trace from one of these.
> >> >>
> >> >> Thanks for sharing them!
> >> >>
> >> >> Many processes are waiting to acquire the LW lock, including the
> >> >> process
> >> >> trying to output the plan(select1.trace).
> >> >>
> >> >> I suspect that this is due to a lock that was acquired prior to being
> >> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
> >> >> to
> >> >> reproduce the same situation..
> >> >>
> >> >
> >> > I don't have time immediately to dig into this, but perhaps loading up
> >> > the core dumps would allow us to see what query is running in each
> >> > backend process (if it hasn't already been discarded by that point)
> >> > and thereby determine what point in each test process led to the error
> >> > condition?
> >>
> >> Thanks for the suggestion.
> >> I am concerned that core dumps may not be readable on different
> >> operating systems or other environments. (Unfortunately, I do not have
> >> Debian on hand)
> >>
> >> It seems that we can know what queries were running from the stack
> >> traces you shared.
> >> As described above, I suspect a lock which was acquired prior to
> >> ProcessLogQueryPlanInterrupt() caused the issue.
> >> I will try a little more to see if I can devise a way to create the
> >> same
> >> situation.
> >>
> >> > Alternatively we might be able to apply the same trick to the test
> >> > client instead...
> >> >
> >> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
> >> > if I'm not mistaken.
> >>
> >> Yeah, and I think it's strange that the lock to 1259 appears twice and
> >> must be avoided.
> >>
> >> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
> >> at
> >> lmgr.c:117
> >> ..
> >> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
> >> explain.c:5158
> >> ..
> >> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
> >> at
> >> lmgr.c:117
> >
> > I chatted with Andres and David about this at PGConf.NYC,
> Thanks again for the discussion with hackers!
>
> > and I think
> > what we need to do is explicitly disallow running this code any time
> > we are inside of lock acquisition code.
>
> Yeah, I think it's a straightforward workaround.
> And I'm also concerned that the condition of being in the process
> of acquiring some kind of lock is too strict and will make it almost
> impossible to output a running plan.

I was concerned about this too, but I was wondering if we might be
able to cheat a bit by making such a case not clear the flag but
instead just skip it for now.

Regards,
James

Hi,

On 2023-10-06 21:58:46 +0900, torikoshia wrote:
> Yeah, I think it's a straightforward workaround.
> And I'm also concerned that the condition of being in the process
> of acquiring some kind of lock is too strict and will make it almost
> impossible to output a running plan.

How so? We shouldn't commonly acquire relevant locks while executing a query?
With a few exceptions, they should instead be acquired t the start of query
processing. We do acquire a lot of lwlocks, obviously, but we don't process
interrupts during the acquisition / holding of lwlocks.

And presumably the interrupt would just be processed the next time interrupt
processing is happening?

Greetings,

Andres Freund

On 2023-10-04 03:00, James Coleman wrote:
> and I think
> what we need to do is explicitly disallow running this code any time
> we are inside of lock acquisition code.

Updated patch to check if any locks have already been acquired by
examining MyProc->heldLocks.

I'm not sure this change can "disallow running this code `any time` we
are inside of lock acquisition code", but as far as select1.trace, which
you shared, I believe it can prevent running explain codes since it must
have set MyProc->heldLocks in LockAcquireExtended() before WaitOnLock():

```
/*
* Set bitmask of locks this process already holds on this
object.
*/
MyProc->heldLocks = proclock->holdMask;

..(snip)..

WaitOnLock(locallock, owner);
```

On 2023-10-07 00:58, Andres Freund wrote:

> How so? We shouldn't commonly acquire relevant locks while executing a
> query?
> With a few exceptions, they should instead be acquired t the start of
> query
> processing. We do acquire a lot of lwlocks, obviously, but we don't
> process
> interrupts during the acquisition / holding of lwlocks.
>
> And presumably the interrupt would just be processed the next time
> interrupt
> processing is happening?

Thanks for your comments!

I tested v30 patch with
v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch which makes
CFI() call ProcessLogQueryPlanInterrupt() internally, and confirmed that
very few logging queries failed with v30 patch.

This is a result in line with your prediction.

```
$ rg -c'ignored request for logging query plan due to lock confilcts'
postmaster.log
8
```

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

Hi,

On Tue, Oct 10, 2023 at 7:00 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:

> Thanks for your comments!
>
> I tested v30 patch with
> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch which makes
> CFI() call ProcessLogQueryPlanInterrupt() internally, and confirmed that
> very few logging queries failed with v30 patch.
>
> This is a result in line with your prediction.
>
>
> ```
> $ rg -c'ignored request for logging query plan due to lock confilcts'
> postmaster.log
> 8

Like many others I think this feature is useful to debug a long running query.

Sorry for jumping late into this.

I have a few of high level comments

There is a lot of similarity between what this feature does and what
auto explain does. I see the code is also duplicated. There is some
merit in avoiding this duplication
1. we will get all the features of auto_explain automatically like
choosing a format (this was expressed somebody earlier in this
thread), setings etc.
2. avoid bugs. E.g your code switches context after ExplainState has
been allocated. These states may leak depending upon when this
function gets called.
3. Building features on top as James envisions will be easier.

Considering the similarity with auto_explain I wondered whether this
function should be part of auto_explain contrib module itself? If we
do that users will need to load auto_explain extension and thus
install executor hooks when this function doesn't need those. So may
not be such a good idea. I didn't see any discussion on this.

I tried following query to pass PID of a non-client backend to this function.
#select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';
pg_log_query_plan | application_name | backend_type
-------------------+------------------+---------------------
t | | autovacuum launcher
(1 row)
I see "LOG: backend with PID 2733631 is not running a query or a
subtransaction is aborted" in server logs. That's ok. But may be we
should not send signal to these kinds of backends at all, thus
avoiding some system calls.

I am also wondering whether it's better to report the WARNING as
status column in the output. E.g. instead of
#select pg_log_query_plan(100);
WARNING: PID 100 is not a PostgreSQL backend process
pg_log_query_plan
-------------------
f
(1 row)
we output
#select pg_log_query_plan(100);
pg_log_query_plan | status
-------------------+---------------------------------------------
f | PID 100 is not a PostgreSQL backend process
(1 row)

That looks neater and can easily be handled by scripts, applications
and such. But it will be inconsistent with other functions like
pg_terminate_backend() and pg_log_backend_memory_contexts().

I do share a concern that was discussed earlier. If a query is running
longer, there's something problematic with it. A diagnostic
intervention breaking it further would be unwelcome. James has run
experiments to shake this code for any loose breakages. He has not
found any. So may be we are good. And we wouldn't know about very rare
corner cases so easily without using it in the field. So fine with it.
If we could add some safety net that will be great but may not be
necessary for the first cut.

--
Best Wishes,
Ashutosh Bapat

On 2023-10-11 16:22, Ashutosh Bapat wrote:

> Like many others I think this feature is useful to debug a long running
> query.
>
> Sorry for jumping late into this.
>
> I have a few of high level comments

Thanks for your comments!

> There is a lot of similarity between what this feature does and what
> auto explain does. I see the code is also duplicated. There is some
> merit in avoiding this duplication
> 1. we will get all the features of auto_explain automatically like
> choosing a format (this was expressed somebody earlier in this
> thread), setings etc.
> 2. avoid bugs. E.g your code switches context after ExplainState has
> been allocated. These states may leak depending upon when this
> function gets called.
> 3. Building features on top as James envisions will be easier.
>
> Considering the similarity with auto_explain I wondered whether this
> function should be part of auto_explain contrib module itself? If we
> do that users will need to load auto_explain extension and thus
> install executor hooks when this function doesn't need those. So may
> not be such a good idea. I didn't see any discussion on this.

I once thought about adding this to auto_explain, but I left it asis for
below reasons:

- One of the typical use case of pg_log_query_plan() would be analyzing
slow query on customer environments. On such environments, We cannot
always control what extensions to install.
Of course auto_explain is a major extension and it is quite possible
that they installed auto_explain, but but it is also possible they do
not.
- It seems a bit counter-intuitive that pg_log_query_plan() is in an
extension called auto_explain, since it `manually`` logs plans

> I tried following query to pass PID of a non-client backend to this
> function.
> #select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';
> pg_log_query_plan | application_name | backend_type
> -------------------+------------------+---------------------
> t | | autovacuum launcher
> (1 row)
> I see "LOG: backend with PID 2733631 is not running a query or a
> subtransaction is aborted" in server logs. That's ok. But may be we
> should not send signal to these kinds of backends at all, thus
> avoiding some system calls.

Agreed, it seems better.
Attached patch checks if the backendType of target process is 'client
backend'.

=# select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';
WARNING: PID 63323 is not a PostgreSQL client backend process
pg_log_query_plan | application_name | backend_type
-------------------+------------------+---------------------
f | | autovacuum launcher

> I am also wondering whether it's better to report the WARNING as
> status column in the output. E.g. instead of
> #select pg_log_query_plan(100);
> WARNING: PID 100 is not a PostgreSQL backend process
> pg_log_query_plan
> -------------------
> f
> (1 row)
> we output
> #select pg_log_query_plan(100);
> pg_log_query_plan | status
> -------------------+---------------------------------------------
> f | PID 100 is not a PostgreSQL backend process
> (1 row)
>
> That looks neater and can easily be handled by scripts, applications
> and such. But it will be inconsistent with other functions like
> pg_terminate_backend() and pg_log_backend_memory_contexts().

It seems neater, but it might be inconvenient because we can no longer
use it in select list like the following query as you wrote:

#select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';

> I do share a concern that was discussed earlier. If a query is running
> longer, there's something problematic with it. A diagnostic
> intervention breaking it further would be unwelcome. James has run
> experiments to shake this code for any loose breakages. He has not
> found any. So may be we are good. And we wouldn't know about very rare
> corner cases so easily without using it in the field. So fine with it.
> If we could add some safety net that will be great but may not be
> necessary for the first cut.

If there are candidates for the safety net, I'm willing to add them.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Thu, Oct 12, 2023 at 6:51 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-10-11 16:22, Ashutosh Bapat wrote:
> >
> > Considering the similarity with auto_explain I wondered whether this
> > function should be part of auto_explain contrib module itself? If we
> > do that users will need to load auto_explain extension and thus
> > install executor hooks when this function doesn't need those. So may
> > not be such a good idea. I didn't see any discussion on this.
>
> I once thought about adding this to auto_explain, but I left it asis for
> below reasons:
>
> - One of the typical use case of pg_log_query_plan() would be analyzing
> slow query on customer environments. On such environments, We cannot
> always control what extensions to install.

The same argument applies to auto_explain functionality as well. But
it's not part of the core.

> Of course auto_explain is a major extension and it is quite possible
> that they installed auto_explain, but but it is also possible they do
> not.
> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
> extension called auto_explain, since it `manually`` logs plans
>

pg_log_query_plan() may not fit auto_explain but
pg_explain_backend_query() does. What we are logging is more than just
plan of the query, it might expand to be closer to explain output.
While auto in auto_explain would refer to its automatically logging
explain outputs, it can provide an additional function which provides
similar functionality by manually triggering it.

But we can defer this to a committer, if you want.

I am more interested in avoiding the duplication of code, esp. the
first comment in my reply
>> There is a lot of similarity between what this feature does and what
>> auto explain does. I see the code is also duplicated. There is some
>> merit in avoiding this duplication
>> 1. we will get all the features of auto_explain automatically like
>> choosing a format (this was expressed somebody earlier in this
>> thread), setings etc.
>> 2. avoid bugs. E.g your code switches context after ExplainState has
>> been allocated. These states may leak depending upon when this
>> function gets called.
>> 3. Building features on top as James envisions will be easier.

>
> =# select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';
> WARNING: PID 63323 is not a PostgreSQL client backend process
> pg_log_query_plan | application_name | backend_type
> -------------------+------------------+---------------------
> f | | autovacuum launcher
>
>
> > I am also wondering whether it's better to report the WARNING as
> > status column in the output. E.g. instead of
> > #select pg_log_query_plan(100);
> > WARNING: PID 100 is not a PostgreSQL backend process
> > pg_log_query_plan
> > -------------------
> > f
> > (1 row)
> > we output
> > #select pg_log_query_plan(100);
> > pg_log_query_plan | status
> > -------------------+---------------------------------------------
> > f | PID 100 is not a PostgreSQL backend process
> > (1 row)
> >
> > That looks neater and can easily be handled by scripts, applications
> > and such. But it will be inconsistent with other functions like
> > pg_terminate_backend() and pg_log_backend_memory_contexts().
>
> It seems neater, but it might be inconvenient because we can no longer
> use it in select list like the following query as you wrote:
>
> #select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';

Why is that?

--
Best Wishes,
Ashutosh Bapat

On 2023-10-16 18:46, Ashutosh Bapat wrote:
> On Thu, Oct 12, 2023 at 6:51 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>>
>> On 2023-10-11 16:22, Ashutosh Bapat wrote:
>> >
>> > Considering the similarity with auto_explain I wondered whether this
>> > function should be part of auto_explain contrib module itself? If we
>> > do that users will need to load auto_explain extension and thus
>> > install executor hooks when this function doesn't need those. So may
>> > not be such a good idea. I didn't see any discussion on this.
>>
>> I once thought about adding this to auto_explain, but I left it asis
>> for
>> below reasons:
>>
>> - One of the typical use case of pg_log_query_plan() would be
>> analyzing
>> slow query on customer environments. On such environments, We cannot
>> always control what extensions to install.
>
> The same argument applies to auto_explain functionality as well. But
> it's not part of the core.

Yeah, and when we have a situation where we want to run
pg_log_query_plan(), we can run it in any environment as long as it is
bundled with the core.
On the other hand, if it is built into auto_explain, we need to start by
installing auto_explain if we do not have auto_explain, which is often
difficult to do in production environments.

>> Of course auto_explain is a major extension and it is quite
>> possible
>> that they installed auto_explain, but but it is also possible they do
>> not.
>> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
>> extension called auto_explain, since it `manually`` logs plans
>>
>
> pg_log_query_plan() may not fit auto_explain but
> pg_explain_backend_query() does. What we are logging is more than just
> plan of the query, it might expand to be closer to explain output.
> While auto in auto_explain would refer to its automatically logging
> explain outputs, it can provide an additional function which provides
> similar functionality by manually triggering it.
>
> But we can defer this to a committer, if you want.
>
> I am more interested in avoiding the duplication of code, esp. the
> first comment in my reply

If there are no objections, I will try porting it to auto_explain and
see its feasibility.

>>> There is a lot of similarity between what this feature does and what
>>> auto explain does. I see the code is also duplicated. There is some
>>> merit in avoiding this duplication
>>> 1. we will get all the features of auto_explain automatically like
>>> choosing a format (this was expressed somebody earlier in this
>>> thread), setings etc.
>>> 2. avoid bugs. E.g your code switches context after ExplainState has
>>> been allocated. These states may leak depending upon when this
>>> function gets called.
>>> 3. Building features on top as James envisions will be easier.
>
>>
>> =# select pg_log_query_plan(pid), application_name, backend_type
>> from
>> pg_stat_activity where backend_type = 'autovacuum launcher';
>> WARNING: PID 63323 is not a PostgreSQL client backend process
>> pg_log_query_plan | application_name | backend_type
>> -------------------+------------------+---------------------
>> f | | autovacuum launcher
>>
>>
>> > I am also wondering whether it's better to report the WARNING as
>> > status column in the output. E.g. instead of
>> > #select pg_log_query_plan(100);
>> > WARNING: PID 100 is not a PostgreSQL backend process
>> > pg_log_query_plan
>> > -------------------
>> > f
>> > (1 row)
>> > we output
>> > #select pg_log_query_plan(100);
>> > pg_log_query_plan | status
>> > -------------------+---------------------------------------------
>> > f | PID 100 is not a PostgreSQL backend process
>> > (1 row)
>> >
>> > That looks neater and can easily be handled by scripts, applications
>> > and such. But it will be inconsistent with other functions like
>> > pg_terminate_backend() and pg_log_backend_memory_contexts().
>>
>> It seems neater, but it might be inconvenient because we can no longer
>> use it in select list like the following query as you wrote:
>>
>> #select pg_log_query_plan(pid), application_name, backend_type from
>> pg_stat_activity where backend_type = 'autovacuum launcher';
>
> Why is that?

Sorry, I misunderstood and confirmed we can run queries like below:

```
=# CREATE OR REPLACE FUNCTION pg_log_query_plan_stab(i int)
RETURNS TABLE(

pg_log_query_plan bool,
status text

) AS $$
DECLARE

BEGIN

RETURN QUERY SELECT false::bool, 'PID 100 is not a PostgreSQL
backend process'::text; END;

$$ LANGUAGE plpgsql;

=# select pg_log_query_plan_stab(pid), application_name, backend_type
from pg_stat_activity where backend_type = 'autovacuum launcher';
pg_log_query_plan_stab | application_name |
backend_type
---------------------------------------------------+------------------+---------------------
(f,"PID 100 is not a PostgreSQL backend process") | |
autovacuum launcher
```
--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Wed, Oct 18, 2023 at 11:39 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> >
> > I am more interested in avoiding the duplication of code, esp. the
> > first comment in my reply
>
> If there are no objections, I will try porting it to auto_explain and
> see its feasibility.

If you want it in core, you will need to port relevant parts of
auto_explain code to core.

--
Best Wishes,
Ashutosh Bapat

On Wed, Oct 18, 2023 at 2:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2023-10-16 18:46, Ashutosh Bapat wrote:
> > On Thu, Oct 12, 2023 at 6:51 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> > wrote:
> >>
> >> On 2023-10-11 16:22, Ashutosh Bapat wrote:
> >> >
> >> > Considering the similarity with auto_explain I wondered whether this
> >> > function should be part of auto_explain contrib module itself? If we
> >> > do that users will need to load auto_explain extension and thus
> >> > install executor hooks when this function doesn't need those. So may
> >> > not be such a good idea. I didn't see any discussion on this.
> >>
> >> I once thought about adding this to auto_explain, but I left it asis
> >> for
> >> below reasons:
> >>
> >> - One of the typical use case of pg_log_query_plan() would be
> >> analyzing
> >> slow query on customer environments. On such environments, We cannot
> >> always control what extensions to install.
> >
> > The same argument applies to auto_explain functionality as well. But
> > it's not part of the core.
>
> Yeah, and when we have a situation where we want to run
> pg_log_query_plan(), we can run it in any environment as long as it is
> bundled with the core.
> On the other hand, if it is built into auto_explain, we need to start by
> installing auto_explain if we do not have auto_explain, which is often
> difficult to do in production environments.
>
> >> Of course auto_explain is a major extension and it is quite
> >> possible
> >> that they installed auto_explain, but but it is also possible they do
> >> not.
> >> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
> >> extension called auto_explain, since it `manually`` logs plans
> >>
> >
> > pg_log_query_plan() may not fit auto_explain but
> > pg_explain_backend_query() does. What we are logging is more than just
> > plan of the query, it might expand to be closer to explain output.
> > While auto in auto_explain would refer to its automatically logging
> > explain outputs, it can provide an additional function which provides
> > similar functionality by manually triggering it.
> >
> > But we can defer this to a committer, if you want.
> >
> > I am more interested in avoiding the duplication of code, esp. the
> > first comment in my reply
>
> If there are no objections, I will try porting it to auto_explain and
> see its feasibility.
>
> >>> There is a lot of similarity between what this feature does and what
> >>> auto explain does. I see the code is also duplicated. There is some
> >>> merit in avoiding this duplication
> >>> 1. we will get all the features of auto_explain automatically like
> >>> choosing a format (this was expressed somebody earlier in this
> >>> thread), setings etc.
> >>> 2. avoid bugs. E.g your code switches context after ExplainState has
> >>> been allocated. These states may leak depending upon when this
> >>> function gets called.
> >>> 3. Building features on top as James envisions will be easier.

In my view the fact that auto_explain is itself not part of core is a
mistake, and I know there are more prominent hackers than myself who
hold that view.

While that decision as regards auto_explain has long since been made
(and there would be work to undo it), I don't believe that we should
repeat that choice here. I'm -10 on moving this into auto_explain.

However perhaps there is still an opportunity for moving some of the
auto_explain code into core so as to enable deduplicating the code.

Regards,
James Coleman

> Hi,
>
> Yeah, and when we have a situation where we want to run
> pg_log_query_plan(), we can run it in any environment as long as it
> is bundled with the core.

Is it possible to get the plan of a backend programmatically without
access to the logs?

Something like pg_get_query_plan(pid, format) which output would be the
same as EXPLAIN.

Regards,
Étienne BERSAC
Dalibo

On 2023-10-24 16:12, Étienne BERSAC wrote:
>> Hi,
>>
>> Yeah, and when we have a situation where we want to run
>> pg_log_query_plan(), we can run it in any environment as long as it
>> is bundled with the core.
>
> Is it possible to get the plan of a backend programmatically without
> access to the logs?
>
> Something like pg_get_query_plan(pid, format) which output would be the
> same as EXPLAIN.

Do you imagine a function like below?

=# select pg_get_query_plan(100, 'plain');
QUERY PLAN
-------------------------------------------------------------------
Limit (cost=0.00..0.04 rows=1 width=273)
-> Seq Scan on pg_class (cost=0.00..17.14 rows=414 width=273)

If so, we once tried to implement such function for getting memory
contexts.
However, this attempt didn't succeed because it could lead dead lock
situation[1].

I think the same problem can occur when implementing
pg_get_query_plan().

[1]
/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com
>
> Regards,
> Étienne BERSAC
> Dalibo

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

On Wed, Oct 18, 2023 at 10:04 PM James Coleman <jtc331(at)gmail(dot)com> wrote:
>
> While that decision as regards auto_explain has long since been made
> (and there would be work to undo it), I don't believe that we should
> repeat that choice here. I'm -10 on moving this into auto_explain.
>

Right.

> However perhaps there is still an opportunity for moving some of the
> auto_explain code into core so as to enable deduplicating the code.
>

Right. That's what I also think.

--
Best Wishes,
Ashutosh Bapat

On 2023-10-25 12:40, Ashutosh Bapat wrote:
> On Wed, Oct 18, 2023 at 10:04 PM James Coleman <jtc331(at)gmail(dot)com>
> wrote:
>>
>> While that decision as regards auto_explain has long since been made
>> (and there would be work to undo it), I don't believe that we should
>> repeat that choice here. I'm -10 on moving this into auto_explain.
>>
>
> Right.
>
>> However perhaps there is still an opportunity for moving some of the
>> auto_explain code into core so as to enable deduplicating the code.
>>
>
> Right. That's what I also think.

Thanks for your comments.

Attached patch adds a new function which assembles es->str for logging
according to specified contents and format.
This is called from both auto_explain and pg_log_query_plan().

On 2023-10-11 16:22, Ashutosh Bapat wrote:
> I am also wondering whether it's better to report the WARNING as
> status column in the output.

Attached patch left as it was since the inconsistency with
pg_terminate_backend() and pg_log_backend_memory_contexts() as you
pointed out.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation

Hi Torikoshia,

> If so, we once tried to implement such function for getting memory
> contexts.
> However, this attempt didn't succeed because it could lead dead lock
> situation[1].

Thanks for the pointer. Why not use client log message to allow client
to get plan without locking backend memory context and without access
to server log ? I missed the rationnal for not sending the plan to
client.

Regards,
Étienne

On 2023-10-27 16:06, Étienne BERSAC wrote:
> Hi Torikoshia,
>
>> If so, we once tried to implement such function for getting memory
>> contexts.
>> However, this attempt didn't succeed because it could lead dead lock
>> situation[1].
>
> Thanks for the pointer. Why not use client log message to allow client
> to get plan without locking backend memory context and without access
> to server log ? I missed the rationnal for not sending the plan to
> client.

If we use client log message, that message is shown on the target
process whose pid is specified by the parameter of pg_log_query_plan():

(pid:1000)=# select pg_sleep(60);
(pid:1001)=# select pg_log_query_plan(1000);
(pid:1000)=# LOG: query plan running on backend with PID 1000 is:
Query Text: select pg_sleep(1000);
Result (cost=0.00..0.01 rows=1 width=4)
Output: pg_sleep('1000'::double precision)

I think this is not an expected behavior and we set elevel to
LOG_SERVER_ONLY.

--
Regards,

--
Atsushi Torikoshi
NTT DATA Group Corporation