Re: Record queryid when auto_explain.log_verbose is on

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