Re: Record queryid when auto_explain.log_verbose is on

From: torikoshia <torikoshia(at)oss(dot)nttdata(dot)com>
To: Justin Pryzby <pryzby(at)telsasoft(dot)com>, rjuju123(at)gmail(dot)com
Cc: pgsql-hackers(at)postgresql(dot)org
Subject: Re: Record queryid when auto_explain.log_verbose is on
Date: 2023-01-17 13:53:23
Message-ID: 4dc1e9a309e854b26c799b975eee8d68@oss.nttdata.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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 Content-Type Size
v2-0001-make-auto_explain-record-queryid.patch text/x-diff 1.5 KB

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Ilaria Battiston 2023-01-17 13:59:48 GSoC 2023
Previous Message Robert Haas 2023-01-17 13:46:12 Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?