On Tue, Apr 2, 2019 at 9:22 AM legrand legrand
<legrand_legr...@hotmail.com> wrote:
>
> >> case avg_tps pct_diff
> >> 0 89 278 --
> >> 1 88 745 0,6%
> >> 2 88 282 1,1%
> >> 3 86 660 2,9%
> >>
> >> This means that even in this extrem test case, the worst degradation is
> >> less
> >> than 3%
> >> (this overhead can be removed using pg_stat_statements.track_planning guc)
>
> > Is the difference between 2 and 3 the extraneous pgss_store call to
> > always store the query text if planner hook doesn't have access to the
> > query text?
>
> Yes it is,
> but I agree it seems a big gap (1,8%) compared to the difference between 1
> and 2 (0,5%).
> Maybe this is just mesure "noise" ...
Rebased patches attached.
From c7a407143d1283a6b86c3244efccf0da7990e330 Mon Sep 17 00:00:00 2001
From: Julien Rouhaud <julien.rouh...@free.fr>
Date: Wed, 27 Mar 2019 11:24:35 +0100
Subject: [PATCH 2/2] Add planning counters to pg_stat_statements
---
contrib/pg_stat_statements/Makefile | 3 +-
.../expected/pg_stat_statements.out | 64 ++++
.../pg_stat_statements--1.7--1.8.sql | 52 ++++
.../pg_stat_statements/pg_stat_statements.c | 293 +++++++++++++-----
.../pg_stat_statements.control | 2 +-
.../sql/pg_stat_statements.sql | 16 +
doc/src/sgml/pgstatstatements.sgml | 49 ++-
7 files changed, 401 insertions(+), 78 deletions(-)
create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 051ce46f0c..db33d9ffe1 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.6--1.7.sql \
+DATA = pg_stat_statements--1.4.sql \
+ pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.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 \
diff --git a/contrib/pg_stat_statements/expected/pg_stat_statements.out b/contrib/pg_stat_statements/expected/pg_stat_statements.out
index c759763be2..8517b124e4 100644
--- a/contrib/pg_stat_statements/expected/pg_stat_statements.out
+++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out
@@ -593,4 +593,68 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
--
DROP ROLE regress_stats_user1;
DROP ROLE regress_stats_user2;
+--
+-- [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() | 0 | 1 | 1
+(5 rows)
+
DROP EXTENSION pg_stat_statements;
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
new file mode 100644
index 0000000000..de75643928
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
@@ -0,0 +1,52 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.8'" 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 total_plan_time float8,
+ OUT calls int8,
+ OUT total_exec_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_8'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT *, total_plan_time + total_exec_time AS total_time
+ FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
+
+
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 490ade9e5f..059d283fd5 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -1,7 +1,8 @@
/*-------------------------------------------------------------------------
*
* pg_stat_statements.c
- * Track statement execution times across a whole database cluster.
+ * Track statement planning and execution times as well as resources
+ * consumption (like block reads, ...) 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
@@ -66,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"
@@ -120,9 +122,17 @@ typedef enum pgssVersion
PGSS_V1_0 = 0,
PGSS_V1_1,
PGSS_V1_2,
- PGSS_V1_3
+ PGSS_V1_3,
+ PGSS_V1_8
} pgssVersion;
+typedef enum pgssStoreKind
+{
+ PGSS_JUMBLE,
+ PGSS_EXEC_TIME,
+ PGSS_PLAN_TIME
+} pgssStoreKind;
+
/*
* Hashtable key that defines the identity of a hashtable entry. We separate
* queries by user and by database even if they are otherwise identical.
@@ -145,11 +155,13 @@ typedef struct pgssHashKey
typedef struct Counters
{
int64 calls; /* # of times executed */
- double total_time; /* total execution time, in msec */
+ double total_exec_time; /* total execution time, in msec */
double min_time; /* minimum execution time in msec */
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 total_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 */
@@ -238,6 +250,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;
@@ -268,6 +281,7 @@ static const struct config_enum_entry track_options[] =
static int pgss_max; /* max # statements to track */
static int pgss_track; /* tracking level */
+static bool pgss_track_planning; /* whether to track planning duration */
static bool pgss_track_utility; /* whether to track utility commands */
static bool pgss_save; /* whether to save stats across shutdown */
@@ -293,10 +307,15 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_reset);
PG_FUNCTION_INFO_V1(pg_stat_statements_reset_1_7);
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_8);
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,
+ const char *query_text,
+ 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,
@@ -311,7 +330,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,
+ pgssStoreKind kind,
+ double timing,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
@@ -340,6 +361,7 @@ static char *generate_normalized_query(pgssJumbleState *jstate, const char *quer
static void fill_in_constant_lengths(pgssJumbleState *jstate, const char *query,
int query_loc);
static int comp_location(const void *a, const void *b);
+static BufferUsage compute_buffer_counters(BufferUsage start, BufferUsage stop);
/*
@@ -398,6 +420,17 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("pg_stat_statements.track_planning",
+ "Selects whether planning duration is tracked by pg_stat_statements.",
+ NULL,
+ &pgss_track_planning,
+ true,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomBoolVariable("pg_stat_statements.save",
"Save pg_stat_statements statistics across server shutdowns.",
NULL,
@@ -424,6 +457,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;
@@ -447,6 +482,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;
@@ -837,12 +873,86 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query)
query->queryId,
query->stmt_location,
query->stmt_len,
+ PGSS_JUMBLE,
0,
0,
NULL,
&jstate);
}
+/*
+ * Planner hook: forward to regular planner, but measure planning time.
+ */
+static PlannedStmt *
+pgss_planner_hook(Query *parse,
+ const char *query_text,
+ int cursorOptions,
+ ParamListInfo boundParams)
+{
+ PlannedStmt *result;
+ BufferUsage bufusage_start,
+ bufusage;
+
+ bufusage_start = pgBufferUsage;
+ if (pgss_enabled() && pgss_track_planning)
+ {
+ instr_time start;
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(start);
+
+ nested_level++;
+ PG_TRY();
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, query_text, cursorOptions,
+ boundParams);
+ else
+ result = standard_planner(parse, query_text, cursorOptions,
+ boundParams);
+ nested_level--;
+ }
+ PG_CATCH();
+ {
+ nested_level--;
+ PG_RE_THROW();
+ }
+ PG_END_TRY();
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+
+ /* calc differences of buffer counters. */
+ bufusage = compute_buffer_counters(bufusage_start, pgBufferUsage);
+
+ /*
+ * we only store planning duration, query text has been initialized
+ * during previous pgss_post_parse_analyze as it not available inside
+ * pgss_planner_hook.
+ */
+ pgss_store(query_text,
+ parse->queryId,
+ parse->stmt_location,
+ parse->stmt_len,
+ PGSS_PLAN_TIME,
+ INSTR_TIME_GET_MILLISEC(duration),
+ 0,
+ &bufusage,
+ NULL);
+ }
+ else
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, query_text, cursorOptions,
+ boundParams);
+ else
+ result = standard_planner(parse, query_text, cursorOptions,
+ boundParams);
+ }
+
+ return result;
+}
+
/*
* ExecutorStart hook: start up tracking if needed
*/
@@ -944,6 +1054,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryId,
queryDesc->plannedstmt->stmt_location,
queryDesc->plannedstmt->stmt_len,
+ PGSS_EXEC_TIME,
queryDesc->totaltime->total * 1000.0, /* convert to msec */
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
@@ -1026,35 +1137,13 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
rows = 0;
/* calc differences of buffer counters. */
- bufusage.shared_blks_hit =
- pgBufferUsage.shared_blks_hit - bufusage_start.shared_blks_hit;
- bufusage.shared_blks_read =
- pgBufferUsage.shared_blks_read - bufusage_start.shared_blks_read;
- bufusage.shared_blks_dirtied =
- pgBufferUsage.shared_blks_dirtied - bufusage_start.shared_blks_dirtied;
- bufusage.shared_blks_written =
- pgBufferUsage.shared_blks_written - bufusage_start.shared_blks_written;
- bufusage.local_blks_hit =
- pgBufferUsage.local_blks_hit - bufusage_start.local_blks_hit;
- bufusage.local_blks_read =
- pgBufferUsage.local_blks_read - bufusage_start.local_blks_read;
- bufusage.local_blks_dirtied =
- pgBufferUsage.local_blks_dirtied - bufusage_start.local_blks_dirtied;
- bufusage.local_blks_written =
- pgBufferUsage.local_blks_written - bufusage_start.local_blks_written;
- bufusage.temp_blks_read =
- pgBufferUsage.temp_blks_read - bufusage_start.temp_blks_read;
- bufusage.temp_blks_written =
- pgBufferUsage.temp_blks_written - bufusage_start.temp_blks_written;
- bufusage.blk_read_time = pgBufferUsage.blk_read_time;
- INSTR_TIME_SUBTRACT(bufusage.blk_read_time, bufusage_start.blk_read_time);
- bufusage.blk_write_time = pgBufferUsage.blk_write_time;
- INSTR_TIME_SUBTRACT(bufusage.blk_write_time, bufusage_start.blk_write_time);
+ bufusage = compute_buffer_counters(bufusage_start, pgBufferUsage);
pgss_store(queryString,
0, /* signal that it's a utility stmt */
pstmt->stmt_location,
pstmt->stmt_len,
+ PGSS_EXEC_TIME,
INSTR_TIME_GET_MILLISEC(duration),
rows,
&bufusage,
@@ -1093,12 +1182,14 @@ pgss_hash_string(const char *str, int len)
*
* If jstate is not NULL then we're trying to create an entry for which
* we have no statistics as yet; we just want to record the normalized
- * query string. total_time, rows, bufusage are ignored in this case.
+ * query string. total_exec_time, rows, bufusage are ignored in this case.
*/
static void
pgss_store(const char *query, uint64 queryId,
int query_location, int query_len,
- double total_time, uint64 rows,
+ pgssStoreKind kind,
+ double timing,
+ uint64 rows,
const BufferUsage *bufusage,
pgssJumbleState *jstate)
{
@@ -1186,8 +1277,10 @@ pgss_store(const char *query, uint64 queryId,
* in the interval where we don't hold the lock below. That case is
* handled by entry_alloc.)
*/
- if (jstate)
+ if (kind == PGSS_JUMBLE)
{
+ Assert(jstate);
+
LWLockRelease(pgss->lock);
norm_query = generate_normalized_query(jstate, query,
query_location,
@@ -1236,7 +1329,7 @@ pgss_store(const char *query, uint64 queryId,
}
/* Increment the counts, except when jstate is not NULL */
- if (!jstate)
+ if (kind != PGSS_JUMBLE)
{
/*
* Grab the spinlock while updating the counters (see comment about
@@ -1250,47 +1343,58 @@ pgss_store(const char *query, uint64 queryId,
if (e->counters.calls == 0)
e->counters.usage = USAGE_INIT;
- e->counters.calls += 1;
- e->counters.total_time += total_time;
- if (e->counters.calls == 1)
+ if (kind == PGSS_EXEC_TIME)
{
- e->counters.min_time = total_time;
- e->counters.max_time = total_time;
- e->counters.mean_time = total_time;
+ /* updating counters for executions */
+ e->counters.calls += 1;
+ e->counters.total_exec_time += timing;
+
+ if (e->counters.calls == 1)
+ {
+ e->counters.min_time = timing;
+ e->counters.max_time = timing;
+ e->counters.mean_time = timing;
+ }
+ else
+ {
+ /*
+ * Welford's method for accurately computing variance. See
+ * <http://www.johndcook.com/blog/standard_deviation/>
+ */
+ double old_mean = e->counters.mean_time;
+
+ e->counters.mean_time +=
+ (timing - old_mean) / e->counters.calls;
+ e->counters.sum_var_time +=
+ (timing - old_mean) * (timing - e->counters.mean_time);
+
+ /* calculate min and max time */
+ if (e->counters.min_time > timing)
+ e->counters.min_time = timing;
+ if (e->counters.max_time < timing)
+ e->counters.max_time = timing;
+ }
+ e->counters.rows += rows;
+ e->counters.shared_blks_hit += bufusage->shared_blks_hit;
+ e->counters.shared_blks_read += bufusage->shared_blks_read;
+ e->counters.shared_blks_dirtied += bufusage->shared_blks_dirtied;
+ e->counters.shared_blks_written += bufusage->shared_blks_written;
+ e->counters.local_blks_hit += bufusage->local_blks_hit;
+ e->counters.local_blks_read += bufusage->local_blks_read;
+ e->counters.local_blks_dirtied += bufusage->local_blks_dirtied;
+ e->counters.local_blks_written += bufusage->local_blks_written;
+ e->counters.temp_blks_read += bufusage->temp_blks_read;
+ e->counters.temp_blks_written += bufusage->temp_blks_written;
+ e->counters.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time);
+ e->counters.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time);
+ e->counters.usage += USAGE_EXEC(total_exec_time);
}
else
{
- /*
- * Welford's method for accurately computing variance. See
- * <http://www.johndcook.com/blog/standard_deviation/>
- */
- double old_mean = e->counters.mean_time;
-
- e->counters.mean_time +=
- (total_time - old_mean) / e->counters.calls;
- e->counters.sum_var_time +=
- (total_time - old_mean) * (total_time - e->counters.mean_time);
-
- /* calculate min and max time */
- if (e->counters.min_time > total_time)
- e->counters.min_time = total_time;
- if (e->counters.max_time < total_time)
- e->counters.max_time = total_time;
+ /* updating counters for planning */
+ e->counters.plans += 1;
+ e->counters.total_plan_time += timing;
}
- e->counters.rows += rows;
- e->counters.shared_blks_hit += bufusage->shared_blks_hit;
- e->counters.shared_blks_read += bufusage->shared_blks_read;
- e->counters.shared_blks_dirtied += bufusage->shared_blks_dirtied;
- e->counters.shared_blks_written += bufusage->shared_blks_written;
- e->counters.local_blks_hit += bufusage->local_blks_hit;
- e->counters.local_blks_read += bufusage->local_blks_read;
- e->counters.local_blks_dirtied += bufusage->local_blks_dirtied;
- e->counters.local_blks_written += bufusage->local_blks_written;
- e->counters.temp_blks_read += bufusage->temp_blks_read;
- e->counters.temp_blks_written += bufusage->temp_blks_written;
- e->counters.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time);
- e->counters.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time);
- e->counters.usage += USAGE_EXEC(total_time);
SpinLockRelease(&e->mutex);
}
@@ -1338,7 +1442,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_8 25
+#define PG_STAT_STATEMENTS_COLS 25 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1350,6 +1455,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_8(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_8, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_3(PG_FUNCTION_ARGS)
{
@@ -1456,6 +1571,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_8:
+ if (api_version != PGSS_V1_8)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1614,8 +1733,13 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (tmp.calls == 0)
continue;
+ if (api_version >= PGSS_V1_8)
+ {
+ values[i++] = Int64GetDatumFast(tmp.plans);
+ values[i++] = Float8GetDatumFast(tmp.total_plan_time);
+ }
values[i++] = Int64GetDatumFast(tmp.calls);
- values[i++] = Float8GetDatumFast(tmp.total_time);
+ values[i++] = Float8GetDatumFast(tmp.total_exec_time);
if (api_version >= PGSS_V1_3)
{
values[i++] = Float8GetDatumFast(tmp.min_time);
@@ -1657,6 +1781,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_8 ? PG_STAT_STATEMENTS_COLS_V1_8 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
@@ -3243,3 +3368,31 @@ comp_location(const void *a, const void *b)
else
return 0;
}
+
+static BufferUsage
+compute_buffer_counters(BufferUsage start, BufferUsage stop)
+{
+ BufferUsage result;
+
+ result.shared_blks_hit = stop.shared_blks_hit - start.shared_blks_hit;
+ result.shared_blks_read = stop.shared_blks_read - start.shared_blks_read;
+ result.shared_blks_dirtied = stop.shared_blks_dirtied -
+ start.shared_blks_dirtied;
+ result.shared_blks_written = stop.shared_blks_written -
+ start.shared_blks_written;
+ result.local_blks_hit = stop.local_blks_hit - start.local_blks_hit;
+ result.local_blks_read = stop.local_blks_read - start.local_blks_read;
+ result.local_blks_dirtied = stop.local_blks_dirtied -
+ start.local_blks_dirtied;
+ result.local_blks_written = stop.local_blks_written -
+ start.local_blks_written;
+ result.temp_blks_read = stop.temp_blks_read - start.temp_blks_read;
+ result.temp_blks_written = stop.temp_blks_written -
+ start.temp_blks_written;
+ result.blk_read_time = stop.blk_read_time;
+ INSTR_TIME_SUBTRACT(result.blk_read_time, start.blk_read_time);
+ result.blk_write_time = stop.blk_write_time;
+ INSTR_TIME_SUBTRACT(result.blk_write_time, start.blk_write_time);
+
+ return result;
+}
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 14cb422354..7fb20df886 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.7'
+default_version = '1.8'
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 aef890d893..4d7d6e584d 100644
--- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql
+++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql
@@ -259,4 +259,20 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C";
DROP ROLE regress_stats_user1;
DROP ROLE regress_stats_user2;
+--
+-- [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 26bb82da4a..368daf3e39 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>total_plan_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>
@@ -89,39 +104,46 @@
<entry>Number of times executed</entry>
</row>
+ <row>
+ <entry><structfield>total_exec_time</structfield></entry>
+ <entry><type>double precision</type></entry>
+ <entry></entry>
+ <entry>Total time spent executing the statement, in milliseconds</entry>
+ </row>
+
<row>
<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 planning and 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>
@@ -431,6 +453,21 @@
</listitem>
</varlistentry>
+ <varlistentry>
+ <term>
+ <varname>pg_stat_statements.track_planning</varname> (<type>boolean</type>)
+ </term>
+
+ <listitem>
+ <para>
+ <varname>pg_stat_statements.track_planning</varname> controls whether
+ planning operations and duration are tracked by the module.
+ The default value is <literal>on</literal>.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term>
<varname>pg_stat_statements.track_utility</varname> (<type>boolean</type>)
--
2.22.0
From 7a98f3c87ea24c705c1ac497c635c1697d766929 Mon Sep 17 00:00:00 2001
From: Julien Rouhaud <julien.rouh...@free.fr>
Date: Thu, 28 Mar 2019 13:33:23 +0100
Subject: [PATCH 1/2] Pass query string to the planner
---
src/backend/commands/copy.c | 3 ++-
src/backend/commands/createas.c | 3 ++-
src/backend/commands/explain.c | 2 +-
src/backend/commands/extension.c | 2 +-
src/backend/commands/matview.c | 2 +-
src/backend/commands/portalcmds.c | 2 +-
src/backend/executor/functions.c | 1 +
src/backend/optimizer/plan/planner.c | 10 ++++++----
src/backend/tcop/postgres.c | 13 ++++++++-----
src/backend/utils/cache/plancache.c | 3 ++-
src/include/optimizer/optimizer.h | 3 ++-
src/include/optimizer/planner.h | 4 +++-
src/include/tcop/tcopprot.h | 6 ++++--
13 files changed, 34 insertions(+), 20 deletions(-)
diff --git a/src/backend/commands/copy.c b/src/backend/commands/copy.c
index f1161f0fee..79c8395627 100644
--- a/src/backend/commands/copy.c
+++ b/src/backend/commands/copy.c
@@ -1580,7 +1580,8 @@ BeginCopy(ParseState *pstate,
}
/* plan the query */
- plan = pg_plan_query(query, CURSOR_OPT_PARALLEL_OK, NULL);
+ plan = pg_plan_query(query, pstate->p_sourcetext,
+ CURSOR_OPT_PARALLEL_OK, NULL);
/*
* With row level security and a user using "COPY relation TO", we
diff --git a/src/backend/commands/createas.c b/src/backend/commands/createas.c
index 4c1d909d38..039be44589 100644
--- a/src/backend/commands/createas.c
+++ b/src/backend/commands/createas.c
@@ -330,7 +330,8 @@ ExecCreateTableAs(CreateTableAsStmt *stmt, const char *queryString,
Assert(query->commandType == CMD_SELECT);
/* plan the query */
- plan = pg_plan_query(query, CURSOR_OPT_PARALLEL_OK, params);
+ plan = pg_plan_query(query, queryString, CURSOR_OPT_PARALLEL_OK,
+ params);
/*
* Use a snapshot with an updated command ID to ensure this query sees
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 92969636b7..f5a94a235e 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -364,7 +364,7 @@ ExplainOneQuery(Query *query, int cursorOptions,
INSTR_TIME_SET_CURRENT(planstart);
/* plan the query */
- plan = pg_plan_query(query, cursorOptions, params);
+ plan = pg_plan_query(query, queryString, cursorOptions, params);
INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);
diff --git a/src/backend/commands/extension.c b/src/backend/commands/extension.c
index 59ca5cd5a9..33e547ab81 100644
--- a/src/backend/commands/extension.c
+++ b/src/backend/commands/extension.c
@@ -728,7 +728,7 @@ execute_sql_string(const char *sql)
NULL,
0,
NULL);
- stmt_list = pg_plan_queries(stmt_list, CURSOR_OPT_PARALLEL_OK, NULL);
+ stmt_list = pg_plan_queries(stmt_list, sql, CURSOR_OPT_PARALLEL_OK, NULL);
foreach(lc2, stmt_list)
{
diff --git a/src/backend/commands/matview.c b/src/backend/commands/matview.c
index 537d0e8cef..6c88a16eb1 100644
--- a/src/backend/commands/matview.c
+++ b/src/backend/commands/matview.c
@@ -391,7 +391,7 @@ refresh_matview_datafill(DestReceiver *dest, Query *query,
CHECK_FOR_INTERRUPTS();
/* Plan the query which will generate data for the refresh. */
- plan = pg_plan_query(query, 0, NULL);
+ plan = pg_plan_query(query, queryString, 0, NULL);
/*
* Use a snapshot with an updated command ID to ensure this query sees
diff --git a/src/backend/commands/portalcmds.c b/src/backend/commands/portalcmds.c
index 83f9959d54..e390776716 100644
--- a/src/backend/commands/portalcmds.c
+++ b/src/backend/commands/portalcmds.c
@@ -89,7 +89,7 @@ PerformCursorOpen(DeclareCursorStmt *cstmt, ParamListInfo params,
elog(ERROR, "non-SELECT statement in DECLARE CURSOR");
/* Plan the query, applying the specified options */
- plan = pg_plan_query(query, cstmt->options, params);
+ plan = pg_plan_query(query, queryString, cstmt->options, params);
/*
* Create a portal and copy the plan and queryString into its memory.
diff --git a/src/backend/executor/functions.c b/src/backend/executor/functions.c
index 29a8a16f5f..107ab2c789 100644
--- a/src/backend/executor/functions.c
+++ b/src/backend/executor/functions.c
@@ -505,6 +505,7 @@ init_execution_state(List *queryTree_list,
}
else
stmt = pg_plan_query(queryTree,
+ fcache->src,
CURSOR_OPT_PARALLEL_OK,
NULL);
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index eadc04222e..209f420992 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -265,19 +265,21 @@ static int common_prefix_cmp(const void *a, const void *b);
*
*****************************************************************************/
PlannedStmt *
-planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
+planner(Query *parse, const char *query_text, int cursorOptions,
+ ParamListInfo boundParams)
{
PlannedStmt *result;
if (planner_hook)
- result = (*planner_hook) (parse, cursorOptions, boundParams);
+ result = (*planner_hook) (parse, query_text, cursorOptions, boundParams);
else
- result = standard_planner(parse, cursorOptions, boundParams);
+ result = standard_planner(parse, query_text, cursorOptions, boundParams);
return result;
}
PlannedStmt *
-standard_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
+standard_planner(Query *parse, const char *querytext, int cursorOptions,
+ ParamListInfo boundParams)
{
PlannedStmt *result;
PlannerGlobal *glob;
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1d4f..af1624fdf5 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -858,7 +858,8 @@ pg_rewrite_query(Query *query)
* This is a thin wrapper around planner() and takes the same parameters.
*/
PlannedStmt *
-pg_plan_query(Query *querytree, int cursorOptions, ParamListInfo boundParams)
+pg_plan_query(Query *querytree, const char *query_text, int cursorOptions,
+ ParamListInfo boundParams)
{
PlannedStmt *plan;
@@ -875,7 +876,7 @@ pg_plan_query(Query *querytree, int cursorOptions, ParamListInfo boundParams)
ResetUsage();
/* call the optimizer */
- plan = planner(querytree, cursorOptions, boundParams);
+ plan = planner(querytree, query_text, cursorOptions, boundParams);
if (log_planner_stats)
ShowUsage("PLANNER STATISTICS");
@@ -943,7 +944,8 @@ pg_plan_query(Query *querytree, int cursorOptions, ParamListInfo boundParams)
* The result is a list of PlannedStmt nodes.
*/
List *
-pg_plan_queries(List *querytrees, int cursorOptions, ParamListInfo boundParams)
+pg_plan_queries(List *querytrees, const char *query_string, int cursorOptions,
+ ParamListInfo boundParams)
{
List *stmt_list = NIL;
ListCell *query_list;
@@ -965,7 +967,8 @@ pg_plan_queries(List *querytrees, int cursorOptions, ParamListInfo boundParams)
}
else
{
- stmt = pg_plan_query(query, cursorOptions, boundParams);
+ stmt = pg_plan_query(query, query_string, cursorOptions,
+ boundParams);
}
stmt_list = lappend(stmt_list, stmt);
@@ -1140,7 +1143,7 @@ exec_simple_query(const char *query_string)
querytree_list = pg_analyze_and_rewrite(parsetree, query_string,
NULL, 0, NULL);
- plantree_list = pg_plan_queries(querytree_list,
+ plantree_list = pg_plan_queries(querytree_list, query_string,
CURSOR_OPT_PARALLEL_OK, NULL);
/* Done with the snapshot used for parsing/planning */
diff --git a/src/backend/utils/cache/plancache.c b/src/backend/utils/cache/plancache.c
index abc3062892..b4ae9fde84 100644
--- a/src/backend/utils/cache/plancache.c
+++ b/src/backend/utils/cache/plancache.c
@@ -930,7 +930,8 @@ BuildCachedPlan(CachedPlanSource *plansource, List *qlist,
/*
* Generate the plan.
*/
- plist = pg_plan_queries(qlist, plansource->cursor_options, boundParams);
+ plist = pg_plan_queries(qlist, plansource->query_string,
+ plansource->cursor_options, boundParams);
/* Release snapshot if we got one */
if (snapshot_set)
diff --git a/src/include/optimizer/optimizer.h b/src/include/optimizer/optimizer.h
index 6b8fd3f285..d99ee69efd 100644
--- a/src/include/optimizer/optimizer.h
+++ b/src/include/optimizer/optimizer.h
@@ -102,7 +102,8 @@ typedef enum
extern int force_parallel_mode;
extern bool parallel_leader_participation;
-extern struct PlannedStmt *planner(Query *parse, int cursorOptions,
+extern struct PlannedStmt *planner(Query *parse, const char *query_text,
+ int cursorOptions,
struct ParamListInfoData *boundParams);
extern Expr *expression_planner(Expr *expr);
diff --git a/src/include/optimizer/planner.h b/src/include/optimizer/planner.h
index 8d30b94215..c4e83e3a73 100644
--- a/src/include/optimizer/planner.h
+++ b/src/include/optimizer/planner.h
@@ -24,6 +24,7 @@
/* Hook for plugins to get control in planner() */
typedef PlannedStmt *(*planner_hook_type) (Query *parse,
+ const char *query_text,
int cursorOptions,
ParamListInfo boundParams);
extern PGDLLIMPORT planner_hook_type planner_hook;
@@ -37,7 +38,8 @@ typedef void (*create_upper_paths_hook_type) (PlannerInfo *root,
extern PGDLLIMPORT create_upper_paths_hook_type create_upper_paths_hook;
-extern PlannedStmt *standard_planner(Query *parse, int cursorOptions,
+extern PlannedStmt *standard_planner(Query *parse, const char *query_text,
+ int cursorOptions,
ParamListInfo boundParams);
extern PlannerInfo *subquery_planner(PlannerGlobal *glob, Query *parse,
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index ec21f7e45c..716b040c04 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -52,9 +52,11 @@ extern List *pg_analyze_and_rewrite_params(RawStmt *parsetree,
ParserSetupHook parserSetup,
void *parserSetupArg,
QueryEnvironment *queryEnv);
-extern PlannedStmt *pg_plan_query(Query *querytree, int cursorOptions,
+extern PlannedStmt *pg_plan_query(Query *querytree, const char *query_text,
+ int cursorOptions,
ParamListInfo boundParams);
-extern List *pg_plan_queries(List *querytrees, int cursorOptions,
+extern List *pg_plan_queries(List *querytrees, const char *query_text,
+ int cursorOptions,
ParamListInfo boundParams);
extern bool check_max_stack_depth(int *newval, void **extra, GucSource source);
--
2.22.0
