Re: RFC: Logging plan of the running query

Hi,

During the discussion about memory contexts dumping[1], there
was a comment that exposing not only memory contexts but also
query plans and untruncated query string would be useful.

I also feel that it would be nice when thinking about situations
such as troubleshooting a long-running query on production
environments where we cannot use debuggers.

At that point of the above comment, I was considering exposing
such information on the shared memory.
However, since memory contexts are now exposed on the log by
pg_log_backend_memory_contexts(PID), I'm thinking about
defining a function that logs the plan of a running query and
untruncated query string on the specified PID in the same way
as below.

postgres=# SELECT * FROM pg_log_current_plan(2155192);
pg_log_current_plan
---------------------
t
(1 row)

$ tail -f data/log/postgresql-2021-05-12.log

2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of
running query on PID 2155192
Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
pgbench_accounts b ON a.aid = b.aid;
Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
Merge Cond: (a.aid = b.aid)
-> Index Scan using pgbench_accounts_pkey on
pgbench_accounts a (cost=0.42..42377.43 rows=1000000 width=89)
-> Index Only Scan using pgbench_accounts_pkey on
pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)

Attached a PoC patch.

Any thoughts?

[1]
https://www.postgresql.org/message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

st 12. 5. 2021 v 13:24 odesílatel torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
napsal:

> Hi,
>
> During the discussion about memory contexts dumping[1], there
> was a comment that exposing not only memory contexts but also
> query plans and untruncated query string would be useful.
>
> I also feel that it would be nice when thinking about situations
> such as troubleshooting a long-running query on production
> environments where we cannot use debuggers.
>
> At that point of the above comment, I was considering exposing
> such information on the shared memory.
> However, since memory contexts are now exposed on the log by
> pg_log_backend_memory_contexts(PID), I'm thinking about
> defining a function that logs the plan of a running query and
> untruncated query string on the specified PID in the same way
> as below.
>
> postgres=# SELECT * FROM pg_log_current_plan(2155192);
> pg_log_current_plan
> ---------------------
> t
> (1 row)
>
> $ tail -f data/log/postgresql-2021-05-12.log
>
> 2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of
> running query on PID 2155192
> Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
> pgbench_accounts b ON a.aid = b.aid;
> Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
> Merge Cond: (a.aid = b.aid)
> -> Index Scan using pgbench_accounts_pkey on
> pgbench_accounts a (cost=0.42..42377.43 rows=1000000 width=89)
> -> Index Only Scan using pgbench_accounts_pkey on
> pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)
>
>
> Attached a PoC patch.
>
> Any thoughts?
>

+1

Pavel

> [1]
>
> https://www.postgresql.org/message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com
>
>
> Regards,
>
> --
> Atsushi Torikoshi
> NTT DATA CORPORATION

On Wed, May 12, 2021 at 4:54 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> Hi,
>
> During the discussion about memory contexts dumping[1], there
> was a comment that exposing not only memory contexts but also
> query plans and untruncated query string would be useful.
>
> I also feel that it would be nice when thinking about situations
> such as troubleshooting a long-running query on production
> environments where we cannot use debuggers.
>
> At that point of the above comment, I was considering exposing
> such information on the shared memory.
> However, since memory contexts are now exposed on the log by
> pg_log_backend_memory_contexts(PID), I'm thinking about
> defining a function that logs the plan of a running query and
> untruncated query string on the specified PID in the same way
> as below.
>
> postgres=# SELECT * FROM pg_log_current_plan(2155192);
> pg_log_current_plan
> ---------------------
> t
> (1 row)
>
> $ tail -f data/log/postgresql-2021-05-12.log
>
> 2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of
> running query on PID 2155192
> Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
> pgbench_accounts b ON a.aid = b.aid;
> Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
> Merge Cond: (a.aid = b.aid)
> -> Index Scan using pgbench_accounts_pkey on
> pgbench_accounts a (cost=0.42..42377.43 rows=1000000 width=89)
> -> Index Only Scan using pgbench_accounts_pkey on
> pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)
>
>
> Attached a PoC patch.
>
> Any thoughts?
>
> [1]
> https://www.postgresql.org/message-id/CA%2BTgmobkpFV0UB67kzXuD36--OFHwz1bs%3DL_6PZbD4nxKqUQMw%40mail.gmail.com

+1 for the idea. It looks like pg_log_current_plan is allowed to run
by superusers. Since it also shows up the full query text and the plan
in the server log as plain text, there are chances that the sensitive
information might be logged into the server log which is a risky thing
from security standpoint. There's another thread (see [1] below) which
discusses this issue by having a separate role for all debugging
purposes. Note that final consensus is not reached yet. We may want to
use the same role for this patch as well.

[1] - https://www.postgresql.org/message-id/CA%2BTgmoZz%3DK1bQRp0Ug%3D6uMGFWg-6kaxdHe6VSWaxq0U-YkppYQ%40mail.gmail.com

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Wed, 12 May 2021 at 13:24, torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> Hi,
>
> During the discussion about memory contexts dumping[1], there
> was a comment that exposing not only memory contexts but also
> query plans and untruncated query string would be useful.
>
> I also feel that it would be nice when thinking about situations
> such as troubleshooting a long-running query on production
> environments where we cannot use debuggers.
>
> At that point of the above comment, I was considering exposing
> such information on the shared memory.
> However, since memory contexts are now exposed on the log by
> pg_log_backend_memory_contexts(PID), I'm thinking about
> defining a function that logs the plan of a running query and
> untruncated query string on the specified PID in the same way
> as below.
>
> postgres=# SELECT * FROM pg_log_current_plan(2155192);
> pg_log_current_plan
> ---------------------
> t
> (1 row)
>
> $ tail -f data/log/postgresql-2021-05-12.log
>
> 2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of
> running query on PID 2155192
> Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
> pgbench_accounts b ON a.aid = b.aid;
> Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
> Merge Cond: (a.aid = b.aid)
> -> Index Scan using pgbench_accounts_pkey on
> pgbench_accounts a (cost=0.42..42377.43 rows=1000000 width=89)
> -> Index Only Scan using pgbench_accounts_pkey on
> pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)
>
>
> Attached a PoC patch.
>
> Any thoughts?

Great idea. One feature I'd suggest would be adding a 'format' option
as well, if such feature would be feasable.

With regards,

Matthias van de Meent

On Wed, May 12, 2021 at 08:24:04PM +0900, torikoshia wrote:
> Hi,
>
> During the discussion about memory contexts dumping[1], there
> was a comment that exposing not only memory contexts but also
> query plans and untruncated query string would be useful.
>
> I also feel that it would be nice when thinking about situations
> such as troubleshooting a long-running query on production
> environments where we cannot use debuggers.
>
> At that point of the above comment, I was considering exposing
> such information on the shared memory.
> However, since memory contexts are now exposed on the log by
> pg_log_backend_memory_contexts(PID), I'm thinking about
> defining a function that logs the plan of a running query and
> untruncated query string on the specified PID in the same way
> as below.
>
> postgres=# SELECT * FROM pg_log_current_plan(2155192);
> pg_log_current_plan
> ---------------------
> t
> (1 row)
>
> $ tail -f data/log/postgresql-2021-05-12.log
>
> 2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of running
> query on PID 2155192
> Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
> pgbench_accounts b ON a.aid = b.aid;
> Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
> Merge Cond: (a.aid = b.aid)
> -> Index Scan using pgbench_accounts_pkey on pgbench_accounts a
> (cost=0.42..42377.43 rows=1000000 width=89)
> -> Index Only Scan using pgbench_accounts_pkey on
> pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)

I didn't read the POC patch yet, but +1 for having that feature.

On Wed, 2021-05-12 at 18:03 +0530, Bharath Rupireddy wrote:
> On Wed, May 12, 2021 at 4:54 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> > During the discussion about memory contexts dumping[1], there
> > was a comment that exposing not only memory contexts but also
> > query plans and untruncated query string would be useful.
> >
> > postgres=# SELECT * FROM pg_log_current_plan(2155192);
> > pg_log_current_plan
> > ---------------------
> > t
> > (1 row)
> >
> > $ tail -f data/log/postgresql-2021-05-12.log
> >
> > 2021-05-12 17:37:19.481 JST [2155192] LOG: logging the plan of
> > running query on PID 2155192
> > Query Text: SELECT a.filler FROM pgbench_accounts a JOIN
> > pgbench_accounts b ON a.aid = b.aid;
> > Merge Join (cost=0.85..83357.85 rows=1000000 width=85)
> > Merge Cond: (a.aid = b.aid)
> > -> Index Scan using pgbench_accounts_pkey on
> > pgbench_accounts a (cost=0.42..42377.43 rows=1000000 width=89)
> > -> Index Only Scan using pgbench_accounts_pkey on
> > pgbench_accounts b (cost=0.42..25980.42 rows=1000000 width=4)

I love the idea, but I didn't look at the patch.

> Since it also shows up the full query text and the plan
> in the server log as plain text, there are chances that the sensitive
> information might be logged into the server log which is a risky thing
> from security standpoint.

I think that is irrelevant.

A superuser can already set "log_statement = 'all'" to get this.
There is no protection from superusers, and it is pointless to require that.

Yours,
Laurenz Albe

Thank you all for your positive comments.

On 2021-05-12 21:55, Matthias van de Meent wrote:

> Great idea. One feature I'd suggest would be adding a 'format' option
> as well, if such feature would be feasable.

Thanks for the comment!

During the development of pg_log_backend_memory_contexts(), I tried to
make the number of contexts to record configurable by making it GUC
variable or putting it on the shared memory, but the former seemed an
overkill and the latter introduced some ugly behaviors, so we decided
to make it a static number[1].
I think we face the same difficulty here.

Allowing to select the format would be better as auto_explain does by
auto_explain.log_format, but I'm a bit doubtful that it is worth the
costs.

[1]
https://www.postgresql.org/message-id/flat/6738f309-a41b-cbe6-bb57-a1c58ce9f05a%40oss.nttdata.com#e687d583080c96563b2fa2e32dbf3fb6

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-05-13 01:08, Laurenz Albe wrote:
> On Wed, 2021-05-12 at 18:03 +0530, Bharath Rupireddy wrote:
>> Since it also shows up the full query text and the plan
>> in the server log as plain text, there are chances that the sensitive
>> information might be logged into the server log which is a risky thing
>> from security standpoint.

Thanks for the notification!

> I think that is irrelevant.
>
> A superuser can already set "log_statement = 'all'" to get this.
> There is no protection from superusers, and it is pointless to require
> that.

AFAIU, since that discussion is whether or not users other than
superusers
should be given the privilege to execute the backtrace printing
function,
I think it might be applicable to pg_log_current_plan().

Since restricting privilege to superusers is stricter, I'm going to
proceed
as it is for now, but depending on the above discussion, it may be
better to
change it.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Wed, May 12, 2021 at 4:54 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> Hi,
>
> During the discussion about memory contexts dumping[1], there
> was a comment that exposing not only memory contexts but also
> query plans and untruncated query string would be useful.
>
> I also feel that it would be nice when thinking about situations
> such as troubleshooting a long-running query on production
> environments where we cannot use debuggers.
>
> At that point of the above comment, I was considering exposing
> such information on the shared memory.
> However, since memory contexts are now exposed on the log by
> pg_log_backend_memory_contexts(PID), I'm thinking about
> defining a function that logs the plan of a running query and
> untruncated query string on the specified PID in the same way
> as below.
>
> postgres=# SELECT * FROM pg_log_current_plan(2155192);
> pg_log_current_plan
> ---------------------
> t
> (1 row)

+1 for the idea. I did not read the complete patch but while reading
through the patch, I noticed that you using elevel as LOG for printing
the stack trace. But I think the backend whose pid you have passed,
the connected client to that backend might not have superuser
privileges and if you use elevel LOG then that message will be sent to
that connected client as well and I don't think that is secure. So
can we use LOG_SERVER_ONLY so that we can prevent
it from sending to the client.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 2:44 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> +1 for the idea. I did not read the complete patch but while reading
> through the patch, I noticed that you using elevel as LOG for printing
> the stack trace. But I think the backend whose pid you have passed,
> the connected client to that backend might not have superuser
> privileges and if you use elevel LOG then that message will be sent to
> that connected client as well and I don't think that is secure. So
> can we use LOG_SERVER_ONLY so that we can prevent
> it from sending to the client.

True, we should use LOG_SERVER_ONLY and not send any logs to the client.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 2:57 PM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> On Thu, May 13, 2021 at 2:44 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> > +1 for the idea. I did not read the complete patch but while reading
> > through the patch, I noticed that you using elevel as LOG for printing
> > the stack trace. But I think the backend whose pid you have passed,
> > the connected client to that backend might not have superuser
> > privileges and if you use elevel LOG then that message will be sent to
> > that connected client as well and I don't think that is secure. So
> > can we use LOG_SERVER_ONLY so that we can prevent
> > it from sending to the client.
>
> True, we should use LOG_SERVER_ONLY and not send any logs to the client.

I further tend to think that, is it correct to log queries with LOG
level when log_statement GUC is set? Or should it also be
LOG_SERVER_ONLY?

