From 06c611027cdf3af52a13f295d4c3a33bcb08d229 Mon Sep 17 00:00:00 2001 From: Thomas Munro 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 @@ The pg_stat_statements 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. @@ -82,6 +83,20 @@ Text of a representative statement + + plans + bigint + + Number of times planned + + + + plan_time + double precision + + Total time spent planning, in milliseconds + + calls bigint 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