public inbox for [email protected]help / color / mirror / Atom feed
[PATCH v5 2/8] amcheck: Fix FullTransactionIdFromXidAndCtx() for xids before epoch 0 30+ messages / 7 participants [nested] [flat]
* [PATCH v5 2/8] amcheck: Fix FullTransactionIdFromXidAndCtx() for xids before epoch 0 @ 2023-03-08 19:57 Andres Freund <[email protected]> 0 siblings, 0 replies; 30+ messages in thread From: Andres Freund @ 2023-03-08 19:57 UTC (permalink / raw) 64bit xids can't represent xids before epoch 0 (see also be504a3e974). When FullTransactionIdFromXidAndCtx() was passed such an xid, it'd create a 64bit xid far into the future. Noticed while adding assertions in the course of investigating be504a3e974, as amcheck's test create such xids. To fix the issue, just return FirstNormalFullTransactionId in this case. A freshly initdb'd cluster already has a newer horizon. The most minimal version of this would make the messages for some detected corruptions differently inaccurate. To make those cases accurate, switch FullTransactionIdFromXidAndCtx() to use the 32bit modulo difference between xid and nextxid to compute the 64bit xid, yielding sensible "in the future" / "in the past" answers. Discussion: https://postgr.es/m/[email protected] Backpatch: 14-, where heapam verification was introduced --- src/bin/pg_amcheck/t/004_verify_heapam.pl | 28 +++++++++++++------ contrib/amcheck/verify_heapam.c | 33 +++++++++++++++++++---- 2 files changed, 48 insertions(+), 13 deletions(-) diff --git a/src/bin/pg_amcheck/t/004_verify_heapam.pl b/src/bin/pg_amcheck/t/004_verify_heapam.pl index 215c30eaa8e..9984d0d9f87 100644 --- a/src/bin/pg_amcheck/t/004_verify_heapam.pl +++ b/src/bin/pg_amcheck/t/004_verify_heapam.pl @@ -217,7 +217,7 @@ my $rel = $node->safe_psql('postgres', my $relpath = "$pgdata/$rel"; # Insert data and freeze public.test -use constant ROWCOUNT => 16; +use constant ROWCOUNT => 17; $node->safe_psql( 'postgres', qq( INSERT INTO public.test (a, b, c) @@ -378,23 +378,24 @@ for (my $tupidx = 0; $tupidx < ROWCOUNT; $tupidx++) elsif ($offnum == 3) { # Corruptly set xmin < datfrozenxid, further back, noting circularity - # of xid comparison. For a new cluster with epoch = 0, the corrupt - # xmin will be interpreted as in the future - $tup->{t_xmin} = 4026531839; + # of xid comparison. + my $xmin = 4026531839; + $tup->{t_xmin} = $xmin; $tup->{t_infomask} &= ~HEAP_XMIN_COMMITTED; $tup->{t_infomask} &= ~HEAP_XMIN_INVALID; push @expected, - qr/${$header}xmin 4026531839 equals or exceeds next valid transaction ID 0:\d+/; + qr/${$header}xmin ${xmin} precedes oldest valid transaction ID 0:\d+/; } elsif ($offnum == 4) { # Corruptly set xmax < relminmxid; - $tup->{t_xmax} = 4026531839; + my $xmax = 4026531839; + $tup->{t_xmax} = $xmax; $tup->{t_infomask} &= ~HEAP_XMAX_INVALID; push @expected, - qr/${$header}xmax 4026531839 equals or exceeds next valid transaction ID 0:\d+/; + qr/${$header}xmax ${xmax} precedes oldest valid transaction ID 0:\d+/; } elsif ($offnum == 5) { @@ -502,7 +503,7 @@ for (my $tupidx = 0; $tupidx < ROWCOUNT; $tupidx++) push @expected, qr/${header}multitransaction ID 4 equals or exceeds next valid multitransaction ID 1/; } - elsif ($offnum == 15) # Last offnum must equal ROWCOUNT + elsif ($offnum == 15) { # Set both HEAP_XMAX_COMMITTED and HEAP_XMAX_IS_MULTI $tup->{t_infomask} |= HEAP_XMAX_COMMITTED; @@ -512,6 +513,17 @@ for (my $tupidx = 0; $tupidx < ROWCOUNT; $tupidx++) push @expected, qr/${header}multitransaction ID 4000000000 precedes relation minimum multitransaction ID threshold 1/; } + elsif ($offnum == 16) # Last offnum must equal ROWCOUNT + { + # Corruptly set xmin > next_xid to be in the future. + my $xmin = 123456; + $tup->{t_xmin} = $xmin; + $tup->{t_infomask} &= ~HEAP_XMIN_COMMITTED; + $tup->{t_infomask} &= ~HEAP_XMIN_INVALID; + + push @expected, + qr/${$header}xmin ${xmin} equals or exceeds next valid transaction ID 0:\d+/; + } write_tuple($file, $offset, $tup); } close($file) diff --git a/contrib/amcheck/verify_heapam.c b/contrib/amcheck/verify_heapam.c index 33c5b338959..94ddccd23a8 100644 --- a/contrib/amcheck/verify_heapam.c +++ b/contrib/amcheck/verify_heapam.c @@ -1574,17 +1574,40 @@ check_tuple(HeapCheckContext *ctx) static FullTransactionId FullTransactionIdFromXidAndCtx(TransactionId xid, const HeapCheckContext *ctx) { - uint32 epoch; + uint64 nextfxid_i; + int32 diff; + FullTransactionId fxid; Assert(TransactionIdIsNormal(ctx->next_xid)); Assert(FullTransactionIdIsNormal(ctx->next_fxid)); + Assert(XidFromFullTransactionId(ctx->next_fxid) == ctx->next_xid); if (!TransactionIdIsNormal(xid)) return FullTransactionIdFromEpochAndXid(0, xid); - epoch = EpochFromFullTransactionId(ctx->next_fxid); - if (xid > ctx->next_xid) - epoch--; - return FullTransactionIdFromEpochAndXid(epoch, xid); + + nextfxid_i = U64FromFullTransactionId(ctx->next_fxid); + + /* compute the 32bit modulo difference */ + diff = (int32) (ctx->next_xid - xid); + + /* + * In cases of corruption we might see a 32bit xid that is before epoch + * 0. We can't represent that as a 64bit xid, due to 64bit xids being + * unsigned integers, without the modulo arithmetic of 32bit xid. There's + * no really nice way to deal with that, but it works ok enough to use + * FirstNormalFullTransactionId in that case, as a freshly initdb'd + * cluster already has a newer horizon. + */ + if (diff > 0 && (nextfxid_i - FirstNormalTransactionId) < (int64) diff) + { + Assert(EpochFromFullTransactionId(ctx->next_fxid) == 0); + fxid = FirstNormalFullTransactionId; + } + else + fxid = FullTransactionIdFromU64(nextfxid_i - diff); + + Assert(FullTransactionIdIsNormal(fxid)); + return fxid; } /* -- 2.38.0 --nw645w6j7vrf6gq5 Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v5-0003-wip-stricter-validation-for-64bit-xids.patch" ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-10-24 12:30 torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2023-10-24 12:30 UTC (permalink / raw) To: Étienne BERSAC <[email protected]>; +Cc: Ashutosh Bapat <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2023-10-24 16:12, Étienne BERSAC wrote: >> Hi, >> >> Yeah, and when we have a situation where we want to run >> pg_log_query_plan(), we can run it in any environment as long as it >> is bundled with the core. > > Is it possible to get the plan of a backend programmatically without > access to the logs? > > Something like pg_get_query_plan(pid, format) which output would be the > same as EXPLAIN. Do you imagine a function like below? =# select pg_get_query_plan(100, 'plain'); QUERY PLAN ------------------------------------------------------------------- Limit (cost=0.00..0.04 rows=1 width=273) -> Seq Scan on pg_class (cost=0.00..17.14 rows=414 width=273) If so, we once tried to implement such function for getting memory contexts. However, this attempt didn't succeed because it could lead dead lock situation[1]. I think the same problem can occur when implementing pg_get_query_plan(). [1] https://www.postgresql.org/message-id/9a50371e15e741e295accabc72a41df1%40oss.nttdata.com > > Regards, > Étienne BERSAC > Dalibo -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-10-27 07:06 Étienne BERSAC <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Étienne BERSAC @ 2023-10-27 07:06 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: Ashutosh Bapat <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] Hi Torikoshia, > If so, we once tried to implement such function for getting memory > contexts. > However, this attempt didn't succeed because it could lead dead lock > situation[1]. Thanks for the pointer. Why not use client log message to allow client to get plan without locking backend memory context and without access to server log ? I missed the rationnal for not sending the plan to client. Regards, Étienne ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-10-27 12:30 torikoshia <[email protected]> parent: Étienne BERSAC <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2023-10-27 12:30 UTC (permalink / raw) To: Étienne BERSAC <[email protected]>; +Cc: Ashutosh Bapat <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2023-10-27 16:06, Étienne BERSAC wrote: > Hi Torikoshia, > >> If so, we once tried to implement such function for getting memory >> contexts. >> However, this attempt didn't succeed because it could lead dead lock >> situation[1]. > > Thanks for the pointer. Why not use client log message to allow client > to get plan without locking backend memory context and without access > to server log ? I missed the rationnal for not sending the plan to > client. If we use client log message, that message is shown on the target process whose pid is specified by the parameter of pg_log_query_plan(): (pid:1000)=# select pg_sleep(60); (pid:1001)=# select pg_log_query_plan(1000); (pid:1000)=# LOG: query plan running on backend with PID 1000 is: Query Text: select pg_sleep(1000); Result (cost=0.00..0.01 rows=1 width=4) Output: pg_sleep('1000'::double precision) I think this is not an expected behavior and we set elevel to LOG_SERVER_ONLY. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-10-27 12:54 Étienne BERSAC <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Étienne BERSAC @ 2023-10-27 12:54 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: Ashutosh Bapat <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] > Hi, > > If we use client log message, that message is shown on the target > process whose pid is specified by the parameter of > pg_log_query_plan(): > > (pid:1000)=# select pg_sleep(60); > (pid:1001)=# select pg_log_query_plan(1000); > (pid:1000)=# LOG: query plan running on backend with PID 1000 is: > Query Text: select pg_sleep(1000); > Result (cost=0.00..0.01 rows=1 width=4) > Output: pg_sleep('1000'::double precision) > > I think this is not an expected behavior and we set elevel to > LOG_SERVER_ONLY. Makes sens. Thanks. ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-03 14:01 Ashutosh Bapat <[email protected]> parent: Étienne BERSAC <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2023-11-03 14:01 UTC (permalink / raw) To: Étienne BERSAC <[email protected]>; torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected] I have following questions related to the functionality. (Please point me to the relevant discussion if this has been already discussed.) 1. When a backend is running nested queries, we will see the plan of the innermost query. That query may not be the actual culprit if the user query is running slowly. E.g a query being run as part of inner side nested loop when the nested loop itself is the bottleneck. I think it will be useful to print plans of all the whole query stack. 2. When a query is running in parallel worker do we want to print that query? It may or may not be interesting given the situation. If the overall plan itself is faulty, output of the parallel worker query is not useful. If the plan is fine but a given worker's leg is running slowly it may be interesting. As a side note, you may want to fix the indentation in ExplainAssembleLogOutput(). On Fri, Oct 27, 2023 at 6:24 PM Étienne BERSAC <[email protected]> wrote: > > > Hi, > > > > > If we use client log message, that message is shown on the target > > process whose pid is specified by the parameter of > > pg_log_query_plan(): > > > > (pid:1000)=# select pg_sleep(60); > > (pid:1001)=# select pg_log_query_plan(1000); > > (pid:1000)=# LOG: query plan running on backend with PID 1000 is: > > Query Text: select pg_sleep(1000); > > Result (cost=0.00..0.01 rows=1 width=4) > > Output: pg_sleep('1000'::double precision) > > > > I think this is not an expected behavior and we set elevel to > > LOG_SERVER_ONLY. > > > Makes sens. Thanks. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-06 06:32 Ashutosh Bapat <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2023-11-06 06:32 UTC (permalink / raw) To: Étienne BERSAC <[email protected]>; torikoshia <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected] On Fri, Nov 3, 2023 at 7:31 PM Ashutosh Bapat <[email protected]> wrote: > > I have following questions related to the functionality. (Please point > me to the relevant discussion if this has been already discussed.) > > 1. When a backend is running nested queries, we will see the plan of > the innermost query. That query may not be the actual culprit if the > user query is running slowly. E.g a query being run as part of inner > side nested loop when the nested loop itself is the bottleneck. I > think it will be useful to print plans of all the whole query stack. To further explain this point, consider following scenario -- A completely useless function which executes two SQL statements which take small amount individually #create function multstmt() returns int language sql as $$ select count(*) from pg_class where reltype = 12345; select count(*) from pg_type limit 10; $$; -- force a suboptimal plan #set enable_hashjoin to false; #set enable_mergejoin to false; -- A completely useless but long running query #select c.oid, t.oid from pg_class c, pg_type t where multstmt(c.oid) = multstmt(t.oid); This take a few minutes on my laptop. In a separate session query pg_stat_activity. We will see the original query #select pid, query, backend_type from pg_stat_activity where pid = 349330; pid | query | backend_type --------+-----------------------------------------------------------------------------------------+---------------- 349330 | select c.oid, t.oid from pg_class c, pg_type t where multstmt(c.oid) = multstmt(t.oid); | client backend (1 row) Run the plan output function a few times #select pg_log_query_plan(349330); You will observe different plans based on which of the innermost query is runnning LOG: query plan running on backend with PID 349330 is: Query Text: select count(*) from pg_class where reltype = typeid; select count(*) from pg_type where oid = typeid; Query Parameters: $1 = '600' Aggregate (cost=18.18..18.19 rows=1 width=8) Output: count(*) -> Seq Scan on pg_catalog.pg_class (cost=0.00..18.18 rows=2 width=0) Output: oid, relname, relnamespace, reltype, reloftype, relowner, relam, relfilenode, reltablespace, relpages, reltuples, relallvisible, reltoastrelid, relhasindex, relisshared, relpersistence, relkind, relnatts, relchecks, relhasrules, relhastriggers, relhassubclass, relrowsecurity, relforcerowsecurity, relispopulated, relreplident, relispartition, relrewrite, relfrozenxid, relminmxid, relacl, reloptions, relpartbound Filter: (pg_class.reltype = $1) Settings: enable_hashjoin = 'off', enable_mergejoin = 'off' 2023-11-06 11:52:25.610 IST [349330] LOG: query plan running on backend with PID 349330 is: Query Text: select count(*) from pg_class where reltype = typeid; select count(*) from pg_type where oid = typeid; Query Parameters: $1 = '2203' Aggregate (cost=4.30..4.31 rows=1 width=4) Output: count(*) -> Index Only Scan using pg_type_oid_index on pg_catalog.pg_type (cost=0.28..4.29 rows=1 width=0) Output: oid Index Cond: (pg_type.oid = $1) Settings: enable_hashjoin = 'off', enable_mergejoin = 'off' Individual pieces are confusing here since the query run by the backend is not the one being EXPLAINed. A user may not know that the queries being EXPLAINed arise from the function call multstmt(). So they won't be able to stitch the pieces together unless they see plan of the outermost query with loops and costs. What might help if we explain each query in the hierarchy. I think we can start with what auto_explain is doing. Always print the plan of the outermost query; the query found in pg_stat_activity. In a later version we might find a way to print plans of all the queries in the stack and do so in a readable manner. This makes tracking activeQueryDesc a bit tricky. My guess is that the outermost query's descriptor will be available through ActivePortal most of the time. But there are cases when ExecutorRun is called by passing a queryDesc directly. So may be there are some cases where that's not true. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-09 06:33 torikoshia <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2023-11-09 06:33 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2023-11-06 15:32, Ashutosh Bapat wrote: Thanks for the suggestion and example. > On Fri, Nov 3, 2023 at 7:31 PM Ashutosh Bapat > <[email protected]> wrote: >> >> I have following questions related to the functionality. (Please point >> me to the relevant discussion if this has been already discussed.) >> >> 1. When a backend is running nested queries, we will see the plan of >> the innermost query. That query may not be the actual culprit if the >> user query is running slowly. E.g a query being run as part of inner >> side nested loop when the nested loop itself is the bottleneck. I >> think it will be useful to print plans of all the whole query stack. This was discussed in previous threads[1] and we thought it'd be useful but since it needed some extra works, we stopped widening the scope. > To further explain this point, consider following scenario > > -- A completely useless function which executes two SQL statements > which take small amount individually > #create function multstmt() returns int > language sql as $$ > select count(*) from pg_class where reltype = 12345; > select count(*) from pg_type limit 10; > $$; > > -- force a suboptimal plan > #set enable_hashjoin to false; > #set enable_mergejoin to false; > > -- A completely useless but long running query > #select c.oid, t.oid from pg_class c, pg_type t where multstmt(c.oid) > = multstmt(t.oid); > > This take a few minutes on my laptop. > > In a separate session query pg_stat_activity. We will see the original > query > #select pid, query, backend_type from pg_stat_activity where pid = > 349330; > pid | query > | backend_type > --------+-----------------------------------------------------------------------------------------+---------------- > 349330 | select c.oid, t.oid from pg_class c, pg_type t where > multstmt(c.oid) = multstmt(t.oid); | client backend > (1 row) > > Run the plan output function a few times > #select pg_log_query_plan(349330); > > You will observe different plans based on which of the innermost query > is runnning > LOG: query plan running on backend with PID 349330 is: > Query Text: > select count(*) from pg_class where reltype = typeid; > select count(*) from pg_type where oid = typeid; > > Query Parameters: $1 = '600' > Aggregate (cost=18.18..18.19 rows=1 width=8) > Output: count(*) > -> Seq Scan on pg_catalog.pg_class (cost=0.00..18.18 rows=2 > width=0) > Output: oid, relname, relnamespace, reltype, > reloftype, relowner, relam, relfilenode, reltablespace, relpages, > reltuples, relallvisible, reltoastrelid, relhasindex, relisshared, > relpersistence, relkind, relnatts, relchecks, relhasrules, > relhastriggers, relhassubclass, relrowsecurity, relforcerowsecurity, > relispopulated, relreplident, relispartition, relrewrite, > relfrozenxid, relminmxid, relacl, reloptions, relpartbound > Filter: (pg_class.reltype = $1) > Settings: enable_hashjoin = 'off', enable_mergejoin = 'off' > 2023-11-06 11:52:25.610 IST [349330] LOG: query plan running on > backend with PID 349330 is: > Query Text: > select count(*) from pg_class where reltype = typeid; > select count(*) from pg_type where oid = typeid; > > Query Parameters: $1 = '2203' > Aggregate (cost=4.30..4.31 rows=1 width=4) > Output: count(*) > -> Index Only Scan using pg_type_oid_index on > pg_catalog.pg_type (cost=0.28..4.29 rows=1 width=0) > Output: oid > Index Cond: (pg_type.oid = $1) > Settings: enable_hashjoin = 'off', enable_mergejoin = 'off' > > Individual pieces are confusing here since the query run by the > backend is not the one being EXPLAINed. A user may not know that the > queries being EXPLAINed arise from the function call multstmt(). So > they won't be able to stitch the pieces together unless they see plan > of the outermost query with loops and costs. What might help if we > explain each query in the hierarchy. > > I think we can start with what auto_explain is doing. Always print the > plan of the outermost query; the query found in pg_stat_activity. In a > later version we might find a way to print plans of all the queries in > the stack and do so in a readable manner. Agreed there are cases printing plan of the outermost query is more useful. > > This makes tracking activeQueryDesc a bit tricky. My guess is that the > outermost query's descriptor will be available through ActivePortal > most of the time. But there are cases when ExecutorRun is called by > passing a queryDesc directly. So may be there are some cases where > that's not true. Yeah, actually the original version of the patch got the plan from ActivePortal, but it failed logging plan when the query was something like this[2]: DO $$ BEGIN PERFORM pg_sleep(100); END$$; > 2. When a query is running in parallel worker do we want to print that > query? It may or may not be interesting given the situation. If the > overall plan itself is faulty, output of the parallel worker query is > not useful. If the plan is fine but a given worker's leg is running > slowly it may be interesting. I think it can be useful. I'm wondering if we can add this after the first patch for this feature is committed. > As a side note, you may want to fix the indentation in > ExplainAssembleLogOutput(). Thanks, modified it. Since the documentation was obsoleted, attached patch also updated it. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation Attachments: [text/x-diff] v33-0001-Add-function-to-log-the-plan-of-the-query.patch (30.3K, ../../[email protected]/2-v33-0001-Add-function-to-log-the-plan-of-the-query.patch) download | inline diff: From 4fb5d29176ed92b9de3b64e1eadf760d49902a40 Mon Sep 17 00:00:00 2001 From: Atsushi Torikoshi <[email protected]> Date: Thu, 9 Nov 2023 15:10:46 +0900 Subject: [PATCH v33] 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 | 50 +++++ 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, 400 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 d963f0a0a0..ada715a934 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -26516,6 +26516,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> @@ -26736,6 +26755,37 @@ 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' + Query Identifier: 8621255546560739680 +</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 74ce5f9491..de4b0542a9 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..a3c0a6a3d9 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 b8c57b3e16..1d7a8de4f3 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 f14aed422a..b693b5327e 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8245,6 +8245,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 f9525fb572..2aee08342c 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 f0cc651435..855cdd33cc 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 590c026b5b..f1b5a5219e 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 548519117a..4952523085 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 0971d5ce33..20f6472998 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: cd694f60dc975e9fe41e8643ca6f0629283d102e -- 2.39.2 ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-09 07:11 Ashutosh Bapat <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2023-11-09 07:11 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Thu, Nov 9, 2023 at 12:03 PM torikoshia <[email protected]> wrote: > >> > >> 1. When a backend is running nested queries, we will see the plan of > >> the innermost query. That query may not be the actual culprit if the > >> user query is running slowly. E.g a query being run as part of inner > >> side nested loop when the nested loop itself is the bottleneck. I > >> think it will be useful to print plans of all the whole query stack. > > This was discussed in previous threads[1] and we thought it'd be useful > but since it needed some extra works, we stopped widening the scope. > > > > > I think we can start with what auto_explain is doing. Always print the > > plan of the outermost query; the query found in pg_stat_activity. In a > > later version we might find a way to print plans of all the queries in > > the stack and do so in a readable manner. > > Agreed there are cases printing plan of the outermost query is more > useful. > I am fine printing the plan of the outermost query. This will help many cases. Printing plans of the whole query stack can be added as an add on later. > > > > This makes tracking activeQueryDesc a bit tricky. My guess is that the > > outermost query's descriptor will be available through ActivePortal > > most of the time. But there are cases when ExecutorRun is called by > > passing a queryDesc directly. So may be there are some cases where > > that's not true. > > Yeah, actually the original version of the patch got the plan from > ActivePortal, but it failed logging plan when the query was something > like this[2]: > > DO $$ > BEGIN > PERFORM pg_sleep(100); > END$$; References [1] and [2] are not listed in your email. Is that because there was no ActivePortal created or the ActivePortal pointed to DO block instead of PERFORM pg_sleep? > > > 2. When a query is running in parallel worker do we want to print that > > query? It may or may not be interesting given the situation. If the > > overall plan itself is faulty, output of the parallel worker query is > > not useful. If the plan is fine but a given worker's leg is running > > slowly it may be interesting. > > I think it can be useful. > I'm wondering if we can add this after the first patch for this feature > is committed. With the current patches, it will print the query from a parallel backend. If that's not desirable we should prohibit that case at least. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-09 11:26 torikoshia <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2023-11-09 11:26 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2023-11-09 16:11, Ashutosh Bapat wrote: > On Thu, Nov 9, 2023 at 12:03 PM torikoshia <[email protected]> > wrote: >> >> >> >> 1. When a backend is running nested queries, we will see the plan of >> >> the innermost query. That query may not be the actual culprit if the >> >> user query is running slowly. E.g a query being run as part of inner >> >> side nested loop when the nested loop itself is the bottleneck. I >> >> think it will be useful to print plans of all the whole query stack. >> >> This was discussed in previous threads[1] and we thought it'd be >> useful >> but since it needed some extra works, we stopped widening the scope. >> >> > >> > I think we can start with what auto_explain is doing. Always print the >> > plan of the outermost query; the query found in pg_stat_activity. In a >> > later version we might find a way to print plans of all the queries in >> > the stack and do so in a readable manner. >> >> Agreed there are cases printing plan of the outermost query is more >> useful. >> > > I am fine printing the plan of the outermost query. This will help > many cases. Printing plans of the whole query stack can be added as an > add on later. > >> > >> > This makes tracking activeQueryDesc a bit tricky. My guess is that the >> > outermost query's descriptor will be available through ActivePortal >> > most of the time. But there are cases when ExecutorRun is called by >> > passing a queryDesc directly. So may be there are some cases where >> > that's not true. >> >> Yeah, actually the original version of the patch got the plan from >> ActivePortal, but it failed logging plan when the query was something >> like this[2]: >> >> DO $$ >> BEGIN >> PERFORM pg_sleep(100); >> END$$; > > References [1] and [2] are not listed in your email. Oops, sorry. Here are links: [1] https://www.postgresql.org/message-id/64f716c44629e303b66e6c24502147cc%40oss.nttdata.com [2] https://www.postgresql.org/message-id/632e99eb-8090-53e6-1b1a-101601904cbd%40oss.nttdata.com > Is that because there was no ActivePortal created or the ActivePortal > pointed to DO block instead of PERFORM pg_sleep? ActivePortal is created but ActivePortal->queryDesc is null. >> > 2. When a query is running in parallel worker do we want to print that >> > query? It may or may not be interesting given the situation. If the >> > overall plan itself is faulty, output of the parallel worker query is >> > not useful. If the plan is fine but a given worker's leg is running >> > slowly it may be interesting. >> >> I think it can be useful. >> I'm wondering if we can add this after the first patch for this >> feature >> is committed. > > With the current patches, it will print the query from a parallel > backend. If that's not desirable we should prohibit that case at > least. Current patch prohibits printing plan if backend type is parallel worker as below: =# select pg_log_query_plan(pid), backend_type from pg_stat_activity where backend_type = 'parallel worker'; pg_log_query_plan | backend_type -------------------+----------------- f | parallel worker f | parallel worker (2 rows) WARNING: PID 4618 is not a PostgreSQL client backend process WARNING: PID 4617 is not a PostgreSQL client backend process Is this the behavior you expect? -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-11-09 14:58 Ashutosh Bapat <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2023-11-09 14:58 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Thu, Nov 9, 2023 at 4:56 PM torikoshia <[email protected]> wrote: > > On 2023-11-09 16:11, Ashutosh Bapat wrote: > > On Thu, Nov 9, 2023 at 12:03 PM torikoshia <[email protected]> > > wrote: > >> >> > >> >> 1. When a backend is running nested queries, we will see the plan of > >> >> the innermost query. That query may not be the actual culprit if the > >> >> user query is running slowly. E.g a query being run as part of inner > >> >> side nested loop when the nested loop itself is the bottleneck. I > >> >> think it will be useful to print plans of all the whole query stack. > >> > >> This was discussed in previous threads[1] and we thought it'd be > >> useful > >> but since it needed some extra works, we stopped widening the scope. > >> > >> > > >> > I think we can start with what auto_explain is doing. Always print the > >> > plan of the outermost query; the query found in pg_stat_activity. In a > >> > later version we might find a way to print plans of all the queries in > >> > the stack and do so in a readable manner. > >> > >> Agreed there are cases printing plan of the outermost query is more > >> useful. > >> > > > > I am fine printing the plan of the outermost query. This will help > > many cases. Printing plans of the whole query stack can be added as an > > add on later. > > > >> > > >> > This makes tracking activeQueryDesc a bit tricky. My guess is that the > >> > outermost query's descriptor will be available through ActivePortal > >> > most of the time. But there are cases when ExecutorRun is called by > >> > passing a queryDesc directly. So may be there are some cases where > >> > that's not true. > >> > >> Yeah, actually the original version of the patch got the plan from > >> ActivePortal, but it failed logging plan when the query was something > >> like this[2]: > >> > >> DO $$ > >> BEGIN > >> PERFORM pg_sleep(100); > >> END$$; > > > > References [1] and [2] are not listed in your email. > > Oops, sorry. Here are links: > > [1] > https://www.postgresql.org/message-id/64f716c44629e303b66e6c24502147cc%40oss.nttdata.com > [2] > https://www.postgresql.org/message-id/632e99eb-8090-53e6-1b1a-101601904cbd%40oss.nttdata.com > > > Is that because there was no ActivePortal created or the ActivePortal > > pointed to DO block instead of PERFORM pg_sleep? > > ActivePortal is created but ActivePortal->queryDesc is null. Thanks. > > >> > 2. When a query is running in parallel worker do we want to print that > >> > query? It may or may not be interesting given the situation. If the > >> > overall plan itself is faulty, output of the parallel worker query is > >> > not useful. If the plan is fine but a given worker's leg is running > >> > slowly it may be interesting. > >> > >> I think it can be useful. > >> I'm wondering if we can add this after the first patch for this > >> feature > >> is committed. > > > > With the current patches, it will print the query from a parallel > > backend. If that's not desirable we should prohibit that case at > > least. > > Current patch prohibits printing plan if backend type is parallel worker > as below: > > =# select pg_log_query_plan(pid), backend_type from pg_stat_activity > where backend_type = 'parallel worker'; > > pg_log_query_plan | backend_type > -------------------+----------------- > f | parallel worker > f | parallel worker > (2 rows) > > WARNING: PID 4618 is not a PostgreSQL client backend process > WARNING: PID 4617 is not a PostgreSQL client backend process > > Is this the behavior you expect? > I misread then. Thanks for correcting me. We could consider plans from parallel workers in v2 of this feature. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-12-06 23:33 Rafael Thofehrn Castro <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Rafael Thofehrn Castro @ 2023-12-06 23:33 UTC (permalink / raw) To: [email protected]; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected] Hello hackers, Last Saturday I submitted a patch to the pgsql-hackers list with the title "Proposal: In-flight explain logging" with a patch proposing a feature very similar to the one being worked on in this thread. I should have done a better search in the commitfest before implementing something from scratch. So, as recommended by Ashutosh, I am sending an incremental patch containing an additional feature I personally think we should include: logging the plan with instrumentation details if enabled. When targeting a query with instrumentation PG should log the complete EXPLAIN ANALYZE plan with current row count and, if enabled, timing for each node. This gives the user not only the ability to see what the plan is but also what was executed so far, which is super useful when troubleshooting queries that never finish. Considering that the query is in progress the output will include the statement (never executed) for nodes that weren't touched yet (or may never be). This feature is already present in the current ExplainNode implementation. I added a new statement (in progress) for nodes currently being executed, ie, InstrStartNode was called and clock is ticking there. Back-reading this thread I saw the discussion about extending pg_log_query_plan to parallel workers or not. I added it in my incremental patch as the new capability of logging instrumentation makes it useful to be able to see what parallel workers are currently doing. # DEMONSTRATION: postgres=# select pid, backend_type,pg_log_query_plan(pid) postgres=# from pg_stat_activity postgres=# where (backend_type = 'client backend' and pid != pg_backend_pid()) postgres=# or backend_type = 'parallel worker'; pid | backend_type | pg_log_query_plan -------+-----------------+------------------- 33833 | client backend | t 47202 | parallel worker | t 47203 | parallel worker | t (3 rows) 2023-12-06 23:14:41.756 UTC [33833] LOG: query plan running on backend with PID 33833 is: Query Text: explain (analyze, buffers) select * from t2 a inner join t1 b on a.c1=b.c1 inner join t1 c on a.c1=c.c1 inner join t1 d on a.c1=d.c1 inner join t1 e on a.c1=e.c1; Gather (cost=70894.63..202643.27 rows=1000000 width=20) (never executed) Output: a.c1, b.c1, c.c1, d.c1, e.c1 Workers Planned: 2 Workers Launched: 2 -> Parallel Hash Join (cost=69894.63..101643.27 rows=416667 width=20) (never executed) Output: a.c1, b.c1, c.c1, d.c1, e.c1 Hash Cond: (a.c1 = e.c1) -> Parallel Hash Join (cost=54466.62..77218.65 rows=416667 width=16) (never executed) Output: a.c1, b.c1, c.c1, d.c1 Hash Cond: (a.c1 = c.c1) -> Parallel Hash Join (cost=15428.00..29997.42 rows=416667 width=8) (actual time=2500.914..2625.922 rows=250412 loops=1) (in progress) Output: a.c1, b.c1 Inner Unique: true Hash Cond: (b.c1 = a.c1) Buffers: shared hit=755 read=2175, temp read=1473 written=1860 -> Parallel Seq Scan on public.t1 b (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.022..20.904 rows=331492 loops=1) Output: b.c1 Buffers: shared hit=602 read=865 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=1745.107..1745.107 rows=330638 loops=1) Output: a.c1 Buffers: shared hit=153 read=1310, temp written=868 -> Parallel Seq Scan on public.t2 a (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.042..27.695 rows=330638 loops=1) Output: a.c1 Buffers: shared hit=153 read=1310 -> Parallel Hash (cost=32202.28..32202.28 rows=416667 width=8) (actual time=2450.489..2450.489 rows=407941 loops=1) Output: c.c1, d.c1 Buffers: shared hit=1141 read=1833, temp read=1938 written=2836 -> Parallel Hash Join (cost=15428.00..32202.28 rows=416667 width=8) (actual time=1323.422..1575.245 rows=407941 loops=1) Output: c.c1, d.c1 Hash Cond: (c.c1 = d.c1) Buffers: shared hit=1141 read=1833, temp read=1938 written=1864 -> Parallel Seq Scan on public.t1 c (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.026..22.223 rows=336238 loops=1) Output: c.c1 Buffers: shared hit=590 read=898 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=653.306..653.306 rows=335836 loops=1) Output: d.c1 Buffers: shared hit=551 read=935, temp written=872 -> Parallel Seq Scan on public.t1 d (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.022..23.127 rows=335836 loops=1) Output: d.c1 Buffers: shared hit=551 read=935 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=590.086..590.086 rows=343696 loops=1) Output: e.c1 Buffers: shared hit=519 read=1002, temp written=896 -> Parallel Seq Scan on public.t1 e (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.066..21.797 rows=343696 loops=1) Output: e.c1 Buffers: shared hit=519 read=1002 2023-12-06 23:14:41.757 UTC [47203] LOG: query plan running on backend with PID 47203 is: Query Text: explain (analyze, buffers) select * from t2 a inner join t1 b on a.c1=b.c1 inner join t1 c on a.c1=c.c1 inner join t1 d on a.c1=d.c1 inner join t1 e on a.c1=e.c1; Parallel Hash Join (cost=69894.63..101643.27 rows=416667 width=20) (never executed) Output: a.c1, b.c1, c.c1, d.c1, e.c1 Hash Cond: (a.c1 = e.c1) -> Parallel Hash Join (cost=54466.62..77218.65 rows=416667 width=16) (never executed) Output: a.c1, b.c1, c.c1, d.c1 Hash Cond: (a.c1 = c.c1) -> Parallel Hash Join (cost=15428.00..29997.42 rows=416667 width=8) (actual time=2464.367..2628.476 rows=258293 loops=1) Output: a.c1, b.c1 Inner Unique: true Hash Cond: (b.c1 = a.c1) Buffers: shared hit=704 read=2213, temp read=1497 written=1860 -> Parallel Seq Scan on public.t1 b (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.032..22.247 rows=330412 loops=1) Output: b.c1 Buffers: shared hit=594 read=868 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=1745.093..1745.093 rows=328830 loops=1) Output: a.c1 Buffers: shared hit=110 read=1345, temp written=868 -> Parallel Seq Scan on public.t2 a (cost=0.00..8591.67 rows=416667 width=4) (actual time=1.141..30.128 rows=328830 loops=1) Output: a.c1 Buffers: shared hit=110 read=1345 -> Parallel Hash (cost=32202.28..32202.28 rows=416667 width=8) (actual time=2449.694..2449.694 rows=295462 loops=1) Output: c.c1, d.c1 Buffers: shared hit=1161 read=1844, temp read=1971 written=2872 -> Parallel Hash Join (cost=15428.00..32202.28 rows=416667 width=8) (actual time=1378.678..1577.182 rows=295462 loops=1) Output: c.c1, d.c1 Hash Cond: (c.c1 = d.c1) Buffers: shared hit=1161 read=1844, temp read=1971 written=1856 -> Parallel Seq Scan on public.t1 c (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.031..22.459 rows=336288 loops=1) Output: c.c1 Buffers: shared hit=590 read=898 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=651.048..651.048 rows=328378 loops=1) Output: d.c1 Buffers: shared hit=507 read=946, temp written=860 -> Parallel Seq Scan on public.t1 d (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.034..24.462 rows=328378 loops=1) Output: d.c1 Buffers: shared hit=507 read=946 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=575.417..575.417 rows=327926 loops=1) Output: e.c1 Buffers: shared hit=522 read=929, temp written=860 -> Parallel Seq Scan on public.t1 e (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.786..23.114 rows=327926 loops=1) Output: e.c1 Buffers: shared hit=522 read=929 2023-12-06 23:14:41.758 UTC [47202] LOG: query plan running on backend with PID 47202 is: Query Text: explain (analyze, buffers) select * from t2 a inner join t1 b on a.c1=b.c1 inner join t1 c on a.c1=c.c1 inner join t1 d on a.c1=d.c1 inner join t1 e on a.c1=e.c1; Parallel Hash Join (cost=69894.63..101643.27 rows=416667 width=20) (never executed) Output: a.c1, b.c1, c.c1, d.c1, e.c1 Hash Cond: (a.c1 = e.c1) -> Parallel Hash Join (cost=54466.62..77218.65 rows=416667 width=16) (never executed) Output: a.c1, b.c1, c.c1, d.c1 Hash Cond: (a.c1 = c.c1) -> Parallel Hash Join (cost=15428.00..29997.42 rows=416667 width=8) (actual time=2500.138..2631.855 rows=254125 loops=1) Output: a.c1, b.c1 Inner Unique: true Hash Cond: (b.c1 = a.c1) Buffers: shared hit=749 read=2254, temp read=1483 written=1896 -> Parallel Seq Scan on public.t1 b (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.027..22.224 rows=338096 loops=1) Output: b.c1 Buffers: shared hit=628 read=868 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=1744.616..1744.616 rows=340532 loops=1) Output: a.c1 Buffers: shared hit=121 read=1386, temp written=892 -> Parallel Seq Scan on public.t2 a (cost=0.00..8591.67 rows=416667 width=4) (actual time=1.138..30.003 rows=340532 loops=1) Output: a.c1 Buffers: shared hit=121 read=1386 -> Parallel Hash (cost=32202.28..32202.28 rows=416667 width=8) (actual time=2450.470..2450.470 rows=296597 loops=1) Output: c.c1, d.c1 Buffers: shared hit=1186 read=1813, temp read=1610 written=2872 -> Parallel Hash Join (cost=15428.00..32202.28 rows=416667 width=8) (actual time=1380.286..1561.412 rows=296597 loops=1) Output: c.c1, d.c1 Hash Cond: (c.c1 = d.c1) Buffers: shared hit=1186 read=1813, temp read=1610 written=1848 -> Parallel Seq Scan on public.t1 c (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.032..22.170 rows=327474 loops=1) Output: c.c1 Buffers: shared hit=548 read=901 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=653.297..653.297 rows=335786 loops=1) Output: d.c1 Buffers: shared hit=574 read=912, temp written=868 -> Parallel Seq Scan on public.t1 d (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.023..24.210 rows=335786 loops=1) Output: d.c1 Buffers: shared hit=574 read=912 -> Parallel Hash (cost=8591.67..8591.67 rows=416667 width=4) (actual time=574.553..574.553 rows=328378 loops=1) Output: e.c1 Buffers: shared hit=495 read=958, temp written=864 -> Parallel Seq Scan on public.t1 e (cost=0.00..8591.67 rows=416667 width=4) (actual time=0.717..23.270 rows=328378 loops=1) Output: e.c1 Buffers: shared hit=495 read=958 The thread of my initial patch contains all important implementation details. Sharing the ones relevant to my incremental patch here: - Safely printing signaled plans with instrumentation A plan string is built in function ExplainNode here ( https://github.com/postgres/postgres/blob/REL_16_STABLE/src/backend/commands/explain.c#L1178 ) which is called at the end of a query execution when EXPLAIN is used. That function performs logic using a PlanState (part of QueryDesc) of the running query and a ExplainState. The main challenge there is that ExplainNode calls InstrEndLoop which changes values in Instrumentation. This is ok for a regular EXPLAIN where the query is already complete but not ok for the new feature with signaled plan logging. So the new code has custom logic to clone Instrumentation instance of the current node. The cloned object can be safely written. Function InstrEndLoop has a safety rule here ( https://github.com/postgres/postgres/blob/REL_16_STABLE/src/backend/executor/instrument.c#L148 ) that prevents adjusting instrumentation details in a running node. This never happens in the current code logic but with the new feature it will happen very often. I didn't want to remove this safety rule as InstrEndLoop gets called in other places too (even in auto_explain) so the solution was to keep InstrEndLoop and have a new InstrEndLoopForce for the signaled plan logging with instrumentation. Both InstrEndLoop and InstrEndLoopForce call a new internal InstrEndLoopInternal to avoid duplicating the code. - Memory management Considering that pg_log_query_plan() creates its own memory context before calling ExplainAssembleLogOutput, the new logic that allocates memory to clone instrumentation doesn't need to free anything. # FINAL CONSIDERATIONS Let me know what you think about this incremental patch. If you think it is useful but needs adjustments I will be happy to change as needed. Kind Regards, Rafael Castro. Attachments: [application/octet-stream] v34-0001-Add-function-to-log-the-plan-of-the-query.patch (30.3K, ../../CAG0ozMqmjpUG65sDQ+RA41mhr_1+Wf2Kk88V4_3MDCy9Xk4-+w@mail.gmail.com/3-v34-0001-Add-function-to-log-the-plan-of-the-query.patch) download | inline diff: From 174d346b117f91235572d958db668ab358a1b1b6 Mon Sep 17 00:00:00 2001 From: Atsushi Torikoshi <[email protected]> Date: Thu, 9 Nov 2023 15:10:46 +0900 Subject: [PATCH v34 1/2] 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 | 50 +++++ 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, 400 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 20da3ed033..b2cc9ff39a 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -26547,6 +26547,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> @@ -26767,6 +26786,37 @@ 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' + Query Identifier: 8621255546560739680 +</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 536edb3792..2241cb3543 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 4206752881..0733748534 100644 --- a/src/backend/catalog/system_functions.sql +++ b/src/backend/catalog/system_functions.sql @@ -756,6 +756,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..a3c0a6a3d9 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 b8c57b3e16..1d7a8de4f3 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 7298a187d1..3753a11926 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 6aeb855e49..310b24821b 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 fb58dee3bc..a22952a004 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8259,6 +8259,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 f9525fb572..2aee08342c 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 f0cc651435..855cdd33cc 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 590c026b5b..f1b5a5219e 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 548519117a..4952523085 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 0971d5ce33..20f6472998 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 9302134077..62983fd6d6 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 d3dc591173..a69290e8c7 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 -- 2.32.0 (Apple Git-132) [application/octet-stream] v34-0002-Log-plan-along-with-instrumentation-details.patch (11.2K, ../../CAG0ozMqmjpUG65sDQ+RA41mhr_1+Wf2Kk88V4_3MDCy9Xk4-+w@mail.gmail.com/4-v34-0002-Log-plan-along-with-instrumentation-details.patch) download | inline diff: From fc656131a2920a8c8a583d749cb7c18c3c57fbfa Mon Sep 17 00:00:00 2001 From: Rafael Castro <[email protected]> Date: Wed, 6 Dec 2023 19:18:32 -0300 Subject: [PATCH v34 2/2] Log plan along with instrumentation details Instrumentation is enabled when using EXPLAIN ANALYZE or with auto_explain and the proper settings. A plan output with instrumentation also contains details for nodes that weren't executed yet, depicted with (never executed). This incremental patch also includes a new visualization, depicted with (in progress) that denotes nodes currently being executed, ie, function InstrStartNode was called but InstrStopNode not yet. --- src/backend/commands/explain.c | 131 +++++++++++++++++++++++------- src/backend/executor/instrument.c | 20 ++++- src/include/executor/instrument.h | 1 + 3 files changed, 120 insertions(+), 32 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index a3c0a6a3d9..7369a75cf7 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1066,8 +1066,17 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) char *relname; char *conname = NULL; - /* Must clean up instrumentation state */ - InstrEndLoop(instr); + /* Signaled explain, clone instrumentation */ + if (es->signaled) { + instr = palloc(sizeof(*instr)); + *instr = *(rInfo->ri_TrigInstrument + nt); + /* Force end loop even if node is in progress */ + InstrEndLoopForce(instr); + } + else { + instr = rInfo->ri_TrigInstrument + nt; + InstrEndLoop(instr); + } /* * We ignore triggers that were never invoked; they likely aren't @@ -1230,6 +1239,7 @@ ExplainNode(PlanState *planstate, List *ancestors, const char *operation = NULL; const char *custom_name = NULL; ExplainWorkersState *save_workers_state = es->workers_state; + Instrumentation *local_instr = NULL; int save_indent = es->indent; bool haschildren; @@ -1682,37 +1692,63 @@ 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 * instrumentation results the user didn't ask for. But we do the * InstrEndLoop call anyway, if possible, to reduce the number of cases * auto_explain has to contend with. + * + * For regular explains instrumentation clean up is called directly in + * the main instrumentation objects. Signaled plan logging needs to clone + * instrumentation object and forcibly end the loop in nodes that may + * be running. */ - if (planstate->instrument && !es->signaled) - InstrEndLoop(planstate->instrument); + if (planstate->instrument) { + /* In flight explain. Clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *planstate->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + /* Use main instrumentation */ + else { + local_instr = planstate->instrument; + InstrEndLoop(local_instr); + } + } if (es->analyze && - planstate->instrument && planstate->instrument->nloops > 0) + local_instr && local_instr->nloops > 0) { - double nloops = planstate->instrument->nloops; - double startup_ms = 1000.0 * planstate->instrument->startup / nloops; - double total_ms = 1000.0 * planstate->instrument->total / nloops; - double rows = planstate->instrument->ntuples / nloops; + double nloops = local_instr->nloops; + double startup_ms = 1000.0 * local_instr->startup / nloops; + double total_ms = 1000.0 * local_instr->total / nloops; + double rows = local_instr->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) { if (es->timing) - appendStringInfo(es->str, + /* Node in progress */ + if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime)) + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f) (in progress)", + startup_ms, total_ms, rows, nloops); + else + appendStringInfo(es->str, " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", startup_ms, total_ms, rows, nloops); else - appendStringInfo(es->str, - " (actual rows=%.0f loops=%.0f)", - rows, nloops); + /* Node in progress */ + if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime)) + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f) (in progress)", + rows, nloops); + else + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f)", + rows, nloops); } else { @@ -1848,7 +1884,7 @@ ExplainNode(PlanState *planstate, List *ancestors, planstate, es); if (es->analyze) ExplainPropertyFloat("Heap Fetches", NULL, - planstate->instrument->ntuples2, 0, es); + local_instr->ntuples2, 0, es); break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -2143,10 +2179,10 @@ ExplainNode(PlanState *planstate, List *ancestors, } /* Show buffer/WAL usage */ - if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->bufusage, false); - if (es->wal && planstate->instrument) - show_wal_usage(es, &planstate->instrument->walusage); + if (es->buffers && local_instr) + show_buffer_usage(es, &local_instr->bufusage, false); + if (es->wal && local_instr) + show_wal_usage(es, &local_instr->walusage); /* Prepare per-worker buffer/WAL usage */ if (es->workers_state && (es->buffers || es->wal) && es->verbose) @@ -4127,11 +4163,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double total; double insert_path; double other_path; - - InstrEndLoop(outerPlanState(mtstate)->instrument); + Instrumentation *local_instr; + + /* Signaled explain, clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; other_path = mtstate->ps.instrument->ntuples2; insert_path = total - other_path; @@ -4143,7 +4190,7 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, } else if (node->operation == CMD_MERGE) { - /* EXPLAIN ANALYZE display of tuples processed */ + /* Signaled explain, clone instrumentation */ if (es->analyze && mtstate->ps.instrument) { double total; @@ -4151,11 +4198,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double update_path; double delete_path; double skipped_path; - - InstrEndLoop(outerPlanState(mtstate)->instrument); + Instrumentation *local_instr; + + /* In flight explain. Clone instrumentation */ + if (es->signaled) { + local_instr = palloc(sizeof(*local_instr)); + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; insert_path = mtstate->mt_merge_inserted; update_path = mtstate->mt_merge_updated; delete_path = mtstate->mt_merge_deleted; @@ -5228,6 +5286,18 @@ ProcessLogQueryPlanInterrupt(void) es->verbose = true; es->signaled = true; + /* + * Adjust instrumentation related settings based + * on QueryDesc object. + */ + es->analyze = ActiveQueryDesc->instrument_options; + es->buffers = (ActiveQueryDesc->instrument_options & + INSTRUMENT_BUFFERS) != 0; + es->wal = (ActiveQueryDesc->instrument_options & + INSTRUMENT_WAL) != 0; + es->timing = (ActiveQueryDesc->instrument_options & + INSTRUMENT_TIMER) != 0; + ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1); ereport(LOG_SERVER_ONLY, @@ -5272,10 +5342,11 @@ pg_log_query_plan(PG_FUNCTION_ARGS) } be_status = pgstat_get_beentry_by_backend_id(proc->backendId); - if (be_status->st_backendType != B_BACKEND) + if (be_status->st_backendType != B_BACKEND && + be_status->st_backendType != B_BG_WORKER) { ereport(WARNING, - (errmsg("PID %d is not a PostgreSQL client backend process", pid))); + (errmsg("PID %d is not a PostgreSQL client backend or background worker process", pid))); PG_RETURN_BOOL(false); } diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index c383f34c06..7000e4d8bc 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -25,6 +25,8 @@ static WalUsage save_pgWalUsage; static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); static void WalUsageAdd(WalUsage *dst, WalUsage *add); +static void InstrEndLoopInternal(Instrumentation *instr, bool force); + /* Allocate new instrumentation structure(s) */ Instrumentation * @@ -137,7 +139,7 @@ InstrUpdateTupleCount(Instrumentation *instr, double nTuples) /* Finish a run cycle for a plan node */ void -InstrEndLoop(Instrumentation *instr) +InstrEndLoopInternal(Instrumentation *instr, bool force) { double totaltime; @@ -145,7 +147,7 @@ InstrEndLoop(Instrumentation *instr) if (!instr->running) return; - if (!INSTR_TIME_IS_ZERO(instr->starttime)) + if (!INSTR_TIME_IS_ZERO(instr->starttime) && !force) elog(ERROR, "InstrEndLoop called on running node"); /* Accumulate per-cycle statistics into totals */ @@ -164,6 +166,20 @@ InstrEndLoop(Instrumentation *instr) instr->tuplecount = 0; } +/* Safely finish a run cycle for a plan node */ +void +InstrEndLoop(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, false); +} + +/* Forcibly finish a run cycle for a plan node */ +void +InstrEndLoopForce(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, true); +} + /* aggregate instrumentation information */ void InstrAggNode(Instrumentation *dst, Instrumentation *add) diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index d5d69941c5..b7c98dfd78 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -108,6 +108,7 @@ extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); extern void InstrUpdateTupleCount(Instrumentation *instr, double nTuples); extern void InstrEndLoop(Instrumentation *instr); +extern void InstrEndLoopForce(Instrumentation *instr); extern void InstrAggNode(Instrumentation *dst, Instrumentation *add); extern void InstrStartParallelQuery(void); extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage); -- 2.32.0 (Apple Git-132) ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2023-12-11 05:46 torikoshia <[email protected]> parent: Rafael Thofehrn Castro <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2023-12-11 05:46 UTC (permalink / raw) To: Rafael Thofehrn Castro <[email protected]>; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected] On 2023-12-07 08:33, Rafael Thofehrn Castro wrote: > Hello hackers, > > Last Saturday I submitted a patch to the pgsql-hackers list with the > title > "Proposal: In-flight explain logging" with a patch proposing a feature > very > similar to the one being worked on in this thread. I should have done > a better > search in the commitfest before implementing something from scratch. > > So, as recommended by Ashutosh, I am sending an incremental patch > containing > an additional feature I personally think we should include: logging > the plan > with instrumentation details if enabled. Thanks for the proposal and making the patch! > When targeting a query with instrumentation PG should log the complete > EXPLAIN ANALYZE plan with current row count and, if enabled, timing > for each > node. This gives the user not only the ability to see what the plan is > but also what was executed so far, which is super useful when > troubleshooting queries that never finish. I think showing the progress of the query execution would be useful. OTOH it seems to at least need some modifications around Instrumentation as your patch. As a first step, I think it would better to minimize the scope and focus on the fundamental function. For the same reason, getting queries for parallel workers is also prohibited in the current patch as discussed here[1]. [1] https://www.postgresql.org/message-id/c25ae6015be96a1964eddd964657660b%40oss.nttdata.com So I think below steps would be better than pushing all the functionalities to the 1st commit. - First, develop function to enable output of query progress(v34-0001-Add-function-to-log-the-plan-of-the-query.patch). - Then enhance the function - showing the progress of the query execution(v34-0002-Log-plan-along-with-instrumentation-details.patch), etc. > --https://www.postgresql.org/message-id/CAG0ozMp3g3drnkDa6RZxXO_OmnisL2sD9vBrmpu5fOBoYpC-3w%40mail.gma... > - ExplainState customization > > A ExplainState is allocated and customized for the in-flight logging. > Instrumentation related settings are enabled based on how the target > query started, which is usually via EXPLAIN ANALYZE or with > auto_explain. Does this mean the progress can be got only when the target query was run with EXPLAIN ANALYZE or auto_explain.log_analyze? If so, there might be limited situations we can get the progress since I imagine EXPLAIN ANALYZE is used when user want to get the plan from the beginning and auto_explain.log_analyze can give negative impact on performance as described in the manual and there may not be many environments which enable it. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-01-29 13:02 torikoshia <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 2 replies; 30+ messages in thread From: torikoshia @ 2024-01-29 13:02 UTC (permalink / raw) To: [email protected]; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected] Hi, Updated the patch to fix typos and move ProcessLogQueryPlanInterruptActive from errfinish() to AbortTransaction. BTW since the thread is getting long, I list the some points of the discussion so far: # Safety concern ## Catalog access inside CFI - it seems safe if the CFI call is inside an existing valid transaction/query state[1] - We did some tests, for example calling ProcessLogQueryPlanInterrupt() in every single CHECK_FOR_INTERRUPTS()[2]. This test passed on my env but was stucked on James's env, so I modified to exit ProcessLogQueryPlanInterrupt() when target process is inside of lock acquisition code[3] ## Risk of calling EXPLAIN code in CFI - EXPLAIN is not a simple logic code, and there exists risk calling it from CFI. For example, if there is a bug, we may find ourselves in a situation where we can't cancel the query - it's a trade-off that's worth making for the introspection benefits this patch would provide?[4] # Design - Although some suggested it should be in auto_explain, current patch introduces this feature to the core[5] - When the target query is nested, only the most inner query's plan is explained. In future, all the nested queries' plans are expected to explained optionally like auto_explain.log_nested_statements[6] - When the target process is a parallel worker, the plan is not shown[6] - When the target query is nested and its subtransaction is aborted, pg_log_query_plan cannot log the parental query plan after the abort even parental query is running[7] - The output corresponds to EXPLAIN with VERBOSE, COST, SETTINGS and FORMAT text. It doesn't do ANALYZE or show the progress of the query execution. Future work proposed by Rafael Thofehrn Castro may realize this[8] - To prevent assertion error, this patch ensures no page lock is held by checking all the LocalLock entries before running explain code, but there is a discussion that ginInsertCleanup() should be modified[9] It may be not so difficult to improve some of restrictions in "Design", but I'd like to limit the scope of the 1st patch to make it simpler. [1] https://www.postgresql.org/message-id/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw%40mail.gma... [2] https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail... [3] https://www.postgresql.org/message-id/0e0e7ca08dff077a625c27a5e0c2ef0a%40oss.nttdata.com [4] https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail... [5] https://www.postgresql.org/message-id/CAAaqYe_1EuoTudAz8mr8-qtN5SoNtYRm4JM2J9CqeverpE3B2A%40mail.gma... [6] https://www.postgresql.org/message-id/CAExHW5sh4ahrJgmMAGfptWVmESt1JLKCNm148XVxTunRr%2B-6gA%40mail.g... [7] https://www.postgresql.org/message-id/3d121ed5f81cef588bac836b43f5d1f9%40oss.nttdata.com [8] https://www.postgresql.org/message-id/c161b5e7e1888eb9c9eb182a7d9dcf89%40oss.nttdata.com [9] https://www.postgresql.org/message-id/20220201.172757.1480996662235658750.horikyota.ntt%40gmail.com -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation Attachments: [text/x-diff] v35-0001-Add-function-to-log-the-plan-of-the-query.patch (30.1K, ../../[email protected]/2-v35-0001-Add-function-to-log-the-plan-of-the-query.patch) download | inline diff: From 65786ad6c2a9b656c3fd36a45118a39a66da0236 Mon Sep 17 00:00:00 2001 From: Atsushi Torikoshi <[email protected]> Date: Mon, 29 Jan 2024 21:40:04 +0900 Subject: [PATCH v35] 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 | 50 +++++ src/backend/access/transam/xact.c | 17 ++ src/backend/catalog/system_functions.sql | 2 + src/backend/commands/explain.c | 208 ++++++++++++++++++- 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/init/globals.c | 2 + src/include/catalog/pg_proc.dat | 6 + src/include/commands/explain.h | 9 + 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, 402 insertions(+), 48 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index c7aacd7812..c0f2ca4c18 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 6788ba8ef4..48e8748fd1 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -26524,6 +26524,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> @@ -27300,6 +27319,37 @@ 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' + Query Identifier: 8621255546560739680 +</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 464858117e..d0b5954627 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,14 @@ AbortTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ @@ -5109,6 +5118,14 @@ AbortSubTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql index 346cfb98a0..c64ca9946e 100644 --- a/src/backend/catalog/system_functions.sql +++ b/src/backend/catalog/system_functions.sql @@ -757,6 +757,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 843472e6dd..6d8d2c2f97 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" @@ -40,6 +44,7 @@ #include "utils/typcache.h" #include "utils/xml.h" +bool ProcessLogQueryPlanInterruptActive = false; /* Hook for plugins to get control in ExplainOneQuery() */ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL; @@ -737,6 +742,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 +1683,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 +1693,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 +5121,170 @@ 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 */ +} + +/* + * 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 conflicts"), + errdetail("You can try again in a moment.")); + hash_seq_term(&status); + + ProcessLogQueryPlanInterruptActive = false; + return; + } + } + + /* + * Ensure no lock is 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 conflicts"), + 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 13a9b7da83..4c7fe35f8f 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 e84619e5a5..69638e64bb 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 c70a1adb9a..fed2ea1924 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 1a34bd3715..07797ef7dd 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/init/globals.c b/src/backend/utils/init/globals.c index 88b03e8fa3..063a92a5bc 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 29af4ce65d..26b11d6a12 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8274,6 +8274,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 1b44d483d6..bbca106e92 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -17,6 +17,8 @@ #include "lib/stringinfo.h" #include "parser/parse_node.h" +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive; + typedef enum ExplainFormat { EXPLAIN_FORMAT_TEXT, @@ -60,6 +62,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 +97,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 +133,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 0b01c1f093..3914ba9f71 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 00679624f7..382930073a 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 52dcb4c2ad..400c527292 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 073fb323bc..3dd7edf93c 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 761ee2512d..3d5b4b37fd 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 7c15477104..f34f2bcd7b 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 851dad90f4..f472a839bf 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: 6a1ea02c491d16474a6214603dce40b5b122d4d1 -- 2.39.2 ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-06 10:51 Ashutosh Bapat <[email protected]> parent: torikoshia <[email protected]> 1 sibling, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2024-02-06 10:51 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] Hi Atsushi, On Mon, Jan 29, 2024 at 6:32 PM torikoshia <[email protected]> wrote: > > Hi, > > Updated the patch to fix typos and move > ProcessLogQueryPlanInterruptActive from errfinish() to AbortTransaction. > > > BTW since the thread is getting long, I list the some points of the > discussion so far: > > # Safety concern > ## Catalog access inside CFI > - it seems safe if the CFI call is inside an existing valid > transaction/query state[1] > > - We did some tests, for example calling ProcessLogQueryPlanInterrupt() > in every single CHECK_FOR_INTERRUPTS()[2]. This test passed on my env > but was stucked on James's env, so I modified to exit > ProcessLogQueryPlanInterrupt() when target process is inside of lock > acquisition code[3] > > ## Risk of calling EXPLAIN code in CFI > - EXPLAIN is not a simple logic code, and there exists risk calling it > from CFI. For example, if there is a bug, we may find ourselves in a > situation where we can't cancel the query > > - it's a trade-off that's worth making for the introspection benefits > this patch would provide?[4] > > # Design > - Although some suggested it should be in auto_explain, current patch > introduces this feature to the core[5] > > - When the target query is nested, only the most inner query's plan is > explained. In future, all the nested queries' plans are expected to > explained optionally like auto_explain.log_nested_statements[6] > > - When the target process is a parallel worker, the plan is not shown[6] > > - When the target query is nested and its subtransaction is aborted, > pg_log_query_plan cannot log the parental query plan after the abort > even parental query is running[7] > > - The output corresponds to EXPLAIN with VERBOSE, COST, SETTINGS and > FORMAT text. It doesn't do ANALYZE or show the progress of the query > execution. Future work proposed by Rafael Thofehrn Castro may realize > this[8] > > - To prevent assertion error, this patch ensures no page lock is held by > checking all the LocalLock entries before running explain code, but > there is a discussion that ginInsertCleanup() should be modified[9] > > > It may be not so difficult to improve some of restrictions in "Design", > but I'd like to limit the scope of the 1st patch to make it simpler. Thanks for the summary. It is helpful. I think patch is also getting better. I have a few questions and suggestions 1. Prologue of GetLockMethodLocalHash() mentions * NOTE: When there are many entries in LockMethodLocalHash, calling this * function and looking into all of them can lead to performance problems. */ How bad this performance could be. Let's assume that a query is taking time and pg_log_query_plan() is invoked to examine the plan of this query. Is it possible that the looping over all the locks itself takes a lot of time delaying the query execution further? 2. What happens if auto_explain is enabled in the backend and pg_log_query_plan() is called on the same backend? Will they conflict? I think we should add a test for the same. Using injection point support we should be able to add tests for testing pg_log_query_plan behaviour when there are page locks held or when auto_explain (with instrumentation) and pg_log_query_plan() work on the same query plan. Use injection point to make the backend running query wait at a suitable point to delay its execution and fire pg_log_query_plan() from other backend. May be the same test could examine the server log file to see if the plan is indeed output to the server log file. Given that the feature will be used when the things have already gone wrong, it should not make things more serious. So more testing and especially automated would help. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-07 04:08 torikoshia <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2024-02-07 04:08 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] Hi Ashutosh, On 2024-02-06 19:51, Ashutosh Bapat wrote: > Thanks for the summary. It is helpful. I think patch is also getting > better. > > I have a few questions and suggestions Thanks for your comments. > 1. Prologue of GetLockMethodLocalHash() mentions > * NOTE: When there are many entries in LockMethodLocalHash, calling > this > * function and looking into all of them can lead to performance > problems. > */ > How bad this performance could be. Let's assume that a query is taking > time and pg_log_query_plan() is invoked to examine the plan of this > query. Is it possible that the looping over all the locks itself takes > a lot of time delaying the query execution further? I think it depends on the number of local locks, but I've measured cpu time for this page lock check by adding below codes and v27-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch[1], which calls ProcessLogQueryPlanInterrupt() in every CFI on my laptop just for your information: diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 5f7d77d567..65b7cb4925 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -44,6 +44,8 @@ +#include "time.h" ... @@ -5287,6 +5292,7 @@ ProcessLogQueryPlanInterrupt(void) * we check all the LocalLock entries and when finding even one, give up * logging the plan. */ + start = clock(); 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 conflicts"), errdetail("You can try again in a moment.")); hash_seq_term(&status); ProcessLogQueryPlanInterruptActive = false; return; } } + end = clock(); + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; + + ereport(LOG, + errmsg("all locallock entry search took: %f", cpu_time_used)); + There were about 3 million log lines which recorded the cpu time, and the duration was quite short: =# -- Extracted cpu_time_used from log and loaded it to cpu_time.d. =# select max(d), min(d), avg(d) from cpu_time ; max | min | avg ----------+-----+----------------------- 0.000116 | 0 | 4.706274625332238e-07 I'm not certain that this is valid for actual use cases, but these results seem to suggest that it will not take that long. > 2. What happens if auto_explain is enabled in the backend and > pg_log_query_plan() is called on the same backend? Will they conflict? > I think we should add a test for the same. Hmm, I think they don't conflict since they just refer QueryDesc and don't modify it and don't use same objects for locking. (I imagine 'conflict' here is something like 'hard conflict' in replication[2].) Actually using both auto_explain and pg_log_query_plan() output each logs separately: (pid:62835)=# select pg_sleep(10); (pid:70000)=# select pg_log_query_plan(62835); (pid:70000)=# \! cat data/log/postgres.log ... 2024-02-06 21:44:17.837 JST [62835:4:0] LOG: 00000: query plan running on backend with PID 62835 is: Query Text: select pg_sleep(10); Result (cost=0.00..0.01 rows=1 width=4) Output: pg_sleep('10'::double precision) Query Identifier: 3506829283127886044 2024-02-06 21:44:17.837 JST [62835:5:0] LOCATION: ProcessLogQueryPlanInterrupt, explain.c:5336 2024-02-06 21:44:26.974 JST [62835:6:0] LOG: 00000: duration: 10000.868 ms plan: Query Text: select pg_sleep(10); Result (cost=0.00..0.01 rows=1 width=4) (actual time=10000.802..10000.804 rows=1 loops=1) > Using injection point support we should be able to add tests for > testing pg_log_query_plan behaviour when there are page locks held or > when auto_explain (with instrumentation) and pg_log_query_plan() work > on the same query plan. Use injection point to make the backend > running query wait at a suitable point to delay its execution and fire > pg_log_query_plan() from other backend. May be the same test could > examine the server log file to see if the plan is indeed output to the > server log file. > > Given that the feature will be used when the things have already gone > wrong, it should not make things more serious. So more testing and > especially automated would help. Thanks for the advice, it seems a good idea. I'm going to try to add tests using injection point. [1] https://www.postgresql.org/message-id/CAAaqYe8LXVXQhYy3yT0QOHUymdM%3Duha0dJ0%3DBEPzVAx2nG1gsw%40mail... [2] https://www.postgresql.org/docs/devel/hot-standby.html#HOT-STANDBY-CONFLICT -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-07 04:58 Ashutosh Bapat <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 2 replies; 30+ messages in thread From: Ashutosh Bapat @ 2024-02-07 04:58 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Wed, Feb 7, 2024 at 9:38 AM torikoshia <[email protected]> wrote: > > Hi Ashutosh, > > On 2024-02-06 19:51, Ashutosh Bapat wrote: > > > Thanks for the summary. It is helpful. I think patch is also getting > > better. > > > > I have a few questions and suggestions > > Thanks for your comments. > > > 1. Prologue of GetLockMethodLocalHash() mentions > > * NOTE: When there are many entries in LockMethodLocalHash, calling > > this > > * function and looking into all of them can lead to performance > > problems. > > */ > > How bad this performance could be. Let's assume that a query is taking > > time and pg_log_query_plan() is invoked to examine the plan of this > > query. Is it possible that the looping over all the locks itself takes > > a lot of time delaying the query execution further? > > I think it depends on the number of local locks, but I've measured cpu > time for this page lock check by adding below codes and > v27-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch[1], which > calls ProcessLogQueryPlanInterrupt() in every CFI on my laptop just for > your information: > > diff --git a/src/backend/commands/explain.c > b/src/backend/commands/explain.c > index 5f7d77d567..65b7cb4925 100644 > --- a/src/backend/commands/explain.c > +++ b/src/backend/commands/explain.c > @@ -44,6 +44,8 @@ > > +#include "time.h" > ... > @@ -5287,6 +5292,7 @@ ProcessLogQueryPlanInterrupt(void) > * we check all the LocalLock entries and when finding even > one, give up > * logging the plan. > */ > + start = clock(); > 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 conflicts"), > errdetail("You can try again in a moment.")); > hash_seq_term(&status); > > ProcessLogQueryPlanInterruptActive = false; > return; > } > } > + end = clock(); > + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; > + > + ereport(LOG, > + errmsg("all locallock entry search took: %f", > cpu_time_used)); > + > > There were about 3 million log lines which recorded the cpu time, and > the duration was quite short: > > =# -- Extracted cpu_time_used from log and loaded it to cpu_time.d. > =# select max(d), min(d), avg(d) from cpu_time ; > max | min | avg > ----------+-----+----------------------- > 0.000116 | 0 | 4.706274625332238e-07 > > I'm not certain that this is valid for actual use cases, but these > results seem to suggest that it will not take that long. What load did you run? I don't think any query in make check would take say thousands of locks. The prologue refers to a very populated lock hash table. I think that will happen if thousands of tables are queried in a single query OR a query runs on a partitioned table with thousands of partitions. May be we want to try that scenario. > > > > 2. What happens if auto_explain is enabled in the backend and > > pg_log_query_plan() is called on the same backend? Will they conflict? > > I think we should add a test for the same. > > Hmm, I think they don't conflict since they just refer QueryDesc and > don't modify it and don't use same objects for locking. > (I imagine 'conflict' here is something like 'hard conflict' in > replication[2].) By conflict, I mean the two features behave weird when used together e.g give wrong results or crash etc. > > Actually using both auto_explain and pg_log_query_plan() output each > logs separately: > > (pid:62835)=# select pg_sleep(10); > (pid:70000)=# select pg_log_query_plan(62835); > > (pid:70000)=# \! cat data/log/postgres.log > ... > 2024-02-06 21:44:17.837 JST [62835:4:0] LOG: 00000: query plan > running on backend with PID 62835 is: > Query Text: select pg_sleep(10); > Result (cost=0.00..0.01 rows=1 width=4) > Output: pg_sleep('10'::double precision) > Query Identifier: 3506829283127886044 > 2024-02-06 21:44:17.837 JST [62835:5:0] LOCATION: > ProcessLogQueryPlanInterrupt, explain.c:5336 > 2024-02-06 21:44:26.974 JST [62835:6:0] LOG: 00000: duration: > 10000.868 ms plan: > Query Text: select pg_sleep(10); > Result (cost=0.00..0.01 rows=1 width=4) (actual > time=10000.802..10000.804 rows=1 loops=1) > > > Using injection point support we should be able to add tests for > > testing pg_log_query_plan behaviour when there are page locks held or > > when auto_explain (with instrumentation) and pg_log_query_plan() work > > on the same query plan. Use injection point to make the backend > > running query wait at a suitable point to delay its execution and fire > > pg_log_query_plan() from other backend. May be the same test could > > examine the server log file to see if the plan is indeed output to the > > server log file. > > > > Given that the feature will be used when the things have already gone > > wrong, it should not make things more serious. So more testing and > > especially automated would help. > > Thanks for the advice, it seems a good idea. > I'm going to try to add tests using injection point. Your test with pg_sleep() is a good basic test. But more involved testing might need something like injection points. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-07 10:14 torikoshia <[email protected]> parent: Ashutosh Bapat <[email protected]> 1 sibling, 1 reply; 30+ messages in thread From: torikoshia @ 2024-02-07 10:14 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2024-02-07 13:58, Ashutosh Bapat wrote: > On Wed, Feb 7, 2024 at 9:38 AM torikoshia <[email protected]> > wrote: >> >> Hi Ashutosh, >> >> On 2024-02-06 19:51, Ashutosh Bapat wrote: >> >> > Thanks for the summary. It is helpful. I think patch is also getting >> > better. >> > >> > I have a few questions and suggestions >> >> Thanks for your comments. >> >> > 1. Prologue of GetLockMethodLocalHash() mentions >> > * NOTE: When there are many entries in LockMethodLocalHash, calling >> > this >> > * function and looking into all of them can lead to performance >> > problems. >> > */ >> > How bad this performance could be. Let's assume that a query is taking >> > time and pg_log_query_plan() is invoked to examine the plan of this >> > query. Is it possible that the looping over all the locks itself takes >> > a lot of time delaying the query execution further? >> >> I think it depends on the number of local locks, but I've measured cpu >> time for this page lock check by adding below codes and >> v27-0002-Testing-attempt-logging-plan-on-ever-CFI-call.patch[1], which >> calls ProcessLogQueryPlanInterrupt() in every CFI on my laptop just >> for >> your information: >> >> diff --git a/src/backend/commands/explain.c >> b/src/backend/commands/explain.c >> index 5f7d77d567..65b7cb4925 100644 >> --- a/src/backend/commands/explain.c >> +++ b/src/backend/commands/explain.c >> @@ -44,6 +44,8 @@ >> >> +#include "time.h" >> ... >> @@ -5287,6 +5292,7 @@ ProcessLogQueryPlanInterrupt(void) >> * we check all the LocalLock entries and when finding even >> one, give up >> * logging the plan. >> */ >> + start = clock(); >> 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 conflicts"), >> errdetail("You can try again in a moment.")); >> hash_seq_term(&status); >> >> ProcessLogQueryPlanInterruptActive = false; >> return; >> } >> } >> + end = clock(); >> + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; >> + >> + ereport(LOG, >> + errmsg("all locallock entry search took: %f", >> cpu_time_used)); >> + >> >> There were about 3 million log lines which recorded the cpu time, and >> the duration was quite short: >> >> =# -- Extracted cpu_time_used from log and loaded it to cpu_time.d. >> =# select max(d), min(d), avg(d) from cpu_time ; >> max | min | avg >> ----------+-----+----------------------- >> 0.000116 | 0 | 4.706274625332238e-07 >> >> I'm not certain that this is valid for actual use cases, but these >> results seem to suggest that it will not take that long. > > What load did you run? I don't think any query in make check would > take say thousands of locks. Sorry, I forgot to write it but ran make check as you imagined. > The prologue refers to a very populated > lock hash table. I think that will happen if thousands of tables are > queried in a single query OR a query runs on a partitioned table with > thousands of partitions. May be we want to try that scenario. OK, I'll try such cases. >> > 2. What happens if auto_explain is enabled in the backend and >> > pg_log_query_plan() is called on the same backend? Will they conflict? >> > I think we should add a test for the same. >> >> Hmm, I think they don't conflict since they just refer QueryDesc and >> don't modify it and don't use same objects for locking. >> (I imagine 'conflict' here is something like 'hard conflict' in >> replication[2].) > > By conflict, I mean the two features behave weird when used together > e.g give wrong results or crash etc. > >> >> Actually using both auto_explain and pg_log_query_plan() output each >> logs separately: >> >> (pid:62835)=# select pg_sleep(10); >> (pid:70000)=# select pg_log_query_plan(62835); >> >> (pid:70000)=# \! cat data/log/postgres.log >> ... >> 2024-02-06 21:44:17.837 JST [62835:4:0] LOG: 00000: query plan >> running on backend with PID 62835 is: >> Query Text: select pg_sleep(10); >> Result (cost=0.00..0.01 rows=1 width=4) >> Output: pg_sleep('10'::double precision) >> Query Identifier: 3506829283127886044 >> 2024-02-06 21:44:17.837 JST [62835:5:0] LOCATION: >> ProcessLogQueryPlanInterrupt, explain.c:5336 >> 2024-02-06 21:44:26.974 JST [62835:6:0] LOG: 00000: duration: >> 10000.868 ms plan: >> Query Text: select pg_sleep(10); >> Result (cost=0.00..0.01 rows=1 width=4) (actual >> time=10000.802..10000.804 rows=1 loops=1) >> >> > Using injection point support we should be able to add tests for >> > testing pg_log_query_plan behaviour when there are page locks held or >> > when auto_explain (with instrumentation) and pg_log_query_plan() work >> > on the same query plan. Use injection point to make the backend >> > running query wait at a suitable point to delay its execution and fire >> > pg_log_query_plan() from other backend. May be the same test could >> > examine the server log file to see if the plan is indeed output to the >> > server log file. >> > >> > Given that the feature will be used when the things have already gone >> > wrong, it should not make things more serious. So more testing and >> > especially automated would help. >> >> Thanks for the advice, it seems a good idea. >> I'm going to try to add tests using injection point. > > Your test with pg_sleep() is a good basic test. But more involved > testing might need something like injection points. It might be so, I will consider whether there are any subtle timing issues, etc. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-12 00:00 jian he <[email protected]> parent: Ashutosh Bapat <[email protected]> 1 sibling, 1 reply; 30+ messages in thread From: jian he @ 2024-02-12 00:00 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Wed, Feb 7, 2024 at 12:58 PM Ashutosh Bapat <[email protected]> wrote: > > > > > > */ > > > How bad this performance could be. Let's assume that a query is taking > > > time and pg_log_query_plan() is invoked to examine the plan of this > > > query. Is it possible that the looping over all the locks itself takes > > > a lot of time delaying the query execution further? > > corner case test: pgbench --initialize --partition-method=range --partitions=20000 Somehow my setup, the pg_bench didn't populate the data but there are 20000 partitions there. (all my other settings are default) some interesting things happened when a query touch so many partitions like: select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1; in another session, if you immediate call SELECT pg_log_query_plan(9482); then output be ` LOG: backend with PID 9482 is not running a query or a subtransaction is aborted ` however if you delay a little bit of time (like 1 second), then LOG will emit the plan with lots of text (not sure the plan is right). I think the reason is that the `InitPlan` within standard_ExecutorStart takes more time to finish when your query touches a lot of partitions. ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-12 00:00 jian he <[email protected]> parent: torikoshia <[email protected]> 1 sibling, 2 replies; 30+ messages in thread From: jian he @ 2024-02-12 00:00 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected] On Mon, Jan 29, 2024 at 9:02 PM torikoshia <[email protected]> wrote: > > Hi, > > Updated the patch to fix typos and move > ProcessLogQueryPlanInterruptActive from errfinish() to AbortTransaction. > + <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> it would be better to explain the meaning of return value TRUE/FALSE? +# 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', you can add `proargnames => '{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); + } I found out that pg_log_query_plan's comments look like pg_log_backend_memory_contexts. pg_log_backend_memory_contexts will iterate through many memory contexts. but pg_log_query_plan for one specific pid will only output one plan? so I am a little bit confused by the comments. + /* + * 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) maybe not that self evident, the above comments still not explained why we need to ensure only PAGE lock was held on this process? In the commit message, can you add all the discussion links? My gmail account doesn't have a previous discussion history. I am not sure this (https://www.postgresql.org/message-id/flat/d68c3ae31672664876b22d2dcbb526d2%40postgrespro.ru) is the only discussion link? I found a bug: src8=# select *, pg_sleep(10) from tenk1 for update; 2024-02-11 15:54:17.944 CST [48602] LOG: query plan running on backend with PID 48602 is: Query Text: select *, pg_sleep(10) from tenk1 for update; LockRows (cost=0.00..570.00 rows=10000 width=254) Output: unique1, unique2, two, four, ten, twenty, hundred, thousand, twothousand, fivethous, tenthous, odd, even, stringu1, stringu2, string4, (pg_sleep('10'::double precision)), ctid -> Seq Scan on public.tenk1 (cost=0.00..470.00 rows=10000 width=254) Output: unique1, unique2, two, four, ten, twenty, hundred, thousand, twothousand, fivethous, tenthous, odd, even, stringu1, stringu2, string4, pg_sleep('10'::double precision), ctid another session (PID) executes `SELECT pg_log_query_plan(48602);` in the meantime. pg_log_query_plan returns true successfully, but PID 48602 was stuck. I have problem using git apply: error: patch failed: src/include/commands/explain.h:94 error: src/include/commands/explain.h: patch does not apply `patch -p1 < /v35-0001-Add-function-to-log-the-plan-of-the-query.patch` works ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-12 04:39 Ashutosh Bapat <[email protected]> parent: jian he <[email protected]> 1 sibling, 0 replies; 30+ messages in thread From: Ashutosh Bapat @ 2024-02-12 04:39 UTC (permalink / raw) To: jian he <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Mon, Feb 12, 2024 at 5:31 AM jian he <[email protected]> wrote: > > I found a bug: > src8=# select *, pg_sleep(10) from tenk1 for update; > 2024-02-11 15:54:17.944 CST [48602] LOG: query plan running on > backend with PID 48602 is: > Query Text: select *, pg_sleep(10) from tenk1 for update; > LockRows (cost=0.00..570.00 rows=10000 width=254) > Output: unique1, unique2, two, four, ten, twenty, hundred, > thousand, twothousand, fivethous, tenthous, odd, even, stringu1, > stringu2, string4, (pg_sleep('10'::double precision)), ctid > -> Seq Scan on public.tenk1 (cost=0.00..470.00 rows=10000 width=254) > Output: unique1, unique2, two, four, ten, twenty, > hundred, thousand, twothousand, fivethous, tenthous, odd, even, > stringu1, stringu2, string4, pg_sleep('10'::double precision), ctid > > another session (PID) executes `SELECT pg_log_query_plan(48602);` in > the meantime. > pg_log_query_plan returns true successfully, but PID 48602 was stuck. What do you mean by PID 48602 was stuck? -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-12 04:42 Ashutosh Bapat <[email protected]> parent: jian he <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Ashutosh Bapat @ 2024-02-12 04:42 UTC (permalink / raw) To: jian he <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Mon, Feb 12, 2024 at 5:31 AM jian he <[email protected]> wrote: > > On Wed, Feb 7, 2024 at 12:58 PM Ashutosh Bapat > <[email protected]> wrote: > > > > > > > > > */ > > > > How bad this performance could be. Let's assume that a query is taking > > > > time and pg_log_query_plan() is invoked to examine the plan of this > > > > query. Is it possible that the looping over all the locks itself takes > > > > a lot of time delaying the query execution further? > > > > corner case test: > pgbench --initialize --partition-method=range --partitions=20000 > Somehow my setup, the pg_bench didn't populate the data but there are > 20000 partitions there. > (all my other settings are default) > > some interesting things happened when a query touch so many partitions like: > select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1; > > in another session, if you immediate call SELECT pg_log_query_plan(9482); > then output be > ` > LOG: backend with PID 9482 is not running a query or a subtransaction > is aborted > ` > however if you delay a little bit of time (like 1 second), then > LOG will emit the plan with lots of text (not sure the plan is right). > > I think the reason is that the `InitPlan` within > standard_ExecutorStart takes more time to finish > when your query touches a lot of partitions. That's probably expected unless we make the ActiveQueryDesc available before ExecutorRun. How much time did it took between issuing SELECT pg_log_query_plan(9482); and plan getting output to the server error logs? How does this time compare with say the same time difference for a simple query and how much of that time can be attributed to Lock table hash scan, if the difference between time difference is huge. -- Best Wishes, Ashutosh Bapat ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-12 07:08 jian he <[email protected]> parent: Ashutosh Bapat <[email protected]> 0 siblings, 0 replies; 30+ messages in thread From: jian he @ 2024-02-12 07:08 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On Mon, Feb 12, 2024 at 12:42 PM Ashutosh Bapat <[email protected]> wrote: > > On Mon, Feb 12, 2024 at 5:31 AM jian he <[email protected]> wrote: > > > > On Wed, Feb 7, 2024 at 12:58 PM Ashutosh Bapat > > <[email protected]> wrote: > > > > > > > > > > > > */ > > > > > How bad this performance could be. Let's assume that a query is taking > > > > > time and pg_log_query_plan() is invoked to examine the plan of this > > > > > query. Is it possible that the looping over all the locks itself takes > > > > > a lot of time delaying the query execution further? > > > > > > corner case test: > > pgbench --initialize --partition-method=range --partitions=20000 > > Somehow my setup, the pg_bench didn't populate the data but there are > > 20000 partitions there. > > (all my other settings are default) > > > > some interesting things happened when a query touch so many partitions like: > > select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1; > > > > in another session, if you immediate call SELECT pg_log_query_plan(9482); > > then output be > > ` > > LOG: backend with PID 9482 is not running a query or a subtransaction > > is aborted > > ` > > however if you delay a little bit of time (like 1 second), then > > LOG will emit the plan with lots of text (not sure the plan is right). > > > > I think the reason is that the `InitPlan` within > > standard_ExecutorStart takes more time to finish > > when your query touches a lot of partitions. > > That's probably expected unless we make the ActiveQueryDesc available > before ExecutorRun. so the error message should be something like: errmsg("backend with PID %d is not running a query or a subtransaction is aborted or the plan is not generated", > > How much time did it took between issuing SELECT > pg_log_query_plan(9482); and plan getting output to the server error > logs? it either says errmsg("backend with PID %d is not running a query,.....) or outputs the plan immediately, if i wait one or two seconds to call pg_log_query_plan. because of previously mentioned: with lots of partitions, initplan took longer to finish. setup: 2 sessions, one runs the query (select abalance, aid from public.pgbench_accounts,pg_sleep(4) where aid > 1;), another one calls pg_log_query_plan. ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-13 00:19 torikoshia <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 0 replies; 30+ messages in thread From: torikoshia @ 2024-02-13 00:19 UTC (permalink / raw) To: Ashutosh Bapat <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected] On 2024-02-07 19:14, torikoshia wrote: > On 2024-02-07 13:58, Ashutosh Bapat wrote: >> The prologue refers to a very populated >> lock hash table. I think that will happen if thousands of tables are >> queried in a single query OR a query runs on a partitioned table with >> thousands of partitions. May be we want to try that scenario. > > OK, I'll try such cases. I measured this using partitioned pgbench_accounts with some modification to v36[1]. The results[2] show that CPU time increases in proportion to the number of partitions, and the increase is not that large. However I've noticed that these ensuring no page lock logic would not be necessary anymore since cc32ec24fdf3b98 removed the assertion which caused an error[1]. $ git show cc32ec24fdf3b98 .. diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c index 0a692ee0a6..f595bce31b 100644 --- a/src/backend/storage/lmgr/lock.c +++ b/src/backend/storage/lmgr/lock.c @@ -186,18 +186,6 @@ static int FastPathLocalUseCount = 0; */ static bool IsRelationExtensionLockHeld PG_USED_FOR_ASSERTS_ONLY = false; - /* - * We don't acquire any other heavyweight lock while holding the page lock - * except for relation extension. - */ - Assert(!IsPageLockHeld || - (locktag->locktag_type == LOCKTAG_RELATION_EXTEND)); I'm going to remove ensuring no page lock logic after some testings. [1] $ git diff _submission/log_running_query-v36 +#include "time.h" + bool ProcessLogQueryPlanInterruptActive = false; /* Hook for plugins to get control in ExplainOneQuery() */ @@ -5258,6 +5260,10 @@ ProcessLogQueryPlanInterrupt(void) MemoryContext old_cxt; LogQueryPlanPending = false; + clock_t start, end; + double cpu_time_used; + int num_hash_entry = 0; + /* Cannot re-enter. */ if (ProcessLogQueryPlanInterruptActive) return; @@ -5287,9 +5293,11 @@ ProcessLogQueryPlanInterrupt(void) * we check all the LocalLock entries and when finding even one, give up * logging the plan. */ + start = clock(); hash_seq_init(&status, GetLockMethodLocalHash()); while ((locallock = (LOCALLOCK *) hash_seq_search(&status)) != NULL) { + num_hash_entry++; if (LOCALLOCK_LOCKTAG(*locallock) == LOCKTAG_PAGE) { ereport(LOG_SERVER_ONLY, @@ -5301,6 +5309,12 @@ ProcessLogQueryPlanInterrupt(void) return; } } + end = clock(); + cpu_time_used = ((double) (end - start)) / CLOCKS_PER_SEC; + + ereport(LOG, + errmsg("locallock entry search took: %f for %d entries", cpu_time_used, num_hash_entry)); [2] # partition number: 512 locallock entry search took: 0.000029 for 1026 entries locallock entry search took: 0.000030 for 1026 entries locallock entry search took: 0.000036 for 1026 entries # partition number: 1024 locallock entry search took: 0.000070 for 2050 entries locallock entry search took: 0.000059 for 2050 entries locallock entry search took: 0.000049 for 2050 entries # partition number: 2048 locallock entry search took: 0.000100 for 4098 entries locallock entry search took: 0.000103 for 4098 entries locallock entry search took: 0.000101 for 4098 entries # partition number: 4096 locallock entry search took: 0.000197 for 8194 entries locallock entry search took: 0.000193 for 8194 entries locallock entry search took: 0.000192 for 8194 entries [3] https://www.postgresql.org/message-id/0642712f-1298-960a-a3ba-e256d56040ac%40oss.nttdata.com -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-13 02:30 torikoshia <[email protected]> parent: jian he <[email protected]> 1 sibling, 1 reply; 30+ messages in thread From: torikoshia @ 2024-02-13 02:30 UTC (permalink / raw) To: jian he <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected] On 2024-02-12 09:00, jian he wrote: Thanks for you comments. > On Mon, Jan 29, 2024 at 9:02 PM torikoshia <[email protected]> > wrote: >> >> Hi, >> >> Updated the patch to fix typos and move >> ProcessLogQueryPlanInterruptActive from errfinish() to >> AbortTransaction. >> > > + <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> > it would be better to explain the meaning of return value TRUE/FALSE? Yeah, but I've noticed that this should be located in 'Table Server Signaling Functions' not 'Table Control Data Functions'. Since 'Table Server Signaling Functions' describes the return code as below, just relocation seems fine. Each of these functions returns true if the signal was successfully sent and false if sending the signal failed. > +# 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', > you can add > `proargnames => '{pid}'` Hmm, pg_log_query_plan() can take one argument, I'm not sure how much sense it makes. Other functions which take one argument such as pg_cancel_backend() does not have proargnames. > + 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); > + } > > I found out that pg_log_query_plan's comments look like > pg_log_backend_memory_contexts. > pg_log_backend_memory_contexts will iterate through many memory > contexts. > but pg_log_query_plan for one specific pid will only output one plan? > so I am a little bit confused by the comments. These "loop" mean backend can run pg_log_query_plan() repeatedly even when failing sending signals. pg_signal_backend() also have such comments. > + /* > + * 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) > maybe not that self evident, the above comments still not explained > why we need to ensure only > PAGE lock was held on this process? This is for preventing assertion error and it seems not necessary anymore as described in [1]. I'm going remove them. > > In the commit message, can you add all the discussion links? > My gmail account doesn't have a previous discussion history. Sure. > I am not sure this > (https://www.postgresql.org/message-id/flat/d68c3ae31672664876b22d2dcbb526d2%40postgrespro.ru) > is the only discussion link? This is the original one: https://www.postgresql.org/message-id/cf8501bcd95ba4d727cbba886ba9eea8%40oss.nttdata.com > I found a bug: > src8=# select *, pg_sleep(10) from tenk1 for update; > 2024-02-11 15:54:17.944 CST [48602] LOG: query plan running on > backend with PID 48602 is: > Query Text: select *, pg_sleep(10) from tenk1 for update; > LockRows (cost=0.00..570.00 rows=10000 width=254) > Output: unique1, unique2, two, four, ten, twenty, hundred, > thousand, twothousand, fivethous, tenthous, odd, even, stringu1, > stringu2, string4, (pg_sleep('10'::double precision)), ctid > -> Seq Scan on public.tenk1 (cost=0.00..470.00 rows=10000 > width=254) > Output: unique1, unique2, two, four, ten, twenty, > hundred, thousand, twothousand, fivethous, tenthous, odd, even, > stringu1, stringu2, string4, pg_sleep('10'::double precision), ctid > > another session (PID) executes `SELECT pg_log_query_plan(48602);` in > the meantime. > pg_log_query_plan returns true successfully, but PID 48602 was stuck. Hmm, it's not simply sleeping, is it? I'm concerned a bit this because estimated rows of tenk1 is 10000. If so, the query will take 10000 * 10 seconds. > I have problem using git apply: > error: patch failed: src/include/commands/explain.h:94 > error: src/include/commands/explain.h: patch does not apply > > `patch -p1 < /v35-0001-Add-function-to-log-the-plan-of-the-query.patch` > works I'll update the patch including other points such as removing ensuring no page lock code. [1] https://www.postgresql.org/message-id/1b2b247530f3ff3afab4ddc2df222e8b%40oss.nttdata.com -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-14 06:29 torikoshia <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: torikoshia @ 2024-02-14 06:29 UTC (permalink / raw) To: [email protected]; +Cc: Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected] On 2024-02-13 11:30, torikoshia wrote: > I'll update the patch including other points such as removing ensuring > no page lock code. Updated the patch. > Using injection point support we should be able to add tests for > testing pg_log_query_plan behaviour when there are page locks held or > when auto_explain (with instrumentation) and pg_log_query_plan() work > on the same query plan. Use injection point to make the backend > running query wait at a suitable point to delay its execution and fire > pg_log_query_plan() from other backend. May be the same test could > examine the server log file to see if the plan is indeed output to the > server log file. Attached patch uses injection point as below: - There may be more points to inject, but added an injection point at ExecutorRun(), which seems to be the first interruption point where plans can be reliably displayed. - At injection point, it'd be possible to wait for some duration and fire pg_log_plan_query() as you suggested. However, I'm not sure how long duration is appropriate considering the variety of testing environments. Instead, attached patch calls HandleLogQueryPlanInterrupt() directly and set InterruptPending. - Tests both pg_log_plan_query() and auto_explain logs for their output, and the logged plans are the same. -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation Attachments: [text/x-diff] v36-0001-Add-function-to-log-the-plan-of-the-query.patch (33.4K, ../../[email protected]/2-v36-0001-Add-function-to-log-the-plan-of-the-query.patch) download | inline diff: From 1dcac4fb4291e3b92733494624cbb090dff7aded Mon Sep 17 00:00:00 2001 From: Atsushi Torikoshi <[email protected]> Date: Wed, 14 Feb 2024 14:41:04 +0900 Subject: [PATCH v36] 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, Jian He Co-authored-by: James Coleman <[email protected]> Discussion: https://www.postgresql.org/message-id/cf8501bcd95ba4d727cbba886ba9eea8%40oss.nttdata.com Discussion: https://www.postgresql.org/message-id/flat/d68c3ae31672664876b22d2dcbb526d2%40postgrespro.ru --- contrib/auto_explain/Makefile | 2 + contrib/auto_explain/auto_explain.c | 23 +-- contrib/auto_explain/t/001_auto_explain.pl | 35 ++++ doc/src/sgml/func.sgml | 50 +++++ src/backend/access/transam/xact.c | 17 ++ src/backend/catalog/system_functions.sql | 2 + src/backend/commands/explain.c | 180 +++++++++++++++++- src/backend/executor/execMain.c | 19 ++ src/backend/storage/ipc/procsignal.c | 4 + src/backend/storage/lmgr/lock.c | 9 +- src/backend/tcop/postgres.c | 4 + src/backend/utils/init/globals.c | 2 + src/include/catalog/pg_proc.dat | 6 + src/include/commands/explain.h | 9 + 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 + .../injection_points/injection_points.c | 11 ++ src/test/regress/expected/misc_functions.out | 54 +++++- src/test/regress/sql/misc_functions.sql | 41 +++- 22 files changed, 427 insertions(+), 48 deletions(-) diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile index efd127d3ca..64fe0e0573 100644 --- a/contrib/auto_explain/Makefile +++ b/contrib/auto_explain/Makefile @@ -8,6 +8,8 @@ PGFILEDESC = "auto_explain - logging facility for execution plans" TAP_TESTS = 1 +EXTRA_INSTALL = src/test/modules/injection_points + ifdef USE_PGXS PG_CONFIG = pg_config PGXS := $(shell $(PG_CONFIG) --pgxs) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 677c135f59..e041b10b0e 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -401,26 +401,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/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl index 0e5b34afa9..36a787174e 100644 --- a/contrib/auto_explain/t/001_auto_explain.pl +++ b/contrib/auto_explain/t/001_auto_explain.pl @@ -35,6 +35,8 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0"); $node->append_conf('postgresql.conf', "auto_explain.log_analyze = on"); $node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points'); + # Simple query. my $log_contents = query_log($node, "SELECT * FROM pg_class;"); @@ -212,4 +214,37 @@ REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1; DROP USER regress_user1; }); +# Check that using both auto_explain and pg_log_query_plan() works fine + +$node->safe_psql('postgres', q{SELECT injection_points_attach('executor-run', 'logqueryplan')}); + +$log_contents = query_log( + $node, + "SELECT * FROM pg_class;", + { + "auto_explain.log_verbose" => "on", + "auto_explain.log_settings" => "on", + "auto_explain.log_analyze" => "off", + "compute_query_id" => "on" + }); + +like( + $log_contents, + qr/query plan running on backend with PID/, + "with pg_log_query_plan(), pg_log_query_plan() logged"); + +like( + $log_contents, + qr/duration: .+ms plan:/, + "with pg_log_query_plan(), auto_explain logged"); + +$log_contents =~ /(Query Text:.*Query Identifier: \d+).*(Query Text:.*Query Identifier: \d+)/s; +my $pg_log_plan_query_output = $1; +my $auto_explain_output = $2; + +cmp_ok( + $pg_log_plan_query_output, "eq", + $auto_explain_output, + "with pg_log_plan_query_log(), logged plans are the same"); + done_testing(); diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml index 8f147a2417..61dec0e415 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -27191,6 +27191,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> @@ -27305,6 +27324,37 @@ 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' + Query Identifier: 8621255546560739680 +</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 464858117e..d0b5954627 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,14 @@ AbortTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ @@ -5109,6 +5118,14 @@ AbortSubTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql index 346cfb98a0..c64ca9946e 100644 --- a/src/backend/catalog/system_functions.sql +++ b/src/backend/catalog/system_functions.sql @@ -757,6 +757,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 83d00a4663..a6565c0bab 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" @@ -40,6 +44,7 @@ #include "utils/typcache.h" #include "utils/xml.h" +bool ProcessLogQueryPlanInterruptActive = false; /* Hook for plugins to get control in ExplainOneQuery() */ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL; @@ -784,6 +789,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 @@ -1694,6 +1730,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 @@ -1701,7 +1740,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 && @@ -5182,3 +5221,142 @@ 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 */ +} + +/* + * 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; + 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 lock is 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 conflicts"), + 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 13a9b7da83..4eee998161 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -61,6 +61,7 @@ #include "tcop/utility.h" #include "utils/acl.h" #include "utils/backend_status.h" +#include "utils/injection_point.h" #include "utils/lsyscache.h" #include "utils/memutils.h" #include "utils/partcache.h" @@ -78,6 +79,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 +307,25 @@ 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; + +#ifdef USE_INJECTION_POINTS + INJECTION_POINT("executor-run"); +#endif + 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 e84619e5a5..69638e64bb 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 c70a1adb9a..fed2ea1924 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 1a34bd3715..07797ef7dd 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/init/globals.c b/src/backend/utils/init/globals.c index 88b03e8fa3..063a92a5bc 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 9c120fc2b7..a54bf97c60 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8274,6 +8274,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 7c0f0b5636..f73f984c37 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -17,6 +17,8 @@ #include "lib/stringinfo.h" #include "parser/parse_node.h" +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive; + typedef enum ExplainFormat { EXPLAIN_FORMAT_TEXT, @@ -61,6 +63,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() */ @@ -96,6 +99,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, const BufferUsage *bufusage, const MemoryContextCounters *mem_counters); +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); @@ -128,4 +135,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 0b01c1f093..3914ba9f71 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 00679624f7..382930073a 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 52dcb4c2ad..400c527292 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 073fb323bc..3dd7edf93c 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 761ee2512d..3d5b4b37fd 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/modules/injection_points/injection_points.c b/src/test/modules/injection_points/injection_points.c index e843e6594f..db0440dd91 100644 --- a/src/test/modules/injection_points/injection_points.c +++ b/src/test/modules/injection_points/injection_points.c @@ -17,6 +17,7 @@ #include "postgres.h" +#include "commands/explain.h" #include "fmgr.h" #include "storage/lwlock.h" #include "storage/shmem.h" @@ -28,6 +29,7 @@ PG_MODULE_MAGIC; extern PGDLLEXPORT void injection_error(const char *name); extern PGDLLEXPORT void injection_notice(const char *name); +extern PGDLLEXPORT void injection_HandleLogQueryPlanInterrupt(const char *name); /* Set of callbacks available to be attached to an injection point. */ @@ -43,6 +45,13 @@ injection_notice(const char *name) elog(NOTICE, "notice triggered for injection point %s", name); } +void +injection_HandleLogQueryPlanInterrupt(const char *name) +{ + HandleLogQueryPlanInterrupt(); + elog(LOG, "triggered injection_HandleLogQueryPlanInterrupt for injection point %s", name); +} + /* * SQL function for creating an injection point. */ @@ -58,6 +67,8 @@ injection_points_attach(PG_FUNCTION_ARGS) function = "injection_error"; else if (strcmp(action, "notice") == 0) function = "injection_notice"; + else if (strcmp(action, "logqueryplan") == 0) + function = "injection_HandleLogQueryPlanInterrupt"; else elog(ERROR, "incorrect action \"%s\" for injection point creation", action); diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out index 7c15477104..f34f2bcd7b 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 851dad90f4..f472a839bf 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: ddd5f4f54a026db6a6692876d0d44aef902ab686 -- 2.39.2 ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-15 09:12 Robert Haas <[email protected]> parent: torikoshia <[email protected]> 0 siblings, 1 reply; 30+ messages in thread From: Robert Haas @ 2024-02-15 09:12 UTC (permalink / raw) To: torikoshia <[email protected]>; +Cc: [email protected]; Étienne BERSAC <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected] Hi, I've just been catching up on this thread. + if (MyProc->heldLocks) + { + ereport(LOG_SERVER_ONLY, + errmsg("ignored request for logging query plan due to lock conflicts"), + errdetail("You can try again in a moment.")); + return; + } I don't like this for several reasons. First, I think it's not nice to have a request just get ignored. A user will expect that if we cannot immediately respond to some request, we'll respond later at the first time that it's safe to do so, rather than just ignoring it and telling them to retry. Second, I don't think that the error message is very good. It talks about lock conflicts, but we don't know that there is any real problem. We know that, if we enter this block, the server is in the middle of trying to acquire some lock, and we also know that we could attempt to acquire a lock as part of generating the EXPLAIN output, and maybe that's an issue. But that's not a lock conflict. That's a re-entrancy problem. I don't know that we want to talk about re-entrancy problems in an error message, and I don't really think this error message should exist in the first place, but if we're going to error out in this case surely we shouldn't do so with an error message that describes a problem we don't have. Third, I think that the re-entrancy problems with this patch may extend well beyond lock acquisition. This is one example of how it can be unsafe to do something as complicated as EXPLAIN at any arbitrary CHECK_FOR_INTERRUPTS(). It is not correct to say, as http://postgr.es/m/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw@mail.gmail.com does, that the problems with running EXPLAIN at an arbitrary point are specific to running this code in an aborted transaction. The existence of this code shows that there is at least one hazard even if the current transaction is not aborted, and I see no analysis on this thread indicating whether there are any more such hazards, or how we could go about finding them all. I think the issue is very general. We have lots of subsystems that both (a) use global variables and (b) contain CHECK_FOR_INTERRUPTS(). If we process an interrupt while that code is in the middle of manipulating its global variables and then again re-enter that code, bad things might happen. We could try to rule that out by analyzing all such subsystems and all places where CHECK_FOR_INTERRUPTS() may appear, but that's very difficult. Suppose we took the alternative approach recommended by Andrey Lepikhov in http://postgr.es/m/[email protected] and instead set a flag that gets handled in some suitable place in the executor code, like ExecProcNode(). If we did that, then we would know that we're not in the middle of a syscache lookup, a catcache lookup, a heavyweight lock acquisition, an ereport, or any other low-level subsystem call that might create problems for the EXPLAIN code. In that design, the hack shown above would go away, and we could be much more certain that we don't need any other similar hacks for other subsystems. The only downside is that we might experience a slightly longer delay before a requested EXPLAIN plan actually shows up, but that seems like a pretty small price to pay for being able to reason about the behavior of the system. I don't *think* there are any cases where we run in the executor for a particularly long time without a new call to ExecProcNode(). I think this case is a bit like vacuum_delay_point(). You might think that vacuum_delay_point() could be moved inside of CHECK_FOR_INTERRUPTS(), but we've made the opposite decision: every vacuum_delay_point() calls CHECK_FOR_INTERRUPTS() but not every CHECK_FOR_INTERRUPTS() calls vacuum_delay_point(). That means that we can allow vacuum_delay_point() only at cases where we know it's safe, rather than at every CHECK_FOR_INTERRUPTS(). I think that's a pretty smart decision, even for vacuum_delay_point(), and AFAICS the code we're proposing to run here does things that are substantially more complicated than what vacuum_delay_point() does. That code just does a bit of reading of shared memory, reports a wait event, and sleeps. That's really simple compared to code that could try to do relcache builds, which can trigger syscache lookups, which can both trigger heavyweight lock acquisition, lightweight lock acquisition, bringing pages into shared_buffers possibly through physical I/O, processing of invalidation messages, and a bunch of other stuff. It's really hard for me to accept that the heavyweight lock problem for which the patch contains a workaround is the only one that exists. I can't see any reason why that should be true. ...Robert ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-15 18:59 Andres Freund <[email protected]> parent: Robert Haas <[email protected]> 0 siblings, 2 replies; 30+ messages in thread From: Andres Freund @ 2024-02-15 18:59 UTC (permalink / raw) To: Robert Haas <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected] Hi, On 2024-02-15 14:42:11 +0530, Robert Haas wrote: > I think the issue is very general. We have lots of subsystems that > both (a) use global variables and (b) contain CHECK_FOR_INTERRUPTS(). > If we process an interrupt while that code is in the middle of > manipulating its global variables and then again re-enter that code, > bad things might happen. We could try to rule that out by analyzing > all such subsystems and all places where CHECK_FOR_INTERRUPTS() may > appear, but that's very difficult. Suppose we took the alternative > approach recommended by Andrey Lepikhov in > http://postgr.es/m/[email protected] > and instead set a flag that gets handled in some suitable place in the > executor code, like ExecProcNode(). If we did that, then we would know > that we're not in the middle of a syscache lookup, a catcache lookup, > a heavyweight lock acquisition, an ereport, or any other low-level > subsystem call that might create problems for the EXPLAIN code. > > In that design, the hack shown above would go away, and we could be > much more certain that we don't need any other similar hacks for other > subsystems. The only downside is that we might experience a slightly > longer delay before a requested EXPLAIN plan actually shows up, but > that seems like a pretty small price to pay for being able to reason > about the behavior of the system. I am very wary of adding overhead to ExecProcNode() - I'm quite sure that adding code there would trigger visible overhead for query times. If we went with something like tht approach, I think we'd have to do something like redirecting node->ExecProcNode to a wrapper, presumably from within a CFI. That wrapper could then implement the explain support, without slowing down the normal execution path. > I don't *think* there are any cases where we run in the executor for a > particularly long time without a new call to ExecProcNode(). I guess it depends on what you call a long time. A large sort, for example, could spend a fair amount of time inside tuplesort, similarly, a gather node might need to wait for a worker for a while etc. > It's really hard for me to accept that the heavyweight lock problem > for which the patch contains a workaround is the only one that exists. > I can't see any reason why that should be true. I suspect you're right. Greetings, Andres Freund ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-16 14:42 torikoshia <[email protected]> parent: Andres Freund <[email protected]> 1 sibling, 0 replies; 30+ messages in thread From: torikoshia @ 2024-02-16 14:42 UTC (permalink / raw) To: Andres Freund <[email protected]>; [email protected]; +Cc: [email protected]; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected] On Thu, Feb 15, 2024 at 6:12 PM Robert Haas <[email protected]> wrote: > Hi, > > I've just been catching up on this thread. > > + if (MyProc->heldLocks) > + { > + ereport(LOG_SERVER_ONLY, > + errmsg("ignored request for logging query plan due to lock > conflicts"), > + errdetail("You can try again in a moment.")); > + return; > + } > > I don't like this for several reasons. > > First, I think it's not nice to have a request just get ignored. A > user will expect that if we cannot immediately respond to some > request, we'll respond later at the first time that it's safe to do > so, rather than just ignoring it and telling them to retry. > > Second, I don't think that the error message is very good. It talks > about lock conflicts, but we don't know that there is any real > problem. We know that, if we enter this block, the server is in the > middle of trying to acquire some lock, and we also know that we could > attempt to acquire a lock as part of generating the EXPLAIN output, > and maybe that's an issue. But that's not a lock conflict. That's a > re-entrancy problem. I don't know that we want to talk about > re-entrancy problems in an error message, and I don't really think > this error message should exist in the first place, but if we're going > to error out in this case surely we shouldn't do so with an error > message that describes a problem we don't have. > > Third, I think that the re-entrancy problems with this patch may > extend well beyond lock acquisition. This is one example of how it can > be unsafe to do something as complicated as EXPLAIN at any arbitrary > CHECK_FOR_INTERRUPTS(). It is not correct to say, as > http://postgr.es/m/CAAaqYe9euUZD8bkjXTVcD9e4n5c7kzHzcvuCJXt-xds9X4c7Fw@mail.gmail.com > does, that the problems with running EXPLAIN at an arbitrary point are > specific to running this code in an aborted transaction. The existence > of this code shows that there is at least one hazard even if the > current transaction is not aborted, and I see no analysis on this > thread indicating whether there are any more such hazards, or how we > could go about finding them all. > > I think the issue is very general. We have lots of subsystems that > both (a) use global variables and (b) contain CHECK_FOR_INTERRUPTS(). > If we process an interrupt while that code is in the middle of > manipulating its global variables and then again re-enter that code, > bad things might happen. We could try to rule that out by analyzing > all such subsystems and all places where CHECK_FOR_INTERRUPTS() may > appear, but that's very difficult. Suppose we took the alternative > approach recommended by Andrey Lepikhov in > http://postgr.es/m/[email protected] > and instead set a flag that gets handled in some suitable place in the > executor code, like ExecProcNode(). If we did that, then we would know > that we're not in the middle of a syscache lookup, a catcache lookup, > a heavyweight lock acquisition, an ereport, or any other low-level > subsystem call that might create problems for the EXPLAIN code. > > In that design, the hack shown above would go away, and we could be > much more certain that we don't need any other similar hacks for other > subsystems. The only downside is that we might experience a slightly > longer delay before a requested EXPLAIN plan actually shows up, but > that seems like a pretty small price to pay for being able to reason > about the behavior of the system. I don't *think* there are any cases > where we run in the executor for a particularly long time without a > new call to ExecProcNode(). > > I think this case is a bit like vacuum_delay_point(). You might think > that vacuum_delay_point() could be moved inside of > CHECK_FOR_INTERRUPTS(), but we've made the opposite decision: every > vacuum_delay_point() calls CHECK_FOR_INTERRUPTS() but not every > CHECK_FOR_INTERRUPTS() calls vacuum_delay_point(). That means that we > can allow vacuum_delay_point() only at cases where we know it's safe, > rather than at every CHECK_FOR_INTERRUPTS(). I think that's a pretty > smart decision, even for vacuum_delay_point(), and AFAICS the code > we're proposing to run here does things that are substantially more > complicated than what vacuum_delay_point() does. That code just does a > bit of reading of shared memory, reports a wait event, and sleeps. > That's really simple compared to code that could try to do relcache > builds, which can trigger syscache lookups, which can both trigger > heavyweight lock acquisition, lightweight lock acquisition, bringing > pages into shared_buffers possibly through physical I/O, processing of > invalidation messages, and a bunch of other stuff. > > It's really hard for me to accept that the heavyweight lock problem > for which the patch contains a workaround is the only one that exists. > I can't see any reason why that should be true. Thanks for the review and the very detailed explanation! I'm convinced that it's unsafe to execute EXPLAIN codes during CHECK_FOR_INTERRUPTS() and we need to execute it in other safe place, as well as the first and second point. On 2024-02-16 03:59, Andres Freund wrote: > Hi, > > On 2024-02-15 14:42:11 +0530, Robert Haas wrote: >> I think the issue is very general. We have lots of subsystems that >> both (a) use global variables and (b) contain CHECK_FOR_INTERRUPTS(). >> If we process an interrupt while that code is in the middle of >> manipulating its global variables and then again re-enter that code, >> bad things might happen. We could try to rule that out by analyzing >> all such subsystems and all places where CHECK_FOR_INTERRUPTS() may >> appear, but that's very difficult. Suppose we took the alternative >> approach recommended by Andrey Lepikhov in >> http://postgr.es/m/[email protected] >> and instead set a flag that gets handled in some suitable place in the >> executor code, like ExecProcNode(). If we did that, then we would know >> that we're not in the middle of a syscache lookup, a catcache lookup, >> a heavyweight lock acquisition, an ereport, or any other low-level >> subsystem call that might create problems for the EXPLAIN code. >> >> In that design, the hack shown above would go away, and we could be >> much more certain that we don't need any other similar hacks for other >> subsystems. The only downside is that we might experience a slightly >> longer delay before a requested EXPLAIN plan actually shows up, but >> that seems like a pretty small price to pay for being able to reason >> about the behavior of the system. > > I am very wary of adding overhead to ExecProcNode() - I'm quite sure > that > adding code there would trigger visible overhead for query times. > > If we went with something like tht approach, I think we'd have to do > something > like redirecting node->ExecProcNode to a wrapper, presumably from > within a > CFI. That wrapper could then implement the explain support, without > slowing > down the normal execution path. Thanks for the idea! I'm not so sure about the implementation now, i.e. finding the next node to be executed from the planstate tree, but I'm going to try this approach. >> I don't *think* there are any cases where we run in the executor for a >> particularly long time without a new call to ExecProcNode(). > > I guess it depends on what you call a long time. A large sort, for > example, > could spend a fair amount of time inside tuplesort, similarly, a gather > node > might need to wait for a worker for a while etc. > > >> It's really hard for me to accept that the heavyweight lock problem >> for which the patch contains a workaround is the only one that exists. >> I can't see any reason why that should be true. > > I suspect you're right. > > Greetings, > > Andres Freund -- Regards, -- Atsushi Torikoshi NTT DATA Group Corporation ^ permalink raw reply [nested|flat] 30+ messages in thread
* Re: RFC: Logging plan of the running query @ 2024-02-20 04:53 Robert Haas <[email protected]> parent: Andres Freund <[email protected]> 1 sibling, 0 replies; 30+ messages in thread From: Robert Haas @ 2024-02-20 04:53 UTC (permalink / raw) To: Andres Freund <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected] On Fri, Feb 16, 2024 at 12:29 AM Andres Freund <[email protected]> wrote: > If we went with something like tht approach, I think we'd have to do something > like redirecting node->ExecProcNode to a wrapper, presumably from within a > CFI. That wrapper could then implement the explain support, without slowing > down the normal execution path. That's an annoying complication; maybe there's some better way to handle this. But I think we need to do something different than what the patch does currently because... > > It's really hard for me to accept that the heavyweight lock problem > > for which the patch contains a workaround is the only one that exists. > > I can't see any reason why that should be true. > > I suspect you're right. ...I think the current approach is just plain dead, because of this issue. We can't take an approach that creates an unbounded number of unclear reentrancy issues and then insert hacks one by one to cure them (or hack around them, more to the point) as they're discovered. The premise has to be that we only allow logging the query plan at points where we know it's safe, rather than, as at present, allowing it in places that are unsafe and then trying to compensate with code elsewhere. That's not likely to ever be as stable as we want PostgreSQL to be. -- Robert Haas EDB: http://www.enterprisedb.com ^ permalink raw reply [nested|flat] 30+ messages in thread
end of thread, other threads:[~2024-02-20 04:53 UTC | newest] Thread overview: 30+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2023-03-08 19:57 [PATCH v5 2/8] amcheck: Fix FullTransactionIdFromXidAndCtx() for xids before epoch 0 Andres Freund <[email protected]> 2023-10-24 12:30 Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2023-10-27 07:06 ` Re: RFC: Logging plan of the running query Étienne BERSAC <[email protected]> 2023-10-27 12:30 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2023-10-27 12:54 ` Re: RFC: Logging plan of the running query Étienne BERSAC <[email protected]> 2023-11-03 14:01 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2023-11-06 06:32 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2023-11-09 06:33 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2023-11-09 07:11 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2023-11-09 11:26 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2023-11-09 14:58 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2023-12-06 23:33 ` Re: RFC: Logging plan of the running query Rafael Thofehrn Castro <[email protected]> 2023-12-11 05:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-01-29 13:02 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-06 10:51 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2024-02-07 04:08 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-07 04:58 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2024-02-07 10:14 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-13 00:19 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-12 00:00 ` Re: RFC: Logging plan of the running query jian he <[email protected]> 2024-02-12 04:42 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2024-02-12 07:08 ` Re: RFC: Logging plan of the running query jian he <[email protected]> 2024-02-12 00:00 ` Re: RFC: Logging plan of the running query jian he <[email protected]> 2024-02-12 04:39 ` Re: RFC: Logging plan of the running query Ashutosh Bapat <[email protected]> 2024-02-13 02:30 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-14 06:29 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-15 09:12 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]> 2024-02-15 18:59 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]> 2024-02-16 14:42 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]> 2024-02-20 04:53 ` Re: RFC: Logging plan of the running query Robert Haas <[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