/* Log immediately if dictated by log_statement */
if (check_log_statement(parsetree_list))
{
ereport(LOG,
(errmsg("statement: %s", query_string),
errhidestmt(true),
errdetail_execute(parsetree_list)));

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 1:56 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>
> On 2021-05-13 01:08, Laurenz Albe wrote:
> > On Wed, 2021-05-12 at 18:03 +0530, Bharath Rupireddy wrote:
> >> Since it also shows up the full query text and the plan
> >> in the server log as plain text, there are chances that the sensitive
> >> information might be logged into the server log which is a risky thing
> >> from security standpoint.
>
> Thanks for the notification!
>
> > I think that is irrelevant.
> >
> > A superuser can already set "log_statement = 'all'" to get this.
> > There is no protection from superusers, and it is pointless to require
> > that.
>
> AFAIU, since that discussion is whether or not users other than
> superusers
> should be given the privilege to execute the backtrace printing
> function,
> I think it might be applicable to pg_log_current_plan().
>
> Since restricting privilege to superusers is stricter, I'm going to
> proceed
> as it is for now, but depending on the above discussion, it may be
> better to
> change it.

Yeah, we can keep it as superuser-only for now.

Might be unrelated, but just for info - there's another thread
"Granting control of SUSET gucs to non-superusers" at [1] discussing
the new roles.

[1] - https://www.postgresql.org/message-id/F9408A5A-B20B-42D2-9E7F-49CD3D1547BC%40enterprisedb.com

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 3:06 PM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>
> On Thu, May 13, 2021 at 2:57 PM Bharath Rupireddy
> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> > On Thu, May 13, 2021 at 2:44 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> > > +1 for the idea. I did not read the complete patch but while reading
> > > through the patch, I noticed that you using elevel as LOG for printing
> > > the stack trace. But I think the backend whose pid you have passed,
> > > the connected client to that backend might not have superuser
> > > privileges and if you use elevel LOG then that message will be sent to
> > > that connected client as well and I don't think that is secure. So
> > > can we use LOG_SERVER_ONLY so that we can prevent
> > > it from sending to the client.
> >
> > True, we should use LOG_SERVER_ONLY and not send any logs to the client.
>
> I further tend to think that, is it correct to log queries with LOG
> level when log_statement GUC is set? Or should it also be
> LOG_SERVER_ONLY?
>
> /* Log immediately if dictated by log_statement */
> if (check_log_statement(parsetree_list))
> {
> ereport(LOG,
> (errmsg("statement: %s", query_string),
> errhidestmt(true),
> errdetail_execute(parsetree_list)));
>

What is your argument behind logging it with LOG? I mean we are
sending the signal to all the backend and some backend might have the
client who is not connected as a superuser so sending the plan to
those clients is not a good idea from a security perspective.
Anyways, LOG_SERVER_ONLY is not an exposed logging level it is used
for an internal purpose. So IMHO it should be logged with
LOG_SERVER_ONLY level.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On 2021-05-13 18:36, Bharath Rupireddy wrote:
> On Thu, May 13, 2021 at 2:57 PM Bharath Rupireddy
> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>> On Thu, May 13, 2021 at 2:44 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com>
>> wrote:
>> > +1 for the idea. I did not read the complete patch but while reading
>> > through the patch, I noticed that you using elevel as LOG for printing
>> > the stack trace. But I think the backend whose pid you have passed,
>> > the connected client to that backend might not have superuser
>> > privileges and if you use elevel LOG then that message will be sent to
>> > that connected client as well and I don't think that is secure. So
>> > can we use LOG_SERVER_ONLY so that we can prevent
>> > it from sending to the client.
>>
>> True, we should use LOG_SERVER_ONLY and not send any logs to the
>> client.

Thanks, agree with changing it to LOG_SERVER_ONLY.

> I further tend to think that, is it correct to log queries with LOG
> level when log_statement GUC is set? Or should it also be
> LOG_SERVER_ONLY?

I feel it's OK to log with LOG_SERVER_ONLY since the log from
log_statement GUC would be printed already and independently.
ISTM people don't expect to log_statement GUC works even on
pg_log_current_plan(), do they?

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Thu, May 13, 2021 at 3:20 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
>
> On Thu, May 13, 2021 at 3:06 PM Bharath Rupireddy
> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> >
> > On Thu, May 13, 2021 at 2:57 PM Bharath Rupireddy
> > <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> > > On Thu, May 13, 2021 at 2:44 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> > > > +1 for the idea. I did not read the complete patch but while reading
> > > > through the patch, I noticed that you using elevel as LOG for printing
> > > > the stack trace. But I think the backend whose pid you have passed,
> > > > the connected client to that backend might not have superuser
> > > > privileges and if you use elevel LOG then that message will be sent to
> > > > that connected client as well and I don't think that is secure. So
> > > > can we use LOG_SERVER_ONLY so that we can prevent
> > > > it from sending to the client.
> > >
> > > True, we should use LOG_SERVER_ONLY and not send any logs to the client.
> >
> > I further tend to think that, is it correct to log queries with LOG
> > level when log_statement GUC is set? Or should it also be
> > LOG_SERVER_ONLY?
> >
> > /* Log immediately if dictated by log_statement */
> > if (check_log_statement(parsetree_list))
> > {
> > ereport(LOG,
> > (errmsg("statement: %s", query_string),
> > errhidestmt(true),
> > errdetail_execute(parsetree_list)));
>
> What is your argument behind logging it with LOG? I mean we are
> sending the signal to all the backend and some backend might have the
> client who is not connected as a superuser so sending the plan to
> those clients is not a good idea from a security perspective.
> Anyways, LOG_SERVER_ONLY is not an exposed logging level it is used
> for an internal purpose. So IMHO it should be logged with
> LOG_SERVER_ONLY level.

I'm saying that - currently, queries are logged with LOG level when
the log_statement GUC is set. The queries might be sent to the
non-superuser clients. So, your point of "sending the plan to those
clients is not a good idea from a security perspective" gets violated
right? Should the log level be changed(in the below code) from "LOG"
to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
to sidetrack the main feature.

/* Log immediately if dictated by log_statement */
if (check_log_statement(parsetree_list))
{
ereport(LOG,
(errmsg("statement: %s", query_string),
errhidestmt(true),
errdetail_execute(parsetree_list)));

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>
> I'm saying that - currently, queries are logged with LOG level when
> the log_statement GUC is set. The queries might be sent to the
> non-superuser clients. So, your point of "sending the plan to those
> clients is not a good idea from a security perspective" gets violated
> right? Should the log level be changed(in the below code) from "LOG"
> to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
> to sidetrack the main feature.
>
> /* Log immediately if dictated by log_statement */
> if (check_log_statement(parsetree_list))
> {
> ereport(LOG,
> (errmsg("statement: %s", query_string),
> errhidestmt(true),
> errdetail_execute(parsetree_list)));
>

Yes, that was my exact point, that in this particular code log with
LOG_SERVER_ONLY.

Like this.
/* Log immediately if dictated by log_statement */
if (check_log_statement(parsetree_list))
{
ereport(LOG_SERVER_ONLY,
.....

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
>
> On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> >
> > I'm saying that - currently, queries are logged with LOG level when
> > the log_statement GUC is set. The queries might be sent to the
> > non-superuser clients. So, your point of "sending the plan to those
> > clients is not a good idea from a security perspective" gets violated
> > right? Should the log level be changed(in the below code) from "LOG"
> > to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
> > to sidetrack the main feature.
> >
> > /* Log immediately if dictated by log_statement */
> > if (check_log_statement(parsetree_list))
> > {
> > ereport(LOG,
> > (errmsg("statement: %s", query_string),
> > errhidestmt(true),
> > errdetail_execute(parsetree_list)));
> >
>
> Yes, that was my exact point, that in this particular code log with
> LOG_SERVER_ONLY.
>
> Like this.
> /* Log immediately if dictated by log_statement */
> if (check_log_statement(parsetree_list))
> {
> ereport(LOG_SERVER_ONLY,

Agree, but let's discuss that in a separate thread.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 5:15 PM Bharath Rupireddy
<bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>
> On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> >
> > On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
> > <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> > >
> > > I'm saying that - currently, queries are logged with LOG level when
> > > the log_statement GUC is set. The queries might be sent to the
> > > non-superuser clients. So, your point of "sending the plan to those
> > > clients is not a good idea from a security perspective" gets violated
> > > right? Should the log level be changed(in the below code) from "LOG"
> > > to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
> > > to sidetrack the main feature.
> > >
> > > /* Log immediately if dictated by log_statement */
> > > if (check_log_statement(parsetree_list))
> > > {
> > > ereport(LOG,
> > > (errmsg("statement: %s", query_string),
> > > errhidestmt(true),
> > > errdetail_execute(parsetree_list)));
> > >
> >
> > Yes, that was my exact point, that in this particular code log with
> > LOG_SERVER_ONLY.
> >
> > Like this.
> > /* Log immediately if dictated by log_statement */
> > if (check_log_statement(parsetree_list))
> > {
> > ereport(LOG_SERVER_ONLY,
>
> Agree, but let's discuss that in a separate thread.

Did not understand why separate thread? this is part of this thread
no? but anyways now everyone agreed that we will log with
LOG_SERVER_ONLY.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Thu, May 13, 2021 at 5:18 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
>
> On Thu, May 13, 2021 at 5:15 PM Bharath Rupireddy
> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> >
> > On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
> > >
> > > On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
> > > <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
> > > >
> > > > I'm saying that - currently, queries are logged with LOG level when
> > > > the log_statement GUC is set. The queries might be sent to the
> > > > non-superuser clients. So, your point of "sending the plan to those
> > > > clients is not a good idea from a security perspective" gets violated
> > > > right? Should the log level be changed(in the below code) from "LOG"
> > > > to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
> > > > to sidetrack the main feature.
> > > >
> > > > /* Log immediately if dictated by log_statement */
> > > > if (check_log_statement(parsetree_list))
> > > > {
> > > > ereport(LOG,
> > > > (errmsg("statement: %s", query_string),
> > > > errhidestmt(true),
> > > > errdetail_execute(parsetree_list)));
> > > >
> > >
> > > Yes, that was my exact point, that in this particular code log with
> > > LOG_SERVER_ONLY.
> > >
> > > Like this.
> > > /* Log immediately if dictated by log_statement */
> > > if (check_log_statement(parsetree_list))
> > > {
> > > ereport(LOG_SERVER_ONLY,
> >
> > Agree, but let's discuss that in a separate thread.
>
> Did not understand why separate thread? this is part of this thread
> no? but anyways now everyone agreed that we will log with
> LOG_SERVER_ONLY.

Bharat offlist pointed to me that here he was talking about another
log that is logging the query and not specific to this patch, so let's
not discuss this point here.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On 2021-05-13 21:57, Dilip Kumar wrote:
> On Thu, May 13, 2021 at 5:18 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com>
> wrote:
>>
>> On Thu, May 13, 2021 at 5:15 PM Bharath Rupireddy
>> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>> >
>> > On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
>> > >
>> > > On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
>> > > <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>> > > >
>> > > > I'm saying that - currently, queries are logged with LOG level when
>> > > > the log_statement GUC is set. The queries might be sent to the
>> > > > non-superuser clients. So, your point of "sending the plan to those
>> > > > clients is not a good idea from a security perspective" gets violated
>> > > > right? Should the log level be changed(in the below code) from "LOG"
>> > > > to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
>> > > > to sidetrack the main feature.
>> > > >
>> > > > /* Log immediately if dictated by log_statement */
>> > > > if (check_log_statement(parsetree_list))
>> > > > {
>> > > > ereport(LOG,
>> > > > (errmsg("statement: %s", query_string),
>> > > > errhidestmt(true),
>> > > > errdetail_execute(parsetree_list)));
>> > > >
>> > >
>> > > Yes, that was my exact point, that in this particular code log with
>> > > LOG_SERVER_ONLY.
>> > >
>> > > Like this.
>> > > /* Log immediately if dictated by log_statement */
>> > > if (check_log_statement(parsetree_list))
>> > > {
>> > > ereport(LOG_SERVER_ONLY,
>> >
>> > Agree, but let's discuss that in a separate thread.
>>
>> Did not understand why separate thread? this is part of this thread
>> no? but anyways now everyone agreed that we will log with
>> LOG_SERVER_ONLY.

Modified elevel from LOG to LOG_SERVER_ONLY.

I also modified the patch to log JIT Summary and GUC settings
information.
If there is other useful information to log, I would appreciate it if
you could point it out.

> Bharat offlist pointed to me that here he was talking about another
> log that is logging the query and not specific to this patch, so let's
> not discuss this point here.

Thanks for sharing the situation!

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-05-28 15:51, torikoshia wrote:
> On 2021-05-13 21:57, Dilip Kumar wrote:
>> On Thu, May 13, 2021 at 5:18 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com>
>> wrote:
>>>
>>> On Thu, May 13, 2021 at 5:15 PM Bharath Rupireddy
>>> <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>>> >
>>> > On Thu, May 13, 2021 at 5:14 PM Dilip Kumar <dilipbalaut(at)gmail(dot)com> wrote:
>>> > >
>>> > > On Thu, May 13, 2021 at 4:16 PM Bharath Rupireddy
>>> > > <bharath(dot)rupireddyforpostgres(at)gmail(dot)com> wrote:
>>> > > >
>>> > > > I'm saying that - currently, queries are logged with LOG level when
>>> > > > the log_statement GUC is set. The queries might be sent to the
>>> > > > non-superuser clients. So, your point of "sending the plan to those
>>> > > > clients is not a good idea from a security perspective" gets violated
>>> > > > right? Should the log level be changed(in the below code) from "LOG"
>>> > > > to "LOG_SERVER_ONLY"? I think we can discuss this separately so as not
>>> > > > to sidetrack the main feature.
>>> > > >
>>> > > > /* Log immediately if dictated by log_statement */
>>> > > > if (check_log_statement(parsetree_list))
>>> > > > {
>>> > > > ereport(LOG,
>>> > > > (errmsg("statement: %s", query_string),
>>> > > > errhidestmt(true),
>>> > > > errdetail_execute(parsetree_list)));
>>> > > >
>>> > >
>>> > > Yes, that was my exact point, that in this particular code log with
>>> > > LOG_SERVER_ONLY.
>>> > >
>>> > > Like this.
>>> > > /* Log immediately if dictated by log_statement */
>>> > > if (check_log_statement(parsetree_list))
>>> > > {
>>> > > ereport(LOG_SERVER_ONLY,
>>> >
>>> > Agree, but let's discuss that in a separate thread.
>>>
>>> Did not understand why separate thread? this is part of this thread
>>> no? but anyways now everyone agreed that we will log with
>>> LOG_SERVER_ONLY.
>
> Modified elevel from LOG to LOG_SERVER_ONLY.
>
> I also modified the patch to log JIT Summary and GUC settings
> information.
> If there is other useful information to log, I would appreciate it if
> you could point it out.

Updated the patch.

- reordered superuser check which was pointed out in another thread[1]
- added a regression test

[1] https://postgr.es/m/YLxw1uVGIAP5uMPl@paquier.xyz

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021/06/09 16:44, torikoshia wrote:
> Updated the patch.

Thanks for updating the patch!

auto_explain can log the plan of even nested statement
if auto_explain.log_nested_statements is enabled.
But ISTM that pg_log_current_plan() cannot log that plan.
Is this intentional?
I think that it's better to make pg_log_current_plan() log
the plan of even nested statement.

+ es->format = EXPLAIN_FORMAT_TEXT;
+ es->settings = true;

Since pg_log_current_plan() is usually used to investigate and
trouble-shoot the long running queries, IMO it's better to
enable es->verbose by default and get additional information
about the queries. Thought?

+ * pg_log_current_plan
+ * Signal a backend process to log plan the of running query.

"plan the of" is typo?

+ * Only superusers are allowed to signal to log plan because any users to
+ * issue this request at an unbounded rate would cause lots of log messages
+ * and which can lead to denial of service.

"because any users" should be "because allowing any users"
like the comment for pg_log_backend_memory_contexts()?

+ * All the actual work is deferred to ProcessLogExplainInterrupt(),

"ProcessLogExplainInterrupt()" should be "ProcessLogCurrentPlanInterrupt()"?

Regards,

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

On 2021-06-09 23:04, Fujii Masao wrote:

Thanks for your review!

> auto_explain can log the plan of even nested statement
> if auto_explain.log_nested_statements is enabled.
> But ISTM that pg_log_current_plan() cannot log that plan.
> Is this intentional?

> I think that it's better to make pg_log_current_plan() log
> the plan of even nested statement.

+1. It would be better.
But currently plan information is got from ActivePortal and ISTM there
are no easy way to retrieve plan information of nested statements from
ActivePortal.
Anyway I'll do some more research.

I think you are right about the following comments.
I'll fix them.

> + es->format = EXPLAIN_FORMAT_TEXT;
> + es->settings = true;
>
> Since pg_log_current_plan() is usually used to investigate and
> trouble-shoot the long running queries, IMO it's better to
> enable es->verbose by default and get additional information
> about the queries. Thought?
> + * pg_log_current_plan
> + * Signal a backend process to log plan the of running query.
>
> "plan the of" is typo?
>
>
> + * Only superusers are allowed to signal to log plan because any users
> to
> + * issue this request at an unbounded rate would cause lots of log
> messages
> + * and which can lead to denial of service.
>
> "because any users" should be "because allowing any users"
> like the comment for pg_log_backend_memory_contexts()?
>
>
> + * All the actual work is deferred to ProcessLogExplainInterrupt(),
>
> "ProcessLogExplainInterrupt()" should be
> "ProcessLogCurrentPlanInterrupt()"?
>
> Regards,

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Wed, Jun 9, 2021 at 1:14 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> Updated the patch.

Thanks for the patch. Here are some comments on v3 patch:

1) We could just say "Requests to log query plan of the presently
running query of a given backend along with an untruncated query
string in the server logs."
Instead of
+ They will be logged at <literal>LOG</literal> message level and
+ will appear in the server log based on the log
+ configuration set (See <xref linkend="runtime-config-logging"/>

2) It's better to do below, for reference see how pg_backend_pid,
pg_terminate_backend, pg_relpages and so on are used in the tests.
+SELECT pg_log_current_plan(pg_backend_pid());
rather than using the function in the FROM clause.
+SELECT * FROM pg_log_current_plan(pg_backend_pid());
If okay, also change it for pg_log_backend_memory_contexts.

3) Since most of the code looks same in pg_log_backend_memory_contexts
and pg_log_current_plan, I think we can have a common function
something like below:
bool
SendProcSignalForLogInfo(ProcSignalReason reason)
{
Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT || reason ==
PROCSIG_LOG_CURRENT_PLAN);

if (!superuser())
{
if (reason == PROCSIG_LOG_MEMORY_CONTEXT)
errmsg("must be a superuser to log memory contexts")
else if (reason == PROCSIG_LOG_CURRENT_PLAN)
errmsg("must be a superuser to log plan of the running query")
}

if (SendProcSignal(pid, reason, proc->backendId) < 0)
{
}
}
Then we could just do:
Datum
pg_log_backend_memory_contexts(PG_FUNCTION_ARGS)
{
PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_MEMORY_CONTEXT));
}
Datum
pg_log_current_plan(PG_FUNCTION_ARGS)
{
PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_CURRENT_PLAN));
}
We can have SendProcSignalForLogInfo function defined in procsignal.c
and procsignal.h

4) I think we can have a sample function usage and how it returns true
value, how the plan looks for a simple query(select 1 or some other
simple/complex generic query or simply select
pg_log_current_plan(pg_backend_pid());) in the documentation, much
like pg_log_backend_memory_contexts.

5) Instead of just showing the true return value of the function
pg_log_current_plan in the sql test, which just shows that the signal
is sent, but it doesn't mean that the backend has processed that
signal and logged the plan. I think we can add the test using TAP
framework, one

6) Do we unnecessarily need to signal the processes such as autovacuum
launcher/workers, logical replication launcher/workers, wal senders,
wal receivers and so on. only to emit a "PID %d is not executing
queries now" message? Moreover, those processes will be waiting in
loops for timeouts to occur, then as soon as they wake up do they need
to process this extra uninformative signal?
We could choose to not signal those processes at all which might or
might not be possible.
Otherwise, we could just emit messages like "XXXX process cannot run a
query" in ProcessInterrupts.

7)Instead of
(errmsg("logging plan of the running query on PID %d\n%s",
how about below?
(errmsg("plan of the query running on backend with PID %d is:\n%s",

8) Instead of
errmsg("PID %d is not executing queries now")
how about below?
errmsg("Backend with PID %d is not running a query")

9) We could just do:
void
ProcessLogCurrentPlanInterrupt(void)
{
ExplainState *es;
LogCurrentPlanPending = false;
if (!ActivePortal || !ActivePortal->queryDesc)
errmsg("PID %d is not executing queries now");
es = NewExplainState();
ExplainQueryText();
ExplainPrintPlan();

10) How about renaming the function pg_log_current_plan to
pg_log_query_plan or pg_log_current_query_plan?

11) What happens if pg_log_current_plan is called for a parallel worker?

With Regards,
Bharath Rupireddy.

On 2021-06-11 01:20, Bharath Rupireddy wrote:

Thanks for your review!

> On Wed, Jun 9, 2021 at 1:14 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>> Updated the patch.
>
> Thanks for the patch. Here are some comments on v3 patch:
>
> 1) We could just say "Requests to log query plan of the presently
> running query of a given backend along with an untruncated query
> string in the server logs."
> Instead of
> + They will be logged at <literal>LOG</literal> message level
> and
> + will appear in the server log based on the log
> + configuration set (See <xref
> linkend="runtime-config-logging"/>

Actually this explanation is almost the same as that of
pg_log_backend_memory_contexts().
Do you think we should change both of them?
I think it may be too detailed but accurate.

> 2) It's better to do below, for reference see how pg_backend_pid,
> pg_terminate_backend, pg_relpages and so on are used in the tests.
> +SELECT pg_log_current_plan(pg_backend_pid());
> rather than using the function in the FROM clause.
> +SELECT * FROM pg_log_current_plan(pg_backend_pid());
> If okay, also change it for pg_log_backend_memory_contexts.

Agreed.

> 3) Since most of the code looks same in pg_log_backend_memory_contexts
> and pg_log_current_plan, I think we can have a common function
> something like below:

Agreed. I'll do some refactoring.

> bool
> SendProcSignalForLogInfo(ProcSignalReason reason)
> {
> Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT || reason ==
> PROCSIG_LOG_CURRENT_PLAN);
>
> if (!superuser())
> {
> if (reason == PROCSIG_LOG_MEMORY_CONTEXT)
> errmsg("must be a superuser to log memory contexts")
> else if (reason == PROCSIG_LOG_CURRENT_PLAN)
> errmsg("must be a superuser to log plan of the running query")
> }
>
> if (SendProcSignal(pid, reason, proc->backendId) < 0)
> {
> }
> }
> Then we could just do:
> Datum
> pg_log_backend_memory_contexts(PG_FUNCTION_ARGS)
> {
> PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_MEMORY_CONTEXT));
> }
> Datum
> pg_log_current_plan(PG_FUNCTION_ARGS)
> {
> PG_RETURN_BOOL(SendProcSignalForLogInfo(PROCSIG_LOG_CURRENT_PLAN));
> }
> We can have SendProcSignalForLogInfo function defined in procsignal.c
> and procsignal.h
>
> 4) I think we can have a sample function usage and how it returns true
> value, how the plan looks for a simple query(select 1 or some other
> simple/complex generic query or simply select
> pg_log_current_plan(pg_backend_pid());) in the documentation, much
> like pg_log_backend_memory_contexts.

+1.

> 5) Instead of just showing the true return value of the function
> pg_log_current_plan in the sql test, which just shows that the signal
> is sent, but it doesn't mean that the backend has processed that
> signal and logged the plan. I think we can add the test using TAP
> framework, one

I once made a tap test for pg_log_backend_memory_contexts(), but it
seemed an overkill and we agreed that it was appropriate just ensuring
the function working as below discussion.

https://www.postgresql.org/message-id/bbecd722d4f8e261b350186ac4bf68a7%40oss.nttdata.com

> 6) Do we unnecessarily need to signal the processes such as autovacuum
> launcher/workers, logical replication launcher/workers, wal senders,
> wal receivers and so on. only to emit a "PID %d is not executing
> queries now" message? Moreover, those processes will be waiting in
> loops for timeouts to occur, then as soon as they wake up do they need
> to process this extra uninformative signal?
> We could choose to not signal those processes at all which might or
> might not be possible.
> Otherwise, we could just emit messages like "XXXX process cannot run a
> query" in ProcessInterrupts.

Agreed.

However it needs to distinguish backends which can execute queries and
other processes such as autovacuum launcher, I don't come up with
easy ways to do so.
I'm going to think about it.

> 7)Instead of
> (errmsg("logging plan of the running query on PID %d\n%s",
> how about below?
> (errmsg("plan of the query running on backend with PID %d is:\n%s",

+1.

> 8) Instead of
> errmsg("PID %d is not executing queries now")
> how about below?
> errmsg("Backend with PID %d is not running a query")

+1.

>
> 9) We could just do:
> void
> ProcessLogCurrentPlanInterrupt(void)
> {
> ExplainState *es;
> LogCurrentPlanPending = false;
> if (!ActivePortal || !ActivePortal->queryDesc)
> errmsg("PID %d is not executing queries now");
> es = NewExplainState();
> ExplainQueryText();
> ExplainPrintPlan();
>
> 10) How about renaming the function pg_log_current_plan to
> pg_log_query_plan or pg_log_current_query_plan?

+1.

> 11) What happens if pg_log_current_plan is called for a parallel
> worker?

AFAIU Parallel worker doesn't have ActivePortal, so it would always
emit the message 'PID %d is not executing queries now'.
As 6), it would be better to distinguish the parallel worker and normal
backend.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Mon, Jun 14, 2021 at 5:48 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> > 1) We could just say "Requests to log query plan of the presently
> > running query of a given backend along with an untruncated query
> > string in the server logs."
> > Instead of
> > + They will be logged at <literal>LOG</literal> message level
> > and
> > + will appear in the server log based on the log
> > + configuration set (See <xref
> > linkend="runtime-config-logging"/>
>
> Actually this explanation is almost the same as that of
> pg_log_backend_memory_contexts().
> Do you think we should change both of them?
> I think it may be too detailed but accurate.

I withdraw my comment. We can keep the explanation similar to
pg_log_backend_memory_contexts as it was agreed upon and committed
text. If the wordings are similar, then it will be easier for users to
understand the documentation.

> > 5) Instead of just showing the true return value of the function
> > pg_log_current_plan in the sql test, which just shows that the signal
> > is sent, but it doesn't mean that the backend has processed that
> > signal and logged the plan. I think we can add the test using TAP
> > framework, one
>
> I once made a tap test for pg_log_backend_memory_contexts(), but it
> seemed an overkill and we agreed that it was appropriate just ensuring
> the function working as below discussion.
>
> https://www.postgresql.org/message-id/bbecd722d4f8e261b350186ac4bf68a7%40oss.nttdata.com

Okay. I withdraw my comment.

> > 6) Do we unnecessarily need to signal the processes such as autovacuum
> > launcher/workers, logical replication launcher/workers, wal senders,
> > wal receivers and so on. only to emit a "PID %d is not executing
> > queries now" message? Moreover, those processes will be waiting in
> > loops for timeouts to occur, then as soon as they wake up do they need
> > to process this extra uninformative signal?
> > We could choose to not signal those processes at all which might or
> > might not be possible.
> > Otherwise, we could just emit messages like "XXXX process cannot run a
> > query" in ProcessInterrupts.
>
> Agreed.
>
> However it needs to distinguish backends which can execute queries and
> other processes such as autovacuum launcher, I don't come up with
> easy ways to do so.
> I'm going to think about it.

I'm not sure if there is any information in the shared memory
accessible to all the backends/sessions that can say a PID is
autovacuum launcher/worker, logical replication launcher/worker or any
other background or parallel worker. If we were to invent a new
mechanism just for addressing the above comment, I would rather choose
to not do that as it seems like an overkill. We can leave it up to the
user whether or not to unnecessarily signal those processes which are
bound to print "PID XXX is not executing queries now" message.

> > 11) What happens if pg_log_current_plan is called for a parallel
> > worker?
>
> AFAIU Parallel worker doesn't have ActivePortal, so it would always
> emit the message 'PID %d is not executing queries now'.
> As 6), it would be better to distinguish the parallel worker and normal
> backend.

As I said, above, I think it will be a bit tough to do. If done, it
seems like an overkill.

With Regards,
Bharath Rupireddy.

On 2021-06-15 13:27, Bharath Rupireddy wrote:
> On Mon, Jun 14, 2021 at 5:48 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>> > 1) We could just say "Requests to log query plan of the presently
>> > running query of a given backend along with an untruncated query
>> > string in the server logs."
>> > Instead of
>> > + They will be logged at <literal>LOG</literal> message level
>> > and
>> > + will appear in the server log based on the log
>> > + configuration set (See <xref
>> > linkend="runtime-config-logging"/>
>>
>> Actually this explanation is almost the same as that of
>> pg_log_backend_memory_contexts().
>> Do you think we should change both of them?
>> I think it may be too detailed but accurate.
>
> I withdraw my comment. We can keep the explanation similar to
> pg_log_backend_memory_contexts as it was agreed upon and committed
> text. If the wordings are similar, then it will be easier for users to
> understand the documentation.
>
>> > 5) Instead of just showing the true return value of the function
>> > pg_log_current_plan in the sql test, which just shows that the signal
>> > is sent, but it doesn't mean that the backend has processed that
>> > signal and logged the plan. I think we can add the test using TAP
>> > framework, one
>>
>> I once made a tap test for pg_log_backend_memory_contexts(), but it
>> seemed an overkill and we agreed that it was appropriate just ensuring
>> the function working as below discussion.
>>
>> https://www.postgresql.org/message-id/bbecd722d4f8e261b350186ac4bf68a7%40oss.nttdata.com
>
> Okay. I withdraw my comment.
>
>> > 6) Do we unnecessarily need to signal the processes such as autovacuum
>> > launcher/workers, logical replication launcher/workers, wal senders,
>> > wal receivers and so on. only to emit a "PID %d is not executing
>> > queries now" message? Moreover, those processes will be waiting in
>> > loops for timeouts to occur, then as soon as they wake up do they need
>> > to process this extra uninformative signal?
>> > We could choose to not signal those processes at all which might or
>> > might not be possible.
>> > Otherwise, we could just emit messages like "XXXX process cannot run a
>> > query" in ProcessInterrupts.
>>
>> Agreed.
>>
>> However it needs to distinguish backends which can execute queries and
>> other processes such as autovacuum launcher, I don't come up with
>> easy ways to do so.
>> I'm going to think about it.
>
> I'm not sure if there is any information in the shared memory
> accessible to all the backends/sessions that can say a PID is
> autovacuum launcher/worker, logical replication launcher/worker or any
> other background or parallel worker.

As far as I looked around, there seems no easy ways to do so.

> If we were to invent a new
> mechanism just for addressing the above comment, I would rather choose
> to not do that as it seems like an overkill. We can leave it up to the
> user whether or not to unnecessarily signal those processes which are
> bound to print "PID XXX is not executing queries now" message.

+1. I'm going to proceed in this direction.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-06-16 20:36, torikoshia wrote:
>> other background or parallel worker.
>
> As far as I looked around, there seems no easy ways to do so.
>
>> If we were to invent a new
>> mechanism just for addressing the above comment, I would rather choose
>> to not do that as it seems like an overkill. We can leave it up to the
>> user whether or not to unnecessarily signal those processes which are
>> bound to print "PID XXX is not executing queries now" message.
>
> +1. I'm going to proceed in this direction.

Updated the patch.

On Thu, Jun 10, 2021 at 11:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
wrote:
> On 2021-06-09 23:04, Fujii Masao wrote:

> > auto_explain can log the plan of even nested statement
> > if auto_explain.log_nested_statements is enabled.
> > But ISTM that pg_log_current_plan() cannot log that plan.
> > Is this intentional?
>
> > I think that it's better to make pg_log_current_plan() log
> > the plan of even nested statement.
>
> +1. It would be better.
> But currently plan information is got from ActivePortal and ISTM there
> are no easy way to retrieve plan information of nested statements from
> ActivePortal.
> Anyway I'll do some more research.

