public inbox for [email protected]
help / color / mirror / Atom feed[PATCH 2/4] psql: add convenience commands: \dA+ and \dn+
25+ messages / 8 participants
[nested] [flat]
* [PATCH 2/4] psql: add convenience commands: \dA+ and \dn+
@ 2021-12-18 20:58 Justin Pryzby <[email protected]>
0 siblings, 0 replies; 25+ messages in thread
From: Justin Pryzby @ 2021-12-18 20:58 UTC (permalink / raw)
show the size only with \dA++ and \dn++ (for which the single-plus
commands have historically not done any slow operations).
Also change to show the size only with \db++ and \l++ (for which it's
useful to show the ACL without also doing any slow operations).
\dt+ and \dP+ are not changed, since showing the table sizes seems to be their
primary purpose.
The idea for plusplus commands were previously discussed here.
https://www.postgresql.org/message-id/20190506163359.GA29291%40alvherre.pgsql
---
src/bin/psql/command.c | 20 +++++++++++-------
src/bin/psql/describe.c | 46 +++++++++++++++++++++++++++++------------
src/bin/psql/describe.h | 8 +++----
3 files changed, 50 insertions(+), 24 deletions(-)
diff --git a/src/bin/psql/command.c b/src/bin/psql/command.c
index 955397ee9dc..875b659a26d 100644
--- a/src/bin/psql/command.c
+++ b/src/bin/psql/command.c
@@ -369,6 +369,7 @@ exec_command(const char *cmd,
else if (strcmp(cmd, "if") == 0)
status = exec_command_if(scan_state, cstack, query_buf);
else if (strcmp(cmd, "l") == 0 || strcmp(cmd, "list") == 0 ||
+ strcmp(cmd, "l++") == 0 || strcmp(cmd, "list++") == 0 ||
strcmp(cmd, "l+") == 0 || strcmp(cmd, "list+") == 0)
status = exec_command_list(scan_state, active_branch, cmd);
else if (strncmp(cmd, "lo_", 3) == 0)
@@ -754,6 +755,7 @@ exec_command_d(PsqlScanState scan_state, bool active_branch, const char *cmd)
if (active_branch)
{
char *pattern;
+ int verbose = 0;
bool show_verbose,
show_system;
@@ -761,7 +763,10 @@ exec_command_d(PsqlScanState scan_state, bool active_branch, const char *cmd)
pattern = psql_scan_slash_option(scan_state,
OT_NORMAL, NULL, true);
- show_verbose = strchr(cmd, '+') ? true : false;
+ for (const char *t = cmd; *t != '\0'; ++t)
+ verbose += *t == '+' ? 1 : 0;
+
+ show_verbose = (bool) (verbose != 0);
show_system = strchr(cmd, 'S') ? true : false;
switch (cmd[1])
@@ -786,7 +791,7 @@ exec_command_d(PsqlScanState scan_state, bool active_branch, const char *cmd)
{
case '\0':
case '+':
- success = describeAccessMethods(pattern, show_verbose);
+ success = describeAccessMethods(pattern, verbose);
break;
case 'c':
success = listOperatorClasses(pattern, pattern2, show_verbose);
@@ -812,7 +817,7 @@ exec_command_d(PsqlScanState scan_state, bool active_branch, const char *cmd)
success = describeAggregates(pattern, show_verbose, show_system);
break;
case 'b':
- success = describeTablespaces(pattern, show_verbose);
+ success = describeTablespaces(pattern, verbose);
break;
case 'c':
if (strncmp(cmd, "dconfig", 7) == 0)
@@ -866,7 +871,7 @@ exec_command_d(PsqlScanState scan_state, bool active_branch, const char *cmd)
success = listLanguages(pattern, show_verbose, show_system);
break;
case 'n':
- success = listSchemas(pattern, show_verbose, show_system);
+ success = listSchemas(pattern, verbose, show_system);
break;
case 'o':
success = exec_command_dfo(scan_state, cmd, pattern,
@@ -1943,14 +1948,15 @@ exec_command_list(PsqlScanState scan_state, bool active_branch, const char *cmd)
if (active_branch)
{
char *pattern;
- bool show_verbose;
+ int verbose = 0;
pattern = psql_scan_slash_option(scan_state,
OT_NORMAL, NULL, true);
- show_verbose = strchr(cmd, '+') ? true : false;
+ for (const char *t = cmd; *t != '\0'; ++t)
+ verbose += *t == '+' ? 1 : 0;
- success = listAllDbs(pattern, show_verbose);
+ success = listAllDbs(pattern, verbose);
free(pattern);
}
diff --git a/src/bin/psql/describe.c b/src/bin/psql/describe.c
index 99e28f607e8..7de604a894d 100644
--- a/src/bin/psql/describe.c
+++ b/src/bin/psql/describe.c
@@ -139,12 +139,12 @@ describeAggregates(const char *pattern, bool verbose, bool showSystem)
* Takes an optional regexp to select particular access methods
*/
bool
-describeAccessMethods(const char *pattern, bool verbose)
+describeAccessMethods(const char *pattern, int verbose)
{
PQExpBufferData buf;
PGresult *res;
printQueryOpt myopt = pset.popt;
- static const bool translate_columns[] = {false, true, false, false};
+ static const bool translate_columns[] = {false, true, false, false, false};
if (pset.sversion < 90600)
{
@@ -176,6 +176,11 @@ describeAccessMethods(const char *pattern, bool verbose)
" pg_catalog.obj_description(oid, 'pg_am') AS \"%s\"",
gettext_noop("Handler"),
gettext_noop("Description"));
+
+ if (verbose > 1 && pset.sversion >= 160000)
+ appendPQExpBuffer(&buf,
+ ",\n pg_catalog.pg_size_pretty(pg_catalog.pg_am_size(oid)) AS \"%s\"",
+ gettext_noop("Size"));
}
appendPQExpBufferStr(&buf,
@@ -214,7 +219,7 @@ describeAccessMethods(const char *pattern, bool verbose)
* Takes an optional regexp to select particular tablespaces
*/
bool
-describeTablespaces(const char *pattern, bool verbose)
+describeTablespaces(const char *pattern, int verbose)
{
PQExpBufferData buf;
PGresult *res;
@@ -234,12 +239,18 @@ describeTablespaces(const char *pattern, bool verbose)
{
appendPQExpBufferStr(&buf, ",\n ");
printACLColumn(&buf, "spcacl");
+
+ appendPQExpBuffer(&buf,
+ ",\n spcoptions AS \"%s\"",
+ gettext_noop("Options"));
+
+ if (verbose > 1)
+ appendPQExpBuffer(&buf,
+ ",\n pg_catalog.pg_size_pretty(pg_catalog.pg_tablespace_size(oid)) AS \"%s\"",
+ gettext_noop("Size"));
+
appendPQExpBuffer(&buf,
- ",\n spcoptions AS \"%s\""
- ",\n pg_catalog.pg_size_pretty(pg_catalog.pg_tablespace_size(oid)) AS \"%s\""
",\n pg_catalog.shobj_description(oid, 'pg_tablespace') AS \"%s\"",
- gettext_noop("Options"),
- gettext_noop("Size"),
gettext_noop("Description"));
}
@@ -914,7 +925,7 @@ error_return:
* for \l, \list, and -l switch
*/
bool
-listAllDbs(const char *pattern, bool verbose)
+listAllDbs(const char *pattern, int verbose)
{
PGresult *res;
PQExpBufferData buf;
@@ -961,20 +972,24 @@ listAllDbs(const char *pattern, bool verbose)
gettext_noop("ICU Rules"));
appendPQExpBufferStr(&buf, " ");
printACLColumn(&buf, "d.datacl");
- if (verbose)
+ if (verbose > 1)
appendPQExpBuffer(&buf,
",\n CASE WHEN pg_catalog.has_database_privilege(d.datname, 'CONNECT')\n"
" THEN pg_catalog.pg_size_pretty(pg_catalog.pg_database_size(d.datname))\n"
" ELSE 'No Access'\n"
- " END as \"%s\""
+ " END as \"%s\"",
+ gettext_noop("Size"));
+
+ if (verbose > 0)
+ appendPQExpBuffer(&buf,
",\n t.spcname as \"%s\""
",\n pg_catalog.shobj_description(d.oid, 'pg_database') as \"%s\"",
- gettext_noop("Size"),
gettext_noop("Tablespace"),
gettext_noop("Description"));
+
appendPQExpBufferStr(&buf,
"\nFROM pg_catalog.pg_database d\n");
- if (verbose)
+ if (verbose > 0)
appendPQExpBufferStr(&buf,
" JOIN pg_catalog.pg_tablespace t on d.dattablespace = t.oid\n");
@@ -4973,7 +4988,7 @@ listCollations(const char *pattern, bool verbose, bool showSystem)
* Describes schemas (namespaces)
*/
bool
-listSchemas(const char *pattern, bool verbose, bool showSystem)
+listSchemas(const char *pattern, int verbose, bool showSystem)
{
PQExpBufferData buf;
PGresult *res;
@@ -4995,6 +5010,11 @@ listSchemas(const char *pattern, bool verbose, bool showSystem)
appendPQExpBuffer(&buf,
",\n pg_catalog.obj_description(n.oid, 'pg_namespace') AS \"%s\"",
gettext_noop("Description"));
+
+ if (verbose > 1 && pset.sversion >= 160000)
+ appendPQExpBuffer(&buf,
+ ",\n pg_catalog.pg_size_pretty(pg_namespace_size(n.oid)) AS \"%s\"",
+ gettext_noop("Size"));
}
appendPQExpBufferStr(&buf,
diff --git a/src/bin/psql/describe.h b/src/bin/psql/describe.h
index 554fe867255..d2fd8a72a36 100644
--- a/src/bin/psql/describe.h
+++ b/src/bin/psql/describe.h
@@ -13,10 +13,10 @@
extern bool describeAggregates(const char *pattern, bool verbose, bool showSystem);
/* \dA */
-extern bool describeAccessMethods(const char *pattern, bool verbose);
+extern bool describeAccessMethods(const char *pattern, int verbose);
/* \db */
-extern bool describeTablespaces(const char *pattern, bool verbose);
+extern bool describeTablespaces(const char *pattern, int verbose);
/* \df, \dfa, \dfn, \dft, \dfw, etc. */
extern bool describeFunctions(const char *functypes, const char *func_pattern,
@@ -62,7 +62,7 @@ extern bool listTSDictionaries(const char *pattern, bool verbose);
extern bool listTSTemplates(const char *pattern, bool verbose);
/* \l */
-extern bool listAllDbs(const char *pattern, bool verbose);
+extern bool listAllDbs(const char *pattern, int verbose);
/* \dt, \di, \ds, \dS, etc. */
extern bool listTables(const char *tabtypes, const char *pattern, bool verbose, bool showSystem);
@@ -87,7 +87,7 @@ extern bool listCasts(const char *pattern, bool verbose);
extern bool listCollations(const char *pattern, bool verbose, bool showSystem);
/* \dn */
-extern bool listSchemas(const char *pattern, bool verbose, bool showSystem);
+extern bool listSchemas(const char *pattern, int verbose, bool showSystem);
/* \dew */
extern bool listForeignDataWrappers(const char *pattern, bool verbose);
--
2.34.1
--OZ1/qgOAlc2dTU8W
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
filename="0003-f-convert-the-other-verbose-to-int-too.patch"
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
@ 2023-09-05 13:58 torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-09-05 13:58 UTC (permalink / raw)
To: James Coleman <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-08-28 22:47, James Coleman wrote:
> On Mon, Aug 28, 2023 at 3:01 AM torikoshia <[email protected]>
> wrote:
>>
>> On 2023-08-26 21:03, James Coleman wrote:
>> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <[email protected]> wrote:
>> >>
>> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
>> >> <[email protected]> wrote:
>> >> >
>> >> > On 2023-06-16 01:34, James Coleman wrote:
>> >> > > Attached is v28
>> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
>> >> > > when necessary. Once built with those two patches I'm simply running
>> >> > > `make check`.
>> >> >
>> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
>> >> > huge
>> >> > amount of memory and under some environments they were terminated by OOM
>> >> > killer.
>> >> >
>> >> > This was because memory was allocated from existing memory contexts and
>> >> > they
>> >> > were not freed after ProcessLogQueryPlanInterrupt().
>> >> > Updated the patch to use dedicated memory context for
>> >> > ProcessLogQueryPlanInterrupt().
>> >> >
>> >> > Applying attached patch and v28-0002 patch, `make check` successfully
>> >> > completed after 20min and 50GB of logs on my environment.
>> >> >
>> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
>> >> > >>> > The tests have been running since last night, but have been apparently
>> >> > >>> > hung now for many hours.
>> >> >
>> >> > I don't know if this has anything to do with the hung you faced, but I
>> >> > thought
>> >> > it might be possible that the large amount of memory usage resulted in
>> >> > swapping, which caused a significant delay in processing.
>> >>
>> >> Ah, yes, I think that could be a possible explanation. I was delaying
>> >> on this thread because I wasn't comfortable with having caused an
>> >> issue once (even if I couldn't easily reproduce) without at least some
>> >> theory as to the cause (and a fix).
>> >>
>> >> > If possible, I would be very grateful if you could try to reproduce this
>> >> > with
>> >> > the v29 patch.
>> >>
>> >> I'll kick off some testing.
>> >>
>> >
>> > I don't have time to investigate what's happening here, but 24 hours
>> > later the first "make check" is still running, and at first glance it
>> > seems to have the same behavior I'd seen that first time. The test
>> > output is to this point:
>> >
>> > # parallel group (5 tests): index_including create_view
>> > index_including_gist create_index create_index_spgist
>> > ok 66 + create_index 26365 ms
>> > ok 67 + create_index_spgist 27675 ms
>> > ok 68 + create_view 1235 ms
>> > ok 69 + index_including 1102 ms
>> > ok 70 + index_including_gist 1633 ms
>> > # parallel group (16 tests): create_aggregate create_cast errors
>> > roleattributes drop_if_exists hash_func typed_table create_am
>> > infinite_recurse
>> >
>> > and it hasn't progressed past that point since at least ~16 hours ago
>> > (the first several hours of the run I wasn't monitoring it).
>> >
>> > I haven't connected up gdb yet, and won't be able to until maybe
>> > tomorrow, but here's the ps output for postgres processes that are
>> > running:
>> >
>> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
>> > /home/admin/postgresql-test/bin/postgres -D
>> > /home/admin/postgresql-test-data
>> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
>> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
>> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
>> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
>> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
>> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
>> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
>> > --schedule=./parallel_schedule
>> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
>> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
>> > listen_addresses= -k /tmp/pg_regress-7mmGUa
>> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
>> > postgres: checkpointer
>> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
>> > postgres: background writer
>> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
>> > postgres: walwriter
>> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
>> > postgres: autovacuum launcher
>> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
>> > postgres: logical replication launcher
>> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
>> > postgres: admin regression [local] VACUUM
>> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
>> > postgres: admin regression [local] SELECT waiting
>> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
>> > postgres: admin regression [local] DELETE waiting
>> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ALTER TABLE waiting
>> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
>> > postgres: admin regression [local] ANALYZE waiting
>> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
>> > postgres: autovacuum worker
>> >
>> > As you can see there are a bunch of backends presumably waiting, and
>> > also the VACUUM process has been pegging a single CPU core for at
>> > least since that ~16 hour ago mark.
>> >
>> > I hope to be able to do more investigation later, but I wanted to at
>> > least give you this information now.
>>
>> Thanks a lot for testing the patch!
>> I really appreciate your cooperation.
>>
>> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
>> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
>> below:
>>
>> ```
>> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
>> $ git apply
>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
>> $ ./configure --enable-debug --enable-cassert
>> $ make
>> $ make check
>>
>> ...(snip)...
>>
>> # parallel group (5 tests): index_including index_including_gist
>> create_view create_index create_index_spgist
>> ok 66 + create_index 25033 ms
>> ok 67 + create_index_spgist 26144 ms
>> ok 68 + create_view 3061 ms
>> ok 69 + index_including 976 ms
>> ok 70 + index_including_gist 2998 ms
>> # parallel group (16 tests): create_cast errors create_aggregate
>> roleattributes drop_if_exists hash_func typed_table
>> create_am select constraints updatable_views inherit triggers vacuum
>> create_function_sql infinite_recurse
>> ok 71 + create_aggregate 225 ms
>> ok 72 + create_function_sql 18874 ms
>> ok 73 + create_cast 168 ms
>>
>> ...(snip)...
>>
>> # All 215 tests passed.
>> ```
>>
>> If you notice any difference, I would be grateful if you could let me
>> know.
>
> I've never been able to reproduce it (haven't tested the new version,
> but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> (first buster and now bullseye).
>
> I'm attaching several stacktraces in the hope that they provide some
> clues. These all match the ps output I sent earlier, though note in
> that output there is both the regress instance and my test instance
> (pid 3213249) running (different ports, of course, and they are from
> the exact same compilation run). I've attached ps output for the
> postgres processes under the make check process to simplify cross
> referencing.
>
> A few interesting things:
> - There's definitely a lock on a relation that seems to be what's
> blocking the processes.
> - When I try to connect with psql the process forks but then hangs
> (see the ps output with task names stuck in "authentication"). I've
> also included a trace from one of these.
Thanks for sharing them!
Many processes are waiting to acquire the LW lock, including the process
trying to output the plan(select1.trace).
I suspect that this is due to a lock that was acquired prior to being
interrupted by ProcessLogQueryPlanInterrupt(), but have not been able to
reproduce the same situation..
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-09-06 02:17 ` James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: James Coleman @ 2023-09-06 02:17 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On Tue, Sep 5, 2023 at 9:59 AM torikoshia <[email protected]> wrote:
>
> On 2023-08-28 22:47, James Coleman wrote:
> > On Mon, Aug 28, 2023 at 3:01 AM torikoshia <[email protected]>
> > wrote:
> >>
> >> On 2023-08-26 21:03, James Coleman wrote:
> >> > On Fri, Aug 25, 2023 at 7:43 AM James Coleman <[email protected]> wrote:
> >> >>
> >> >> On Thu, Aug 17, 2023 at 10:02 AM torikoshia
> >> >> <[email protected]> wrote:
> >> >> >
> >> >> > On 2023-06-16 01:34, James Coleman wrote:
> >> >> > > Attached is v28
> >> >> > > which sets ProcessLogQueryPlanInterruptActive to false in errfinish
> >> >> > > when necessary. Once built with those two patches I'm simply running
> >> >> > > `make check`.
> >> >> >
> >> >> > With v28-0001 and v28-0002 patch, I confirmed backend processes consume
> >> >> > huge
> >> >> > amount of memory and under some environments they were terminated by OOM
> >> >> > killer.
> >> >> >
> >> >> > This was because memory was allocated from existing memory contexts and
> >> >> > they
> >> >> > were not freed after ProcessLogQueryPlanInterrupt().
> >> >> > Updated the patch to use dedicated memory context for
> >> >> > ProcessLogQueryPlanInterrupt().
> >> >> >
> >> >> > Applying attached patch and v28-0002 patch, `make check` successfully
> >> >> > completed after 20min and 50GB of logs on my environment.
> >> >> >
> >> >> > >>> On 2023-06-15 01:48, James Coleman wrote:
> >> >> > >>> > The tests have been running since last night, but have been apparently
> >> >> > >>> > hung now for many hours.
> >> >> >
> >> >> > I don't know if this has anything to do with the hung you faced, but I
> >> >> > thought
> >> >> > it might be possible that the large amount of memory usage resulted in
> >> >> > swapping, which caused a significant delay in processing.
> >> >>
> >> >> Ah, yes, I think that could be a possible explanation. I was delaying
> >> >> on this thread because I wasn't comfortable with having caused an
> >> >> issue once (even if I couldn't easily reproduce) without at least some
> >> >> theory as to the cause (and a fix).
> >> >>
> >> >> > If possible, I would be very grateful if you could try to reproduce this
> >> >> > with
> >> >> > the v29 patch.
> >> >>
> >> >> I'll kick off some testing.
> >> >>
> >> >
> >> > I don't have time to investigate what's happening here, but 24 hours
> >> > later the first "make check" is still running, and at first glance it
> >> > seems to have the same behavior I'd seen that first time. The test
> >> > output is to this point:
> >> >
> >> > # parallel group (5 tests): index_including create_view
> >> > index_including_gist create_index create_index_spgist
> >> > ok 66 + create_index 26365 ms
> >> > ok 67 + create_index_spgist 27675 ms
> >> > ok 68 + create_view 1235 ms
> >> > ok 69 + index_including 1102 ms
> >> > ok 70 + index_including_gist 1633 ms
> >> > # parallel group (16 tests): create_aggregate create_cast errors
> >> > roleattributes drop_if_exists hash_func typed_table create_am
> >> > infinite_recurse
> >> >
> >> > and it hasn't progressed past that point since at least ~16 hours ago
> >> > (the first several hours of the run I wasn't monitoring it).
> >> >
> >> > I haven't connected up gdb yet, and won't be able to until maybe
> >> > tomorrow, but here's the ps output for postgres processes that are
> >> > running:
> >> >
> >> > admin 3213249 0.0 0.0 196824 20552 ? Ss Aug25 0:00
> >> > /home/admin/postgresql-test/bin/postgres -D
> >> > /home/admin/postgresql-test-data
> >> > admin 3213250 0.0 0.0 196964 7284 ? Ss Aug25 0:00
> >> > postgres: checkpointer
> >> > admin 3213251 0.0 0.0 196956 4276 ? Ss Aug25 0:00
> >> > postgres: background writer
> >> > admin 3213253 0.0 0.0 196956 8600 ? Ss Aug25 0:00
> >> > postgres: walwriter
> >> > admin 3213254 0.0 0.0 198424 7316 ? Ss Aug25 0:00
> >> > postgres: autovacuum launcher
> >> > admin 3213255 0.0 0.0 198412 5488 ? Ss Aug25 0:00
> >> > postgres: logical replication launcher
> >> > admin 3237967 0.0 0.0 2484 516 pts/4 S+ Aug25 0:00
> >> > /bin/sh -c echo "# +++ regress check in src/test/regress +++" &&
> >> > PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/bin:/home/admin/postgres/src/test/regress:$PATH"
> >> > LD_LIBRARY_PATH="/home/admin/postgres/tmp_install/home/admin/postgresql-test/lib"
> >> > INITDB_TEMPLATE='/home/admin/postgres'/tmp_install/initdb-template
> >> > ../../../src/test/regress/pg_regress --temp-instance=./tmp_check
> >> > --inputdir=. --bindir= --dlpath=. --max-concurrent-tests=20
> >> > --schedule=./parallel_schedule
> >> > admin 3237973 0.0 0.0 197880 20688 pts/4 S+ Aug25 0:00
> >> > postgres -D /home/admin/postgres/src/test/regress/tmp_check/data -F -c
> >> > listen_addresses= -k /tmp/pg_regress-7mmGUa
> >> > admin 3237976 0.0 0.1 198332 44608 ? Ss Aug25 0:00
> >> > postgres: checkpointer
> >> > admin 3237977 0.0 0.0 198032 4640 ? Ss Aug25 0:00
> >> > postgres: background writer
> >> > admin 3237979 0.0 0.0 197880 8580 ? Ss Aug25 0:00
> >> > postgres: walwriter
> >> > admin 3237980 0.0 0.0 199484 7608 ? Ss Aug25 0:00
> >> > postgres: autovacuum launcher
> >> > admin 3237981 0.0 0.0 199460 5488 ? Ss Aug25 0:00
> >> > postgres: logical replication launcher
> >> > admin 3243644 0.0 0.2 252400 74656 ? Ss Aug25 0:01
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243645 0.0 0.1 205480 33992 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243654 99.9 0.0 203156 31504 ? Rs Aug25 1437:49
> >> > postgres: admin regression [local] VACUUM
> >> > admin 3243655 0.0 0.1 212036 38504 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] SELECT waiting
> >> > admin 3243656 0.0 0.0 206024 30892 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] DELETE waiting
> >> > admin 3243657 0.0 0.1 205568 32232 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] ALTER TABLE waiting
> >> > admin 3243658 0.0 0.0 203740 21532 ? Ss Aug25 0:00
> >> > postgres: admin regression [local] ANALYZE waiting
> >> > admin 3243798 0.0 0.0 199884 8464 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> > admin 3244733 0.0 0.0 199492 5956 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> > admin 3245652 0.0 0.0 199884 8468 ? Ss Aug25 0:00
> >> > postgres: autovacuum worker
> >> >
> >> > As you can see there are a bunch of backends presumably waiting, and
> >> > also the VACUUM process has been pegging a single CPU core for at
> >> > least since that ~16 hour ago mark.
> >> >
> >> > I hope to be able to do more investigation later, but I wanted to at
> >> > least give you this information now.
> >>
> >> Thanks a lot for testing the patch!
> >> I really appreciate your cooperation.
> >>
> >> Hmm, I also tested on the current HEAD(165d581f146b09) again on Ubuntu
> >> 22.04 and macOS, but unfortunately(fortunately?) they succeeded as
> >> below:
> >>
> >> ```
> >> $ git apply v29-0001-Add-function-to-log-the-plan-of-the-query.patch
> >> $ git apply
> >> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch
> >> $ ./configure --enable-debug --enable-cassert
> >> $ make
> >> $ make check
> >>
> >> ...(snip)...
> >>
> >> # parallel group (5 tests): index_including index_including_gist
> >> create_view create_index create_index_spgist
> >> ok 66 + create_index 25033 ms
> >> ok 67 + create_index_spgist 26144 ms
> >> ok 68 + create_view 3061 ms
> >> ok 69 + index_including 976 ms
> >> ok 70 + index_including_gist 2998 ms
> >> # parallel group (16 tests): create_cast errors create_aggregate
> >> roleattributes drop_if_exists hash_func typed_table
> >> create_am select constraints updatable_views inherit triggers vacuum
> >> create_function_sql infinite_recurse
> >> ok 71 + create_aggregate 225 ms
> >> ok 72 + create_function_sql 18874 ms
> >> ok 73 + create_cast 168 ms
> >>
> >> ...(snip)...
> >>
> >> # All 215 tests passed.
> >> ```
> >>
> >> If you notice any difference, I would be grateful if you could let me
> >> know.
> >
> > I've never been able to reproduce it (haven't tested the new version,
> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> > (first buster and now bullseye).
> >
> > I'm attaching several stacktraces in the hope that they provide some
> > clues. These all match the ps output I sent earlier, though note in
> > that output there is both the regress instance and my test instance
> > (pid 3213249) running (different ports, of course, and they are from
> > the exact same compilation run). I've attached ps output for the
> > postgres processes under the make check process to simplify cross
> > referencing.
> >
> > A few interesting things:
> > - There's definitely a lock on a relation that seems to be what's
> > blocking the processes.
> > - When I try to connect with psql the process forks but then hangs
> > (see the ps output with task names stuck in "authentication"). I've
> > also included a trace from one of these.
>
> Thanks for sharing them!
>
> Many processes are waiting to acquire the LW lock, including the process
> trying to output the plan(select1.trace).
>
> I suspect that this is due to a lock that was acquired prior to being
> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able to
> reproduce the same situation..
>
I don't have time immediately to dig into this, but perhaps loading up
the core dumps would allow us to see what query is running in each
backend process (if it hasn't already been discarded by that point)
and thereby determine what point in each test process led to the error
condition?
Alternatively we might be able to apply the same trick to the test
client instead...
BTW, for my own easy reference in this thread: relid 1259 is pg_class
if I'm not mistaken.
Thoughts?
James Coleman
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
@ 2023-09-07 06:09 ` torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
0 siblings, 2 replies; 25+ messages in thread
From: torikoshia @ 2023-09-07 06:09 UTC (permalink / raw)
To: James Coleman <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-09-06 11:17, James Coleman wrote:
>> > I've never been able to reproduce it (haven't tested the new version,
>> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
>> > (first buster and now bullseye).
>> >
>> > I'm attaching several stacktraces in the hope that they provide some
>> > clues. These all match the ps output I sent earlier, though note in
>> > that output there is both the regress instance and my test instance
>> > (pid 3213249) running (different ports, of course, and they are from
>> > the exact same compilation run). I've attached ps output for the
>> > postgres processes under the make check process to simplify cross
>> > referencing.
>> >
>> > A few interesting things:
>> > - There's definitely a lock on a relation that seems to be what's
>> > blocking the processes.
>> > - When I try to connect with psql the process forks but then hangs
>> > (see the ps output with task names stuck in "authentication"). I've
>> > also included a trace from one of these.
>>
>> Thanks for sharing them!
>>
>> Many processes are waiting to acquire the LW lock, including the
>> process
>> trying to output the plan(select1.trace).
>>
>> I suspect that this is due to a lock that was acquired prior to being
>> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
>> to
>> reproduce the same situation..
>>
>
> I don't have time immediately to dig into this, but perhaps loading up
> the core dumps would allow us to see what query is running in each
> backend process (if it hasn't already been discarded by that point)
> and thereby determine what point in each test process led to the error
> condition?
Thanks for the suggestion.
I am concerned that core dumps may not be readable on different
operating systems or other environments. (Unfortunately, I do not have
Debian on hand)
It seems that we can know what queries were running from the stack
traces you shared.
As described above, I suspect a lock which was acquired prior to
ProcessLogQueryPlanInterrupt() caused the issue.
I will try a little more to see if I can devise a way to create the same
situation.
> Alternatively we might be able to apply the same trick to the test
> client instead...
>
> BTW, for my own easy reference in this thread: relid 1259 is pg_class
> if I'm not mistaken.
Yeah, and I think it's strange that the lock to 1259 appears twice and
must be avoided.
#10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
lmgr.c:117
..
#49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
explain.c:5158
..
#53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
lmgr.c:117
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-09-15 06:21 ` Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 25+ messages in thread
From: Lepikhov Andrei @ 2023-09-15 06:21 UTC (permalink / raw)
To: torikoshia <[email protected]>; James Coleman <[email protected]>; +Cc: 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
> On 2023-09-06 11:17, James Coleman wrote:
> It seems that we can know what queries were running from the stack
> traces you shared.
> As described above, I suspect a lock which was acquired prior to
> ProcessLogQueryPlanInterrupt() caused the issue.
> I will try a little more to see if I can devise a way to create the same
> situation.
Hi,
I have explored this patch and, by and large, agree with the code. But some questions I want to discuss:
1. Maybe add a hook to give a chance for extensions, like pg_query_state, to do their job?
2. In this implementation, ProcessInterrupts does a lot of work during the explain creation: memory allocations, pass through the plan, systables locks, syscache access, etc. I guess it can change the semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be called - I can imagine a SELECT query, which would call a stored procedure, which executes some DDL and acquires row exclusive lock at the time of interruption. So, in my mind, it is too unpredictable to make the explain in the place of interruption processing. Maybe it is better to think about some hook at the end of ExecProcNode, where a pending explain could be created?
Also, I suggest minor code change with the diff in attachment.
--
Regards,
Andrei Lepikhov
Attachments:
[application/octet-stream] improve.diff (772B, ../../[email protected]/2-improve.diff)
download | inline diff:
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 5e2c10dc57..dc8aa94eee 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -5209,16 +5209,15 @@ pg_log_query_plan(PG_FUNCTION_ARGS)
*/
ereport(WARNING,
(errmsg("PID %d is not a PostgreSQL backend process", pid)));
- PG_RETURN_BOOL(false);
}
-
- if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+ else if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
{
/* Again, just a warning to allow loops */
ereport(WARNING,
(errmsg("could not send signal to process %d: %m", pid)));
- PG_RETURN_BOOL(false);
}
+ else
+ PG_RETURN_BOOL(true);
- PG_RETURN_BOOL(true);
+ PG_RETURN_BOOL(false);
}
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
@ 2023-09-19 13:39 ` torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-09-19 13:39 UTC (permalink / raw)
To: Lepikhov Andrei <[email protected]>; +Cc: James Coleman <[email protected]>; 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-09-15 15:21, Lepikhov Andrei wrote:
> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>> On 2023-09-06 11:17, James Coleman wrote:
>> It seems that we can know what queries were running from the stack
>> traces you shared.
>> As described above, I suspect a lock which was acquired prior to
>> ProcessLogQueryPlanInterrupt() caused the issue.
>> I will try a little more to see if I can devise a way to create the
>> same
>> situation.
> Hi,
> I have explored this patch and, by and large, agree with the code. But
> some questions I want to discuss:
> 1. Maybe add a hook to give a chance for extensions, like
> pg_query_state, to do their job?
Do you imagine adding a hook which enables adding custom interrupt codes
like below?
https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch
If so, that would be possible, but this patch doesn't require the
functionality and I feel it'd be better doing in independent patch.
> 2. In this implementation, ProcessInterrupts does a lot of work during
> the explain creation: memory allocations, pass through the plan,
> systables locks, syscache access, etc. I guess it can change the
> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
> called - I can imagine a SELECT query, which would call a stored
> procedure, which executes some DDL and acquires row exclusive lock at
> the time of interruption. So, in my mind, it is too unpredictable to
> make the explain in the place of interruption processing. Maybe it is
> better to think about some hook at the end of ExecProcNode, where a
> pending explain could be created?
Yeah, I withdrew this patch once for that reason, but we are resuming
development in response to the results of a discussion by James and
others at this year's pgcon about the safety of this process in CFI:
https://www.postgresql.org/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gma...
BTW it seems pg_query_state also enables users to get running query
plans using CFI.
Does pg_query_state do something for this safety concern?
> Also, I suggest minor code change with the diff in attachment.
Thanks!
This might be biased opinion and objections are welcomed, but I feel the
original patch is easier to read since PG_RETURN_BOOL(true/false) is
located in near place to each cases.
Also the existing function pg_log_backend_memory_contexts(), which does
the same thing, has the same form as the original patch.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-09-20 05:39 ` Lepikhov Andrei <[email protected]>
2023-09-25 07:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: Lepikhov Andrei @ 2023-09-20 05:39 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: James Coleman <[email protected]>; 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On Tue, Sep 19, 2023, at 8:39 PM, torikoshia wrote:
> On 2023-09-15 15:21, Lepikhov Andrei wrote:
>> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>> I have explored this patch and, by and large, agree with the code. But
>> some questions I want to discuss:
>> 1. Maybe add a hook to give a chance for extensions, like
>> pg_query_state, to do their job?
>
> Do you imagine adding a hook which enables adding custom interrupt codes
> like below?
>
> https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch
No, I think around the hook, which would allow us to rewrite the pg_query_state extension without additional patches by using the functionality provided by your patch. I mean, an extension could provide console UI, not only server logging. And obtain from target backend so much information in the explain as the instrumentation level of the current query can give.
It may make pg_query_state shorter and more stable.
>> 2. In this implementation, ProcessInterrupts does a lot of work during
>> the explain creation: memory allocations, pass through the plan,
>> systables locks, syscache access, etc. I guess it can change the
>> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
>> called - I can imagine a SELECT query, which would call a stored
>> procedure, which executes some DDL and acquires row exclusive lock at
>> the time of interruption. So, in my mind, it is too unpredictable to
>> make the explain in the place of interruption processing. Maybe it is
>> better to think about some hook at the end of ExecProcNode, where a
>> pending explain could be created?
>
> Yeah, I withdrew this patch once for that reason, but we are resuming
> development in response to the results of a discussion by James and
> others at this year's pgcon about the safety of this process in CFI:
>
> https://www.postgresql.org/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gma...
I can't track the logic path of the decision provided at this conference. But my anxiety related to specific place, where ActiveQueryDesc points top-level query and interruption comes during DDL, wrapped up in stored procedure. For example:
CREATE TABLE test();
CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
BEGIN
EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
...
END; $$ LANGUAGE plpgsql VOLATILE;
SELECT ddl(), ... FROM ...;
> BTW it seems pg_query_state also enables users to get running query
> plans using CFI.
> Does pg_query_state do something for this safety concern?
No, and I'm looking for the solution, which could help to rewrite pg_query_state as a clean extension, without patches.
>> Also, I suggest minor code change with the diff in attachment.
>
> Thanks!
>
> This might be biased opinion and objections are welcomed, but I feel the
> original patch is easier to read since PG_RETURN_BOOL(true/false) is
> located in near place to each cases.
> Also the existing function pg_log_backend_memory_contexts(), which does
> the same thing, has the same form as the original patch.
I got it, thank you.
--
Regards,
Andrei Lepikhov
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
@ 2023-09-25 07:21 ` torikoshia <[email protected]>
2023-09-25 09:49 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-09-25 07:21 UTC (permalink / raw)
To: Lepikhov Andrei <[email protected]>; +Cc: James Coleman <[email protected]>; 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-09-20 14:39, Lepikhov Andrei wrote:
Thanks for your reply.
> On Tue, Sep 19, 2023, at 8:39 PM, torikoshia wrote:
>> On 2023-09-15 15:21, Lepikhov Andrei wrote:
>>> On Thu, Sep 7, 2023, at 1:09 PM, torikoshia wrote:
>>> I have explored this patch and, by and large, agree with the code.
>>> But
>>> some questions I want to discuss:
>>> 1. Maybe add a hook to give a chance for extensions, like
>>> pg_query_state, to do their job?
>>
>> Do you imagine adding a hook which enables adding custom interrupt
>> codes
>> like below?
>>
>> https://github.com/postgrespro/pg_query_state/blob/master/patches/custom_signals_15.0.patch
>
> No, I think around the hook, which would allow us to rewrite the
> pg_query_state extension without additional patches by using the
> functionality provided by your patch. I mean, an extension could
> provide console UI, not only server logging. And obtain from target
> backend so much information in the explain as the instrumentation
> level of the current query can give.
> It may make pg_query_state shorter and more stable.
>
>>> 2. In this implementation, ProcessInterrupts does a lot of work
>>> during
>>> the explain creation: memory allocations, pass through the plan,
>>> systables locks, syscache access, etc. I guess it can change the
>>> semantic meaning of 'safe place' where CHECK_FOR_INTERRUPTS can be
>>> called - I can imagine a SELECT query, which would call a stored
>>> procedure, which executes some DDL and acquires row exclusive lock at
>>> the time of interruption. So, in my mind, it is too unpredictable to
>>> make the explain in the place of interruption processing. Maybe it is
>>> better to think about some hook at the end of ExecProcNode, where a
>>> pending explain could be created?
>>
>> Yeah, I withdrew this patch once for that reason, but we are resuming
>> development in response to the results of a discussion by James and
>> others at this year's pgcon about the safety of this process in CFI:
>>
>> https://www.postgresql.org/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gma...
>
> I can't track the logic path of the decision provided at this
> conference. But my anxiety related to specific place, where
> ActiveQueryDesc points top-level query and interruption comes during
> DDL, wrapped up in stored procedure. For example:
> CREATE TABLE test();
> CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
> BEGIN
> EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
> ...
> END; $$ LANGUAGE plpgsql VOLATILE;
> SELECT ddl(), ... FROM ...;
Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
all CFI using
v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
ran the following query but did not cause any problems.
```
=# CREATE TABLE test();
=# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
BEGIN
EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
PERFORM pg_sleep(5);
END; $$ LANGUAGE plpgsql VOLATILE;
=# SELECT ddl();
```
Is this the case you're worrying about?
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-25 07:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-09-25 09:49 ` Andrey Lepikhov <[email protected]>
2023-09-28 02:04 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: Andrey Lepikhov @ 2023-09-25 09:49 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: James Coleman <[email protected]>; 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 25/9/2023 14:21, torikoshia wrote:
> On 2023-09-20 14:39, Lepikhov Andrei wrote:
> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
> all CFI using
> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
> ran the following query but did not cause any problems.
>
> ```
> =# CREATE TABLE test();
> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
> BEGIN
> EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
> PERFORM pg_sleep(5);
> END; $$ LANGUAGE plpgsql VOLATILE;
> =# SELECT ddl();
> ```
>
> Is this the case you're worrying about?
I didn't find a problem either. I just feel uncomfortable if, at the
moment of interruption, we have a descriptor of another query than the
query have been executing and holding resources.
--
regards,
Andrey Lepikhov
Postgres Professional
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-25 07:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-25 09:49 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
@ 2023-09-28 02:04 ` torikoshia <[email protected]>
2023-09-28 02:32 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-09-28 02:04 UTC (permalink / raw)
To: Andrey Lepikhov <[email protected]>; +Cc: James Coleman <[email protected]>; 'Andres Freund' <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-09-25 18:49, Andrey Lepikhov wrote:
> On 25/9/2023 14:21, torikoshia wrote:
>> On 2023-09-20 14:39, Lepikhov Andrei wrote:
>> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
>> all CFI using
>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and then
>> ran the following query but did not cause any problems.
>>
>> ```
>> =# CREATE TABLE test();
>> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
>> BEGIN
>> EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
>> PERFORM pg_sleep(5);
>> END; $$ LANGUAGE plpgsql VOLATILE;
>> =# SELECT ddl();
>> ```
>>
>> Is this the case you're worrying about?
>
> I didn't find a problem either. I just feel uncomfortable if, at the
> moment of interruption, we have a descriptor of another query than the
> query have been executing and holding resources.
I think that "descriptor" here refers to ActiveQueryDesc, in which case
it is updated at the beginning of ExecutorRun(), so I am wondering if
the situation you're worried about would not occur.
---------
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
---------
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-25 07:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-25 09:49 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
2023-09-28 02:04 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-09-28 02:32 ` Andrey Lepikhov <[email protected]>
0 siblings, 0 replies; 25+ messages in thread
From: Andrey Lepikhov @ 2023-09-28 02:32 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: [email protected]
On 28/9/2023 09:04, torikoshia wrote:
> On 2023-09-25 18:49, Andrey Lepikhov wrote:
>> On 25/9/2023 14:21, torikoshia wrote:
>>> On 2023-09-20 14:39, Lepikhov Andrei wrote:
>>> Hmm, as a test, I made sure to call ProcessLogQueryPlanInterrupt() on
>>> all CFI using
>>> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch, and
>>> then ran the following query but did not cause any problems.
>>>
>>> ```
>>> =# CREATE TABLE test();
>>> =# CREATE OR REPLACE FUNCTION ddl() RETURNS void AS $$
>>> BEGIN
>>> EXECUTE format('ALTER TABLE test ADD COLUMN x integer;');
>>> PERFORM pg_sleep(5);
>>> END; $$ LANGUAGE plpgsql VOLATILE;
>>> =# SELECT ddl();
>>> ```
>>>
>>> Is this the case you're worrying about?
>>
>> I didn't find a problem either. I just feel uncomfortable if, at the
>> moment of interruption, we have a descriptor of another query than the
>> query have been executing and holding resources.
>
> I think that "descriptor" here refers to ActiveQueryDesc, in which case
> it is updated at the beginning of ExecutorRun(), so I am wondering if
> the situation you're worried about would not occur.
As you can see, in my example we have the only DDL and no queries with
plans. In this case postgres doesn't call ExecutorRun() just because it
doesn't have a plan. But locks will be obtained.
--
regards,
Andrey Lepikhov
Postgres Professional
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-03 18:00 ` James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 25+ messages in thread
From: James Coleman @ 2023-10-03 18:00 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On Thu, Sep 7, 2023 at 2:09 AM torikoshia <[email protected]> wrote:
>
> On 2023-09-06 11:17, James Coleman wrote:
>
> >> > I've never been able to reproduce it (haven't tested the new version,
> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> >> > (first buster and now bullseye).
> >> >
> >> > I'm attaching several stacktraces in the hope that they provide some
> >> > clues. These all match the ps output I sent earlier, though note in
> >> > that output there is both the regress instance and my test instance
> >> > (pid 3213249) running (different ports, of course, and they are from
> >> > the exact same compilation run). I've attached ps output for the
> >> > postgres processes under the make check process to simplify cross
> >> > referencing.
> >> >
> >> > A few interesting things:
> >> > - There's definitely a lock on a relation that seems to be what's
> >> > blocking the processes.
> >> > - When I try to connect with psql the process forks but then hangs
> >> > (see the ps output with task names stuck in "authentication"). I've
> >> > also included a trace from one of these.
> >>
> >> Thanks for sharing them!
> >>
> >> Many processes are waiting to acquire the LW lock, including the
> >> process
> >> trying to output the plan(select1.trace).
> >>
> >> I suspect that this is due to a lock that was acquired prior to being
> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
> >> to
> >> reproduce the same situation..
> >>
> >
> > I don't have time immediately to dig into this, but perhaps loading up
> > the core dumps would allow us to see what query is running in each
> > backend process (if it hasn't already been discarded by that point)
> > and thereby determine what point in each test process led to the error
> > condition?
>
> Thanks for the suggestion.
> I am concerned that core dumps may not be readable on different
> operating systems or other environments. (Unfortunately, I do not have
> Debian on hand)
>
> It seems that we can know what queries were running from the stack
> traces you shared.
> As described above, I suspect a lock which was acquired prior to
> ProcessLogQueryPlanInterrupt() caused the issue.
> I will try a little more to see if I can devise a way to create the same
> situation.
>
> > Alternatively we might be able to apply the same trick to the test
> > client instead...
> >
> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
> > if I'm not mistaken.
>
> Yeah, and I think it's strange that the lock to 1259 appears twice and
> must be avoided.
>
> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
> lmgr.c:117
> ..
> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
> explain.c:5158
> ..
> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1) at
> lmgr.c:117
I chatted with Andres and David about this at PGConf.NYC, and I think
what we need to do is explicitly disallow running this code any time
we are inside of lock acquisition code.
Regards,
James Coleman
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
@ 2023-10-06 12:58 ` torikoshia <[email protected]>
2023-10-06 13:10 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
0 siblings, 2 replies; 25+ messages in thread
From: torikoshia @ 2023-10-06 12:58 UTC (permalink / raw)
To: James Coleman <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On 2023-10-04 03:00, James Coleman wrote:
> On Thu, Sep 7, 2023 at 2:09 AM torikoshia <[email protected]>
> wrote:
>>
>> On 2023-09-06 11:17, James Coleman wrote:
>>
>> >> > I've never been able to reproduce it (haven't tested the new version,
>> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
>> >> > (first buster and now bullseye).
>> >> >
>> >> > I'm attaching several stacktraces in the hope that they provide some
>> >> > clues. These all match the ps output I sent earlier, though note in
>> >> > that output there is both the regress instance and my test instance
>> >> > (pid 3213249) running (different ports, of course, and they are from
>> >> > the exact same compilation run). I've attached ps output for the
>> >> > postgres processes under the make check process to simplify cross
>> >> > referencing.
>> >> >
>> >> > A few interesting things:
>> >> > - There's definitely a lock on a relation that seems to be what's
>> >> > blocking the processes.
>> >> > - When I try to connect with psql the process forks but then hangs
>> >> > (see the ps output with task names stuck in "authentication"). I've
>> >> > also included a trace from one of these.
>> >>
>> >> Thanks for sharing them!
>> >>
>> >> Many processes are waiting to acquire the LW lock, including the
>> >> process
>> >> trying to output the plan(select1.trace).
>> >>
>> >> I suspect that this is due to a lock that was acquired prior to being
>> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
>> >> to
>> >> reproduce the same situation..
>> >>
>> >
>> > I don't have time immediately to dig into this, but perhaps loading up
>> > the core dumps would allow us to see what query is running in each
>> > backend process (if it hasn't already been discarded by that point)
>> > and thereby determine what point in each test process led to the error
>> > condition?
>>
>> Thanks for the suggestion.
>> I am concerned that core dumps may not be readable on different
>> operating systems or other environments. (Unfortunately, I do not have
>> Debian on hand)
>>
>> It seems that we can know what queries were running from the stack
>> traces you shared.
>> As described above, I suspect a lock which was acquired prior to
>> ProcessLogQueryPlanInterrupt() caused the issue.
>> I will try a little more to see if I can devise a way to create the
>> same
>> situation.
>>
>> > Alternatively we might be able to apply the same trick to the test
>> > client instead...
>> >
>> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
>> > if I'm not mistaken.
>>
>> Yeah, and I think it's strange that the lock to 1259 appears twice and
>> must be avoided.
>>
>> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
>> at
>> lmgr.c:117
>> ..
>> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
>> explain.c:5158
>> ..
>> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
>> at
>> lmgr.c:117
>
> I chatted with Andres and David about this at PGConf.NYC,
Thanks again for the discussion with hackers!
> and I think
> what we need to do is explicitly disallow running this code any time
> we are inside of lock acquisition code.
Yeah, I think it's a straightforward workaround.
And I'm also concerned that the condition of being in the process
of acquiring some kind of lock is too strict and will make it almost
impossible to output a running plan.
Anyway I'm going to implement it and run pg_log_query_plan()
while the regression test is running to see how successful the plan
output is.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-06 13:10 ` James Coleman <[email protected]>
1 sibling, 0 replies; 25+ messages in thread
From: James Coleman @ 2023-10-06 13:10 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
On Fri, Oct 6, 2023 at 8:58 AM torikoshia <[email protected]> wrote:
>
> On 2023-10-04 03:00, James Coleman wrote:
> > On Thu, Sep 7, 2023 at 2:09 AM torikoshia <[email protected]>
> > wrote:
> >>
> >> On 2023-09-06 11:17, James Coleman wrote:
> >>
> >> >> > I've never been able to reproduce it (haven't tested the new version,
> >> >> > but v28 at least) on my M1 Mac; where I've reproduced it is on Debian
> >> >> > (first buster and now bullseye).
> >> >> >
> >> >> > I'm attaching several stacktraces in the hope that they provide some
> >> >> > clues. These all match the ps output I sent earlier, though note in
> >> >> > that output there is both the regress instance and my test instance
> >> >> > (pid 3213249) running (different ports, of course, and they are from
> >> >> > the exact same compilation run). I've attached ps output for the
> >> >> > postgres processes under the make check process to simplify cross
> >> >> > referencing.
> >> >> >
> >> >> > A few interesting things:
> >> >> > - There's definitely a lock on a relation that seems to be what's
> >> >> > blocking the processes.
> >> >> > - When I try to connect with psql the process forks but then hangs
> >> >> > (see the ps output with task names stuck in "authentication"). I've
> >> >> > also included a trace from one of these.
> >> >>
> >> >> Thanks for sharing them!
> >> >>
> >> >> Many processes are waiting to acquire the LW lock, including the
> >> >> process
> >> >> trying to output the plan(select1.trace).
> >> >>
> >> >> I suspect that this is due to a lock that was acquired prior to being
> >> >> interrupted by ProcessLogQueryPlanInterrupt(), but have not been able
> >> >> to
> >> >> reproduce the same situation..
> >> >>
> >> >
> >> > I don't have time immediately to dig into this, but perhaps loading up
> >> > the core dumps would allow us to see what query is running in each
> >> > backend process (if it hasn't already been discarded by that point)
> >> > and thereby determine what point in each test process led to the error
> >> > condition?
> >>
> >> Thanks for the suggestion.
> >> I am concerned that core dumps may not be readable on different
> >> operating systems or other environments. (Unfortunately, I do not have
> >> Debian on hand)
> >>
> >> It seems that we can know what queries were running from the stack
> >> traces you shared.
> >> As described above, I suspect a lock which was acquired prior to
> >> ProcessLogQueryPlanInterrupt() caused the issue.
> >> I will try a little more to see if I can devise a way to create the
> >> same
> >> situation.
> >>
> >> > Alternatively we might be able to apply the same trick to the test
> >> > client instead...
> >> >
> >> > BTW, for my own easy reference in this thread: relid 1259 is pg_class
> >> > if I'm not mistaken.
> >>
> >> Yeah, and I think it's strange that the lock to 1259 appears twice and
> >> must be avoided.
> >>
> >> #10 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
> >> at
> >> lmgr.c:117
> >> ..
> >> #49 0x0000559d61b4989d in ProcessLogQueryPlanInterrupt () at
> >> explain.c:5158
> >> ..
> >> #53 0x0000559d61d8ee6e in LockRelationOid (relid=1259, lockmode=1)
> >> at
> >> lmgr.c:117
> >
> > I chatted with Andres and David about this at PGConf.NYC,
> Thanks again for the discussion with hackers!
>
> > and I think
> > what we need to do is explicitly disallow running this code any time
> > we are inside of lock acquisition code.
>
> Yeah, I think it's a straightforward workaround.
> And I'm also concerned that the condition of being in the process
> of acquiring some kind of lock is too strict and will make it almost
> impossible to output a running plan.
I was concerned about this too, but I was wondering if we might be
able to cheat a bit by making such a case not clear the flag but
instead just skip it for now.
Regards,
James
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-06 15:58 ` Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 25+ messages in thread
From: Andres Freund @ 2023-10-06 15:58 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: James Coleman <[email protected]>; [email protected]; Greg Stark <[email protected]>; Ronan Dunklau <[email protected]>; [email protected]; Heikki Linnakangas <[email protected]>
Hi,
On 2023-10-06 21:58:46 +0900, torikoshia wrote:
> Yeah, I think it's a straightforward workaround.
> And I'm also concerned that the condition of being in the process
> of acquiring some kind of lock is too strict and will make it almost
> impossible to output a running plan.
How so? We shouldn't commonly acquire relevant locks while executing a query?
With a few exceptions, they should instead be acquired t the start of query
processing. We do acquire a lot of lwlocks, obviously, but we don't process
interrupts during the acquisition / holding of lwlocks.
And presumably the interrupt would just be processed the next time interrupt
processing is happening?
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
@ 2023-10-10 13:27 ` torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-10-10 13:27 UTC (permalink / raw)
To: Andres Freund <[email protected]>; [email protected]; +Cc: [email protected]
On 2023-10-04 03:00, James Coleman wrote:
> and I think
> what we need to do is explicitly disallow running this code any time
> we are inside of lock acquisition code.
Updated patch to check if any locks have already been acquired by
examining MyProc->heldLocks.
I'm not sure this change can "disallow running this code `any time` we
are inside of lock acquisition code", but as far as select1.trace, which
you shared, I believe it can prevent running explain codes since it must
have set MyProc->heldLocks in LockAcquireExtended() before WaitOnLock():
```
/*
* Set bitmask of locks this process already holds on this
object.
*/
MyProc->heldLocks = proclock->holdMask;
..(snip)..
WaitOnLock(locallock, owner);
```
On 2023-10-07 00:58, Andres Freund wrote:
> How so? We shouldn't commonly acquire relevant locks while executing a
> query?
> With a few exceptions, they should instead be acquired t the start of
> query
> processing. We do acquire a lot of lwlocks, obviously, but we don't
> process
> interrupts during the acquisition / holding of lwlocks.
>
> And presumably the interrupt would just be processed the next time
> interrupt
> processing is happening?
Thanks for your comments!
I tested v30 patch with
v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch which makes
CFI() call ProcessLogQueryPlanInterrupt() internally, and confirmed that
very few logging queries failed with v30 patch.
This is a result in line with your prediction.
```
$ rg -c'ignored request for logging query plan due to lock confilcts'
postmaster.log
8
```
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
Attachments:
[text/x-diff] v30-0001-Add-function-to-log-the-plan-of-the-query.patch (27.4K, ../../[email protected]/2-v30-0001-Add-function-to-log-the-plan-of-the-query.patch)
download | inline diff:
From aaaca1523ed5342c9f77d79963e0d256146381d2 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Tue, 10 Oct 2023 22:07:28 +0900
Subject: [PATCH v30] Add function to log the plan of the query
Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.
By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.
On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.
Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar,
Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby, Kyotaro
Horiguchi, Robert Treat, Alena Rybakina
Co-authored-by: James Coleman <[email protected]>
---
doc/src/sgml/func.sgml | 49 +++++
src/backend/access/transam/xact.c | 13 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 177 ++++++++++++++++++-
src/backend/executor/execMain.c | 14 ++
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/storage/lmgr/lock.c | 9 +-
src/backend/tcop/postgres.c | 4 +
src/backend/utils/error/elog.c | 2 +
src/backend/utils/init/globals.c | 2 +
src/include/catalog/pg_proc.dat | 6 +
src/include/commands/explain.h | 4 +
src/include/miscadmin.h | 1 +
src/include/storage/lock.h | 2 -
src/include/storage/procsignal.h | 1 +
src/include/tcop/pquery.h | 2 +-
src/include/utils/elog.h | 1 +
src/test/regress/expected/misc_functions.out | 54 ++++--
src/test/regress/sql/misc_functions.sql | 41 +++--
19 files changed, 360 insertions(+), 28 deletions(-)
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index f1ad64c3d6..b7c7fa9169 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -26308,6 +26308,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
</para></entry>
</row>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>pg_log_query_plan</primary>
+ </indexterm>
+ <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+ <returnvalue>boolean</returnvalue>
+ </para>
+ <para>
+ Requests to log the plan of the query currently running on the
+ backend with specified process ID.
+ It 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"/>
+ for more information), but will not be sent to the client
+ regardless of <xref linkend="guc-client-min-messages"/>.
+ </para></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -26528,6 +26547,36 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+ Query Text: SELECT * FROM pgbench_accounts;
+ Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+ Output: aid, bid, abalance, filler
+ Settings: work_mem = '1MB'
+</screen>
+ Note that when statements are executed inside a function, only the
+ plan of the most deeply nested query is logged.
+ </para>
+
+ <para>
+ When a subtransaction is aborted, <function>pg_log_query_plan</function>
+ cannot log the query plan after the abort.
+ </para>
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 37c5e34cce..a2b0266dd3 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -61,6 +61,7 @@
#include "storage/procarray.h"
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
+#include "tcop/pquery.h"
#include "utils/builtins.h"
#include "utils/catcache.h"
#include "utils/combocid.h"
@@ -2750,6 +2751,12 @@ AbortTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
@@ -5109,6 +5116,12 @@ AbortSubTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 07c0d89c4f..80792913bd 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -722,6 +722,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 13217807ee..9398a1da79 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -21,6 +21,7 @@
#include "executor/nodeHash.h"
#include "foreign/fdwapi.h"
#include "jit/jit.h"
+#include "miscadmin.h"
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
@@ -28,6 +29,8 @@
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
#include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "tcop/pquery.h"
#include "tcop/tcopprot.h"
#include "utils/builtins.h"
#include "utils/guc_tables.h"
@@ -1647,6 +1650,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
/*
* We have to forcibly clean up the instrumentation state because we
* haven't done ExecutorEnd yet. This is pretty grotty ...
+ * This cleanup should not be done when the query has already been
+ * executed and explain has been called by signal, as the target query
+ * may use instrumentation and clean itself up.
*
* Note: contrib/auto_explain could cause instrumentation to be set up
* even though we didn't ask for it here. Be careful not to print any
@@ -1654,7 +1660,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
* InstrEndLoop call anyway, if possible, to reduce the number of cases
* auto_explain has to contend with.
*/
- if (planstate->instrument)
+ if (planstate->instrument && !es->signaled)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
@@ -5060,3 +5066,172 @@ escape_yaml(StringInfo buf, const char *str)
{
escape_json(buf, str);
}
+
+/*
+ * HandleLogQueryPlanInterrupt
+ * Handle receipt of an interrupt indicating logging the plan of
+ * the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+ InterruptPending = true;
+ LogQueryPlanPending = true;
+ /* latch will be set by procsignal_sigusr1_handler */
+}
+
+bool ProcessLogQueryPlanInterruptActive = false;
+/*
+ * ProcessLogQueryPlanInterrupt
+ * Perform logging the plan of the currently running query on this
+ * backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange to call
+ * this function if we see LogQueryPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ ExplainState *es;
+ HASH_SEQ_STATUS status;
+ LOCALLOCK *locallock;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+ LogQueryPlanPending = false;
+
+ /* Cannot re-enter. */
+ if (ProcessLogQueryPlanInterruptActive)
+ return;
+
+ ProcessLogQueryPlanInterruptActive = true;
+
+ if (ActiveQueryDesc == NULL)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is not running a query or a subtransaction is aborted",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+
+ /*
+ * Ensure no page lock is held on this process.
+ *
+ * If page lock is held at the time of the interrupt, we can't acquire any
+ * other heavyweight lock, which might be necessary for explaining the plan
+ * when retrieving column names.
+ *
+ * This may be overkill, but since page locks are held for a short duration
+ * we check all the LocalLock entries and when finding even one, give up
+ * logging the plan.
+ */
+ hash_seq_init(&status, GetLockMethodLocalHash());
+ while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL)
+ {
+ if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to page lock confilcts"),
+ errdetail("You can try again in a moment."));
+ hash_seq_term(&status);
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+ }
+
+ /*
+ * Ensure no locks already held on the lockable object.
+ *
+ * Otherwise EXPLAIN can be also hold on it.
+ */
+ if (MyProc->heldLocks)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to lock confilcts"),
+ errdetail("You can try again in a moment."));
+ return;
+ }
+
+ es = NewExplainState();
+
+ es->format = EXPLAIN_FORMAT_TEXT;
+ es->settings = true;
+ es->verbose = true;
+ es->signaled = true;
+
+ ExplainBeginOutput(es);
+ ExplainQueryText(es, ActiveQueryDesc);
+
+ cxt = AllocSetContextCreate(CurrentMemoryContext,
+ "log_query_plan temporary context",
+ ALLOCSET_DEFAULT_SIZES);
+ old_cxt = MemoryContextSwitchTo(cxt);
+
+ ExplainPrintPlan(es, ActiveQueryDesc);
+
+ MemoryContextSwitchTo(old_cxt);
+ MemoryContextDelete(cxt);
+
+ ExplainPrintJITSummary(es, ActiveQueryDesc);
+ ExplainEndOutput(es);
+
+ /* Remove last line break */
+ if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+ es->str->data[--es->str->len] = '\0';
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * pg_log_query_plan
+ * Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+ int pid = PG_GETARG_INT32(0);
+ PGPROC *proc;
+
+ proc = BackendPidGetProc(pid);
+
+ if (proc == NULL)
+ {
+ /*
+ * This is just a warning so a loop-through-resultset will not abort
+ * if one backend terminated on its own during the run.
+ */
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL backend process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+ {
+ /* Again, just a warning to allow loops */
+ ereport(WARNING,
+ (errmsg("could not send signal to process %d: %m", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 4c5a7bbf62..4772cb97e7 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -78,6 +78,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
/* Hook for plugin to get control in ExecCheckPermissions() */
ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
/* decls for local routines only used within this module */
static void InitPlan(QueryDesc *queryDesc, int eflags);
static void CheckValidRowMarkRel(Relation rel, RowMarkType markType);
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
+
if (ExecutorRun_hook)
(*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
else
standard_ExecutorRun(queryDesc, direction, count, execute_once);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index b7427906de..ddaf829917 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -20,6 +20,7 @@
#include "access/parallel.h"
#include "port/pg_bitutils.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "replication/logicalworker.h"
@@ -658,6 +659,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
HandleLogMemoryContextInterrupt();
+ if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN))
+ HandleLogQueryPlanInterrupt();
+
if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE))
HandleParallelApplyMessageInterrupt();
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index ec6240fbae..c6eb340d7a 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -602,17 +602,18 @@ LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode)
return (locallock && locallock->nLocks > 0);
}
-#ifdef USE_ASSERT_CHECKING
/*
- * GetLockMethodLocalHash -- return the hash of local locks, for modules that
- * evaluate assertions based on all locks held.
+ * GetLockMethodLocalHash -- return the hash of local locks, mainly for
+ * modules that evaluate assertions based on all locks held.
+ *
+ * NOTE: When there are many entries in LockMethodLocalHash, calling this
+ * function and looking into all of them can lead to performance problems.
*/
HTAB *
GetLockMethodLocalHash(void)
{
return LockMethodLocalHash;
}
-#endif
/*
* LockHasWaiters -- look up 'locktag' and check if releasing this
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 21b9763183..da687ee09e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -36,6 +36,7 @@
#include "access/xact.h"
#include "catalog/pg_type.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "commands/prepare.h"
#include "common/pg_prng.h"
#include "jit/jit.h"
@@ -3460,6 +3461,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
HandleParallelApplyMessages();
}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8e1f3e8521..36847c950a 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -513,6 +513,8 @@ errfinish(const char *filename, int lineno, const char *funcname)
econtext = econtext->previous)
econtext->callback(econtext->arg);
+ if (elevel >= ERROR)
+ ProcessLogQueryPlanInterruptActive = false;
/*
* If ERROR (not more nor less) we pass it off to the current handler.
* Printing it and popping the stack is the responsibility of the handler.
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 011ec18015..c451f84e07 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -37,6 +37,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index f0b7b9cbd8..3c5843529f 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8241,6 +8241,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..ccae06a8fd 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,7 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
typedef enum ExplainFormat
{
EXPLAIN_FORMAT_TEXT,
@@ -60,6 +61,7 @@ typedef struct ExplainState
bool hide_workers; /* set if we find an invisible Gather */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool signaled; /* whether explain is called by signal */
} ExplainState;
/* Hook for plugins to get control in ExplainOneQuery() */
@@ -126,4 +128,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
extern void ExplainCloseGroup(const char *objtype, const char *labelname,
bool labeled, ExplainState *es);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 14bd574fc2..f805daec16 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -95,6 +95,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 8575bea25c..63f0454378 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -569,9 +569,7 @@ extern void LockReleaseSession(LOCKMETHODID lockmethodid);
extern void LockReleaseCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern void LockReassignCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern bool LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode);
-#ifdef USE_ASSERT_CHECKING
extern HTAB *GetLockMethodLocalHash(void);
-#endif
extern bool LockHasWaiters(const LOCKTAG *locktag,
LOCKMODE lockmode, bool sessionLock);
extern VirtualTransactionId *GetLockConflicts(const LOCKTAG *locktag,
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index 3a3a7eca77..b5d2a1be28 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index a5e65b98aa..a6ae947a0f 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,7 +21,7 @@ struct PlannedStmt; /* avoid including plannodes.h here */
extern PGDLLIMPORT Portal ActivePortal;
-
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
extern PortalStrategy ChoosePortalStrategy(List *stmts);
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 4a9562fdaa..6b03682934 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
extern bool message_level_is_interesting(int elevel);
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
extern bool errstart(int elevel, const char *domain);
extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c669948370..0b98f8a972 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -276,14 +276,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
../jkl/mno
(1 row)
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -297,8 +298,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
t
(1 row)
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
has_function_privilege
------------------------
@@ -306,15 +307,15 @@ SELECT has_function_privilege('regress_log_memory',
(1 row)
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
has_function_privilege
------------------------
t
(1 row)
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -323,8 +324,41 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+ FROM regress_log_function;
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
--
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index b57f01f3e9..84327408d8 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: 98e89740e5a816f9ef2b71b1a1b62a9aff23d194
--
2.39.2
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-11 07:22 ` Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: Ashutosh Bapat @ 2023-10-11 07:22 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
Hi,
On Tue, Oct 10, 2023 at 7:00 PM torikoshia <[email protected]> wrote:
> Thanks for your comments!
>
> I tested v30 patch with
> v28-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch which makes
> CFI() call ProcessLogQueryPlanInterrupt() internally, and confirmed that
> very few logging queries failed with v30 patch.
>
> This is a result in line with your prediction.
>
>
> ```
> $ rg -c'ignored request for logging query plan due to lock confilcts'
> postmaster.log
> 8
Like many others I think this feature is useful to debug a long running query.
Sorry for jumping late into this.
I have a few of high level comments
There is a lot of similarity between what this feature does and what
auto explain does. I see the code is also duplicated. There is some
merit in avoiding this duplication
1. we will get all the features of auto_explain automatically like
choosing a format (this was expressed somebody earlier in this
thread), setings etc.
2. avoid bugs. E.g your code switches context after ExplainState has
been allocated. These states may leak depending upon when this
function gets called.
3. Building features on top as James envisions will be easier.
Considering the similarity with auto_explain I wondered whether this
function should be part of auto_explain contrib module itself? If we
do that users will need to load auto_explain extension and thus
install executor hooks when this function doesn't need those. So may
not be such a good idea. I didn't see any discussion on this.
I tried following query to pass PID of a non-client backend to this function.
#select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';
pg_log_query_plan | application_name | backend_type
-------------------+------------------+---------------------
t | | autovacuum launcher
(1 row)
I see "LOG: backend with PID 2733631 is not running a query or a
subtransaction is aborted" in server logs. That's ok. But may be we
should not send signal to these kinds of backends at all, thus
avoiding some system calls.
I am also wondering whether it's better to report the WARNING as
status column in the output. E.g. instead of
#select pg_log_query_plan(100);
WARNING: PID 100 is not a PostgreSQL backend process
pg_log_query_plan
-------------------
f
(1 row)
we output
#select pg_log_query_plan(100);
pg_log_query_plan | status
-------------------+---------------------------------------------
f | PID 100 is not a PostgreSQL backend process
(1 row)
That looks neater and can easily be handled by scripts, applications
and such. But it will be inconsistent with other functions like
pg_terminate_backend() and pg_log_backend_memory_contexts().
I do share a concern that was discussed earlier. If a query is running
longer, there's something problematic with it. A diagnostic
intervention breaking it further would be unwelcome. James has run
experiments to shake this code for any loose breakages. He has not
found any. So may be we are good. And we wouldn't know about very rare
corner cases so easily without using it in the field. So fine with it.
If we could add some safety net that will be great but may not be
necessary for the first cut.
--
Best Wishes,
Ashutosh Bapat
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
@ 2023-10-12 13:21 ` torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: torikoshia @ 2023-10-12 13:21 UTC (permalink / raw)
To: Ashutosh Bapat <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
On 2023-10-11 16:22, Ashutosh Bapat wrote:
> Like many others I think this feature is useful to debug a long running
> query.
>
> Sorry for jumping late into this.
>
> I have a few of high level comments
Thanks for your comments!
> There is a lot of similarity between what this feature does and what
> auto explain does. I see the code is also duplicated. There is some
> merit in avoiding this duplication
> 1. we will get all the features of auto_explain automatically like
> choosing a format (this was expressed somebody earlier in this
> thread), setings etc.
> 2. avoid bugs. E.g your code switches context after ExplainState has
> been allocated. These states may leak depending upon when this
> function gets called.
> 3. Building features on top as James envisions will be easier.
>
> Considering the similarity with auto_explain I wondered whether this
> function should be part of auto_explain contrib module itself? If we
> do that users will need to load auto_explain extension and thus
> install executor hooks when this function doesn't need those. So may
> not be such a good idea. I didn't see any discussion on this.
I once thought about adding this to auto_explain, but I left it asis for
below reasons:
- One of the typical use case of pg_log_query_plan() would be analyzing
slow query on customer environments. On such environments, We cannot
always control what extensions to install.
Of course auto_explain is a major extension and it is quite possible
that they installed auto_explain, but but it is also possible they do
not.
- It seems a bit counter-intuitive that pg_log_query_plan() is in an
extension called auto_explain, since it `manually`` logs plans
> I tried following query to pass PID of a non-client backend to this
> function.
> #select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';
> pg_log_query_plan | application_name | backend_type
> -------------------+------------------+---------------------
> t | | autovacuum launcher
> (1 row)
> I see "LOG: backend with PID 2733631 is not running a query or a
> subtransaction is aborted" in server logs. That's ok. But may be we
> should not send signal to these kinds of backends at all, thus
> avoiding some system calls.
Agreed, it seems better.
Attached patch checks if the backendType of target process is 'client
backend'.
=# select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';
WARNING: PID 63323 is not a PostgreSQL client backend process
pg_log_query_plan | application_name | backend_type
-------------------+------------------+---------------------
f | | autovacuum launcher
> I am also wondering whether it's better to report the WARNING as
> status column in the output. E.g. instead of
> #select pg_log_query_plan(100);
> WARNING: PID 100 is not a PostgreSQL backend process
> pg_log_query_plan
> -------------------
> f
> (1 row)
> we output
> #select pg_log_query_plan(100);
> pg_log_query_plan | status
> -------------------+---------------------------------------------
> f | PID 100 is not a PostgreSQL backend process
> (1 row)
>
> That looks neater and can easily be handled by scripts, applications
> and such. But it will be inconsistent with other functions like
> pg_terminate_backend() and pg_log_backend_memory_contexts().
It seems neater, but it might be inconvenient because we can no longer
use it in select list like the following query as you wrote:
#select pg_log_query_plan(pid), application_name, backend_type from
pg_stat_activity where backend_type = 'autovacuum launcher';
> I do share a concern that was discussed earlier. If a query is running
> longer, there's something problematic with it. A diagnostic
> intervention breaking it further would be unwelcome. James has run
> experiments to shake this code for any loose breakages. He has not
> found any. So may be we are good. And we wouldn't know about very rare
> corner cases so easily without using it in the field. So fine with it.
> If we could add some safety net that will be great but may not be
> necessary for the first cut.
If there are candidates for the safety net, I'm willing to add them.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
Attachments:
[text/x-diff] v31-0001-Add-function-to-log-the-plan-of-the-query.patch (27.7K, ../../[email protected]/2-v31-0001-Add-function-to-log-the-plan-of-the-query.patch)
download | inline diff:
From b7902cf43254450cc7831c235982438ea1e5e8b7 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Thu, 12 Oct 2023 22:03:48 +0900
Subject: [PATCH v31] Add function to log the plan of the query
Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.
By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.
On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.
Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar,
Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby, Kyotaro
Horiguchi, Robert Treat, Alena Rybakina, Ashutosh Bapat
Co-authored-by: James Coleman <[email protected]>
---
doc/src/sgml/func.sgml | 49 +++++
src/backend/access/transam/xact.c | 13 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 188 ++++++++++++++++++-
src/backend/executor/execMain.c | 14 ++
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/storage/lmgr/lock.c | 9 +-
src/backend/tcop/postgres.c | 4 +
src/backend/utils/error/elog.c | 2 +
src/backend/utils/init/globals.c | 2 +
src/include/catalog/pg_proc.dat | 6 +
src/include/commands/explain.h | 4 +
src/include/miscadmin.h | 1 +
src/include/storage/lock.h | 2 -
src/include/storage/procsignal.h | 1 +
src/include/tcop/pquery.h | 2 +-
src/include/utils/elog.h | 1 +
src/test/regress/expected/misc_functions.out | 54 +++++-
src/test/regress/sql/misc_functions.sql | 41 +++-
19 files changed, 371 insertions(+), 28 deletions(-)
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index f1ad64c3d6..b7c7fa9169 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -26308,6 +26308,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
</para></entry>
</row>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>pg_log_query_plan</primary>
+ </indexterm>
+ <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+ <returnvalue>boolean</returnvalue>
+ </para>
+ <para>
+ Requests to log the plan of the query currently running on the
+ backend with specified process ID.
+ It 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"/>
+ for more information), but will not be sent to the client
+ regardless of <xref linkend="guc-client-min-messages"/>.
+ </para></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -26528,6 +26547,36 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+ Query Text: SELECT * FROM pgbench_accounts;
+ Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+ Output: aid, bid, abalance, filler
+ Settings: work_mem = '1MB'
+</screen>
+ Note that when statements are executed inside a function, only the
+ plan of the most deeply nested query is logged.
+ </para>
+
+ <para>
+ When a subtransaction is aborted, <function>pg_log_query_plan</function>
+ cannot log the query plan after the abort.
+ </para>
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 37c5e34cce..a2b0266dd3 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -61,6 +61,7 @@
#include "storage/procarray.h"
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
+#include "tcop/pquery.h"
#include "utils/builtins.h"
#include "utils/catcache.h"
#include "utils/combocid.h"
@@ -2750,6 +2751,12 @@ AbortTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
@@ -5109,6 +5116,12 @@ AbortSubTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 07c0d89c4f..80792913bd 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -722,6 +722,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 13217807ee..7310bb7361 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -21,6 +21,7 @@
#include "executor/nodeHash.h"
#include "foreign/fdwapi.h"
#include "jit/jit.h"
+#include "miscadmin.h"
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
@@ -28,7 +29,10 @@
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
#include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "tcop/pquery.h"
#include "tcop/tcopprot.h"
+#include "utils/backend_status.h"
#include "utils/builtins.h"
#include "utils/guc_tables.h"
#include "utils/json.h"
@@ -1647,6 +1651,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
/*
* We have to forcibly clean up the instrumentation state because we
* haven't done ExecutorEnd yet. This is pretty grotty ...
+ * This cleanup should not be done when the query has already been
+ * executed and explain has been called by signal, as the target query
+ * may use instrumentation and clean itself up.
*
* Note: contrib/auto_explain could cause instrumentation to be set up
* even though we didn't ask for it here. Be careful not to print any
@@ -1654,7 +1661,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
* InstrEndLoop call anyway, if possible, to reduce the number of cases
* auto_explain has to contend with.
*/
- if (planstate->instrument)
+ if (planstate->instrument && !es->signaled)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
@@ -5060,3 +5067,182 @@ escape_yaml(StringInfo buf, const char *str)
{
escape_json(buf, str);
}
+
+/*
+ * HandleLogQueryPlanInterrupt
+ * Handle receipt of an interrupt indicating logging the plan of
+ * the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+ InterruptPending = true;
+ LogQueryPlanPending = true;
+ /* latch will be set by procsignal_sigusr1_handler */
+}
+
+bool ProcessLogQueryPlanInterruptActive = false;
+/*
+ * ProcessLogQueryPlanInterrupt
+ * Perform logging the plan of the currently running query on this
+ * backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange to call
+ * this function if we see LogQueryPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ ExplainState *es;
+ HASH_SEQ_STATUS status;
+ LOCALLOCK *locallock;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+ LogQueryPlanPending = false;
+
+ /* Cannot re-enter. */
+ if (ProcessLogQueryPlanInterruptActive)
+ return;
+
+ ProcessLogQueryPlanInterruptActive = true;
+
+ if (ActiveQueryDesc == NULL)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is not running a query or a subtransaction is aborted",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+
+ /*
+ * Ensure no page lock is held on this process.
+ *
+ * If page lock is held at the time of the interrupt, we can't acquire any
+ * other heavyweight lock, which might be necessary for explaining the plan
+ * when retrieving column names.
+ *
+ * This may be overkill, but since page locks are held for a short duration
+ * we check all the LocalLock entries and when finding even one, give up
+ * logging the plan.
+ */
+ hash_seq_init(&status, GetLockMethodLocalHash());
+ while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL)
+ {
+ if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to page lock confilcts"),
+ errdetail("You can try again in a moment."));
+ hash_seq_term(&status);
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+ }
+
+ /*
+ * Ensure no locks already held on the lockable object.
+ *
+ * Otherwise EXPLAIN can be also hold on it.
+ */
+ if (MyProc->heldLocks)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to lock confilcts"),
+ errdetail("You can try again in a moment."));
+ return;
+ }
+
+ cxt = AllocSetContextCreate(CurrentMemoryContext,
+ "log_query_plan temporary context",
+ ALLOCSET_DEFAULT_SIZES);
+
+ old_cxt = MemoryContextSwitchTo(cxt);
+
+ es = NewExplainState();
+
+ es->format = EXPLAIN_FORMAT_TEXT;
+ es->settings = true;
+ es->verbose = true;
+ es->signaled = true;
+
+ ExplainBeginOutput(es);
+ ExplainQueryText(es, ActiveQueryDesc);
+
+ ExplainPrintPlan(es, ActiveQueryDesc);
+
+ ExplainPrintJITSummary(es, ActiveQueryDesc);
+ ExplainEndOutput(es);
+
+ /* Remove last line break */
+ if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+ es->str->data[--es->str->len] = '\0';
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ MemoryContextSwitchTo(old_cxt);
+ MemoryContextDelete(cxt);
+
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * pg_log_query_plan
+ * Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+ int pid = PG_GETARG_INT32(0);
+ PGPROC *proc;
+ PgBackendStatus *be_status;
+
+ proc = BackendPidGetProc(pid);
+
+ if (proc == NULL)
+ {
+ /*
+ * This is just a warning so a loop-through-resultset will not abort
+ * if one backend terminated on its own during the run.
+ */
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL backend process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ be_status = pgstat_get_beentry_by_backend_id(proc->backendId);
+ if (be_status->st_backendType != B_BACKEND)
+ {
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL client backend process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+ {
+ /* Again, just a warning to allow loops */
+ ereport(WARNING,
+ (errmsg("could not send signal to process %d: %m", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 4c5a7bbf62..4772cb97e7 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -78,6 +78,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
/* Hook for plugin to get control in ExecCheckPermissions() */
ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
/* decls for local routines only used within this module */
static void InitPlan(QueryDesc *queryDesc, int eflags);
static void CheckValidRowMarkRel(Relation rel, RowMarkType markType);
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
+
if (ExecutorRun_hook)
(*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
else
standard_ExecutorRun(queryDesc, direction, count, execute_once);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index b7427906de..ddaf829917 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -20,6 +20,7 @@
#include "access/parallel.h"
#include "port/pg_bitutils.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "replication/logicalworker.h"
@@ -658,6 +659,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
HandleLogMemoryContextInterrupt();
+ if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN))
+ HandleLogQueryPlanInterrupt();
+
if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE))
HandleParallelApplyMessageInterrupt();
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index ec6240fbae..c6eb340d7a 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -602,17 +602,18 @@ LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode)
return (locallock && locallock->nLocks > 0);
}
-#ifdef USE_ASSERT_CHECKING
/*
- * GetLockMethodLocalHash -- return the hash of local locks, for modules that
- * evaluate assertions based on all locks held.
+ * GetLockMethodLocalHash -- return the hash of local locks, mainly for
+ * modules that evaluate assertions based on all locks held.
+ *
+ * NOTE: When there are many entries in LockMethodLocalHash, calling this
+ * function and looking into all of them can lead to performance problems.
*/
HTAB *
GetLockMethodLocalHash(void)
{
return LockMethodLocalHash;
}
-#endif
/*
* LockHasWaiters -- look up 'locktag' and check if releasing this
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f3c9f1f9ba..c6a74df29e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -36,6 +36,7 @@
#include "access/xact.h"
#include "catalog/pg_type.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "commands/prepare.h"
#include "common/pg_prng.h"
#include "jit/jit.h"
@@ -3460,6 +3461,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
HandleParallelApplyMessages();
}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8e1f3e8521..36847c950a 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -513,6 +513,8 @@ errfinish(const char *filename, int lineno, const char *funcname)
econtext = econtext->previous)
econtext->callback(econtext->arg);
+ if (elevel >= ERROR)
+ ProcessLogQueryPlanInterruptActive = false;
/*
* If ERROR (not more nor less) we pass it off to the current handler.
* Printing it and popping the stack is the responsibility of the handler.
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 011ec18015..c451f84e07 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -37,6 +37,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index f0b7b9cbd8..3c5843529f 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8241,6 +8241,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..ccae06a8fd 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,7 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
typedef enum ExplainFormat
{
EXPLAIN_FORMAT_TEXT,
@@ -60,6 +61,7 @@ typedef struct ExplainState
bool hide_workers; /* set if we find an invisible Gather */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool signaled; /* whether explain is called by signal */
} ExplainState;
/* Hook for plugins to get control in ExplainOneQuery() */
@@ -126,4 +128,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
extern void ExplainCloseGroup(const char *objtype, const char *labelname,
bool labeled, ExplainState *es);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index c2f9de63a1..a51283ba9d 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -95,6 +95,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 8575bea25c..63f0454378 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -569,9 +569,7 @@ extern void LockReleaseSession(LOCKMETHODID lockmethodid);
extern void LockReleaseCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern void LockReassignCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern bool LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode);
-#ifdef USE_ASSERT_CHECKING
extern HTAB *GetLockMethodLocalHash(void);
-#endif
extern bool LockHasWaiters(const LOCKTAG *locktag,
LOCKMODE lockmode, bool sessionLock);
extern VirtualTransactionId *GetLockConflicts(const LOCKTAG *locktag,
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index 3a3a7eca77..b5d2a1be28 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index a5e65b98aa..a6ae947a0f 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,7 +21,7 @@ struct PlannedStmt; /* avoid including plannodes.h here */
extern PGDLLIMPORT Portal ActivePortal;
-
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
extern PortalStrategy ChoosePortalStrategy(List *stmts);
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 4a9562fdaa..6b03682934 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
extern bool message_level_is_interesting(int elevel);
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
extern bool errstart(int elevel, const char *domain);
extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c669948370..0b98f8a972 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -276,14 +276,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
../jkl/mno
(1 row)
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -297,8 +298,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
t
(1 row)
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
has_function_privilege
------------------------
@@ -306,15 +307,15 @@ SELECT has_function_privilege('regress_log_memory',
(1 row)
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
has_function_privilege
------------------------
t
(1 row)
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -323,8 +324,41 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+ FROM regress_log_function;
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
--
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index b57f01f3e9..84327408d8 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: f0c409d9c7a6a92bb4a6b5812ffc5ef94b4c8ed0
--
2.39.2
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-16 09:46 ` Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: Ashutosh Bapat @ 2023-10-16 09:46 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
On Thu, Oct 12, 2023 at 6:51 PM torikoshia <[email protected]> wrote:
>
> On 2023-10-11 16:22, Ashutosh Bapat wrote:
> >
> > Considering the similarity with auto_explain I wondered whether this
> > function should be part of auto_explain contrib module itself? If we
> > do that users will need to load auto_explain extension and thus
> > install executor hooks when this function doesn't need those. So may
> > not be such a good idea. I didn't see any discussion on this.
>
> I once thought about adding this to auto_explain, but I left it asis for
> below reasons:
>
> - One of the typical use case of pg_log_query_plan() would be analyzing
> slow query on customer environments. On such environments, We cannot
> always control what extensions to install.
The same argument applies to auto_explain functionality as well. But
it's not part of the core.
> Of course auto_explain is a major extension and it is quite possible
> that they installed auto_explain, but but it is also possible they do
> not.
> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
> extension called auto_explain, since it `manually`` logs plans
>
pg_log_query_plan() may not fit auto_explain but
pg_explain_backend_query() does. What we are logging is more than just
plan of the query, it might expand to be closer to explain output.
While auto in auto_explain would refer to its automatically logging
explain outputs, it can provide an additional function which provides
similar functionality by manually triggering it.
But we can defer this to a committer, if you want.
I am more interested in avoiding the duplication of code, esp. the
first comment in my reply
>> There is a lot of similarity between what this feature does and what
>> auto explain does. I see the code is also duplicated. There is some
>> merit in avoiding this duplication
>> 1. we will get all the features of auto_explain automatically like
>> choosing a format (this was expressed somebody earlier in this
>> thread), setings etc.
>> 2. avoid bugs. E.g your code switches context after ExplainState has
>> been allocated. These states may leak depending upon when this
>> function gets called.
>> 3. Building features on top as James envisions will be easier.
>
> =# select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';
> WARNING: PID 63323 is not a PostgreSQL client backend process
> pg_log_query_plan | application_name | backend_type
> -------------------+------------------+---------------------
> f | | autovacuum launcher
>
>
> > I am also wondering whether it's better to report the WARNING as
> > status column in the output. E.g. instead of
> > #select pg_log_query_plan(100);
> > WARNING: PID 100 is not a PostgreSQL backend process
> > pg_log_query_plan
> > -------------------
> > f
> > (1 row)
> > we output
> > #select pg_log_query_plan(100);
> > pg_log_query_plan | status
> > -------------------+---------------------------------------------
> > f | PID 100 is not a PostgreSQL backend process
> > (1 row)
> >
> > That looks neater and can easily be handled by scripts, applications
> > and such. But it will be inconsistent with other functions like
> > pg_terminate_backend() and pg_log_backend_memory_contexts().
>
> It seems neater, but it might be inconvenient because we can no longer
> use it in select list like the following query as you wrote:
>
> #select pg_log_query_plan(pid), application_name, backend_type from
> pg_stat_activity where backend_type = 'autovacuum launcher';
Why is that?
--
Best Wishes,
Ashutosh Bapat
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
@ 2023-10-18 06:09 ` torikoshia <[email protected]>
2023-10-18 10:13 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 16:34 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-24 07:12 ` Re: RFC: Logging plan of the running query Étienne BERSAC <[email protected]>
0 siblings, 3 replies; 25+ messages in thread
From: torikoshia @ 2023-10-18 06:09 UTC (permalink / raw)
To: Ashutosh Bapat <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
On 2023-10-16 18:46, Ashutosh Bapat wrote:
> On Thu, Oct 12, 2023 at 6:51 PM torikoshia <[email protected]>
> wrote:
>>
>> On 2023-10-11 16:22, Ashutosh Bapat wrote:
>> >
>> > Considering the similarity with auto_explain I wondered whether this
>> > function should be part of auto_explain contrib module itself? If we
>> > do that users will need to load auto_explain extension and thus
>> > install executor hooks when this function doesn't need those. So may
>> > not be such a good idea. I didn't see any discussion on this.
>>
>> I once thought about adding this to auto_explain, but I left it asis
>> for
>> below reasons:
>>
>> - One of the typical use case of pg_log_query_plan() would be
>> analyzing
>> slow query on customer environments. On such environments, We cannot
>> always control what extensions to install.
>
> The same argument applies to auto_explain functionality as well. But
> it's not part of the core.
Yeah, and when we have a situation where we want to run
pg_log_query_plan(), we can run it in any environment as long as it is
bundled with the core.
On the other hand, if it is built into auto_explain, we need to start by
installing auto_explain if we do not have auto_explain, which is often
difficult to do in production environments.
>> Of course auto_explain is a major extension and it is quite
>> possible
>> that they installed auto_explain, but but it is also possible they do
>> not.
>> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
>> extension called auto_explain, since it `manually`` logs plans
>>
>
> pg_log_query_plan() may not fit auto_explain but
> pg_explain_backend_query() does. What we are logging is more than just
> plan of the query, it might expand to be closer to explain output.
> While auto in auto_explain would refer to its automatically logging
> explain outputs, it can provide an additional function which provides
> similar functionality by manually triggering it.
>
> But we can defer this to a committer, if you want.
>
> I am more interested in avoiding the duplication of code, esp. the
> first comment in my reply
If there are no objections, I will try porting it to auto_explain and
see its feasibility.
>>> There is a lot of similarity between what this feature does and what
>>> auto explain does. I see the code is also duplicated. There is some
>>> merit in avoiding this duplication
>>> 1. we will get all the features of auto_explain automatically like
>>> choosing a format (this was expressed somebody earlier in this
>>> thread), setings etc.
>>> 2. avoid bugs. E.g your code switches context after ExplainState has
>>> been allocated. These states may leak depending upon when this
>>> function gets called.
>>> 3. Building features on top as James envisions will be easier.
>
>>
>> =# select pg_log_query_plan(pid), application_name, backend_type
>> from
>> pg_stat_activity where backend_type = 'autovacuum launcher';
>> WARNING: PID 63323 is not a PostgreSQL client backend process
>> pg_log_query_plan | application_name | backend_type
>> -------------------+------------------+---------------------
>> f | | autovacuum launcher
>>
>>
>> > I am also wondering whether it's better to report the WARNING as
>> > status column in the output. E.g. instead of
>> > #select pg_log_query_plan(100);
>> > WARNING: PID 100 is not a PostgreSQL backend process
>> > pg_log_query_plan
>> > -------------------
>> > f
>> > (1 row)
>> > we output
>> > #select pg_log_query_plan(100);
>> > pg_log_query_plan | status
>> > -------------------+---------------------------------------------
>> > f | PID 100 is not a PostgreSQL backend process
>> > (1 row)
>> >
>> > That looks neater and can easily be handled by scripts, applications
>> > and such. But it will be inconsistent with other functions like
>> > pg_terminate_backend() and pg_log_backend_memory_contexts().
>>
>> It seems neater, but it might be inconvenient because we can no longer
>> use it in select list like the following query as you wrote:
>>
>> #select pg_log_query_plan(pid), application_name, backend_type from
>> pg_stat_activity where backend_type = 'autovacuum launcher';
>
> Why is that?
Sorry, I misunderstood and confirmed we can run queries like below:
```
=# CREATE OR REPLACE FUNCTION pg_log_query_plan_stab(i int)
RETURNS TABLE(
pg_log_query_plan bool,
status text
) AS $$
DECLARE
BEGIN
RETURN QUERY SELECT false::bool, 'PID 100 is not a PostgreSQL
backend process'::text; END;
$$ LANGUAGE plpgsql;
=# select pg_log_query_plan_stab(pid), application_name, backend_type
from pg_stat_activity where backend_type = 'autovacuum launcher';
pg_log_query_plan_stab | application_name |
backend_type
---------------------------------------------------+------------------+---------------------
(f,"PID 100 is not a PostgreSQL backend process") | |
autovacuum launcher
```
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-18 10:13 ` Ashutosh Bapat <[email protected]>
2 siblings, 0 replies; 25+ messages in thread
From: Ashutosh Bapat @ 2023-10-18 10:13 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
On Wed, Oct 18, 2023 at 11:39 AM torikoshia <[email protected]> wrote:
> >
> > I am more interested in avoiding the duplication of code, esp. the
> > first comment in my reply
>
> If there are no objections, I will try porting it to auto_explain and
> see its feasibility.
If you want it in core, you will need to port relevant parts of
auto_explain code to core.
--
Best Wishes,
Ashutosh Bapat
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-18 16:34 ` James Coleman <[email protected]>
2023-10-25 03:40 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2 siblings, 1 reply; 25+ messages in thread
From: James Coleman @ 2023-10-18 16:34 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: Ashutosh Bapat <[email protected]>; Andres Freund <[email protected]>; [email protected]
On Wed, Oct 18, 2023 at 2:09 AM torikoshia <[email protected]> wrote:
>
> On 2023-10-16 18:46, Ashutosh Bapat wrote:
> > On Thu, Oct 12, 2023 at 6:51 PM torikoshia <[email protected]>
> > wrote:
> >>
> >> On 2023-10-11 16:22, Ashutosh Bapat wrote:
> >> >
> >> > Considering the similarity with auto_explain I wondered whether this
> >> > function should be part of auto_explain contrib module itself? If we
> >> > do that users will need to load auto_explain extension and thus
> >> > install executor hooks when this function doesn't need those. So may
> >> > not be such a good idea. I didn't see any discussion on this.
> >>
> >> I once thought about adding this to auto_explain, but I left it asis
> >> for
> >> below reasons:
> >>
> >> - One of the typical use case of pg_log_query_plan() would be
> >> analyzing
> >> slow query on customer environments. On such environments, We cannot
> >> always control what extensions to install.
> >
> > The same argument applies to auto_explain functionality as well. But
> > it's not part of the core.
>
> Yeah, and when we have a situation where we want to run
> pg_log_query_plan(), we can run it in any environment as long as it is
> bundled with the core.
> On the other hand, if it is built into auto_explain, we need to start by
> installing auto_explain if we do not have auto_explain, which is often
> difficult to do in production environments.
>
> >> Of course auto_explain is a major extension and it is quite
> >> possible
> >> that they installed auto_explain, but but it is also possible they do
> >> not.
> >> - It seems a bit counter-intuitive that pg_log_query_plan() is in an
> >> extension called auto_explain, since it `manually`` logs plans
> >>
> >
> > pg_log_query_plan() may not fit auto_explain but
> > pg_explain_backend_query() does. What we are logging is more than just
> > plan of the query, it might expand to be closer to explain output.
> > While auto in auto_explain would refer to its automatically logging
> > explain outputs, it can provide an additional function which provides
> > similar functionality by manually triggering it.
> >
> > But we can defer this to a committer, if you want.
> >
> > I am more interested in avoiding the duplication of code, esp. the
> > first comment in my reply
>
> If there are no objections, I will try porting it to auto_explain and
> see its feasibility.
>
> >>> There is a lot of similarity between what this feature does and what
> >>> auto explain does. I see the code is also duplicated. There is some
> >>> merit in avoiding this duplication
> >>> 1. we will get all the features of auto_explain automatically like
> >>> choosing a format (this was expressed somebody earlier in this
> >>> thread), setings etc.
> >>> 2. avoid bugs. E.g your code switches context after ExplainState has
> >>> been allocated. These states may leak depending upon when this
> >>> function gets called.
> >>> 3. Building features on top as James envisions will be easier.
In my view the fact that auto_explain is itself not part of core is a
mistake, and I know there are more prominent hackers than myself who
hold that view.
While that decision as regards auto_explain has long since been made
(and there would be work to undo it), I don't believe that we should
repeat that choice here. I'm -10 on moving this into auto_explain.
However perhaps there is still an opportunity for moving some of the
auto_explain code into core so as to enable deduplicating the code.
Regards,
James Coleman
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-18 16:34 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
@ 2023-10-25 03:40 ` Ashutosh Bapat <[email protected]>
2023-10-26 06:53 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 25+ messages in thread
From: Ashutosh Bapat @ 2023-10-25 03:40 UTC (permalink / raw)
To: James Coleman <[email protected]>; +Cc: torikoshia <[email protected]>; Andres Freund <[email protected]>; [email protected]
On Wed, Oct 18, 2023 at 10:04 PM James Coleman <[email protected]> wrote:
>
> While that decision as regards auto_explain has long since been made
> (and there would be work to undo it), I don't believe that we should
> repeat that choice here. I'm -10 on moving this into auto_explain.
>
Right.
> However perhaps there is still an opportunity for moving some of the
> auto_explain code into core so as to enable deduplicating the code.
>
Right. That's what I also think.
--
Best Wishes,
Ashutosh Bapat
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-18 16:34 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-25 03:40 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
@ 2023-10-26 06:53 ` torikoshia <[email protected]>
0 siblings, 0 replies; 25+ messages in thread
From: torikoshia @ 2023-10-26 06:53 UTC (permalink / raw)
To: Ashutosh Bapat <[email protected]>; +Cc: James Coleman <[email protected]>; Andres Freund <[email protected]>; [email protected]
On 2023-10-25 12:40, Ashutosh Bapat wrote:
> On Wed, Oct 18, 2023 at 10:04 PM James Coleman <[email protected]>
> wrote:
>>
>> While that decision as regards auto_explain has long since been made
>> (and there would be work to undo it), I don't believe that we should
>> repeat that choice here. I'm -10 on moving this into auto_explain.
>>
>
> Right.
>
>> However perhaps there is still an opportunity for moving some of the
>> auto_explain code into core so as to enable deduplicating the code.
>>
>
> Right. That's what I also think.
Thanks for your comments.
Attached patch adds a new function which assembles es->str for logging
according to specified contents and format.
This is called from both auto_explain and pg_log_query_plan().
On 2023-10-11 16:22, Ashutosh Bapat wrote:
> I am also wondering whether it's better to report the WARNING as
> status column in the output.
Attached patch left as it was since the inconsistency with
pg_terminate_backend() and pg_log_backend_memory_contexts() as you
pointed out.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
Attachments:
[text/x-diff] v32-0001-Add-function-to-log-the-plan-of-the-query.patch (30.3K, ../../[email protected]/2-v32-0001-Add-function-to-log-the-plan-of-the-query.patch)
download | inline diff:
From 336ba3943f631dcbc0d1226ebd0a7675cf78c1f8 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Thu, 26 Oct 2023 15:42:36 +0900
Subject: [PATCH v32] Add function to log the plan of the query
Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.
By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.
On receipt of the request, at the next CHECK_FOR_INTERRUPTS(),
the target backend logs its plan at LOG_SERVER_ONLY level, so
that these plans will appear in the server log but not be sent
to the client.
Reviewed-by: Bharath Rupireddy, Fujii Masao, Dilip Kumar,
Masahiro Ikeda, Ekaterina Sokolova, Justin Pryzby, Kyotaro
Horiguchi, Robert Treat, Alena Rybakina, Ashutosh Bapat
Co-authored-by: James Coleman <[email protected]>
---
contrib/auto_explain/auto_explain.c | 23 +-
doc/src/sgml/func.sgml | 49 +++++
src/backend/access/transam/xact.c | 13 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 209 ++++++++++++++++++-
src/backend/executor/execMain.c | 14 ++
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/storage/lmgr/lock.c | 9 +-
src/backend/tcop/postgres.c | 4 +
src/backend/utils/error/elog.c | 2 +
src/backend/utils/init/globals.c | 2 +
src/include/catalog/pg_proc.dat | 6 +
src/include/commands/explain.h | 8 +
src/include/miscadmin.h | 1 +
src/include/storage/lock.h | 2 -
src/include/storage/procsignal.h | 1 +
src/include/tcop/pquery.h | 2 +-
src/include/utils/elog.h | 1 +
src/test/regress/expected/misc_functions.out | 54 ++++-
src/test/regress/sql/misc_functions.sql | 41 +++-
20 files changed, 399 insertions(+), 48 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c3ac27ae99..20a73df8c4 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -399,26 +399,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es->format = auto_explain_log_format;
es->settings = auto_explain_log_settings;
- ExplainBeginOutput(es);
- ExplainQueryText(es, queryDesc);
- ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
- ExplainPrintPlan(es, queryDesc);
- if (es->analyze && auto_explain_log_triggers)
- ExplainPrintTriggers(es, queryDesc);
- if (es->costs)
- ExplainPrintJITSummary(es, queryDesc);
- ExplainEndOutput(es);
-
- /* Remove last line break */
- if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
- es->str->data[--es->str->len] = '\0';
-
- /* Fix JSON to output an object */
- if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
- {
- es->str->data[0] = '{';
- es->str->data[es->str->len - 1] = '}';
- }
+ ExplainAssembleLogOutput(es, queryDesc, auto_explain_log_format,
+ auto_explain_log_triggers,
+ auto_explain_log_parameter_max_length);
/*
* Note: we rely on the existing logging of context or
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 7c3e940afe..8d77fe1a5b 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -26406,6 +26406,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
</para></entry>
</row>
+ <row>
+ <entry role="func_table_entry"><para role="func_signature">
+ <indexterm>
+ <primary>pg_log_query_plan</primary>
+ </indexterm>
+ <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+ <returnvalue>boolean</returnvalue>
+ </para>
+ <para>
+ Requests to log the plan of the query currently running on the
+ backend with specified process ID.
+ It 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"/>
+ for more information), but will not be sent to the client
+ regardless of <xref linkend="guc-client-min-messages"/>.
+ </para></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -26626,6 +26645,36 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+ Query Text: SELECT * FROM pgbench_accounts;
+ Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+ Output: aid, bid, abalance, filler
+ Settings: work_mem = '1MB'
+</screen>
+ Note that when statements are executed inside a function, only the
+ plan of the most deeply nested query is logged.
+ </para>
+
+ <para>
+ When a subtransaction is aborted, <function>pg_log_query_plan</function>
+ cannot log the query plan after the abort.
+ </para>
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 37c5e34cce..a2b0266dd3 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -61,6 +61,7 @@
#include "storage/procarray.h"
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
+#include "tcop/pquery.h"
#include "utils/builtins.h"
#include "utils/catcache.h"
#include "utils/combocid.h"
@@ -2750,6 +2751,12 @@ AbortTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
@@ -5109,6 +5116,12 @@ AbortSubTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+
/*
* check the current transaction state
*/
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 35d738d576..e42db525dc 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -742,6 +742,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f1d71bc54e..db2fcbd5cf 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -21,6 +21,7 @@
#include "executor/nodeHash.h"
#include "foreign/fdwapi.h"
#include "jit/jit.h"
+#include "miscadmin.h"
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
@@ -28,7 +29,10 @@
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
#include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "tcop/pquery.h"
#include "tcop/tcopprot.h"
+#include "utils/backend_status.h"
#include "utils/builtins.h"
#include "utils/guc_tables.h"
#include "utils/json.h"
@@ -737,6 +741,37 @@ ExplainPrintSettings(ExplainState *es)
}
}
+/*
+ * ExplainAssembleLogOutput -
+ * Assemble es->str for logging according to specified contents and format
+ */
+
+void
+ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc, int logFormat,
+ bool logTriggers, int logParameterMaxLength)
+{
+ ExplainBeginOutput(es);
+ ExplainQueryText(es, queryDesc);
+ ExplainQueryParameters(es, queryDesc->params, logParameterMaxLength);
+ ExplainPrintPlan(es, queryDesc);
+ if (es->analyze && logTriggers)
+ ExplainPrintTriggers(es, queryDesc);
+ if (es->costs)
+ ExplainPrintJITSummary(es, queryDesc);
+ ExplainEndOutput(es);
+
+ /* Remove last line break */
+ if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+ es->str->data[--es->str->len] = '\0';
+
+ /* Fix JSON to output an object */
+ if (logFormat == EXPLAIN_FORMAT_JSON)
+ {
+ es->str->data[0] = '{';
+ es->str->data[es->str->len - 1] = '}';
+ }
+}
+
/*
* ExplainPrintPlan -
* convert a QueryDesc's plan tree to text and append it to es->str
@@ -1647,6 +1682,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
/*
* We have to forcibly clean up the instrumentation state because we
* haven't done ExecutorEnd yet. This is pretty grotty ...
+ * This cleanup should not be done when the query has already been
+ * executed and explain has been called by signal, as the target query
+ * may use instrumentation and clean itself up.
*
* Note: contrib/auto_explain could cause instrumentation to be set up
* even though we didn't ask for it here. Be careful not to print any
@@ -1654,7 +1692,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
* InstrEndLoop call anyway, if possible, to reduce the number of cases
* auto_explain has to contend with.
*/
- if (planstate->instrument)
+ if (planstate->instrument && !es->signaled)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
@@ -5082,3 +5120,172 @@ escape_yaml(StringInfo buf, const char *str)
{
escape_json(buf, str);
}
+
+/*
+ * HandleLogQueryPlanInterrupt
+ * Handle receipt of an interrupt indicating logging the plan of
+ * the currently running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+ InterruptPending = true;
+ LogQueryPlanPending = true;
+ /* latch will be set by procsignal_sigusr1_handler */
+}
+
+bool ProcessLogQueryPlanInterruptActive = false;
+/*
+ * ProcessLogQueryPlanInterrupt
+ * Perform logging the plan of the currently running query on this
+ * backend process.
+ *
+ * Any backend that participates in ProcSignal signaling must arrange to call
+ * this function if we see LogQueryPlanPending set.
+ * It is called from CHECK_FOR_INTERRUPTS(), which is enough because the target
+ * process for logging plan is a backend.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ ExplainState *es;
+ HASH_SEQ_STATUS status;
+ LOCALLOCK *locallock;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+ LogQueryPlanPending = false;
+
+ /* Cannot re-enter. */
+ if (ProcessLogQueryPlanInterruptActive)
+ return;
+
+ ProcessLogQueryPlanInterruptActive = true;
+
+ if (ActiveQueryDesc == NULL)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is not running a query or a subtransaction is aborted",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+
+ /*
+ * Ensure no page lock is held on this process.
+ *
+ * If page lock is held at the time of the interrupt, we can't acquire any
+ * other heavyweight lock, which might be necessary for explaining the plan
+ * when retrieving column names.
+ *
+ * This may be overkill, but since page locks are held for a short duration
+ * we check all the LocalLock entries and when finding even one, give up
+ * logging the plan.
+ */
+ hash_seq_init(&status, GetLockMethodLocalHash());
+ while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL)
+ {
+ if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to page lock confilcts"),
+ errdetail("You can try again in a moment."));
+ hash_seq_term(&status);
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+ }
+
+ /*
+ * Ensure no locks already held on the lockable object.
+ *
+ * Otherwise EXPLAIN can be also hold on it.
+ */
+ if (MyProc->heldLocks)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("ignored request for logging query plan due to lock confilcts"),
+ errdetail("You can try again in a moment."));
+ return;
+ }
+
+ cxt = AllocSetContextCreate(CurrentMemoryContext,
+ "log_query_plan temporary context",
+ ALLOCSET_DEFAULT_SIZES);
+
+ old_cxt = MemoryContextSwitchTo(cxt);
+
+ es = NewExplainState();
+
+ es->format = EXPLAIN_FORMAT_TEXT;
+ es->settings = true;
+ es->verbose = true;
+ es->signaled = true;
+
+ ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1);
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ MemoryContextSwitchTo(old_cxt);
+ MemoryContextDelete(cxt);
+
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * pg_log_query_plan
+ * Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+ int pid = PG_GETARG_INT32(0);
+ PGPROC *proc;
+ PgBackendStatus *be_status;
+
+ proc = BackendPidGetProc(pid);
+
+ if (proc == NULL)
+ {
+ /*
+ * This is just a warning so a loop-through-resultset will not abort
+ * if one backend terminated on its own during the run.
+ */
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL backend process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ be_status = pgstat_get_beentry_by_backend_id(proc->backendId);
+ if (be_status->st_backendType != B_BACKEND)
+ {
+ ereport(WARNING,
+ (errmsg("PID %d is not a PostgreSQL client backend process", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->backendId) < 0)
+ {
+ /* Again, just a warning to allow loops */
+ ereport(WARNING,
+ (errmsg("could not send signal to process %d: %m", pid)));
+ PG_RETURN_BOOL(false);
+ }
+
+ PG_RETURN_BOOL(true);
+}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 4c5a7bbf62..4772cb97e7 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -78,6 +78,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
/* Hook for plugin to get control in ExecCheckPermissions() */
ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
/* decls for local routines only used within this module */
static void InitPlan(QueryDesc *queryDesc, int eflags);
static void CheckValidRowMarkRel(Relation rel, RowMarkType markType);
@@ -303,10 +306,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
+
if (ExecutorRun_hook)
(*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
else
standard_ExecutorRun(queryDesc, direction, count, execute_once);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index b7427906de..ddaf829917 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -20,6 +20,7 @@
#include "access/parallel.h"
#include "port/pg_bitutils.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "replication/logicalworker.h"
@@ -658,6 +659,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
HandleLogMemoryContextInterrupt();
+ if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN))
+ HandleLogQueryPlanInterrupt();
+
if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE))
HandleParallelApplyMessageInterrupt();
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index ec6240fbae..c6eb340d7a 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -602,17 +602,18 @@ LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode)
return (locallock && locallock->nLocks > 0);
}
-#ifdef USE_ASSERT_CHECKING
/*
- * GetLockMethodLocalHash -- return the hash of local locks, for modules that
- * evaluate assertions based on all locks held.
+ * GetLockMethodLocalHash -- return the hash of local locks, mainly for
+ * modules that evaluate assertions based on all locks held.
+ *
+ * NOTE: When there are many entries in LockMethodLocalHash, calling this
+ * function and looking into all of them can lead to performance problems.
*/
HTAB *
GetLockMethodLocalHash(void)
{
return LockMethodLocalHash;
}
-#endif
/*
* LockHasWaiters -- look up 'locktag' and check if releasing this
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 6a070b5d8c..320c0148b4 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -37,6 +37,7 @@
#include "catalog/pg_type.h"
#include "commands/async.h"
#include "commands/event_trigger.h"
+#include "commands/explain.h"
#include "commands/prepare.h"
#include "common/pg_prng.h"
#include "jit/jit.h"
@@ -3457,6 +3458,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
HandleParallelApplyMessages();
}
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index eeb238331e..63b99dafa5 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -513,6 +513,8 @@ errfinish(const char *filename, int lineno, const char *funcname)
econtext = econtext->previous)
econtext->callback(econtext->arg);
+ if (elevel >= ERROR)
+ ProcessLogQueryPlanInterruptActive = false;
/*
* If ERROR (not more nor less) we pass it off to the current handler.
* Printing it and popping the stack is the responsibility of the handler.
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 60bc1217fb..fee49243a6 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -37,6 +37,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 06435e8b92..7002a71792 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8250,6 +8250,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..99358222ae 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,7 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
typedef enum ExplainFormat
{
EXPLAIN_FORMAT_TEXT,
@@ -60,6 +61,7 @@ typedef struct ExplainState
bool hide_workers; /* set if we find an invisible Gather */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool signaled; /* whether explain is called by signal */
} ExplainState;
/* Hook for plugins to get control in ExplainOneQuery() */
@@ -94,6 +96,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
const instr_time *planduration,
const BufferUsage *bufusage);
+extern void ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc,
+ int logFormat, bool logTriggers,
+ int logParameterMaxLength);
+
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
@@ -126,4 +132,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
extern void ExplainCloseGroup(const char *objtype, const char *labelname,
bool labeled, ExplainState *es);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 7232b03e37..9258640ac4 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -95,6 +95,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 8575bea25c..63f0454378 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -569,9 +569,7 @@ extern void LockReleaseSession(LOCKMETHODID lockmethodid);
extern void LockReleaseCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern void LockReassignCurrentOwner(LOCALLOCK **locallocks, int nlocks);
extern bool LockHeldByMe(const LOCKTAG *locktag, LOCKMODE lockmode);
-#ifdef USE_ASSERT_CHECKING
extern HTAB *GetLockMethodLocalHash(void);
-#endif
extern bool LockHasWaiters(const LOCKTAG *locktag,
LOCKMODE lockmode, bool sessionLock);
extern VirtualTransactionId *GetLockConflicts(const LOCKTAG *locktag,
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index 3a3a7eca77..b5d2a1be28 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index a5e65b98aa..a6ae947a0f 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,7 +21,7 @@ struct PlannedStmt; /* avoid including plannodes.h here */
extern PGDLLIMPORT Portal ActivePortal;
-
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
extern PortalStrategy ChoosePortalStrategy(List *stmts);
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 0292e88b4f..1e35f57a3e 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
extern bool message_level_is_interesting(int elevel);
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
extern bool errstart(int elevel, const char *domain);
extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c669948370..0b98f8a972 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -276,14 +276,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
../jkl/mno
(1 row)
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -297,8 +298,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
t
(1 row)
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
has_function_privilege
------------------------
@@ -306,15 +307,15 @@ SELECT has_function_privilege('regress_log_memory',
(1 row)
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
has_function_privilege
------------------------
t
(1 row)
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -323,8 +324,41 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+ FROM regress_log_function;
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
--
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index b57f01f3e9..84327408d8 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: f0efa5aec19358e2282d4968a03db1db56f0ac3f
--
2.39.2
^ permalink raw reply [nested|flat] 25+ messages in thread
* Re: RFC: Logging plan of the running query
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2023-10-24 07:12 ` Étienne BERSAC <[email protected]>
2 siblings, 0 replies; 25+ messages in thread
From: Étienne BERSAC @ 2023-10-24 07:12 UTC (permalink / raw)
To: torikoshia <[email protected]>; Ashutosh Bapat <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]
> Hi,
>
> Yeah, and when we have a situation where we want to run
> pg_log_query_plan(), we can run it in any environment as long as it
> is bundled with the core.
Is it possible to get the plan of a backend programmatically without
access to the logs?
Something like pg_get_query_plan(pid, format) which output would be the
same as EXPLAIN.
Regards,
Étienne BERSAC
Dalibo
^ permalink raw reply [nested|flat] 25+ messages in thread
end of thread, other threads:[~2023-10-26 06:53 UTC | newest]
Thread overview: 25+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-12-18 20:58 [PATCH 2/4] psql: add convenience commands: \dA+ and \dn+ Justin Pryzby <[email protected]>
2023-09-05 13:58 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-06 02:17 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-09-07 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-15 06:21 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-19 13:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-20 05:39 ` Re: RFC: Logging plan of the running query Lepikhov Andrei <[email protected]>
2023-09-25 07:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-25 09:49 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
2023-09-28 02:04 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-09-28 02:32 ` Re: RFC: Logging plan of the running query Andrey Lepikhov <[email protected]>
2023-10-03 18:00 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 12:58 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-06 13:10 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-06 15:58 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2023-10-10 13:27 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-11 07:22 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-12 13:21 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-16 09:46 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 06:09 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-18 10:13 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-18 16:34 ` Re: RFC: Logging plan of the running query James Coleman <[email protected]>
2023-10-25 03:40 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]>
2023-10-26 06:53 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2023-10-24 07:12 ` Re: RFC: Logging plan of the running query Étienne BERSAC <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox