Planning counters in pg_stat_statements
Hi hackers,
I have often wanted $SUBJECT and was happy to find that Fujii-san had
posted a patch five years ago[1]/messages/by-id/CAHGQGwFx_=DO-Gu-MfPW3VQ4qC7TfVdH2zHmvZfrGv6fQ3D-Tw@mail.gmail.com. The reception then seemed positive.
So here is a refurbished and (hopefully) improved version of his patch
with a new column for the replan count. Thoughts?
Example output:
query | plans | plan_time | calls | total_time
--------------------------------+-------+-----------+-------+------------
prepare x as select $1 | 1 | 0.026 | 12 | 0.06
select substr(query, $1, $2), | 11 | 1.427 | 11 | 3.565
prepare y as select * from foo | 2 | 7.336 | 5 | 0.331
I agree with the sentiment on the old thread that
{total,min,max,mean,stddev}_time now seem badly named, but adding
"execution" makes them so long... Thoughts?
[1]: /messages/by-id/CAHGQGwFx_=DO-Gu-MfPW3VQ4qC7TfVdH2zHmvZfrGv6fQ3D-Tw@mail.gmail.com
--
Thomas Munro
http://www.enterprisedb.com
Attachments:
pg-stat-statements-planning-v1.patchapplication/octet-stream; name=pg-stat-statements-planning-v1.patchDownload
From 06c611027cdf3af52a13f295d4c3a33bcb08d229 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@enterprisedb.com>
Date: Tue, 7 Nov 2017 17:33:24 +1300
Subject: [PATCH] Add plan count and time to pg_stat_statements.
This allows administrators to look out for statements that should ideally be
changed to prepared statements, and monitor how often prepared statements
are [re]planned.
Author: Fujii Masao and Thomas Munro
Discussion: https://postgr.es/m/CAHGQGwFx_%3DDO-Gu-MfPW3VQ4qC7TfVdH2zHmvZfrGv6fQ3D-Tw%40mail.gmail.com
---
contrib/pg_stat_statements/Makefile | 2 +-
.../expected/pg_stat_statements.out | 64 ++++++++++++
.../pg_stat_statements/pg_stat_statements--1.5.sql | 50 ++++++++++
contrib/pg_stat_statements/pg_stat_statements.c | 110 +++++++++++++++++++--
.../pg_stat_statements/sql/pg_stat_statements.sql | 16 +++
doc/src/sgml/pgstatstatements.sgml | 17 +++-
src/backend/nodes/copyfuncs.c | 1 +
src/backend/nodes/outfuncs.c | 1 +
src/backend/nodes/readfuncs.c | 1 +
src/backend/optimizer/plan/planner.c | 1 +
src/include/nodes/plannodes.h | 4 +
11 files changed, 258 insertions(+), 9 deletions(-)
create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.5.sql
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 39b368b70eb..4d658d0ec74 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -4,7 +4,7 @@ MODULE_big = pg_stat_statements
OBJS = pg_stat_statements.o $(WIN32RES)
EXTENSION = pg_stat_statements
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.4--1.5.sql \
+DATA = pg_stat_statements--1.5.sql pg_stat_statements--1.4--1.5.sql \
pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \
pg_stat_statements--1.1--1.2.sql pg_stat_statements--1.0--1.1.sql \
pg_stat_statements--unpackaged--1.0.sql
diff --git a/contrib/pg_stat_statements/expected/pg_stat_statements.out b/contrib/pg_stat_statements/expected/pg_stat_statements.out
index 5318c3550c7..76669176447 100644
--- a/contrib/pg_stat_statements/expected/pg_stat_statements.out
+++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out
@@ -395,4 +395,68 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
SELECT pg_stat_statements_reset() | 1 | 1
(8 rows)
+--
+-- [re]plan counting
+--
+SELECT pg_stat_statements_reset();
+ pg_stat_statements_reset
+--------------------------
+
+(1 row)
+
+CREATE TABLE test ();
+PREPARE prep1 AS SELECT COUNT(*) FROM test;;
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+ALTER TABLE test ADD COLUMN x int;
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT query, plans, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+ query | plans | calls | rows
+--------------------------------------------+-------+-------+------
+ ALTER TABLE test ADD COLUMN x int | 0 | 1 | 0
+ CREATE TABLE test () | 0 | 1 | 0
+ PREPARE prep1 AS SELECT COUNT(*) FROM test | 2 | 4 | 4
+ SELECT $1 | 3 | 3 | 3
+ SELECT pg_stat_statements_reset() | 1 | 1 | 1
+(5 rows)
+
DROP EXTENSION pg_stat_statements;
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.5.sql b/contrib/pg_stat_statements/pg_stat_statements--1.5.sql
new file mode 100644
index 00000000000..c211bcf8801
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.5.sql
@@ -0,0 +1,50 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.5.sql */
+
+-- complain if script is sourced in psql, rather than via CREATE EXTENSION
+\echo Use "CREATE EXTENSION pg_stat_statements" to load this file. \quit
+
+-- Register functions.
+CREATE FUNCTION pg_stat_statements_reset()
+RETURNS void
+AS 'MODULE_PATHNAME'
+LANGUAGE C PARALLEL SAFE;
+
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT plan_time float8,
+ OUT calls int8,
+ OUT total_time float8,
+ OUT min_time float8,
+ OUT max_time float8,
+ OUT mean_time float8,
+ OUT stddev_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT blk_read_time float8,
+ OUT blk_write_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_4'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+-- Register a view on the function for ease of use.
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
+
+-- Don't want this to be available to non-superusers.
+REVOKE ALL ON FUNCTION pg_stat_statements_reset() FROM PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 3de8333be2b..9ff91fb25ca 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -1,7 +1,7 @@
/*-------------------------------------------------------------------------
*
* pg_stat_statements.c
- * Track statement execution times across a whole database cluster.
+ * Track statement planning and execution times across a whole cluster.
*
* Execution costs are totalled for each distinct source query, and kept in
* a shared hashtable. (We track only as many distinct queries as will fit
@@ -67,6 +67,7 @@
#include "funcapi.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
+#include "optimizer/planner.h"
#include "parser/analyze.h"
#include "parser/parsetree.h"
#include "parser/scanner.h"
@@ -119,7 +120,8 @@ typedef enum pgssVersion
PGSS_V1_0 = 0,
PGSS_V1_1,
PGSS_V1_2,
- PGSS_V1_3
+ PGSS_V1_3,
+ PGSS_V1_4
} pgssVersion;
/*
@@ -149,6 +151,8 @@ typedef struct Counters
double max_time; /* maximum execution time in msec */
double mean_time; /* mean execution time in msec */
double sum_var_time; /* sum of variances in execution time in msec */
+ int64 plans; /* # of times planned */
+ double plan_time; /* total planning time, in msec */
int64 rows; /* total # of retrieved or affected rows */
int64 shared_blks_hit; /* # of shared buffer hits */
int64 shared_blks_read; /* # of shared disk blocks read */
@@ -237,6 +241,7 @@ static int nested_level = 0;
/* Saved hook values in case of unload */
static shmem_startup_hook_type prev_shmem_startup_hook = NULL;
+static planner_hook_type prev_planner_hook = NULL;
static post_parse_analyze_hook_type prev_post_parse_analyze_hook = NULL;
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
@@ -291,10 +296,14 @@ void _PG_fini(void);
PG_FUNCTION_INFO_V1(pg_stat_statements_reset);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_2);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_4);
PG_FUNCTION_INFO_V1(pg_stat_statements);
static void pgss_shmem_startup(void);
static void pgss_shmem_shutdown(int code, Datum arg);
+static PlannedStmt *pgss_planner_hook(Query *parse,
+ int cursorOptions,
+ ParamListInfo boundParams);
static void pgss_post_parse_analyze(ParseState *pstate, Query *query);
static void pgss_ExecutorStart(QueryDesc *queryDesc, int eflags);
static void pgss_ExecutorRun(QueryDesc *queryDesc,
@@ -309,7 +318,9 @@ static void pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
static uint64 pgss_hash_string(const char *str, int len);
static void pgss_store(const char *query, uint64 queryId,
int query_location, int query_len,
- double total_time, uint64 rows,
+ double total_time,
+ double plan_time,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
@@ -422,6 +433,8 @@ _PG_init(void)
*/
prev_shmem_startup_hook = shmem_startup_hook;
shmem_startup_hook = pgss_shmem_startup;
+ prev_planner_hook = planner_hook;
+ planner_hook = pgss_planner_hook;
prev_post_parse_analyze_hook = post_parse_analyze_hook;
post_parse_analyze_hook = pgss_post_parse_analyze;
prev_ExecutorStart = ExecutorStart_hook;
@@ -445,6 +458,7 @@ _PG_fini(void)
/* Uninstall hooks. */
shmem_startup_hook = prev_shmem_startup_hook;
post_parse_analyze_hook = prev_post_parse_analyze_hook;
+ planner_hook = prev_planner_hook;
ExecutorStart_hook = prev_ExecutorStart;
ExecutorRun_hook = prev_ExecutorRun;
ExecutorFinish_hook = prev_ExecutorFinish;
@@ -770,6 +784,54 @@ error:
unlink(PGSS_TEXT_FILE);
}
+/*
+ * Planner hook: forward to regular planner, but measure planning time.
+ */
+static PlannedStmt *pgss_planner_hook(Query *parse,
+ int cursorOptions,
+ ParamListInfo boundParams)
+{
+ PlannedStmt *result;
+
+ if (pgss_enabled())
+ {
+ instr_time start;
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(start);
+
+ nested_level++;
+ PG_TRY();
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ nested_level--;
+ }
+ PG_CATCH();
+ {
+ nested_level--;
+ PG_RE_THROW();
+ }
+ PG_END_TRY();
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+
+ result->plan_time = INSTR_TIME_GET_DOUBLE(duration);
+ }
+ else
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ }
+
+ return result;
+}
+
/*
* Post-parse-analysis hook: mark query with a queryId
*/
@@ -837,6 +899,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query)
query->stmt_len,
0,
0,
+ 0,
NULL,
&jstate);
}
@@ -943,9 +1006,16 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->plannedstmt->stmt_location,
queryDesc->plannedstmt->stmt_len,
queryDesc->totaltime->total * 1000.0, /* convert to msec */
+ queryDesc->plannedstmt->plan_time * 1000.0,
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
NULL);
+
+ /*
+ * Clear plan_time, so that we only count it once for each replanning
+ * of a prepared statement.
+ */
+ queryDesc->plannedstmt->plan_time = 0;
}
if (prev_ExecutorEnd)
@@ -974,8 +1044,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
* hash table entry for the PREPARE (with hash calculated from the query
* string), and then a different one with the same query string (but hash
* calculated from the query tree) would be used to accumulate costs of
- * ensuing EXECUTEs. This would be confusing, and inconsistent with other
- * cases where planning time is not included at all.
+ * ensuing EXECUTEs.
*
* Likewise, we don't track execution of DEALLOCATE.
*/
@@ -1054,6 +1123,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
pstmt->stmt_location,
pstmt->stmt_len,
INSTR_TIME_GET_MILLISEC(duration),
+ 0,
rows,
&bufusage,
NULL);
@@ -1096,7 +1166,9 @@ pgss_hash_string(const char *str, int len)
static void
pgss_store(const char *query, uint64 queryId,
int query_location, int query_len,
- double total_time, uint64 rows,
+ double total_time,
+ double plan_time,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate)
{
@@ -1265,6 +1337,9 @@ pgss_store(const char *query, uint64 queryId,
if (e->counters.max_time < total_time)
e->counters.max_time = total_time;
}
+ if (plan_time > 0)
+ e->counters.plans += 1;
+ e->counters.plan_time += plan_time;
e->counters.rows += rows;
e->counters.shared_blks_hit += bufusage->shared_blks_hit;
e->counters.shared_blks_read += bufusage->shared_blks_read;
@@ -1310,7 +1385,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_1 18
#define PG_STAT_STATEMENTS_COLS_V1_2 19
#define PG_STAT_STATEMENTS_COLS_V1_3 23
-#define PG_STAT_STATEMENTS_COLS 23 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_4 25
+#define PG_STAT_STATEMENTS_COLS 25 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1322,6 +1398,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_4(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_4, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_3(PG_FUNCTION_ARGS)
{
@@ -1428,6 +1514,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_3)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_4:
+ if (api_version != PGSS_V1_4)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1586,6 +1676,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (tmp.calls == 0)
continue;
+ if (api_version >= PGSS_V1_4)
+ {
+ values[i++] = Int64GetDatumFast(tmp.plans);
+ values[i++] = Float8GetDatumFast(tmp.plan_time);
+ }
values[i++] = Int64GetDatumFast(tmp.calls);
values[i++] = Float8GetDatumFast(tmp.total_time);
if (api_version >= PGSS_V1_3)
@@ -1629,6 +1724,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
api_version == PGSS_V1_2 ? PG_STAT_STATEMENTS_COLS_V1_2 :
api_version == PGSS_V1_3 ? PG_STAT_STATEMENTS_COLS_V1_3 :
+ api_version == PGSS_V1_4 ? PG_STAT_STATEMENTS_COLS_V1_4 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/contrib/pg_stat_statements/sql/pg_stat_statements.sql b/contrib/pg_stat_statements/sql/pg_stat_statements.sql
index a8361fd1bff..e15b789369a 100644
--- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql
+++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql
@@ -195,4 +195,20 @@ DROP FUNCTION PLUS_TWO(INTEGER);
SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+--
+-- [re]plan counting
+--
+SELECT pg_stat_statements_reset();
+CREATE TABLE test ();
+PREPARE prep1 AS SELECT COUNT(*) FROM test;;
+EXECUTE prep1;
+EXECUTE prep1;
+EXECUTE prep1;
+ALTER TABLE test ADD COLUMN x int;
+EXECUTE prep1;
+SELECT 42;
+SELECT 42;
+SELECT 42;
+SELECT query, plans, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+
DROP EXTENSION pg_stat_statements;
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index 4b15a268cd7..d31f08b3166 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -9,7 +9,8 @@
<para>
The <filename>pg_stat_statements</filename> module provides a means for
- tracking execution statistics of all SQL statements executed by a server.
+ tracking planning and execution statistics of all SQL statements executed by
+ a server.
</para>
<para>
@@ -82,6 +83,20 @@
<entry>Text of a representative statement</entry>
</row>
+ <row>
+ <entry><structfield>plans</structfield></entry>
+ <entry><type>bigint</type></entry>
+ <entry></entry>
+ <entry>Number of times planned</entry>
+ </row>
+
+ <row>
+ <entry><structfield>plan_time</structfield></entry>
+ <entry><type>double precision</type></entry>
+ <entry></entry>
+ <entry>Total time spent planning, in milliseconds</entry>
+ </row>
+
<row>
<entry><structfield>calls</structfield></entry>
<entry><type>bigint</type></entry>
diff --git a/src/backend/nodes/copyfuncs.c b/src/backend/nodes/copyfuncs.c
index c1a83ca9098..691e19231d3 100644
--- a/src/backend/nodes/copyfuncs.c
+++ b/src/backend/nodes/copyfuncs.c
@@ -99,6 +99,7 @@ _copyPlannedStmt(const PlannedStmt *from)
COPY_NODE_FIELD(invalItems);
COPY_SCALAR_FIELD(nParamExec);
COPY_NODE_FIELD(utilityStmt);
+ COPY_SCALAR_FIELD(plan_time);
COPY_LOCATION_FIELD(stmt_location);
COPY_LOCATION_FIELD(stmt_len);
diff --git a/src/backend/nodes/outfuncs.c b/src/backend/nodes/outfuncs.c
index 43d62062bc0..73a926fcfde 100644
--- a/src/backend/nodes/outfuncs.c
+++ b/src/backend/nodes/outfuncs.c
@@ -284,6 +284,7 @@ _outPlannedStmt(StringInfo str, const PlannedStmt *node)
WRITE_NODE_FIELD(invalItems);
WRITE_INT_FIELD(nParamExec);
WRITE_NODE_FIELD(utilityStmt);
+ WRITE_FLOAT_FIELD(plan_time, "%.0f");
WRITE_LOCATION_FIELD(stmt_location);
WRITE_LOCATION_FIELD(stmt_len);
}
diff --git a/src/backend/nodes/readfuncs.c b/src/backend/nodes/readfuncs.c
index ccb6a1f4acb..0e794e12627 100644
--- a/src/backend/nodes/readfuncs.c
+++ b/src/backend/nodes/readfuncs.c
@@ -1482,6 +1482,7 @@ _readPlannedStmt(void)
READ_NODE_FIELD(invalItems);
READ_INT_FIELD(nParamExec);
READ_NODE_FIELD(utilityStmt);
+ READ_FLOAT_FIELD(plan_time);
READ_LOCATION_FIELD(stmt_location);
READ_LOCATION_FIELD(stmt_len);
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index d58635c887c..c7b36f0f8b5 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -469,6 +469,7 @@ standard_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
result->nParamExec = glob->nParamExec;
/* utilityStmt should be null, but we might as well copy it */
result->utilityStmt = parse->utilityStmt;
+ result->plan_time = 0;
result->stmt_location = parse->stmt_location;
result->stmt_len = parse->stmt_len;
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index dd74efa9a41..512b2acbc5e 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -26,6 +26,7 @@
* ----------------------------------------------------------------
*/
+
/* ----------------
* PlannedStmt node
*
@@ -93,6 +94,9 @@ typedef struct PlannedStmt
Node *utilityStmt; /* non-null if this is utility stmt */
+ /* This is always set to 0 by the core system, but plugins can change it. */
+ double plan_time;
+
/* statement location in source string (copied from Query) */
int stmt_location; /* start location, or -1 if unknown */
int stmt_len; /* length in bytes; 0 means "rest of string" */
--
2.14.1
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Thomas Munro
I have often wanted $SUBJECT and was happy to find that Fujii-san had posted
a patch five years ago[1]. The reception then seemed positive.
So here is a refurbished and (hopefully) improved version of his patch with
a new column for the replan count. Thoughts?
That's a timely proposal. I sometimes faced performance problems where the time pg_stat_statements shows is much shorter than the application perceives. The latest experience was that the execution time of a transaction, which consists of dozens of DMLs and COMMIT, was about 200ms from the application's perspective, while pg_stat_statements showed only about 10ms in total. The network should not be the cause because the application ran on the same host as the database server. I wanted to know how long the parsing and planning time was.
BTW, the current pg_stat_statement shows unexpected time for COMMIT. I expect it to include the whole COMMIT processing, including the long WAL flush and sync rep wait. However, it only shows the time for the transaction state change in memory.
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Tue, Nov 7, 2017 at 6:39 PM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Thomas Munro
I have often wanted $SUBJECT and was happy to find that Fujii-san had posted
a patch five years ago[1]. The reception then seemed positive.
So here is a refurbished and (hopefully) improved version of his patch with
a new column for the replan count. Thoughts?That's a timely proposal. I sometimes faced performance problems where the time pg_stat_statements shows is much shorter than the application perceives. The latest experience was that the execution time of a transaction, which consists of dozens of DMLs and COMMIT, was about 200ms from the application's perspective, while pg_stat_statements showed only about 10ms in total. The network should not be the cause because the application ran on the same host as the database server. I wanted to know how long the parsing and planning time was.
Note that this patch doesn't include the parse or parse analysis
times. I guess they would be less interesting? But perhaps someone
would want to have the complete query production line measured.
BTW the reason I was looking into this was because an Oracle user
asked me how to see "hard parse" times on Postgres, and I've talked to
others who seem strangely concerned with "parsing" time. On Oracle I
believe that term covers (among other things) actually planning, and I
guess planning is the most interesting component. Planning is the
thing I've wanted to measure myself, to diagnose problems relating to
partition/inheritance planning and join explosions and to figure out
which things should be changed to PREPARE/EXECUTE. Perhaps a separate
parse/analysis counter might become more interesting for us if we ever
add automatic plan cache so you could assess how often you're getting
an implicit prepared statement (something like Oracle's "soft parse")?
BTW, the current pg_stat_statement shows unexpected time for COMMIT. I expect it to include the whole COMMIT processing, including the long WAL flush and sync rep wait. However, it only shows the time for the transaction state change in memory.
That's an interesting point. You could install a transaction hook to
measure that easily enough, but I'm not sure how useful it'd be: you'd
be grouping together COMMIT timing data from transactions that are
doing very different things (including nothing). Would that tell you
anything actionable? If you include commit time for COMMIT statements
then you'd also have to decide whether to include it for DML
statements that run in an implicit transaction. The trouble with that
is that the same statement inside an explicit transaction wouldn't
have any commit time, so you'd be mixing oranges and apples. I guess
you could fix that by putting adding "commits" and "commit_time"
columns (= counters for this statement run as implicit transaction),
but I wonder if commit time monitoring really belongs somewhere else.
For sync rep waits, that's what the pg_stat_replication.XXX_lag
columns tell you.
--
Thomas Munro
http://www.enterprisedb.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Tue, Nov 7, 2017 at 4:10 PM, Thomas Munro <thomas.munro@enterprisedb.com>
wrote:
Hi hackers,
I have often wanted $SUBJECT and was happy to find that Fujii-san had
posted a patch five years ago[1]. The reception then seemed positive.
So here is a refurbished and (hopefully) improved version of his patch
with a new column for the replan count. Thoughts?
Thanks for the patch.
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.4--1.5.sql \
+DATA = pg_stat_statements--1.5.sql pg_stat_statements--1.4--1.5.sql \The current version of the pg_stat_statements is already 1.5, this patch
should increase it to 1.6.
+/* contrib/pg_stat_statements/pg_stat_statements--1.5.sql */
Add the contents of the pg_stat_statements--1.4--1.5.sql file here,
otherwise
when the user installs this as a new extension, he will loose those changes.
+ OUT plans int8,
Addition of this column is good to find out how many time the plan is
generated
for the same query. But I am thinking "plans" column name may confuse?
+ OUT plan_time float8,
I am fine with the current name also, just checking how about
"planning_time"
similar like EXPLAIN?
+ <row>
+ <entry><structfield>plan_time</structfield></entry>
+ <entry><type>double precision</type></entry>
+ <entry></entry>
+ <entry>Total time spent planning, in milliseconds</entry>
+ </row>How about "Total time spent in the statement planning"?
And also it needs an update for the total_time column as
"Total time spent in the statement execution".
+
/* ----------------
* PlannedStmt node
*
Extra change.
Regards,
Hari Babu
Fujitsu Australia
On Thu, Jan 11, 2018 at 7:36 PM, Haribabu Kommi
<kommi.haribabu@gmail.com> wrote:
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.4--1.5.sql \ +DATA = pg_stat_statements--1.5.sql pg_stat_statements--1.4--1.5.sql \The current version of the pg_stat_statements is already 1.5, this patch
should increase it to 1.6.
Uglhl, yeah. Fixed. So I've removed the 1.4 script, added a 1.6
script and provided the 1.5->1.6 upgrade script. I've tested
installing 1.6 directly, as well as installing 1.5 from unpatched
master and then upgrading to 1.6 with ALTER EXTENSION
pg_stat_statements UPDATE TO "1.6".
+/* contrib/pg_stat_statements/pg_stat_statements--1.5.sql */
Add the contents of the pg_stat_statements--1.4--1.5.sql file here,
otherwise
when the user installs this as a new extension, he will loose those changes.
That GRANT command is now in pg_stat_statements--1.6.sql.
+ OUT plans int8,
Addition of this column is good to find out how many time the plan is
generated
for the same query. But I am thinking "plans" column name may confuse?
What else would you call that? It's the number of plans that have
been created. It sits nicely beside "calls" don't you think? I could
change it to "plan_count" but that's longer and not like "calls".
+ OUT plan_time float8,
I am fine with the current name also, just checking how about
"planning_time"
similar like EXPLAIN?
Ok, changed to planning_time.
+ <row> + <entry><structfield>plan_time</structfield></entry> + <entry><type>double precision</type></entry> + <entry></entry> + <entry>Total time spent planning, in milliseconds</entry> + </row>How about "Total time spent in the statement planning"?
Ok, changed to:
+ <entry>Total time spent planning the statement, in milliseconds</entry>
And also it needs an update for the total_time column as
"Total time spent in the statement execution".
Ok, changed to:
- <entry>Total time spent in the statement, in milliseconds</entry>
+ <entry>Total time spent executing the statement, in milliseconds</entry>... and likewise for the min, max, avg, stddev columns.
+
/* ----------------
* PlannedStmt node
*Extra change.
Fixed.
Thanks!
--
Thomas Munro
http://www.enterprisedb.com
Attachments:
pg-stat-statements-planning-v2.patchapplication/octet-stream; name=pg-stat-statements-planning-v2.patchDownload
From 56d2884a9d958fc52ad512c39f9c3fed52abb356 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@enterprisedb.com>
Date: Tue, 7 Nov 2017 17:33:24 +1300
Subject: [PATCH] Add plan count and time to pg_stat_statements.
This allows administrators to look out for statements that should ideally be
changed to prepared statements, and monitor how often prepared statements
are [re]planned.
Author: Fujii Masao and Thomas Munro
Reviewed-By: Haribabu Kommi
Discussion: https://postgr.es/m/CAEepm%3D0e59Y_6Q_YXYCTHZkqOc6H2pJ54C_Xe%3DVFu50Aqqp_sA%40mail.gmail.com
Discussion: https://postgr.es/m/CAHGQGwFx_%3DDO-Gu-MfPW3VQ4qC7TfVdH2zHmvZfrGv6fQ3D-Tw%40mail.gmail.com
---
contrib/pg_stat_statements/Makefile | 3 +-
.../expected/pg_stat_statements.out | 64 ++++++++++++
.../pg_stat_statements--1.5--1.6.sql | 49 +++++++++
...ements--1.4.sql => pg_stat_statements--1.6.sql} | 8 +-
contrib/pg_stat_statements/pg_stat_statements.c | 110 +++++++++++++++++++--
.../pg_stat_statements/pg_stat_statements.control | 2 +-
.../pg_stat_statements/sql/pg_stat_statements.sql | 16 +++
doc/src/sgml/pgstatstatements.sgml | 27 +++--
src/backend/nodes/copyfuncs.c | 1 +
src/backend/nodes/outfuncs.c | 1 +
src/backend/nodes/readfuncs.c | 1 +
src/backend/optimizer/plan/planner.c | 1 +
src/include/nodes/plannodes.h | 3 +
13 files changed, 269 insertions(+), 17 deletions(-)
create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql
rename contrib/pg_stat_statements/{pg_stat_statements--1.4.sql => pg_stat_statements--1.6.sql} (84%)
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 39b368b70eb..d21e9a83a32 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -4,7 +4,8 @@ MODULE_big = pg_stat_statements
OBJS = pg_stat_statements.o $(WIN32RES)
EXTENSION = pg_stat_statements
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.4--1.5.sql \
+DATA = pg_stat_statements--1.6.sql \
+ pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \
pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \
pg_stat_statements--1.1--1.2.sql pg_stat_statements--1.0--1.1.sql \
pg_stat_statements--unpackaged--1.0.sql
diff --git a/contrib/pg_stat_statements/expected/pg_stat_statements.out b/contrib/pg_stat_statements/expected/pg_stat_statements.out
index 5318c3550c7..76669176447 100644
--- a/contrib/pg_stat_statements/expected/pg_stat_statements.out
+++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out
@@ -395,4 +395,68 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
SELECT pg_stat_statements_reset() | 1 | 1
(8 rows)
+--
+-- [re]plan counting
+--
+SELECT pg_stat_statements_reset();
+ pg_stat_statements_reset
+--------------------------
+
+(1 row)
+
+CREATE TABLE test ();
+PREPARE prep1 AS SELECT COUNT(*) FROM test;;
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+ALTER TABLE test ADD COLUMN x int;
+EXECUTE prep1;
+ count
+-------
+ 0
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT 42;
+ ?column?
+----------
+ 42
+(1 row)
+
+SELECT query, plans, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+ query | plans | calls | rows
+--------------------------------------------+-------+-------+------
+ ALTER TABLE test ADD COLUMN x int | 0 | 1 | 0
+ CREATE TABLE test () | 0 | 1 | 0
+ PREPARE prep1 AS SELECT COUNT(*) FROM test | 2 | 4 | 4
+ SELECT $1 | 3 | 3 | 3
+ SELECT pg_stat_statements_reset() | 1 | 1 | 1
+(5 rows)
+
DROP EXTENSION pg_stat_statements;
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql b/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql
new file mode 100644
index 00000000000..3cb6eec081e
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql
@@ -0,0 +1,49 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.6'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT planning_time float8,
+ OUT calls int8,
+ OUT total_time float8,
+ OUT min_time float8,
+ OUT max_time float8,
+ OUT mean_time float8,
+ OUT stddev_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT blk_read_time float8,
+ OUT blk_write_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_4'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.4.sql b/contrib/pg_stat_statements/pg_stat_statements--1.6.sql
similarity index 84%
rename from contrib/pg_stat_statements/pg_stat_statements--1.4.sql
rename to contrib/pg_stat_statements/pg_stat_statements--1.6.sql
index 58cdf600fce..0ddd6162eb0 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.4.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.6.sql
@@ -1,4 +1,4 @@
-/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */
+/* contrib/pg_stat_statements/pg_stat_statements--1.6.sql */
-- complain if script is sourced in psql, rather than via CREATE EXTENSION
\echo Use "CREATE EXTENSION pg_stat_statements" to load this file. \quit
@@ -14,6 +14,8 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean,
OUT dbid oid,
OUT queryid bigint,
OUT query text,
+ OUT plans int8,
+ OUT planning_time float8,
OUT calls int8,
OUT total_time float8,
OUT min_time float8,
@@ -35,7 +37,7 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean,
OUT blk_write_time float8
)
RETURNS SETOF record
-AS 'MODULE_PATHNAME', 'pg_stat_statements_1_3'
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_4'
LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
-- Register a view on the function for ease of use.
@@ -46,3 +48,5 @@ GRANT SELECT ON pg_stat_statements TO PUBLIC;
-- Don't want this to be available to non-superusers.
REVOKE ALL ON FUNCTION pg_stat_statements_reset() FROM PUBLIC;
+
+GRANT EXECUTE ON FUNCTION pg_stat_statements_reset() TO pg_read_all_stats;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 928673498af..1bec296f58e 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -1,7 +1,7 @@
/*-------------------------------------------------------------------------
*
* pg_stat_statements.c
- * Track statement execution times across a whole database cluster.
+ * Track statement planning and execution times across a whole cluster.
*
* Execution costs are totalled for each distinct source query, and kept in
* a shared hashtable. (We track only as many distinct queries as will fit
@@ -67,6 +67,7 @@
#include "funcapi.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
+#include "optimizer/planner.h"
#include "parser/analyze.h"
#include "parser/parsetree.h"
#include "parser/scanner.h"
@@ -119,7 +120,8 @@ typedef enum pgssVersion
PGSS_V1_0 = 0,
PGSS_V1_1,
PGSS_V1_2,
- PGSS_V1_3
+ PGSS_V1_3,
+ PGSS_V1_4
} pgssVersion;
/*
@@ -149,6 +151,8 @@ typedef struct Counters
double max_time; /* maximum execution time in msec */
double mean_time; /* mean execution time in msec */
double sum_var_time; /* sum of variances in execution time in msec */
+ int64 plans; /* # of times planned */
+ double planning_time; /* total planning time, in msec */
int64 rows; /* total # of retrieved or affected rows */
int64 shared_blks_hit; /* # of shared buffer hits */
int64 shared_blks_read; /* # of shared disk blocks read */
@@ -237,6 +241,7 @@ static int nested_level = 0;
/* Saved hook values in case of unload */
static shmem_startup_hook_type prev_shmem_startup_hook = NULL;
+static planner_hook_type prev_planner_hook = NULL;
static post_parse_analyze_hook_type prev_post_parse_analyze_hook = NULL;
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
@@ -291,10 +296,14 @@ void _PG_fini(void);
PG_FUNCTION_INFO_V1(pg_stat_statements_reset);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_2);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_4);
PG_FUNCTION_INFO_V1(pg_stat_statements);
static void pgss_shmem_startup(void);
static void pgss_shmem_shutdown(int code, Datum arg);
+static PlannedStmt *pgss_planner_hook(Query *parse,
+ int cursorOptions,
+ ParamListInfo boundParams);
static void pgss_post_parse_analyze(ParseState *pstate, Query *query);
static void pgss_ExecutorStart(QueryDesc *queryDesc, int eflags);
static void pgss_ExecutorRun(QueryDesc *queryDesc,
@@ -309,7 +318,9 @@ static void pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
static uint64 pgss_hash_string(const char *str, int len);
static void pgss_store(const char *query, uint64 queryId,
int query_location, int query_len,
- double total_time, uint64 rows,
+ double total_time,
+ double planning_time,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
@@ -422,6 +433,8 @@ _PG_init(void)
*/
prev_shmem_startup_hook = shmem_startup_hook;
shmem_startup_hook = pgss_shmem_startup;
+ prev_planner_hook = planner_hook;
+ planner_hook = pgss_planner_hook;
prev_post_parse_analyze_hook = post_parse_analyze_hook;
post_parse_analyze_hook = pgss_post_parse_analyze;
prev_ExecutorStart = ExecutorStart_hook;
@@ -445,6 +458,7 @@ _PG_fini(void)
/* Uninstall hooks. */
shmem_startup_hook = prev_shmem_startup_hook;
post_parse_analyze_hook = prev_post_parse_analyze_hook;
+ planner_hook = prev_planner_hook;
ExecutorStart_hook = prev_ExecutorStart;
ExecutorRun_hook = prev_ExecutorRun;
ExecutorFinish_hook = prev_ExecutorFinish;
@@ -770,6 +784,54 @@ error:
unlink(PGSS_TEXT_FILE);
}
+/*
+ * Planner hook: forward to regular planner, but measure planning time.
+ */
+static PlannedStmt *pgss_planner_hook(Query *parse,
+ int cursorOptions,
+ ParamListInfo boundParams)
+{
+ PlannedStmt *result;
+
+ if (pgss_enabled())
+ {
+ instr_time start;
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(start);
+
+ nested_level++;
+ PG_TRY();
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ nested_level--;
+ }
+ PG_CATCH();
+ {
+ nested_level--;
+ PG_RE_THROW();
+ }
+ PG_END_TRY();
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+
+ result->planning_time = INSTR_TIME_GET_DOUBLE(duration);
+ }
+ else
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ }
+
+ return result;
+}
+
/*
* Post-parse-analysis hook: mark query with a queryId
*/
@@ -837,6 +899,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query)
query->stmt_len,
0,
0,
+ 0,
NULL,
&jstate);
}
@@ -943,9 +1006,16 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->plannedstmt->stmt_location,
queryDesc->plannedstmt->stmt_len,
queryDesc->totaltime->total * 1000.0, /* convert to msec */
+ queryDesc->plannedstmt->planning_time * 1000.0,
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
NULL);
+
+ /*
+ * Clear planning_time, so that we only count it once for each
+ * replanning of a prepared statement.
+ */
+ queryDesc->plannedstmt->planning_time = 0;
}
if (prev_ExecutorEnd)
@@ -974,8 +1044,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
* hash table entry for the PREPARE (with hash calculated from the query
* string), and then a different one with the same query string (but hash
* calculated from the query tree) would be used to accumulate costs of
- * ensuing EXECUTEs. This would be confusing, and inconsistent with other
- * cases where planning time is not included at all.
+ * ensuing EXECUTEs.
*
* Likewise, we don't track execution of DEALLOCATE.
*/
@@ -1054,6 +1123,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
pstmt->stmt_location,
pstmt->stmt_len,
INSTR_TIME_GET_MILLISEC(duration),
+ 0,
rows,
&bufusage,
NULL);
@@ -1096,7 +1166,9 @@ pgss_hash_string(const char *str, int len)
static void
pgss_store(const char *query, uint64 queryId,
int query_location, int query_len,
- double total_time, uint64 rows,
+ double total_time,
+ double planning_time,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate)
{
@@ -1265,6 +1337,9 @@ pgss_store(const char *query, uint64 queryId,
if (e->counters.max_time < total_time)
e->counters.max_time = total_time;
}
+ if (planning_time > 0)
+ e->counters.plans += 1;
+ e->counters.planning_time += planning_time;
e->counters.rows += rows;
e->counters.shared_blks_hit += bufusage->shared_blks_hit;
e->counters.shared_blks_read += bufusage->shared_blks_read;
@@ -1310,7 +1385,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_1 18
#define PG_STAT_STATEMENTS_COLS_V1_2 19
#define PG_STAT_STATEMENTS_COLS_V1_3 23
-#define PG_STAT_STATEMENTS_COLS 23 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_4 25
+#define PG_STAT_STATEMENTS_COLS 25 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1322,6 +1398,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_4(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_4, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_3(PG_FUNCTION_ARGS)
{
@@ -1428,6 +1514,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_3)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_4:
+ if (api_version != PGSS_V1_4)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1586,6 +1676,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (tmp.calls == 0)
continue;
+ if (api_version >= PGSS_V1_4)
+ {
+ values[i++] = Int64GetDatumFast(tmp.plans);
+ values[i++] = Float8GetDatumFast(tmp.planning_time);
+ }
values[i++] = Int64GetDatumFast(tmp.calls);
values[i++] = Float8GetDatumFast(tmp.total_time);
if (api_version >= PGSS_V1_3)
@@ -1629,6 +1724,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
api_version == PGSS_V1_2 ? PG_STAT_STATEMENTS_COLS_V1_2 :
api_version == PGSS_V1_3 ? PG_STAT_STATEMENTS_COLS_V1_3 :
+ api_version == PGSS_V1_4 ? PG_STAT_STATEMENTS_COLS_V1_4 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 193fcdfafa0..617038b4c05 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
# pg_stat_statements extension
comment = 'track execution statistics of all SQL statements executed'
-default_version = '1.5'
+default_version = '1.6'
module_pathname = '$libdir/pg_stat_statements'
relocatable = true
diff --git a/contrib/pg_stat_statements/sql/pg_stat_statements.sql b/contrib/pg_stat_statements/sql/pg_stat_statements.sql
index a8361fd1bff..e15b789369a 100644
--- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql
+++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql
@@ -195,4 +195,20 @@ DROP FUNCTION PLUS_TWO(INTEGER);
SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+--
+-- [re]plan counting
+--
+SELECT pg_stat_statements_reset();
+CREATE TABLE test ();
+PREPARE prep1 AS SELECT COUNT(*) FROM test;;
+EXECUTE prep1;
+EXECUTE prep1;
+EXECUTE prep1;
+ALTER TABLE test ADD COLUMN x int;
+EXECUTE prep1;
+SELECT 42;
+SELECT 42;
+SELECT 42;
+SELECT query, plans, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
+
DROP EXTENSION pg_stat_statements;
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index c0217ed485f..19b8f3bb1aa 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -9,7 +9,8 @@
<para>
The <filename>pg_stat_statements</filename> module provides a means for
- tracking execution statistics of all SQL statements executed by a server.
+ tracking planning and execution statistics of all SQL statements executed by
+ a server.
</para>
<para>
@@ -82,6 +83,20 @@
<entry>Text of a representative statement</entry>
</row>
+ <row>
+ <entry><structfield>plans</structfield></entry>
+ <entry><type>bigint</type></entry>
+ <entry></entry>
+ <entry>Number of times the statement was planned</entry>
+ </row>
+
+ <row>
+ <entry><structfield>planning_time</structfield></entry>
+ <entry><type>double precision</type></entry>
+ <entry></entry>
+ <entry>Total time spent planning the statement, in milliseconds</entry>
+ </row>
+
<row>
<entry><structfield>calls</structfield></entry>
<entry><type>bigint</type></entry>
@@ -93,35 +108,35 @@
<entry><structfield>total_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
- <entry>Total time spent in the statement, in milliseconds</entry>
+ <entry>Total time spent executing the statement, in milliseconds</entry>
</row>
<row>
<entry><structfield>min_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
- <entry>Minimum time spent in the statement, in milliseconds</entry>
+ <entry>Minimum time spent executing the statement, in milliseconds</entry>
</row>
<row>
<entry><structfield>max_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
- <entry>Maximum time spent in the statement, in milliseconds</entry>
+ <entry>Maximum time spent executing the statement, in milliseconds</entry>
</row>
<row>
<entry><structfield>mean_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
- <entry>Mean time spent in the statement, in milliseconds</entry>
+ <entry>Mean time spent executing the statement, in milliseconds</entry>
</row>
<row>
<entry><structfield>stddev_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
- <entry>Population standard deviation of time spent in the statement, in milliseconds</entry>
+ <entry>Population standard deviation of time spent executing the statement, in milliseconds</entry>
</row>
<row>
diff --git a/src/backend/nodes/copyfuncs.c b/src/backend/nodes/copyfuncs.c
index ddbbc79823e..35ea267a5cc 100644
--- a/src/backend/nodes/copyfuncs.c
+++ b/src/backend/nodes/copyfuncs.c
@@ -99,6 +99,7 @@ _copyPlannedStmt(const PlannedStmt *from)
COPY_NODE_FIELD(invalItems);
COPY_NODE_FIELD(paramExecTypes);
COPY_NODE_FIELD(utilityStmt);
+ COPY_SCALAR_FIELD(planning_time);
COPY_LOCATION_FIELD(stmt_location);
COPY_LOCATION_FIELD(stmt_len);
diff --git a/src/backend/nodes/outfuncs.c b/src/backend/nodes/outfuncs.c
index 5e72df137e7..ff71b63f5b4 100644
--- a/src/backend/nodes/outfuncs.c
+++ b/src/backend/nodes/outfuncs.c
@@ -284,6 +284,7 @@ _outPlannedStmt(StringInfo str, const PlannedStmt *node)
WRITE_NODE_FIELD(invalItems);
WRITE_NODE_FIELD(paramExecTypes);
WRITE_NODE_FIELD(utilityStmt);
+ WRITE_FLOAT_FIELD(planning_time, "%.0f");
WRITE_LOCATION_FIELD(stmt_location);
WRITE_LOCATION_FIELD(stmt_len);
}
diff --git a/src/backend/nodes/readfuncs.c b/src/backend/nodes/readfuncs.c
index 9925866b53a..4c5d30277d1 100644
--- a/src/backend/nodes/readfuncs.c
+++ b/src/backend/nodes/readfuncs.c
@@ -1482,6 +1482,7 @@ _readPlannedStmt(void)
READ_NODE_FIELD(invalItems);
READ_NODE_FIELD(paramExecTypes);
READ_NODE_FIELD(utilityStmt);
+ READ_FLOAT_FIELD(planning_time);
READ_LOCATION_FIELD(stmt_location);
READ_LOCATION_FIELD(stmt_len);
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index 7b52dadd817..05a3aacb2c0 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -478,6 +478,7 @@ standard_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
result->paramExecTypes = glob->paramExecTypes;
/* utilityStmt should be null, but we might as well copy it */
result->utilityStmt = parse->utilityStmt;
+ result->planning_time = 0;
result->stmt_location = parse->stmt_location;
result->stmt_len = parse->stmt_len;
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index 74e9fb5f7bd..f6d8c260370 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -93,6 +93,9 @@ typedef struct PlannedStmt
Node *utilityStmt; /* non-null if this is utility stmt */
+ /* This is always set to 0 by the core system, but plugins can change it. */
+ double planning_time;
+
/* statement location in source string (copied from Query) */
int stmt_location; /* start location, or -1 if unknown */
int stmt_len; /* length in bytes; 0 means "rest of string" */
--
2.15.1
On Thu, Jan 11, 2018 at 10:00 PM, Thomas Munro <
thomas.munro@enterprisedb.com> wrote:
On Thu, Jan 11, 2018 at 7:36 PM, Haribabu Kommi
<kommi.haribabu@gmail.com> wrote:+ OUT plans int8,
Addition of this column is good to find out how many time the plan is
generated
for the same query. But I am thinking "plans" column name may confuse?What else would you call that? It's the number of plans that have
been created. It sits nicely beside "calls" don't you think? I could
change it to "plan_count" but that's longer and not like "calls".
OK.
I checked the latest patch and it is working fine and I don't have any
further comments. Marked the patch as "ready for committer".
Regards,
Hari Babu
Fujitsu Australia
Haribabu Kommi <kommi.haribabu@gmail.com> writes:
I checked the latest patch and it is working fine and I don't have any
further comments. Marked the patch as "ready for committer".
I started to look at this patch, and I'm not entirely convinced whether
it is a good thing for the planner_hook to bump nested_level. ISTM
that will change behavior in some ways, in particular when the planner
chooses to evaluate an immutable or stable function that runs the
executor (probably via SPI). Before, that execution would have been
regarded as a top-level call, now it will not be. Maybe that's fine,
but did anyone think hard about it?
A possible alternative behavior is for planner_hook to maintain its
own nesting depth counter, separate from the one for execution
nesting depth. I'm not sure if that's better or not.
Discuss ...
regards, tom lane
I wrote:
Haribabu Kommi <kommi.haribabu@gmail.com> writes:
I checked the latest patch and it is working fine and I don't have any
further comments. Marked the patch as "ready for committer".
I started to look at this patch,
... looking further, I'm really seriously unhappy about this bit:
@@ -943,9 +1006,16 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
...
+
+ /*
+ * Clear planning_time, so that we only count it once for each
+ * replanning of a prepared statement.
+ */
+ queryDesc->plannedstmt->planning_time = 0;
}What we have here is pgss_ExecutorEnd stomping on the plan cache.
I do *not* find that acceptable. At the very least, it ruins the
theory that this field is a shared resource.
What we could/should do instead, I think, is have pgss_planner_hook
make its own pgss_store() call to log the planning time results
(which would mean we don't need the added PlannedStmt field at all).
That would increase the overhead of this feature, which might mean
that it'd be worth having a pg_stat_statements GUC to enable it.
But it'd be a whole lot cleaner.
regards, tom lane
On Sat, Jan 13, 2018 at 2:16 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
I wrote:
Haribabu Kommi <kommi.haribabu@gmail.com> writes:
I checked the latest patch and it is working fine and I don't have any
further comments. Marked the patch as "ready for committer".I started to look at this patch,
Thanks!
... looking further, I'm really seriously unhappy about this bit:
@@ -943,9 +1006,16 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) ... + + /* + * Clear planning_time, so that we only count it once for each + * replanning of a prepared statement. + */ + queryDesc->plannedstmt->planning_time = 0; }What we have here is pgss_ExecutorEnd stomping on the plan cache.
I do *not* find that acceptable. At the very least, it ruins the
theory that this field is a shared resource.
The idea was that planning_time is work space for extensions to do
whatever they like with, but objection noted.
What we could/should do instead, I think, is have pgss_planner_hook
make its own pgss_store() call to log the planning time results
(which would mean we don't need the added PlannedStmt field at all).
That would increase the overhead of this feature, which might mean
that it'd be worth having a pg_stat_statements GUC to enable it.
But it'd be a whole lot cleaner.
Ok. It seems a bit strange to have to go through the locking twice,
but I don't have a better idea. First attempt seems to be working.
I'll post an updated patch in a couple of days when I'm back from
travelling and have a tidier version with a new GUC and have thought
about the nested_level question.
--
Thomas Munro
http://www.enterprisedb.com
On Fri, Jan 19, 2018 at 12:14 AM, Thomas Munro
<thomas.munro@enterprisedb.com> wrote:
On Sat, Jan 13, 2018 at 2:16 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
What we could/should do instead, I think, is have pgss_planner_hook
make its own pgss_store() call to log the planning time results
(which would mean we don't need the added PlannedStmt field at all).
That would increase the overhead of this feature, which might mean
that it'd be worth having a pg_stat_statements GUC to enable it.
But it'd be a whole lot cleaner.Ok. It seems a bit strange to have to go through the locking twice,
but I don't have a better idea. First attempt seems to be working.
One problem is that pgss_planner_hook doesn't have the source query
text. That problem could be solved by adding a query_string argument
to the planner hook function type and also planner(),
standard_planner(), pg_plan_query(), pg_plan_queries(). I don't know
if that change would be acceptable or if there is a better way that
doesn't change extern functions that will annoy extension owners.
When I tried that it basically worked except for a problem with
"PREPARE ... <actual query>" (what we want to show) vs "<actual
query>" (what my experimental patch now shows -- oops).
Something I wondered about but didn't try: we could skip the above
problem AND the extra pgss_store() by instead pushing (query ID,
planning time) into a backend-private buffer and then later pushing it
into shmem when we eventually call pgss_store() for the execution
counters. If you think of that as using global variables to pass
state between functions just because we didn't structure our program
right it sounds terrible, but if you think of it as a dtrace-style
per-thread tracing event buffer that improves performance by batching
up collected data, it sounds great :-D
Unfortunately I'm not going to have bandwidth to figure this out
during this commitfest due to other priorities so I'm going to call
this "returned with feedback".
--
Thomas Munro
http://www.enterprisedb.com
Thomas Munro <thomas.munro@enterprisedb.com> writes:
One problem is that pgss_planner_hook doesn't have the source query
text. That problem could be solved by adding a query_string argument
to the planner hook function type and also planner(),
standard_planner(), pg_plan_query(), pg_plan_queries(). I don't know
if that change would be acceptable or if there is a better way that
doesn't change extern functions that will annoy extension owners.
Within the planner, I'd be inclined to store the query string pointer in
PlannerGlobal (which is accessible from PlannerInfo "root"), but I'm
not sure how many of the functions you mention would still need an
explicit signature change. Anyway that doesn't particularly bother
me --- it's something that might need to happen anyway, if we ever
hope to throw errors with location pointers from inside the planner.
Something I wondered about but didn't try: we could skip the above
problem AND the extra pgss_store() by instead pushing (query ID,
planning time) into a backend-private buffer and then later pushing it
into shmem when we eventually call pgss_store() for the execution
counters.
Meh. Part of the reason I don't like what you submitted before is that
it supposes there's a mostly one-to-one relationship between planner calls
and executor calls; which there is not, when you start considering edge
cases like prepared statements. A global would make that worse.
Unfortunately I'm not going to have bandwidth to figure this out
during this commitfest due to other priorities so I'm going to call
this "returned with feedback".
OK. There's still time to get it done in the March 'fest.
regards, tom lane
On Tue, Jan 23, 2018 at 3:31 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Unfortunately I'm not going to have bandwidth to figure this out
during this commitfest due to other priorities so I'm going to call
this "returned with feedback".OK. There's still time to get it done in the March 'fest.
I've had an interesting incident earlier this week where seeing planning
time in pg_stat_statements would have been very helpful to determine the
root cause more quickly.
Essentially the situation was a statement that executed < 1ms but took more
than 250ms to plan, running often - once we found the statement (using
pg_stat_activity sampling) we were able to fix quickly by rewriting the
query and reduce system load from ~8 to ~1. Having this patch in
pg_stat_statements would have been critical to get the full picture of what
was going on earlier.
Thomas: I'm not as familiar with planner internals as you are, but happy to
try and contribute here. Would it be useful for me to try to adjust the
patch to Tom's proposal?
Best,
Lukas
--
Lukas Fittl
On Sat, Mar 31, 2018 at 8:04 AM, Lukas Fittl <lukas@fittl.com> wrote:
On Tue, Jan 23, 2018 at 3:31 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Unfortunately I'm not going to have bandwidth to figure this out
during this commitfest due to other priorities so I'm going to call
this "returned with feedback".OK. There's still time to get it done in the March 'fest.
I've had an interesting incident earlier this week where seeing planning
time in pg_stat_statements would have been very helpful to determine the
root cause more quickly.Essentially the situation was a statement that executed < 1ms but took more
than 250ms to plan, running often - once we found the statement (using
pg_stat_activity sampling) we were able to fix quickly by rewriting the
query and reduce system load from ~8 to ~1. Having this patch in
pg_stat_statements would have been critical to get the full picture of what
was going on earlier.Thomas: I'm not as familiar with planner internals as you are, but happy to
try and contribute here. Would it be useful for me to try to adjust the
patch to Tom's proposal?
Hi Lukas,
Please feel free! I'm sure this will be a useful feature.
Unfortunately I wasn't able to get back to it in time for PG11. It
did make an attempt though, and got stuck on some confusion about
whether you want the PREPARE or the "real" statement when using
prepared plans; I don't recall the details now.
--
Thomas Munro
http://www.enterprisedb.com
+1
Shouldn't this be added in next CF ?
nb: As plan_time is not included into total_time, could it be added to usage
(for statement eviction calculation) ? I will try to include plan_time into
my proposed version of pgss with planid.
http://www.postgresql-archive.org/Poc-pg-stat-statements-with-planid-td6014027.html
Regards
PAscal
--
Sent from: http://www.postgresql-archive.org/PostgreSQL-hackers-f1928748.html
Hello,
When testing this patch on my WIN1252 database with my java front end, using
11devel snapshot
I get
org.posgresql.util.PSQLException: ERROR: character with byte sequence 0x90
in encoding
"WIN1252" has no equivalent in encoding "UTF8"
When using psql with client_encoding = WIN1252, query text are truncated:
postgres=# select pg_stat_statements_reset();
pg_stat_statements_reset
--------------------------
(1 row)
postgres=# show client_encoding;
client_encoding
-----------------
WIN1252
(1 row)
postgres=# select substr(query,1,20) from pg_stat_statements;
substr
--------------------
tatements_reset();
ding;
(2 rows)
Regards
PAscal
--
Sent from: http://www.postgresql-archive.org/PostgreSQL-hackers-f1928748.html
I forgot to recompile core ...
now only utility statements (with 0 plans) seems truncated.
Regards
PAscal
--
Sent from: http://www.postgresql-archive.org/PostgreSQL-hackers-f1928748.html
Hi,
Is anybody still working on this? Are there any plans to add this to
commitfest?
I'd like to add planning time to auto_explain, and it turns out that
this patch is somewhat relevant to that feature.
The current approach here is to set planning_time in PlannedStmt via
planner_hook, which (in my opinion) has several flaws:
1. Depending on the order of extensions in shared_preload_libraries, it
might not measure time spent on preceding planner hooks.
2. Provided that there are multiple users of this metric, it might
become a little too costy to register several hooks with identical
purpose.
3. [Bikeshedding] Although planning time is stored in PlannedStmt, it's
definitely not an inherent property of a plan. You could have two
machines with identical settings but quite different planning times due
to various circumstances (raw CPU power, I/O etc).
I'd argue that it might be better to add a new argument to
pg_plan_query() and pg_plan_queries() and a new field to QueryDesc,
i.e.:
PlannedStmt *
pg_plan_query(Query *querytree,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime)
List *
pg_plan_queries(List *querytrees,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime) /* total time as in BuildCachedPlan() */
The measured time can later be passed to QueryDesc via
PortalDefineQuery(). Of course, this requires more changes, but the
result might be worth it.
What do you think?
--
Dmitry Ivanov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Hi Dmitry,
On Tue, May 15, 2018 at 11:10 PM, Dmitry Ivanov <d.ivanov@postgrespro.ru> wrote:
Is anybody still working on this? Are there any plans to add this to
commitfest?
I am not actively working on this now, but I'll come back to it for
PG12 if you or Lukas don't beat me to it, and I'll help/test/review if
I you do. It seems there is plenty of demand for the feature and I'll
be very happy to see it.
I'd like to add planning time to auto_explain, and it turns out that this
patch is somewhat relevant to that feature.
Sounds very useful.
The current approach here is to set planning_time in PlannedStmt via
planner_hook, which (in my opinion) has several flaws:1. Depending on the order of extensions in shared_preload_libraries, it
might not measure time spent on preceding planner hooks.2. Provided that there are multiple users of this metric, it might become a
little too costy to register several hooks with identical purpose.3. [Bikeshedding] Although planning time is stored in PlannedStmt, it's
definitely not an inherent property of a plan. You could have two machines
with identical settings but quite different planning times due to various
circumstances (raw CPU power, I/O etc).
Yeah. Putting that inside the PlannedStmt wasn't very nice. Another
thing I tried was to have some opaque extension workspace, but that
runs into a number of technical problem. That idea is definitely
dead.
I'd argue that it might be better to add a new argument to pg_plan_query()
and pg_plan_queries() and a new field to QueryDesc, i.e.:PlannedStmt *
pg_plan_query(Query *querytree,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime)List *
pg_plan_queries(List *querytrees,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime) /* total time as in
BuildCachedPlan() */The measured time can later be passed to QueryDesc via PortalDefineQuery().
Of course, this requires more changes, but the result might be worth it.What do you think?
So who does the actual timing work in this model? Does the core code
do the timing, but it'd be disabled by default because NULL is usually
passed in, and you need to register an extension that provides a place
to stick the result in order to turn on the time-measuring code? If
you mean that it's still the extension that does the timing, it seems
strange to have struct members and parameter arguments for something
specific that the core code doesn't understand.
As a more general version of that, I wondered about having some kind
of associative data structure (hash table, assoc list, etc) that would
somehow travel everywhere with the PlannedStmt, but not inside it,
just for the use of extensions. Then planning time could be stored in
there by a planner hook, and the fished out by any other hook that
knows the same key (not sure how you manage that key space but I'm
sure you could come up with something). That could have uses for
other extensions too, and could also be used for the "query ID", which
is, after all, the model that the abandoned planning_time member was
following. Just a thought.
--
Thomas Munro
http://www.enterprisedb.com
I am not actively working on this now, but I'll come back to it for
PG12 if you or Lukas don't beat me to it, and I'll help/test/review if
I you do. It seems there is plenty of demand for the feature and I'll
be very happy to see it.
Good to know, thanks!
I'd argue that it might be better to add a new argument to
pg_plan_query()
and pg_plan_queries() and a new field to QueryDesc, i.e.:PlannedStmt *
pg_plan_query(Query *querytree,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime)List *
pg_plan_queries(List *querytrees,
int cursorOptions,
ParamListInfo boundParams,
double *planningTime) /* total time as
in
BuildCachedPlan() */The measured time can later be passed to QueryDesc via
PortalDefineQuery().
Of course, this requires more changes, but the result might be worth
it.What do you think?
So who does the actual timing work in this model? Does the core code
do the timing, but it'd be disabled by default because NULL is usually
passed in, and you need to register an extension that provides a place
to stick the result in order to turn on the time-measuring code? If
you mean that it's still the extension that does the timing, it seems
strange to have struct members and parameter arguments for something
specific that the core code doesn't understand.
Right, I guess my proposal was too brief. Yes, my idea's that the core
code
should do the timing, which might be disabled by passing NULL to those
functions. However, given that there's lots of people out there who use
pg_stat_statements on a regular basis, it might be meaningful to just
turn it on unconditionally (my assumptions might be wrong, of course).
Alternatively, we could introduce a new GUC variable to disable this
feature.
The extensions would no longer have to do the accounting.
As a more general version of that, I wondered about having some kind
of associative data structure (hash table, assoc list, etc) that would
somehow travel everywhere with the PlannedStmt, but not inside it,
just for the use of extensions. Then planning time could be stored in
there by a planner hook, and the fished out by any other hook that
knows the same key (not sure how you manage that key space but I'm
sure you could come up with something). That could have uses for
other extensions too, and could also be used for the "query ID", which
is, after all, the model that the abandoned planning_time member was
following. Just a thought.
Perhaps we could change planner() so that it would return pointer to
some
struct holding PlannedStmt and a List of some nodes or structs for
accounting.
--
Dmitry Ivanov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company