Re: Record queryid when auto_explain.log_verbose is on

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.