Thread: Record queryid when auto_explain.log_verbose is on

Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
Julien Rouhaud
Date:
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.



Re: Record queryid when auto_explain.log_verbose is on

From
Justin Pryzby
Date:
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



Re: Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
Julien Rouhaud
Date:
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.



Re: Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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



Re: Record queryid when auto_explain.log_verbose is on

From
Michael Paquier
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
Michael Paquier
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
Michael Paquier
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
Michael Paquier
Date:
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

Re: Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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



Re: Record queryid when auto_explain.log_verbose is on

From
Michael Paquier
Date:
On Thu, Jan 26, 2023 at 10:00:04PM +0900, torikoshia wrote:
> I'll work on this next.

Cool, thanks!
--
Michael

Attachment

Re: Record queryid when auto_explain.log_verbose is on

From
"Imseih (AWS), Sami"
Date:
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)



Re: Record queryid when auto_explain.log_verbose is on

From
torikoshia
Date:
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



Re: Record queryid when auto_explain.log_verbose is on

From
"Imseih (AWS), Sami"
Date:
> > 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)