I haven't found a proper way yet but it seems necessary to use something
other than ActivePortal and I'm now thinking this could be a separate
patch in the future.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021/06/22 11:30, torikoshia wrote:
> On Thu, Jun 10, 2021 at 11:09 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>> On 2021-06-09 23:04, Fujii Masao wrote:
>
>> > auto_explain can log the plan of even nested statement
>> > if auto_explain.log_nested_statements is enabled.
>> > But ISTM that pg_log_current_plan() cannot log that plan.
>> > Is this intentional?
>>
>> > I think that it's better to make pg_log_current_plan() log
>> > the plan of even nested statement.
>>
>> +1. It would be better.
>> But currently plan information is got from ActivePortal and ISTM there
>> are no easy way to retrieve plan information of nested statements from
>> ActivePortal.
>> Anyway I'll do some more research.
>
> I haven't found a proper way yet but it seems necessary to use something other than ActivePortal and I'm now thinking this could be a separate patch in the future.

DO $$
BEGIN
PERFORM pg_sleep(100);
END$$;

When I called pg_log_current_query_plan() to send the signal to
the backend executing the above query, I got the following log message.
I think that this is not expected message. I guess this issue happened
because the information about query text and plan is retrieved
from ActivePortal. If this understanding is right, ISTM that we should
implement new mechanism so that we can retrieve those information
even while nested query is being executed.

LOG: backend with PID 42449 is not running a query

Regards,

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

On Tue, Jun 22, 2021 at 8:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> Updated the patch.

Thanks for the patch. Here are some comments on the v4 patch:

1) Can we do + ExplainState *es = NewExplainState(); and es
assignments after if (!ActivePortal || !ActivePortal->queryDesc), just
to avoid unnecessary call in case of error hit? Also note that, we can
easily hit the error case.

2) It looks like there's an improper indentation. MyProcPid and
es->str->data, should start from the ".
+ ereport(LOG_SERVER_ONLY,
+ (errmsg("backend with PID %d is not running a query",
+ MyProcPid)));

+ ereport(LOG_SERVER_ONLY,
+ (errmsg("plan of the query running on backend with PID %d is:\n%s",
+ MyProcPid,
+ es->str->data),
For reference see errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",

3)I prefer to do this so that any new piece of code can be introduced
in between easily and it will be more readable as well.
+Datum
+pg_log_current_query_plan(PG_FUNCTION_ARGS)
+{
+ pid_t pid;
+ bool result;
+
+ pid = PG_GETARG_INT32(0);
+ result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN);
+
+ PG_RETURN_BOOL(result);
+}
If okay, please also change for the pg_log_backend_memory_contexts.

4) Extra whitespace before the second line i.e. 2nd line reason should
be aligned with the 1st line reason.
+ Assert(reason == PROCSIG_LOG_MEMORY_CONTEXT ||
+ reason == PROCSIG_LOG_CURRENT_PLAN);

5) How about "Requests to log the plan of the query currently running
on the backend with specified process ID along with the untruncated
query string"?
+ Requests to log the untruncated query string and its plan for
+ the query currently running on the backend with the specified
+ process ID.

6) A typo: it is "nested statements (..) are not"
+ Note that nested statements (statements executed inside a function) is not

7) I'm not sure what you mean by "Some functions output what you want
to the log."
--- Memory contexts are logged and they are not returned to the function.
+-- Some functions output what you want to the log.
Instead, can we say "These functions return true if the specified
backend is successfully signaled, otherwise false. Upon receiving the
signal, the backend will log the information to the server log."

Regards,
Bharath Rupireddy.

On 2021-07-02 23:21, Bharath Rupireddy wrote:
> On Tue, Jun 22, 2021 at 8:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
>> Updated the patch.
>
> Thanks for the patch. Here are some comments on the v4 patch:

Thanks for your comments and suggestions!
I agree with you and updated the patch.

On Thu, Jul 1, 2021 at 3:34 PM Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com>
wrote:

> DO $$
> BEGIN
> PERFORM pg_sleep(100);
> END$$;
>
> When I called pg_log_current_query_plan() to send the signal to
> the backend executing the above query, I got the following log message.
> I think that this is not expected message. I guess this issue happened
> because the information about query text and plan is retrieved
> from ActivePortal. If this understanding is right, ISTM that we should
> implement new mechanism so that we can retrieve those information
> even while nested query is being executed.

I'm now working on this comment.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Tue, Jun 22, 2021 at 8:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
wrote:
> Updated the patch.

Hi, torikoshi-san

Thanks for your great work! I'd like to use this feature in v15.
I confirmed that it works with queries I tried and make check-world has
no error.

When I tried this feature, I realized two things. So, I share them.

(1) About output contents

> The format of the query plan is the same as when <literal>FORMAT
> TEXT</literal>
> and <literal>VEBOSE</literal> are used in the
> <command>EXPLAIN</command> command.
> For example:

I think the above needs to add COSTS and SETTINGS options too, and it's
better to use an
example which the SETTINGS option works like the following.

```
2021-07-13 21:59:56 JST 69757 [client backend] LOG: plan of the query
running on backend with PID 69757 is:
Query Text: PREPARE query2 AS SELECT COUNT(*) FROM
pgbench_accounts t1, pgbench_accounts t2;
Aggregate (cost=3750027242.84..3750027242.86 rows=1 width=8)
Output: count(*)
-> Nested Loop (cost=0.84..3125027242.84 rows=250000000000
width=0)
-> Index Only Scan using pgbench_accounts_pkey on
public.pgbench_accounts t1 (cost=0.42..12996.42 rows=500000 width=0)
Output: t1.aid
-> Materialize (cost=0.42..15496.42 rows=500000
width=0)
-> Index Only Scan using pgbench_accounts_pkey on
public.pgbench_accounts t2 (cost=0.42..12996.42 rows=500000 width=0)
Settings: effective_cache_size = '8GB', work_mem = '16MB'
```

(2) About EXPLAIN "BUFFER" option

When I checked EXPLAIN option, I found there is another option "BUFFER"
which can be
used without the "ANALYZE" option.

I'm not sure it's useful because your target use-case is analyzing a
long-running query,
not its planning phase. If so, the planning buffer usage is not so much
useful. But, since
the overhead to output buffer usages is not high and it's used for
debugging use cases,
I wonder it's not a bad idea to output buffer usages too. Thought?

Regards,
--
Masahiro Ikeda
NTT DATA CORPORATION

On Tue, Jul 13, 2021 at 11:11 PM Masahiro Ikeda
<ikedamsh(at)oss(dot)nttdata(dot)com> wrote:

> When I tried this feature, I realized two things. So, I share them.

Thanks for your review!

> (1) About output contents
>
> > The format of the query plan is the same as when <literal>FORMAT
> > TEXT</literal>
> > and <literal>VEBOSE</literal> are used in the
> > <command>EXPLAIN</command> command.
> > For example:

> I think the above needs to add COSTS and SETTINGS options too, and it's
> better to use an
> example which the SETTINGS option works like the following.

Agreed. Updated the patch.

> (2) About EXPLAIN "BUFFER" option
>
> When I checked EXPLAIN option, I found there is another option "BUFFER"
> which can be
> used without the "ANALYZE" option.
>
> I'm not sure it's useful because your target use-case is analyzing a
> long-running query,
> not its planning phase. If so, the planning buffer usage is not so much
> useful. But, since
> the overhead to output buffer usages is not high and it's used for
> debugging use cases,
> I wonder it's not a bad idea to output buffer usages too. Thought?

As you pointed out, I also think it would be useful when queries are
taking a long time in the planning phase.
However, as far as I read ExplainOneQuery(), the buffer usages in the
planner phase are not retrieved by default. They are retrieved only when
BUFFERS is specified in the EXPLAIN.

If we change it to always get the buffer usages and expose them as a
global variable, we can get them through pg_log_current_plan(), but I
think it doesn't pay.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021/07/19 11:28, torikoshia wrote:
> Agreed. Updated the patch.

Thanks for updating the patch!

+bool
+SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason)

I don't think that procsignal.c is proper place to check the permission and
check whether the specified PID indicates a PostgreSQL server process, etc
because procsignal.c just provides fundamental routines for interprocess
signaling. Isn't it better to move the function to signalfuncs.c or elsewhere?

+ ExplainQueryText(es, ActivePortal->queryDesc);
+ ExplainPrintPlan(es, ActivePortal->queryDesc);
+ ExplainPrintJITSummary(es, ActivePortal->queryDesc);

When text format is used, ExplainBeginOutput() and ExplainEndOutput()
do nothing. So (I guess) you thought that they don't need to be called and
implemented the code in that way. But IMO it's better to comment
why they don't need to be called, or to just call both of them
even if they do nothing in text format.

+ ExplainPrintJITSummary(es, ActivePortal->queryDesc);

It's better to check es->costs before calling this function,
like explain_ExecutorEnd() and ExplainOnePlan() do?

+ result = SendProcSignalForLogInfo(pid, PROCSIG_LOG_CURRENT_PLAN);
+
+ PG_RETURN_BOOL(result);

Currently SendProcSignalForLogInfo() calls PG_RETURN_BOOL() in some cases,
but instead it should just return true/false because pg_log_current_query_plan()
expects that?

Regards,

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

On 2021/07/09 14:05, torikoshia wrote:
> On 2021-07-02 23:21, Bharath Rupireddy wrote:
>> On Tue, Jun 22, 2021 at 8:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
>>> Updated the patch.
>>
>> Thanks for the patch. Here are some comments on the v4 patch:
>
> Thanks for your comments and suggestions!
> I agree with you and updated the patch.
>
> On Thu, Jul 1, 2021 at 3:34 PM Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com> wrote:
>
>>      DO $$
>>      BEGIN
>>      PERFORM pg_sleep(100);
>>      END$$;
>>
>> When I called pg_log_current_query_plan() to send the signal to
>> the backend executing the above query, I got the following log message.
>> I think that this is not expected message. I guess this issue happened
>> because the information about query text and plan is retrieved
>> from ActivePortal. If this understanding is right, ISTM that we should
>> implement new mechanism so that we can retrieve those information
>> even while nested query is being executed.
>
> I'm now working on this comment.

One idea is to define new global pointer, e.g., "QueryDesc *ActiveQueryDesc;".
This global pointer is set to queryDesc in ExecutorRun()
(also maybe ExecutorStart()). And this is reset to NULL in ExecutorEnd() and
when an error is thrown. Then ProcessLogCurrentPlanInterrupt() can
get the plan of the currently running query from that global pointer
instead of ActivePortal, and log it. Thought?

Regards,

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

út 27. 7. 2021 v 20:34 odesílatel Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com>
napsal:

>
>
> On 2021/07/09 14:05, torikoshia wrote:
> > On 2021-07-02 23:21, Bharath Rupireddy wrote:
> >> On Tue, Jun 22, 2021 at 8:00 AM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
> wrote:
> >>> Updated the patch.
> >>
> >> Thanks for the patch. Here are some comments on the v4 patch:
> >
> > Thanks for your comments and suggestions!
> > I agree with you and updated the patch.
> >
> > On Thu, Jul 1, 2021 at 3:34 PM Fujii Masao <masao(dot)fujii(at)oss(dot)nttdata(dot)com>
> wrote:
> >
> >> DO $$
> >> BEGIN
> >> PERFORM pg_sleep(100);
> >> END$$;
> >>
> >> When I called pg_log_current_query_plan() to send the signal to
> >> the backend executing the above query, I got the following log message.
> >> I think that this is not expected message. I guess this issue happened
> >> because the information about query text and plan is retrieved
> >> from ActivePortal. If this understanding is right, ISTM that we should
> >> implement new mechanism so that we can retrieve those information
> >> even while nested query is being executed.
> >
> > I'm now working on this comment.
>
> One idea is to define new global pointer, e.g., "QueryDesc
> *ActiveQueryDesc;".
> This global pointer is set to queryDesc in ExecutorRun()
> (also maybe ExecutorStart()). And this is reset to NULL in ExecutorEnd()
> and
> when an error is thrown. Then ProcessLogCurrentPlanInterrupt() can
> get the plan of the currently running query from that global pointer
> instead of ActivePortal, and log it. Thought?
>

