Thread: Record queryid when auto_explain.log_verbose is on
Hi, As far as I read the manual below, auto_explain.log_verbose should record logs equivalent to VERBOSE option of EXPLAIN. > -- https://www.postgresql.org/docs/devel/auto-explain.html > auto_explain.log_verbose controls whether verbose details are printed > when an execution plan is logged; it's equivalent to the VERBOSE option > of EXPLAIN. However, when compute_query_id is on, query identifiers are only printed when using VERBOSE option of EXPLAIN. EXPLAIN VERBOSE: ``` =# show auto_explain.log_verbose; auto_explain.log_verbose -------------------------- on (1 row) =# show compute_query_id; compute_query_id ------------------ on (1 row) =# explain verbose select 1; QUERY PLAN ------------------------------------------ Result (cost=0.00..0.01 rows=1 width=4) Output: 1 Query Identifier: -1801652217649936326 (3 rows) ``` auto_explain: ``` LOG: 00000: duration: 0.000 ms plan: Query Text: explain verbose select 1; Result (cost=0.00..0.01 rows=1 width=4) Output: 1 ``` Attached patch makes auto_explain also print query identifiers. What do you think? -- Regards, -- Atsushi Torikoshi NTT DATA CORPORATION
Attachment
Hi,
On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote:
>
> As far as I read the manual below, auto_explain.log_verbose should record
> logs equivalent to VERBOSE option of EXPLAIN.
Ah good catch, that's clearly an oversight!
> Attached patch makes auto_explain also print query identifiers.
>
> What do you think?
@@ -407,6 +408,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
ExplainPrintTriggers(es, queryDesc);
if (es->costs)
ExplainPrintJITSummary(es, queryDesc);
+ if (es->verbose && queryDesc->plannedstmt->queryId != UINT64CONST(0))
+ ExplainPropertyInteger("Query Identifier", NULL, (int64)
+ queryDesc->plannedstmt->queryId, es);
For interactive EXPLAIN the query identifier is printed just after the plan,
before the triggers and the JIT summary so auto_explain should do the same.
Other than that looks good to me.
On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote: > Attached patch makes auto_explain also print query identifiers. This was asked during the initial patch; does your patch address the issues here ? https://www.postgresql.org/message-id/20200308142644.vlihk7djpwqjkp7w%40nol -- Justin
On 2023-01-16 22:07, Julien Rouhaud wrote:
> Hi,
>
> On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote:
>>
>> As far as I read the manual below, auto_explain.log_verbose should
>> record
>> logs equivalent to VERBOSE option of EXPLAIN.
>
> Ah good catch, that's clearly an oversight!
>
>> Attached patch makes auto_explain also print query identifiers.
>>
>> What do you think?
>
> @@ -407,6 +408,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
> ExplainPrintTriggers(es, queryDesc);
> if (es->costs)
> ExplainPrintJITSummary(es, queryDesc);
> + if (es->verbose && queryDesc->plannedstmt->queryId !=
> UINT64CONST(0))
> + ExplainPropertyInteger("Query Identifier", NULL, (int64)
> + queryDesc->plannedstmt->queryId, es);
>
> For interactive EXPLAIN the query identifier is printed just after the
> plan,
> before the triggers and the JIT summary so auto_explain should do the
> same.
Thanks for the comment!
Agreed and updated the patch.
On 2023-01-17 03:53, Justin Pryzby wrote:
> On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote:
>> Attached patch makes auto_explain also print query identifiers.
>
> This was asked during the initial patch; does your patch address the
> issues here ?
>
> https://www.postgresql.org/message-id/20200308142644.vlihk7djpwqjkp7w%40nol
Thanks!
I may misunderstand something, but it seems that the issue occurred
since queryid was calculated in pgss_post_parse_analyze() at that time.
```
--- queryid_exposure-v6.diff, which is the patch just before the
discussion
@@ -792,16 +801,34 @@ pgss_post_parse_analyze(ParseState *pstate, Query
*query)
..snip..
if (query->utilityStmt)
{
- query->queryId = UINT64CONST(0);
+ if (pgss_track_utility &&
PGSS_HANDLED_UTILITY(query->utilityStmt)
+ && pstate->p_sourcetext)
+ {
+ const char *querytext = pstate->p_sourcetext;
+ int query_location = query->stmt_location;
+ int query_len = query->stmt_len;
+
+ /*
+ * Confine our attention to the relevant part of the string,
if the
+ * query is a portion of a multi-statement source string.
+ */
+ querytext = pgss_clean_querytext(pstate->p_sourcetext,
+ &query_location,
+ &query_len);
+
+ query->queryId = pgss_compute_utility_queryid(querytext,
query_len);
```
Currently queryId is not calculated in pgss_post_parse_analyze() and the
issue does not occur, doesn't it?
I confirmed the attached patch logged queryid for some utility
statements.
```
LOG: 00000: duration: 0.017 ms plan:
Query Text: prepare p1 as select 1;
Result (cost=0.00..0.01 rows=1 width=4)
Output: 1
Query Identifier: -1801652217649936326
```
--
Regards,
--
Atsushi Torikoshi
NTT DATA CORPORATION
Attachment
Hi, On Tue, Jan 17, 2023 at 10:53:23PM +0900, torikoshia wrote: > > > > For interactive EXPLAIN the query identifier is printed just after the > > plan, > > before the triggers and the JIT summary so auto_explain should do the > > same. > Thanks for the comment! > Agreed and updated the patch. Thanks! > On 2023-01-17 03:53, Justin Pryzby wrote: > > On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote: > > > Attached patch makes auto_explain also print query identifiers. > > > > This was asked during the initial patch; does your patch address the > > issues here ? > > > > https://www.postgresql.org/message-id/20200308142644.vlihk7djpwqjkp7w%40nol > > Thanks! > I may misunderstand something, but it seems that the issue occurred since > queryid was calculated in pgss_post_parse_analyze() at that time. > > ``` > --- queryid_exposure-v6.diff, which is the patch just before the discussion > @@ -792,16 +801,34 @@ pgss_post_parse_analyze(ParseState *pstate, Query > *query) > ..snip.. > > if (query->utilityStmt) > { > - query->queryId = UINT64CONST(0); > + if (pgss_track_utility && PGSS_HANDLED_UTILITY(query->utilityStmt) > + && pstate->p_sourcetext) > + { > + const char *querytext = pstate->p_sourcetext; > + int query_location = query->stmt_location; > + int query_len = query->stmt_len; > + > + /* > + * Confine our attention to the relevant part of the string, if > the > + * query is a portion of a multi-statement source string. > + */ > + querytext = pgss_clean_querytext(pstate->p_sourcetext, > + &query_location, > + &query_len); > + > + query->queryId = pgss_compute_utility_queryid(querytext, > query_len); > ``` > > Currently queryId is not calculated in pgss_post_parse_analyze() and the > issue does not occur, doesn't it? > I confirmed the attached patch logged queryid for some utility statements. > > ``` > LOG: 00000: duration: 0.017 ms plan: > Query Text: prepare p1 as select 1; > Result (cost=0.00..0.01 rows=1 width=4) > Output: 1 > Query Identifier: -1801652217649936326 > ``` Yes, this problem was fixed a long time ago. Just to be sure I checked that auto_explain and explain agree on the queryid: =# select count(*) from pg_class; [...] LOG: duration: 0.239 ms plan: Query Text: select count(*) from pg_class; Aggregate (cost=15.45..15.46 rows=1 width=8) Output: count(*) -> Index Only Scan using pg_class_tblspc_relfilenode_index on pg_catalog.pg_class (cost=0.15..14.40 rows=417 width=0) Output: reltablespace, relfilenode Query Identifier: 2855866587085353326 =# explain (verbose) select count(*) from pg_class; QUERY PLAN > -------------------------------------------------------------------------------------------------------------> Aggregate (cost=15.45..15.46 rows=1 width=8) Output: count(*) -> Index Only Scan using pg_class_tblspc_relfilenode_index on pg_catalog.pg_class (cost=0.15..14.40 rows> Output: reltablespace, relfilenode Query Identifier: 2855866587085353326 LOG: duration: 0.000 ms plan: Query Text: explain (verbose) select count(*) from pg_class; Aggregate (cost=15.45..15.46 rows=1 width=8) Output: count(*) -> Index Only Scan using pg_class_tblspc_relfilenode_index on pg_catalog.pg_class (cost=0.15..14.40 rows=417 width=0) Output: reltablespace, relfilenode Query Identifier: 2855866587085353326 So the patch looks good to me. I didn't find any entry in the commitfest, did I miss it? If not, could you create one (feel free to add me and Justin as reviewer, and probably mark is as RfC). It's a bit annoying that the info is missing since pg 14, but we probably can't backpatch this as it might break log parser tools.
On 2023-01-19 19:05, Julien Rouhaud wrote: > Hi, > > On Tue, Jan 17, 2023 at 10:53:23PM +0900, torikoshia wrote: >> > >> > For interactive EXPLAIN the query identifier is printed just after the >> > plan, >> > before the triggers and the JIT summary so auto_explain should do the >> > same. >> Thanks for the comment! >> Agreed and updated the patch. > > Thanks! > >> On 2023-01-17 03:53, Justin Pryzby wrote: >> > On Mon, Jan 16, 2023 at 09:36:59PM +0900, torikoshia wrote: >> > > Attached patch makes auto_explain also print query identifiers. >> > >> > This was asked during the initial patch; does your patch address the >> > issues here ? >> > >> > https://www.postgresql.org/message-id/20200308142644.vlihk7djpwqjkp7w%40nol >> >> Thanks! >> I may misunderstand something, but it seems that the issue occurred >> since >> queryid was calculated in pgss_post_parse_analyze() at that time. >> >> ``` >> --- queryid_exposure-v6.diff, which is the patch just before the >> discussion >> @@ -792,16 +801,34 @@ pgss_post_parse_analyze(ParseState *pstate, >> Query >> *query) >> ..snip.. >> >> if (query->utilityStmt) >> { >> - query->queryId = UINT64CONST(0); >> + if (pgss_track_utility && >> PGSS_HANDLED_UTILITY(query->utilityStmt) >> + && pstate->p_sourcetext) >> + { >> + const char *querytext = pstate->p_sourcetext; >> + int query_location = query->stmt_location; >> + int query_len = query->stmt_len; >> + >> + /* >> + * Confine our attention to the relevant part of the >> string, if >> the >> + * query is a portion of a multi-statement source string. >> + */ >> + querytext = pgss_clean_querytext(pstate->p_sourcetext, >> + &query_location, >> + &query_len); >> + >> + query->queryId = pgss_compute_utility_queryid(querytext, >> query_len); >> ``` >> >> Currently queryId is not calculated in pgss_post_parse_analyze() and >> the >> issue does not occur, doesn't it? >> I confirmed the attached patch logged queryid for some utility >> statements. >> >> ``` >> LOG: 00000: duration: 0.017 ms plan: >> Query Text: prepare p1 as select 1; >> Result (cost=0.00..0.01 rows=1 width=4) >> Output: 1 >> Query Identifier: -1801652217649936326 >> ``` > > Yes, this problem was fixed a long time ago. Just to be sure I checked > that > auto_explain and explain agree on the queryid: Thanks for your comment and check! > > =# select count(*) from pg_class; > [...] > LOG: duration: 0.239 ms plan: > Query Text: select count(*) from pg_class; > Aggregate (cost=15.45..15.46 rows=1 width=8) > Output: count(*) > -> Index Only Scan using pg_class_tblspc_relfilenode_index on > pg_catalog.pg_class (cost=0.15..14.40 rows=417 width=0) > Output: reltablespace, relfilenode > Query Identifier: 2855866587085353326 > > =# explain (verbose) select count(*) from pg_class; > QUERY PLAN > > > -------------------------------------------------------------------------------------------------------------> > Aggregate (cost=15.45..15.46 rows=1 width=8) > Output: count(*) > -> Index Only Scan using pg_class_tblspc_relfilenode_index on > pg_catalog.pg_class (cost=0.15..14.40 rows> > Output: reltablespace, relfilenode > Query Identifier: 2855866587085353326 > > LOG: duration: 0.000 ms plan: > Query Text: explain (verbose) select count(*) from pg_class; > Aggregate (cost=15.45..15.46 rows=1 width=8) > Output: count(*) > -> Index Only Scan using pg_class_tblspc_relfilenode_index on > pg_catalog.pg_class (cost=0.15..14.40 rows=417 width=0) > Output: reltablespace, relfilenode > Query Identifier: 2855866587085353326 > > So the patch looks good to me. I didn't find any entry in the > commitfest, did > I miss it? If not, could you create one (feel free to add me and > Justin as > reviewer, and probably mark is as RfC). Sorry to make you go through the trouble of looking for it. I've now created it. https://commitfest.postgresql.org/42/4136/ > > It's a bit annoying that the info is missing since pg 14, but we > probably can't > backpatch this as it might break log parser tools. +1 -- Regards, -- Atsushi Torikoshi NTT DATA CORPORATION
On Fri, Jan 20, 2023 at 11:43:51AM +0900, torikoshia wrote: > Sorry to make you go through the trouble of looking for it. > I've now created it. > https://commitfest.postgresql.org/42/4136/ FWIW, no objections from here. This maps with EXPLAIN where the query ID is only printed under VERBOSE. -- Michael
Attachment
On Fri, Jan 20, 2023 at 12:32:58PM +0900, Michael Paquier wrote: > FWIW, no objections from here. This maps with EXPLAIN where the query > ID is only printed under VERBOSE. While looking at this change, I have been wondering about something.. Isn't the knowledge of the query ID something that should be pushed within ExplainPrintPlan() so as we don't duplicate in two places the checks that show it? In short, the patch ignores the case where compute_query_id = regress in auto_explain. ExplainPrintTriggers() is kind of different because there is auto_explain_log_triggers. Still, we could add a flag in ExplainState deciding if the triggers should be printed, so as it would be possible to move ExplainPrintTriggers() and ExplainPrintJITSummary() within ExplainPrintPlan(), as well? The same kind of logic could be applied for the planning time and the buffer usage if these are tracked in ExplainState rather than being explicit arguments of ExplainOnePlan(). Not to mention that this reduces the differences between ExplainOneUtility() and ExplainOnePlan(). Leaving this comment aside, I think that this should have at least one regression test in 001_auto_explain.pl, where query_log() can be called while the verbose GUC of auto_explain is enabled. -- Michael
Attachment
On 2023-01-23 09:35, Michael Paquier wrote: > On Fri, Jan 20, 2023 at 12:32:58PM +0900, Michael Paquier wrote: >> FWIW, no objections from here. This maps with EXPLAIN where the query >> ID is only printed under VERBOSE. > > While looking at this change, I have been wondering about something.. > Isn't the knowledge of the query ID something that should be pushed > within ExplainPrintPlan() so as we don't duplicate in two places the > checks that show it? In short, the patch ignores the case where > compute_query_id = regress in auto_explain. Thanks! It seems better and updated the patch. > > ExplainPrintTriggers() is kind of different because there is > auto_explain_log_triggers. Still, we could add a flag in ExplainState > deciding if the triggers should be printed, so as it would be possible > to move ExplainPrintTriggers() and ExplainPrintJITSummary() within > ExplainPrintPlan(), as well? The same kind of logic could be applied > for the planning time and the buffer usage if these are tracked in > ExplainState rather than being explicit arguments of ExplainOnePlan(). > Not to mention that this reduces the differences between > ExplainOneUtility() and ExplainOnePlan(). Hmm, this refactoring would worth considering, but should be done in another patch? > Leaving this comment aside, I think that this should have at least one > regression test in 001_auto_explain.pl, where query_log() can be > called while the verbose GUC of auto_explain is enabled. Agreed. Added a test for queryid logging. > -- > Michael -- Regards, -- Atsushi Torikoshi NTT DATA CORPORATION
Attachment
On Tue, Jan 24, 2023 at 11:01:46PM +0900, torikoshia wrote: > On 2023-01-23 09:35, Michael Paquier wrote: >> ExplainPrintTriggers() is kind of different because there is >> auto_explain_log_triggers. Still, we could add a flag in ExplainState >> deciding if the triggers should be printed, so as it would be possible >> to move ExplainPrintTriggers() and ExplainPrintJITSummary() within >> ExplainPrintPlan(), as well? The same kind of logic could be applied >> for the planning time and the buffer usage if these are tracked in >> ExplainState rather than being explicit arguments of ExplainOnePlan(). >> Not to mention that this reduces the differences between >> ExplainOneUtility() and ExplainOnePlan(). > > Hmm, this refactoring would worth considering, but should be done in another > patch? It could be. That's fine by me to not do that as a first step as the query ID computation is done just after ExplainPrintPlan(). An argument could be made about ExplainPrintPlan(), though compute_query_id = regress offers an option to control that, as well. >> Leaving this comment aside, I think that this should have at least one >> regression test in 001_auto_explain.pl, where query_log() can be >> called while the verbose GUC of auto_explain is enabled. > > Agreed. > Added a test for queryid logging. Thanks. Will check and probably apply on HEAD. -- Michael
Attachment
On Wed, Jan 25, 2023 at 04:46:36PM +0900, Michael Paquier wrote: > Thanks. Will check and probably apply on HEAD. Done, after adding one test case with compute_query_id=regress and applying some indentation. -- Michael
Attachment
On 2023-01-26 12:40, Michael Paquier wrote: > On Wed, Jan 25, 2023 at 04:46:36PM +0900, Michael Paquier wrote: >> Thanks. Will check and probably apply on HEAD. > > Done, after adding one test case with compute_query_id=regress and > applying some indentation. > -- > Michael Thanks! >> On 2023-01-23 09:35, Michael Paquier wrote: >>> ExplainPrintTriggers() is kind of different because there is >>> auto_explain_log_triggers. Still, we could add a flag in >>> ExplainState >>> deciding if the triggers should be printed, so as it would be >>> possible >>> to move ExplainPrintTriggers() and ExplainPrintJITSummary() within >>> ExplainPrintPlan(), as well? The same kind of logic could be applied >>> for the planning time and the buffer usage if these are tracked in >>> ExplainState rather than being explicit arguments of >>> ExplainOnePlan(). >>> Not to mention that this reduces the differences between >>> ExplainOneUtility() and ExplainOnePlan(). I'll work on this next. -- Regards, -- Atsushi Torikoshi NTT DATA CORPORATION
On Thu, Jan 26, 2023 at 10:00:04PM +0900, torikoshia wrote: > I'll work on this next. Cool, thanks! -- Michael
Attachment
I am wondering if this patch should be backpatched? The reason being is in auto_explain documentation [1], there is a claim of equivalence of the auto_explain.log_verbose option and EXPLAIN(verbose) "..... it's equivalent to the VERBOSE option of EXPLAIN." This can be quite confusing for users of the extension. The documentation should either be updated or a backpatch all the way down to 14, which the version the query identifier was moved to core. I am in favor of the latter. Any thoughts? [1] https://www.postgresql.org/docs/14/auto-explain.html Regards, -- Sami Imseih Amazon Web Services (AWS)
On 2023-03-07 08:50, Imseih (AWS), Sami wrote: > I am wondering if this patch should be backpatched? > > The reason being is in auto_explain documentation [1], > there is a claim of equivalence of the auto_explain.log_verbose > option and EXPLAIN(verbose) > > "..... it's equivalent to the VERBOSE option of EXPLAIN." > > This can be quite confusing for users of the extension. > The documentation should either be updated or a backpatch > all the way down to 14, which the version the query identifier > was moved to core. I am in favor of the latter. > > Any thoughts? We discussed a bit whether to backpatch this, but agreed that it would be better not to do so for the following reasons: > It's a bit annoying that the info is missing since pg 14, but we > probably can't > backpatch this as it might break log parser tools. What do you think? -- Regards, -- Atsushi Torikoshi NTT DATA CORPORATION
> > It's a bit annoying that the info is missing since pg 14, but we > > probably can't > > backpatch this as it might break log parser tools. > What do you think? That's a good point about log parsing tools, i.e. pgbadger. Backpatching does not sounds to appealing to me after giving this a second thought. However, I do feel it needs to be called out in docs, that "Query Identifier" is not available in auto_explain until version 16. Regards, -- Sami Imseih Amazon Web Services (AWS)