Hi, The code looks good. Some comments on the tests:
+-- last_execution_start timestamp tests +-- +-- Reset stats first to avoid queryId collisions: simple "SELECT const AS alias" +-- queries all share the same normalized structure as the STMTTS queries above, +-- so EXECSTART entries would otherwise land on the pre-existing STMTTS entry. +SELECT pg_stat_statements_reset() IS NOT NULL AS t; I don't think the comment on queryId collision is necessary. Looking at other tests, it's a common pattern to do a pgss reset before starting a set of tests. +-- last_execution_start should be set and >= ref_ts_upd1, because the +-- statement started after we captured the reference timestamp. +SELECT + query, + last_execution_start IS NOT NULL as has_ts, + last_execution_start >= :'ref_ts_upd1' as after_ref1, + stats_since <= last_execution_start as after_stats_since +FROM pg_stat_statements +WHERE query LIKE '%EXECSTART%' +ORDER BY query COLLATE "C"; The test is also checking stats_since and shows that last_execution_start < stats_since, is it necessary? The result is also a bit confusing, but makes sense since stats_since is the time the entry is created in pgss, which happens before ExecutorEnd. +-- Run EXECSTART1 again and verify that last_execution_start is updated. +SELECT now() AS ref_ts_upd2 \gset +SELECT 1 AS "EXECSTART1"; +SELECT + query, + last_execution_start >= :'ref_ts_upd2' as updated +FROM pg_stat_statements +WHERE query LIKE '%EXECSTART1%'; + +-- test filtering (monitoring use case): find statements that started +-- executing since our last observation (ref_ts_upd2). +SELECT count(*) as filtered_count +FROM pg_stat_statements +WHERE last_execution_start >= :'ref_ts_upd2' + AND query LIKE '%EXECSTART%'; The 'test filtering' feels redundant, we already have the list of queries executed after ref_ts_upd2. +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. When using the extended protocol with \bind \g, a Sync message is immediately sent, and since you're in an implicit transaction, finish_xact_command will drop the portal and call ExecutorEnd. Also, doing a `SELECT now()` closes the unnamed portal, even when using the simple protocol. 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; SELECT query, last_execution_start < :'query_stmt_ts' as before_next FROM pg_stat_statements WHERE query LIKE '%DEFERRED_END%' ORDER BY query COLLATE "C"; With entry->last_execution_start = GetCurrentStatementStartTimestamp(), you will have last_execution_start > query_stmt_ts since it will be using END's statement_start. With entry->last_execution_start = exec_start, you use the statement start set during the Bind message, which should be smaller than statement_timestamp() (which is the statement start set during the Execute message). On that note, I wonder if relying on GetCurrentStatementStartTimestamp() wouldn't be good enough? That would remove the need to keep track of this state in EState. Regards, Anthonin Bonnefoy
