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