It cannot work - there can be a lot of nested queries, and at the end you
cannot reset to null, but you should return back pointer to outer query.

Regards

Pavel

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

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

Thanks for your comment!

I'm wondering if we can avoid this problem by saving one outer level
QueryDesc in addition to the current one.
I'm going to try it.

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

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

I have updated the patch in this way.

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

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

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

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

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

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

Any thoughts?

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021/08/10 21:22, torikoshia wrote:
> I have updated the patch in this way.

Thanks for updating the patch!

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

Looks good to me.

> Any thoughts?

+ ereport(LOG_SERVER_ONLY,
+ (errmsg("plan of the query running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true)));

Shouldn't we hide context information by calling errhidecontext(true)?

While "make installcheck" regression test was running, I repeated
executing pg_log_current_query_plan() and got the failure of join_hash test
with the following diff. This means that pg_log_current_query_plan() could
cause the query that should be completed successfully to fail with the error.
Isn't this a bug?

I *guess* that the cause of this issue is that ExplainNode() can call
InstrEndLoop() more than once unexpectedly.

------------------------------------------------------------------------------
$$
select count(*) from simple r join simple s using (id);
$$);
- initially_multibatch | increased_batches
-----------------------+-------------------
- f | f
-(1 row)
-
+ERROR: InstrEndLoop called on running node
+CONTEXT: PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE statement
rollback to settings;
-- parallel with parallel-oblivious hash join
savepoint settings;
@@ -687,11 +684,9 @@
left join (select b1.id, b1.t from join_bar b1 join join_bar b2 using (id)) ss
on join_foo.id < ss.id + 1 and join_foo.id > ss.id - 1;
$$);
- multibatch
-------------
- t
-(1 row)
-
+ERROR: InstrEndLoop called on running node
+CONTEXT: parallel worker
+PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE statement
rollback to settings;
-- single-batch with rescan, parallel-aware
savepoint settings;
------------------------------------------------------------------------------

Regards,

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

On 2021-08-11 00:21, Fujii Masao wrote:

> On 2021/08/10 21:22, torikoshia wrote:
>> I have updated the patch in this way.
>
> Thanks for updating the patch!
>
>
>> In this patch, getting the plan to the DO statement is as follows.
>
> Looks good to me.
>
>
>> Any thoughts?
>
> + ereport(LOG_SERVER_ONLY,
> + (errmsg("plan of the query running on backend with PID %d is:\n%s",
> + MyProcPid, es->str->data),
> + errhidestmt(true)));
>
> Shouldn't we hide context information by calling errhidecontext(true)?

Agreed.

> While "make installcheck" regression test was running, I repeated
> executing pg_log_current_query_plan() and got the failure of join_hash
> test
> with the following diff. This means that pg_log_current_query_plan()
> could
> cause the query that should be completed successfully to fail with the
> error.
> Isn't this a bug?

Thanks for finding the bug.
I also reproduced it.

> I *guess* that the cause of this issue is that ExplainNode() can call
> InstrEndLoop() more than once unexpectedly.

As far as I looked into, pg_log_current_plan() can call InstrEndLoop()
through ExplainNode().
I added a flag to ExplainState to avoid calling InstrEndLoop() when
ExplainNode() is called from pg_log_current_plan().

>
>
> ------------------------------------------------------------------------------
> $$
> select count(*) from simple r join simple s using (id);
> $$);
> - initially_multibatch | increased_batches
> -----------------------+-------------------
> - f | f
> -(1 row)
> -
> +ERROR: InstrEndLoop called on running node
> +CONTEXT: PL/pgSQL function hash_join_batches(text) line 6 at FOR
> over EXECUTE statement
> rollback to settings;
> -- parallel with parallel-oblivious hash join
> savepoint settings;
> @@ -687,11 +684,9 @@
> left join (select b1.id, b1.t from join_bar b1 join join_bar b2
> using (id)) ss
> on join_foo.id < ss.id + 1 and join_foo.id > ss.id - 1;
> $$);
> - multibatch
> -------------
> - t
> -(1 row)
> -
> +ERROR: InstrEndLoop called on running node
> +CONTEXT: parallel worker
> +PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE
> statement
> rollback to settings;
> -- single-batch with rescan, parallel-aware
> savepoint settings;
>
> ------------------------------------------------------------------------------
>
> Regards,

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021/08/11 21:14, torikoshia wrote:
> As far as I looked into, pg_log_current_plan() can call InstrEndLoop() through ExplainNode().
> I added a flag to ExplainState to avoid calling InstrEndLoop() when ExplainNode() is called from pg_log_current_plan().

Thanks for updating the patch!
I tried to test the patch again and encountered two issues.

(1)
The following WITH RECURSIVE query failed with the error
"ERROR: failed to find plan for CTE sg" when I ran
pg_log_current_query_plan() against the backend executing that query.
Is this a bug?

create table graph0( f int, t int, label text );
insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 -> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');

with recursive search_graph(f, t, label, i) as (
select *, 1||pg_sleep(1)::text from graph0 g
union distinct
select g.*,1||pg_sleep(1)::text
from graph0 g, search_graph sg
where g.f = sg.t
) search breadth first by f, t set seq
select * from search_graph order by seq;

(2)
When I ran pg_log_current_query_plan() while "make installcheck" test
was running, I got the following assertion failure.

TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type == LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)

0 postgres 0x000000010ec23557 ExceptionalCondition + 231
1 postgres 0x000000010e9eff15 LockAcquireExtended + 1461
2 postgres 0x000000010e9ed14d LockRelationOid + 61
3 postgres 0x000000010e41251b relation_open + 91
4 postgres 0x000000010e509679 table_open + 25
5 postgres 0x000000010ebf9462 SearchCatCacheMiss + 274
6 postgres 0x000000010ebf5979 SearchCatCacheInternal + 761
7 postgres 0x000000010ebf566c SearchCatCache + 60
8 postgres 0x000000010ec1a9e0 SearchSysCache + 144
9 postgres 0x000000010ec1ae03 SearchSysCacheExists + 51
10 postgres 0x000000010e58ce35 TypeIsVisible + 437
11 postgres 0x000000010ea98e4c format_type_extended + 1964
12 postgres 0x000000010ea9900e format_type_with_typemod + 30
13 postgres 0x000000010eb78d76 get_const_expr + 742
14 postgres 0x000000010eb79bc8 get_rule_expr + 232
15 postgres 0x000000010eb8140f get_func_expr + 1247
16 postgres 0x000000010eb79dcd get_rule_expr + 749
17 postgres 0x000000010eb81688 get_rule_expr_paren + 136
18 postgres 0x000000010eb7bf38 get_rule_expr + 9304
19 postgres 0x000000010eb72ad5 deparse_expression_pretty + 149
20 postgres 0x000000010eb73463 deparse_expression + 83
21 postgres 0x000000010e68eaf1 show_plan_tlist + 353
22 postgres 0x000000010e68adaf ExplainNode + 4991
23 postgres 0x000000010e688b4b ExplainPrintPlan + 283
24 postgres 0x000000010e68e1aa ProcessLogCurrentPlanInterrupt + 266
25 postgres 0x000000010ea133bb ProcessInterrupts + 3435
26 postgres 0x000000010e738c97 vacuum_delay_point + 55
27 postgres 0x000000010e42bb4b ginInsertCleanup + 1531
28 postgres 0x000000010e42d418 gin_clean_pending_list + 776
29 postgres 0x000000010e74955a ExecInterpExpr + 2522
30 postgres 0x000000010e7487e2 ExecInterpExprStillValid + 82
31 postgres 0x000000010e7ae83b ExecEvalExprSwitchContext + 59
32 postgres 0x000000010e7ae7be ExecProject + 78
33 postgres 0x000000010e7ae4e9 ExecResult + 345
34 postgres 0x000000010e764e42 ExecProcNodeFirst + 82
35 postgres 0x000000010e75ccb2 ExecProcNode + 50
36 postgres 0x000000010e758301 ExecutePlan + 193
37 postgres 0x000000010e7581d1 standard_ExecutorRun + 609
38 auto_explain.so 0x000000010f1df3a7 explain_ExecutorRun + 247
39 postgres 0x000000010e757f3b ExecutorRun + 91
40 postgres 0x000000010ea1cb49 PortalRunSelect + 313
41 postgres 0x000000010ea1c4dd PortalRun + 861
42 postgres 0x000000010ea17474 exec_simple_query + 1540
43 postgres 0x000000010ea164d4 PostgresMain + 2580
44 postgres 0x000000010e91d159 BackendRun + 89
45 postgres 0x000000010e91c6a5 BackendStartup + 565
46 postgres 0x000000010e91b3fe ServerLoop + 638
47 postgres 0x000000010e918b9d PostmasterMain + 6717
48 postgres 0x000000010e7efd43 main + 819
49 libdyld.dylib 0x00007fff6a46e3d5 start + 1
50 ??? 0x0000000000000003 0x0 + 3

LOG: server process (PID 61512) was terminated by signal 6: Abort trap: 6
DETAIL: Failed process was running: select gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;

Regards,

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

On 2021-08-20 01:12, Fujii Masao wrote:
> On 2021/08/11 21:14, torikoshia wrote:
>> As far as I looked into, pg_log_current_plan() can call InstrEndLoop()
>> through ExplainNode().
>> I added a flag to ExplainState to avoid calling InstrEndLoop() when
>> ExplainNode() is called from pg_log_current_plan().
>
> Thanks for updating the patch!
> I tried to test the patch again and encountered two issues.

Thanks for finding these issues!

>
> (1)
> The following WITH RECURSIVE query failed with the error
> "ERROR: failed to find plan for CTE sg" when I ran
> pg_log_current_query_plan() against the backend executing that query.
> Is this a bug?
>
> create table graph0( f int, t int, label text );
> insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 ->
> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');
>
> with recursive search_graph(f, t, label, i) as (
> select *, 1||pg_sleep(1)::text from graph0 g
> union distinct
> select g.*,1||pg_sleep(1)::text
> from graph0 g, search_graph sg
> where g.f = sg.t
> ) search breadth first by f, t set seq
> select * from search_graph order by seq;

This ERROR occurred without applying the patch and just calling
EXPLAIN(VERBOSE) to CTE with SEARCH BREADTH FIRST.

I'm going to make another thread to discuss it.

> (2)
> When I ran pg_log_current_query_plan() while "make installcheck" test
> was running, I got the following assertion failure.
>
> TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type ==
> LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)
>
> 0 postgres 0x000000010ec23557
> ExceptionalCondition + 231
> 1 postgres 0x000000010e9eff15
> LockAcquireExtended + 1461
> 2 postgres 0x000000010e9ed14d
> LockRelationOid + 61
> 3 postgres 0x000000010e41251b
> relation_open + 91
> 4 postgres 0x000000010e509679 table_open +
> 25
> 5 postgres 0x000000010ebf9462
> SearchCatCacheMiss + 274
> 6 postgres 0x000000010ebf5979
> SearchCatCacheInternal + 761
> 7 postgres 0x000000010ebf566c
> SearchCatCache + 60
> 8 postgres 0x000000010ec1a9e0
> SearchSysCache + 144
> 9 postgres 0x000000010ec1ae03
> SearchSysCacheExists + 51
> 10 postgres 0x000000010e58ce35
> TypeIsVisible + 437
> 11 postgres 0x000000010ea98e4c
> format_type_extended + 1964
> 12 postgres 0x000000010ea9900e
> format_type_with_typemod + 30
> 13 postgres 0x000000010eb78d76
> get_const_expr + 742
> 14 postgres 0x000000010eb79bc8
> get_rule_expr + 232
> 15 postgres 0x000000010eb8140f
> get_func_expr + 1247
> 16 postgres 0x000000010eb79dcd
> get_rule_expr + 749
> 17 postgres 0x000000010eb81688
> get_rule_expr_paren + 136
> 18 postgres 0x000000010eb7bf38
> get_rule_expr + 9304
> 19 postgres 0x000000010eb72ad5
> deparse_expression_pretty + 149
> 20 postgres 0x000000010eb73463
> deparse_expression + 83
> 21 postgres 0x000000010e68eaf1
> show_plan_tlist + 353
> 22 postgres 0x000000010e68adaf ExplainNode
> + 4991
> 23 postgres 0x000000010e688b4b
> ExplainPrintPlan + 283
> 24 postgres 0x000000010e68e1aa
> ProcessLogCurrentPlanInterrupt + 266
> 25 postgres 0x000000010ea133bb
> ProcessInterrupts + 3435
> 26 postgres 0x000000010e738c97
> vacuum_delay_point + 55
> 27 postgres 0x000000010e42bb4b
> ginInsertCleanup + 1531
> 28 postgres 0x000000010e42d418
> gin_clean_pending_list + 776
> 29 postgres 0x000000010e74955a
> ExecInterpExpr + 2522
> 30 postgres 0x000000010e7487e2
> ExecInterpExprStillValid + 82
> 31 postgres 0x000000010e7ae83b
> ExecEvalExprSwitchContext + 59
> 32 postgres 0x000000010e7ae7be ExecProject
> + 78
> 33 postgres 0x000000010e7ae4e9 ExecResult +
> 345
> 34 postgres 0x000000010e764e42
> ExecProcNodeFirst + 82
> 35 postgres 0x000000010e75ccb2 ExecProcNode
> + 50
> 36 postgres 0x000000010e758301 ExecutePlan
> + 193
> 37 postgres 0x000000010e7581d1
> standard_ExecutorRun + 609
> 38 auto_explain.so 0x000000010f1df3a7
> explain_ExecutorRun + 247
> 39 postgres 0x000000010e757f3b ExecutorRun
> + 91
> 40 postgres 0x000000010ea1cb49
> PortalRunSelect + 313
> 41 postgres 0x000000010ea1c4dd PortalRun +
> 861
> 42 postgres 0x000000010ea17474
> exec_simple_query + 1540
> 43 postgres 0x000000010ea164d4 PostgresMain
> + 2580
> 44 postgres 0x000000010e91d159 BackendRun +
> 89
> 45 postgres 0x000000010e91c6a5
> BackendStartup + 565
> 46 postgres 0x000000010e91b3fe ServerLoop +
> 638
> 47 postgres 0x000000010e918b9d
> PostmasterMain + 6717
> 48 postgres 0x000000010e7efd43 main + 819
> 49 libdyld.dylib 0x00007fff6a46e3d5 start + 1
> 50 ??? 0x0000000000000003 0x0 + 3
>
> LOG: server process (PID 61512) was terminated by signal 6: Abort
> trap: 6
> DETAIL: Failed process was running: select
> gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;

As far as I understand, since explaining plans can acquire heavyweight
lock for example to get column names, when page lock is held at the time
of the interrupt, this assertion error occurs.

The attached patch tries to avoid this by checking each LocalLock entry
and when finding even one, giving up logging the plan.

Thoughts?

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-09-07 12:39, torikoshia wrote:
> On 2021-08-20 01:12, Fujii Masao wrote:
>> On 2021/08/11 21:14, torikoshia wrote:
>>> As far as I looked into, pg_log_current_plan() can call
>>> InstrEndLoop() through ExplainNode().
>>> I added a flag to ExplainState to avoid calling InstrEndLoop() when
>>> ExplainNode() is called from pg_log_current_plan().
>>
>> Thanks for updating the patch!
>> I tried to test the patch again and encountered two issues.
>
> Thanks for finding these issues!
>
>>
>> (1)
>> The following WITH RECURSIVE query failed with the error
>> "ERROR: failed to find plan for CTE sg" when I ran
>> pg_log_current_query_plan() against the backend executing that query.
>> Is this a bug?
>>
>> create table graph0( f int, t int, label text );
>> insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 ->
>> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');
>>
>> with recursive search_graph(f, t, label, i) as (
>> select *, 1||pg_sleep(1)::text from graph0 g
>> union distinct
>> select g.*,1||pg_sleep(1)::text
>> from graph0 g, search_graph sg
>> where g.f = sg.t
>> ) search breadth first by f, t set seq
>> select * from search_graph order by seq;
>
> This ERROR occurred without applying the patch and just calling
> EXPLAIN(VERBOSE) to CTE with SEARCH BREADTH FIRST.
>
> I'm going to make another thread to discuss it.
>
>> (2)
>> When I ran pg_log_current_query_plan() while "make installcheck" test
>> was running, I got the following assertion failure.
>>
>> TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type ==
>> LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)
>>
>> 0 postgres 0x000000010ec23557
>> ExceptionalCondition + 231
>> 1 postgres 0x000000010e9eff15
>> LockAcquireExtended + 1461
>> 2 postgres 0x000000010e9ed14d
>> LockRelationOid + 61
>> 3 postgres 0x000000010e41251b
>> relation_open + 91
>> 4 postgres 0x000000010e509679 table_open
>> + 25
>> 5 postgres 0x000000010ebf9462
>> SearchCatCacheMiss + 274
>> 6 postgres 0x000000010ebf5979
>> SearchCatCacheInternal + 761
>> 7 postgres 0x000000010ebf566c
>> SearchCatCache + 60
>> 8 postgres 0x000000010ec1a9e0
>> SearchSysCache + 144
>> 9 postgres 0x000000010ec1ae03
>> SearchSysCacheExists + 51
>> 10 postgres 0x000000010e58ce35
>> TypeIsVisible + 437
>> 11 postgres 0x000000010ea98e4c
>> format_type_extended + 1964
>> 12 postgres 0x000000010ea9900e
>> format_type_with_typemod + 30
>> 13 postgres 0x000000010eb78d76
>> get_const_expr + 742
>> 14 postgres 0x000000010eb79bc8
>> get_rule_expr + 232
>> 15 postgres 0x000000010eb8140f
>> get_func_expr + 1247
>> 16 postgres 0x000000010eb79dcd
>> get_rule_expr + 749
>> 17 postgres 0x000000010eb81688
>> get_rule_expr_paren + 136
>> 18 postgres 0x000000010eb7bf38
>> get_rule_expr + 9304
>> 19 postgres 0x000000010eb72ad5
>> deparse_expression_pretty + 149
>> 20 postgres 0x000000010eb73463
>> deparse_expression + 83
>> 21 postgres 0x000000010e68eaf1
>> show_plan_tlist + 353
>> 22 postgres 0x000000010e68adaf ExplainNode
>> + 4991
>> 23 postgres 0x000000010e688b4b
>> ExplainPrintPlan + 283
>> 24 postgres 0x000000010e68e1aa
>> ProcessLogCurrentPlanInterrupt + 266
>> 25 postgres 0x000000010ea133bb
>> ProcessInterrupts + 3435
>> 26 postgres 0x000000010e738c97
>> vacuum_delay_point + 55
>> 27 postgres 0x000000010e42bb4b
>> ginInsertCleanup + 1531
>> 28 postgres 0x000000010e42d418
>> gin_clean_pending_list + 776
>> 29 postgres 0x000000010e74955a
>> ExecInterpExpr + 2522
>> 30 postgres 0x000000010e7487e2
>> ExecInterpExprStillValid + 82
>> 31 postgres 0x000000010e7ae83b
>> ExecEvalExprSwitchContext + 59
>> 32 postgres 0x000000010e7ae7be ExecProject
>> + 78
>> 33 postgres 0x000000010e7ae4e9 ExecResult
>> + 345
>> 34 postgres 0x000000010e764e42
>> ExecProcNodeFirst + 82
>> 35 postgres 0x000000010e75ccb2
>> ExecProcNode + 50
>> 36 postgres 0x000000010e758301 ExecutePlan
>> + 193
>> 37 postgres 0x000000010e7581d1
>> standard_ExecutorRun + 609
>> 38 auto_explain.so 0x000000010f1df3a7
>> explain_ExecutorRun + 247
>> 39 postgres 0x000000010e757f3b ExecutorRun
>> + 91
>> 40 postgres 0x000000010ea1cb49
>> PortalRunSelect + 313
>> 41 postgres 0x000000010ea1c4dd PortalRun +
>> 861
>> 42 postgres 0x000000010ea17474
>> exec_simple_query + 1540
>> 43 postgres 0x000000010ea164d4
>> PostgresMain + 2580
>> 44 postgres 0x000000010e91d159 BackendRun
>> + 89
>> 45 postgres 0x000000010e91c6a5
>> BackendStartup + 565
>> 46 postgres 0x000000010e91b3fe ServerLoop
>> + 638
>> 47 postgres 0x000000010e918b9d
>> PostmasterMain + 6717
>> 48 postgres 0x000000010e7efd43 main + 819
>> 49 libdyld.dylib 0x00007fff6a46e3d5 start + 1
>> 50 ??? 0x0000000000000003 0x0 + 3
>>
>> LOG: server process (PID 61512) was terminated by signal 6: Abort
>> trap: 6
>> DETAIL: Failed process was running: select
>> gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;
>
> As far as I understand, since explaining plans can acquire heavyweight
> lock for example to get column names, when page lock is held at the
> time of the interrupt, this assertion error occurs.
>
> The attached patch tries to avoid this by checking each LocalLock
> entry and when finding even one, giving up logging the plan.
>
> Thoughts?

Regression tests failed on windows.
Updated patch attached.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

Hi, hackers!

• The last version of patch is correct applied. It changes 8 files from
/src/backend, and 9 other files.

• I have 1 error and 1 warning during compilation on Mac.

explain.c:4985:25: error: implicit declaration of function
'GetLockMethodLocalHash' is invalid in C99
[-Werror,-Wimplicit-function-declaration]
hash_seq_init(&status, GetLockMethodLocalHash());
explain.c:4985:25: warning: incompatible integer to pointer conversion
passing 'int' to parameter of type 'HTAB *' (aka 'struct HTAB *')
[-Wint-conversion]
hash_seq_init(&status, GetLockMethodLocalHash());

This error doesn't appear at my second machine with Ubuntu.

I found the reason. You delete #ifdef USE_ASSERT_CHECKING from
implementation of function GetLockMethodLocalHash(void), but this ifdef
exists around function declaration. There may be a situation, when
implementation exists without declaration, so files with using of
function produce errors. I create new version of patch with fix of this
problem.

I'm agree that seeing the details of a query is a useful feature, but I
have several doubts:

1) There are lots of changes of core's code. But not all users need this
functionality. So adding this functionality like extension seemed more
reasonable.

