Record queryid when auto_explain.log_verbose is on

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 ?

/messages/by-id/20200308142644.vlihk7djpwqjkp7w@nol

--
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 ?

/messages/by-id/20200308142644.vlihk7djpwqjkp7w@nol

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

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 ?

/messages/by-id/20200308142644.vlihk7djpwqjkp7w@nol

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 ?

/messages/by-id/20200308142644.vlihk7djpwqjkp7w@nol

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

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

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

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

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

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

I am wondering if this patch should be backpatched?

The reason being is in auto_explain documentation [1]https://www.postgresql.org/docs/14/auto-explain.html,
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)