Re: [PATCH v4] pg_stat_statements: Add last_execution_start column

Hi,

Sorry for the delay in response to this. I spent time today looking at
v4 and here are my comments.

1/
v4 captures the timestamp conditionally inside the pgss hook, meaning that
there is an ownership issue with this field. It's a core field, so only
core should set it, and extensions should only read it.

It is best that queryDesc->estate->es_exec_start is set inside ExecutorStart.

```
/* pgss_ExecutorStart (original) */
static void
pgss_ExecutorStart(QueryDesc *queryDesc, int eflags)
{
if (prev_ExecutorStart)
prev_ExecutorStart(queryDesc, eflags);
else
standard_ExecutorStart(queryDesc, eflags);

/*
* Capture the statement start timestamp into EState here after the estate
* has been created by standard_ExecutorStart.
*/
if (pgss_enabled(nesting_level) && queryDesc->plannedstmt->queryId
!= INT64CONST(0))
queryDesc->estate->es_exec_start = GetCurrentStatementStartTimestamp();
}
```

Also, in pgss_ProcessUtility, we should not call
GetCurrentStatementStartTimestamp() directly,
but rather should track an execution start time field in PlannedStmt.

```
@@ -1212,7 +1228,8 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const
char *queryString,
NULL,
0,
0,
- saved_planOrigin);
+ saved_planOrigin,
+ GetCurrentStatementStartTimestamp());
```

PlannedStmt docs already acknowledge it being used this way:

```
* For simplicity in APIs, we also wrap utility statements in PlannedStmt
* nodes; in such cases, commandType == CMD_UTILITY, the statement itself
* is in the utilityStmt field, and the rest of the struct is mostly dummy.
* (We do use canSetTag, stmt_location, stmt_len, and possibly queryId.)
```

Note that ProcessUtility receives a potentially read-only tree when called from
the plan cache (readOnlyTree == true). We need to copyObject before writing
es_exec_start, otherwise we corrupt the cached plan. standard_ProcessUtility
already does this copy internally, but hooks never see it:

```
/*
* If the given node tree is read-only, make a copy to ensure that parse
* transformations don't damage the original tree. This could be
* refactored to avoid making unnecessary copies in more cases, but it's
* not clear that it's worth a great deal of trouble over. Statements
* that are complex enough to be expensive to copy are exactly the ones
* we'd need to copy, so that only marginal savings seem possible.
*/
if (readOnlyTree)
pstmt = copyObject(pstmt);
```

So the copy needs to happen in ProcessUtility() itself, before calling into
hooks:

```
if (readOnlyTree)
pstmt = copyObject(pstmt);
pstmt->es_exec_start = GetCurrentStatementStartTimestamp();
```

Also note that currently pgss_ProcessUtility already sets
pstmt->queryId before calling
through to standard_ProcessUtility, which looks like a latent bug.

```
if (enabled)
pstmt->queryId = INT64CONST(0);
```
Adding TimestampTz to PlannedStmt also requires teaching gen_node_support.pl
about the type.

2/

Also, Why do we need to track last_execution_start time for the planner?
This field is for the last time the query execution start.

```
@@ -958,7 +965,8 @@ pgss_planner(Query *parse,
NULL,
0,
0,
- result->planOrigin);
+ result->planOrigin,
+ GetCurrentStatementStartTimestamp());
```

3/ DDL tests are needed. Right now, we are only testing DML.

4/ To some points made earlier here regarding the test [1]

> +SELECT now() AS ref_ts_ext \gset
> +-- Use \bind \g to force the extended query protocol.
> +SELECT pg_sleep(0.5) AS "DEFERRED_END" \bind \g
> +-- Capture a timestamp *after* the sleep finishes but *before* the next
> +-- extended-protocol statement replaces the unnamed portal.
> +SELECT now() AS ref_ts_ext2 \gset
> +-- The pg_sleep query's last_execution_start should be close to ref_ts_ext
> +-- (before the sleep), NOT to ref_ts_ext2 (after the sleep).

> I think the test doesn't work, or at least, doesn't check what you're
> expecting. If I set last_execution_start to
> GetCurrentStatementStartTimestamp(), it still passes.

correct. The deferred test needs to be done in an explicit transaction

> You could do something like that (and avoid a pg_sleep):

> BEGIN;
> SELECT 1 AS DEFERRED_END, statement_timestamp() AS query_stmt_ts \bind \gset
> -- With an explicit transaction + extended protocol, the portal is left opened
> -- ExecutorEnd will only be called when the next command is processed
> END;

That is a better, and much simpler test.

[1] https://www.postgresql.org/message-id/CAO6_XqoRLxL2%2BFsaE3JbwOH%2BoZ%3DCAjN8yK9-%2Bp7QeH_LY5B%2Bag%40mail.gmail.com

--
Sami Imseih
Amazon Web Services (AWS)