2) There are many tools available to monitor the status of a query. How
much do we need another one? For example:
• pg_stat_progress_* is set of views with current status of ANALYZE,
CREATE INDEX, VACUUM, CLUSTER, COPY, Base Backup. You can find it in
PostgreSQL documentation [1].
• pg_query_state is contrib with 2 patches for core (I hope someday
Community will support adding this patches to PostgreSQL). It contains
function with printing table with pid, full query text, plan and current
progress of every node like momentary EXPLAIN ANALYSE for SELECT,
UPDATE, INSERT, DELETE. So it supports every flags and formats of
EXPLAIN. You can find current version of pg_query_state on github [2].
Also I found old discussion about first version of it in Community [3].

3) Have you measured the overload of your feature? It would be really
interesting to know the changes in speed and performance.

Thank you for working on this issue. I would be glad to continue to
follow the development of this issue.

Links above:
[1] https://www.postgresql.org/docs/current/progress-reporting.html
[2] https://github.com/postgrespro/pg_query_state
[3]
https://www.postgresql.org/message-id/dbfb1a42-ee58-88fd-8d77-550498f52bc5@postgrespro.ru

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

On 2021-10-13 23:28, Ekaterina Sokolova wrote:
> Hi, hackers!
>
> • The last version of patch is correct applied. It changes 8 files
> from /src/backend, and 9 other files.
>
> • I have 1 error and 1 warning during compilation on Mac.
>
> explain.c:4985:25: error: implicit declaration of function
> 'GetLockMethodLocalHash' is invalid in C99
> [-Werror,-Wimplicit-function-declaration]
> hash_seq_init(&status, GetLockMethodLocalHash());
> explain.c:4985:25: warning: incompatible integer to pointer conversion
> passing 'int' to parameter of type 'HTAB *' (aka 'struct HTAB *')
> [-Wint-conversion]
> hash_seq_init(&status, GetLockMethodLocalHash());
>
> This error doesn't appear at my second machine with Ubuntu.
>
> I found the reason. You delete #ifdef USE_ASSERT_CHECKING from
> implementation of function GetLockMethodLocalHash(void), but this
> ifdef exists around function declaration. There may be a situation,
> when implementation exists without declaration, so files with using of
> function produce errors. I create new version of patch with fix of
> this problem.

Thanks for fixing that!

> I'm agree that seeing the details of a query is a useful feature, but
> I have several doubts:
>
> 1) There are lots of changes of core's code. But not all users need
> this functionality. So adding this functionality like extension seemed
> more reasonable.

It would be good if we can implement this feature in an extension, but
as pg_query_state extension needs applying patches to PostgreSQL, I
think this kind of feature needs PostgreSQL core modification.
IMHO extensions which need core modification are not easy to use in
production environments..

> 2) There are many tools available to monitor the status of a query.
> How much do we need another one? For example:
> • pg_stat_progress_* is set of views with current status of
> ANALYZE, CREATE INDEX, VACUUM, CLUSTER, COPY, Base Backup. You can
> find it in PostgreSQL documentation [1].
> • pg_query_state is contrib with 2 patches for core (I hope
> someday Community will support adding this patches to PostgreSQL). It
> contains function with printing table with pid, full query text, plan
> and current progress of every node like momentary EXPLAIN ANALYSE for
> SELECT, UPDATE, INSERT, DELETE. So it supports every flags and formats
> of EXPLAIN. You can find current version of pg_query_state on github
> [2]. Also I found old discussion about first version of it in
> Community [3].

Thanks for introducing the extension!

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?

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.

Some of the comments of [3] seem useful for my patch, I'm going to
consider them. Thanks!

> 3) Have you measured the overload of your feature? It would be really
> interesting to know the changes in speed and performance.

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.

> Thank you for working on this issue. I would be glad to continue to
> follow the development of this issue.

Thanks for your help!

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-10-15 15:17, torikoshia wrote:
> 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?

Sorry, I forgot to add the URL.
[1]
https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

> 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.
https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Wed, Oct 13, 2021 at 05:28:30PM +0300, Ekaterina Sokolova wrote:
> Hi, hackers!
>
> • pg_query_state is contrib with 2 patches for core (I hope someday
> Community will support adding this patches to PostgreSQL). It contains

I reviewed this version of the patch - I have some language fixes.

I didn't know about pg_query_state, thanks.

> To improve this situation, this patch adds
> pg_log_current_query_plan() function that requests to log the
> plan of the specified backend process.

To me, "current plan" seems to mean "plan of *this* backend" (which makes no
sense to log). I think the user-facing function could be called
pg_log_query_plan(). It's true that the implementation is a request to another
backend to log its *own* query plan - but users shouldn't need to know about
the implementation.

> + Only superusers can request to log plan of the running query.

.. log the plan of a running query.

> + Note that nested statements (statements executed inside a function) are not
> + considered for logging. Only the deepest nesting query's plan is logged.

Only the plan of the most deeply nested query is logged.

> + (errmsg("backend with PID %d is not running a query",
> + MyProcPid)));

The extra parens around errmsg() are not needed since e3a87b499.

> + (errmsg("backend with PID %d is now holding a page lock. Try again",

remove "now"

> + (errmsg("plan of the query running on backend with PID %d is:\n%s",
> + MyProcPid, es->str->data),

Maybe this should say "query plan running on backend with PID 17793 is:"

> + * would cause lots of log messages and which can lead to denial of

remove "and"

> + errmsg("must be a superuser to log information about specified process")));

I think it should say not say "specified", since that sounds like the user
might have access to log information about some other processes:
| must be a superuser to log information about processes

> +
> + proc = BackendPidGetProc(pid);
> +
> + /*
> + * BackendPidGetProc returns NULL if the pid isn't valid; but by the time
> + * we reach kill(), a process for which we get a valid proc here might
> + * have terminated on its own. There's no way to acquire a lock on an
> + * arbitrary process to prevent that. But since this mechanism is usually
> + * used to below purposes, it might end its own first and the information

used for below purposes,

--
Justin

On Wed, Oct 13, 2021 at 7:58 PM Ekaterina Sokolova
<e(dot)sokolova(at)postgrespro(dot)ru> wrote:
> Thank you for working on this issue. I would be glad to continue to
> follow the development of this issue.

Thanks for the patch. I'm not sure if v11 is the latest patch, if yes,
I have the following comments:

1) Firstly, v11 patch isn't getting applied on the master -
http://cfbot.cputube.org/patch_35_3142.log.

2) I think we are moving away from if (!superuser()) checks, see the
commit [1]. The goal is to let the GRANT-REVOKE system deal with who
is supposed to run these system functions. Since
pg_log_current_query_plan also writes the info to server logs, I think
it should do the same thing as commit [1] did for
pg_log_backend_memory_contexts.

With v11, you are re-introducing the superuser() check in the
pg_log_backend_memory_contexts which is wrong.

3) I think SendProcSignalForLogInfo can be more generic, meaning, it
can also send signal to auxiliary processes if asked to do this will
simplify the things for pg_log_backend_memory_contexts and other
patches like pg_print_backtrace. I would imagine it to be "bool
SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason, bool
signal_aux_proc);".

[1] commit f0b051e322d530a340e62f2ae16d99acdbcb3d05
Author: Jeff Davis <jdavis(at)postgresql(dot)org>
Date: Tue Oct 26 13:13:52 2021 -0700

Allow GRANT on pg_log_backend_memory_contexts().

Remove superuser check, allowing any user granted permissions on
pg_log_backend_memory_contexts() to log the memory contexts of any
backend.

Note that this could allow a privileged non-superuser to log the
memory contexts of a superuser backend, but as discussed, that does
not seem to be a problem.

Reviewed-by: Nathan Bossart, Bharath Rupireddy, Michael Paquier,
Kyotaro Horiguchi, Andres Freund
Discussion:
https://postgr.es/m/e5cf6684d17c8d1ef4904ae248605ccd6da03e72.camel@j-davis.com

Regards,
Bharath Rupireddy.

On 2021-11-13 22:29, Bharath Rupireddy wrote:
Thanks for your review!

> On Wed, Oct 13, 2021 at 7:58 PM Ekaterina Sokolova
> <e(dot)sokolova(at)postgrespro(dot)ru> wrote:
>> Thank you for working on this issue. I would be glad to continue to
>> follow the development of this issue.
>
> Thanks for the patch. I'm not sure if v11 is the latest patch, if yes,
> I have the following comments:
>
> 1) Firstly, v11 patch isn't getting applied on the master -
> http://cfbot.cputube.org/patch_35_3142.log.
Updated the patch.

> 2) I think we are moving away from if (!superuser()) checks, see the
> commit [1]. The goal is to let the GRANT-REVOKE system deal with who
> is supposed to run these system functions. Since
> pg_log_current_query_plan also writes the info to server logs, I think
> it should do the same thing as commit [1] did for
> pg_log_backend_memory_contexts.
>
> With v11, you are re-introducing the superuser() check in the
> pg_log_backend_memory_contexts which is wrong.

Yeah, I removed superuser() check and make it possible to be executed by
non-superusers when users are granted to do so.
>
> 3) I think SendProcSignalForLogInfo can be more generic, meaning, it
> can also send signal to auxiliary processes if asked to do this will
> simplify the things for pg_log_backend_memory_contexts and other
> patches like pg_print_backtrace. I would imagine it to be "bool
> SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason, bool
> signal_aux_proc);".

I agree with your idea.
Since sending signals to auxiliary processes to dump memory contexts and
pg_print_backtrace is still under discussion, IMHO it would be better to
refactor SendProcSignalForLogInfo after these patches are commited.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On 2021-11-13 03:37, Justin Pryzby wrote:

> I reviewed this version of the patch - I have some language fixes.

Thanks for your review!
Attached patch that reflects your comments.

Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION

On Mon, Nov 15, 2021 at 6:29 PM torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> wrote:
> > 3) I think SendProcSignalForLogInfo can be more generic, meaning, it
> > can also send signal to auxiliary processes if asked to do this will
> > simplify the things for pg_log_backend_memory_contexts and other
> > patches like pg_print_backtrace. I would imagine it to be "bool
> > SendProcSignalForLogInfo(pid_t pid, ProcSignalReason reason, bool
> > signal_aux_proc);".
>
> I agree with your idea.
> Since sending signals to auxiliary processes to dump memory contexts and
> pg_print_backtrace is still under discussion, IMHO it would be better to
> refactor SendProcSignalForLogInfo after these patches are commited.

+1.

I have another comment: isn't it a good idea that an overloaded
version of the new function pg_log_query_plan can take the available
explain command options as a text argument? I'm not sure if it is
possible to get the stats like buffers, costs etc of a running query,
if yes, something like pg_log_query_plan(pid, 'buffers',
'costs'....);? It looks to be an overkill at first sight, but these
can be useful to know more detailed plan of the query.

Thoughts?

Regards,
Bharath Rupireddy.

On 2021-11-15 23:15, Bharath Rupireddy wrote:

> I have another comment: isn't it a good idea that an overloaded
> version of the new function pg_log_query_plan can take the available
> explain command options as a text argument? I'm not sure if it is
> possible to get the stats like buffers, costs etc of a running query,
> if yes, something like pg_log_query_plan(pid, 'buffers',
> 'costs'....);? It looks to be an overkill at first sight, but these
> can be useful to know more detailed plan of the query.

I also think the overloaded version would be useful.
However as discussed in [1], it seems to introduce other difficulties.
I think it would be enough that the first version of pg_log_query_plan
doesn't take any parameters.

[1]
https://www.postgresql.org/message-id/ce86e4f72f09d5497e8ad3a162861d33%40oss.nttdata.com

--
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION