From f82c38be8848a9c560546438d54bac1b66ac7121 Mon Sep 17 00:00:00 2001 From: Julien Rouhaud Date: Wed, 27 Mar 2019 11:24:35 +0100 Subject: [PATCH v5 2/3] Add planning counters to pg_stat_statements --- contrib/pg_stat_statements/Makefile | 3 +- .../expected/pg_stat_statements.out | 231 +++++++++----- .../pg_stat_statements--1.7--1.8.sql | 56 ++++ .../pg_stat_statements/pg_stat_statements.c | 302 +++++++++++++----- .../pg_stat_statements.control | 2 +- .../sql/pg_stat_statements.sql | 16 + doc/src/sgml/pgstatstatements.sgml | 49 ++- 7 files changed, 498 insertions(+), 161 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 80042a0905..0f45e85b5b 100644 --- a/contrib/pg_stat_statements/Makefile +++ b/contrib/pg_stat_statements/Makefile @@ -6,7 +6,8 @@ OBJS = \ pg_stat_statements.o 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 6787ec1efd..7612bed6d5 100644 --- a/contrib/pg_stat_statements/expected/pg_stat_statements.out +++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out @@ -96,25 +96,26 @@ EXECUTE pgss_test(1); DEALLOCATE pgss_test; SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows ----------------------------------------------------+-------+------ - PREPARE pgss_test (int) AS SELECT $1, $2 LIMIT $3 | 1 | 1 - SELECT $1 +| 4 | 4 - +| | - AS "text" | | - SELECT $1 + $2 | 2 | 2 - SELECT $1 + $2 + $3 AS "add" | 3 | 3 - SELECT $1 AS "float" | 1 | 1 - SELECT $1 AS "int" | 2 | 2 - SELECT $1 AS i UNION SELECT $2 ORDER BY i | 1 | 2 - SELECT $1 || $2 | 1 | 1 - SELECT pg_stat_statements_reset() | 1 | 1 - WITH t(f) AS ( +| 1 | 2 - VALUES ($1), ($2) +| | - ) +| | - SELECT f FROM t ORDER BY f | | - select $1::jsonb ? $2 | 1 | 1 -(11 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + PREPARE pgss_test (int) AS SELECT $1, $2 LIMIT $3 | 1 | 1 + SELECT $1 +| 4 | 4 + +| | + AS "text" | | + SELECT $1 + $2 | 2 | 2 + SELECT $1 + $2 + $3 AS "add" | 3 | 3 + SELECT $1 AS "float" | 1 | 1 + SELECT $1 AS "int" | 2 | 2 + SELECT $1 AS i UNION SELECT $2 ORDER BY i | 1 | 2 + SELECT $1 || $2 | 1 | 1 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 + WITH t(f) AS ( +| 1 | 2 + VALUES ($1), ($2) +| | + ) +| | + SELECT f FROM t ORDER BY f | | + select $1::jsonb ? $2 | 1 | 1 +(12 rows) -- -- CRUD: INSERT SELECT UPDATE DELETE on test table @@ -196,18 +197,19 @@ SELECT * FROM test WHERE a IN (1, 2, 3, 4, 5); (8 rows) SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows --------------------------------------------------------------+-------+------ - DELETE FROM test WHERE a > $1 | 1 | 1 - INSERT INTO test (a, b) VALUES ($1, $2), ($3, $4), ($5, $6) | 1 | 3 - INSERT INTO test VALUES(generate_series($1, $2), $3) | 1 | 10 - SELECT * FROM test ORDER BY a | 1 | 12 - SELECT * FROM test WHERE a > $1 ORDER BY a | 2 | 4 - SELECT * FROM test WHERE a IN ($1, $2, $3, $4, $5) | 1 | 8 - SELECT pg_stat_statements_reset() | 1 | 1 - UPDATE test SET b = $1 WHERE a = $2 | 6 | 6 - UPDATE test SET b = $1 WHERE a > $2 | 1 | 3 -(9 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + DELETE FROM test WHERE a > $1 | 1 | 1 + INSERT INTO test (a, b) VALUES ($1, $2), ($3, $4), ($5, $6) | 1 | 3 + INSERT INTO test VALUES(generate_series($1, $2), $3) | 1 | 10 + SELECT * FROM test ORDER BY a | 1 | 12 + SELECT * FROM test WHERE a > $1 ORDER BY a | 2 | 4 + SELECT * FROM test WHERE a IN ($1, $2, $3, $4, $5) | 1 | 8 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 + UPDATE test SET b = $1 WHERE a = $2 | 6 | 6 + UPDATE test SET b = $1 WHERE a > $2 | 1 | 3 +(10 rows) -- -- pg_stat_statements.track = none @@ -288,13 +290,14 @@ SELECT PLUS_ONE(10); (1 row) SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows ------------------------------------+-------+------ - SELECT $1::TEXT | 1 | 1 - SELECT PLUS_ONE($1) | 2 | 2 - SELECT PLUS_TWO($1) | 2 | 2 - SELECT pg_stat_statements_reset() | 1 | 1 -(4 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + SELECT $1::TEXT | 1 | 1 + SELECT PLUS_ONE($1) | 2 | 2 + SELECT PLUS_TWO($1) | 2 | 2 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 +(5 rows) -- -- pg_stat_statements.track = all @@ -345,14 +348,15 @@ SELECT PLUS_ONE(1); (1 row) SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows ------------------------------------+-------+------ - SELECT (i + $2 + $3)::INTEGER | 2 | 2 - SELECT (i + $2)::INTEGER LIMIT $3 | 2 | 2 - SELECT PLUS_ONE($1) | 2 | 2 - SELECT PLUS_TWO($1) | 2 | 2 - SELECT pg_stat_statements_reset() | 1 | 1 -(5 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + SELECT (i + $2 + $3)::INTEGER | 2 | 2 + SELECT (i + $2)::INTEGER LIMIT $3 | 2 | 2 + SELECT PLUS_ONE($1) | 2 | 2 + SELECT PLUS_TWO($1) | 2 | 2 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 +(6 rows) -- -- queries with locking clauses @@ -437,8 +441,9 @@ SELECT calls, query FROM pg_stat_statements ORDER BY query COLLATE "C"; 1 | SELECT * FROM pgss_a JOIN pgss_b ON pgss_b.a_id = pgss_a.id FOR UPDATE OF pgss_b 1 | SELECT * FROM pgss_a JOIN pgss_b ON pgss_b.a_id = pgss_a.id FOR UPDATE OF pgss_b, pgss_a 1 | SELECT * FROM pgss_a JOIN pgss_b ON pgss_b.a_id = pgss_a.id FOR UPDATE SKIP LOCKED + 0 | SELECT calls, query FROM pg_stat_statements ORDER BY query COLLATE "C" 1 | SELECT pg_stat_statements_reset() -(11 rows) +(12 rows) DROP TABLE pgss_a, pgss_b CASCADE; -- @@ -470,17 +475,18 @@ NOTICE: table "test" does not exist, skipping NOTICE: function plus_one(pg_catalog.int4) does not exist, skipping DROP FUNCTION PLUS_TWO(INTEGER); SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows --------------------------------------------+-------+------ - CREATE INDEX test_b ON test(b) | 1 | 0 - DROP FUNCTION IF EXISTS PLUS_ONE(INTEGER) | 1 | 0 - DROP FUNCTION PLUS_ONE(INTEGER) | 1 | 0 - DROP FUNCTION PLUS_TWO(INTEGER) | 1 | 0 - DROP TABLE IF EXISTS test | 3 | 0 - DROP TABLE test | 1 | 0 - SELECT $1 | 1 | 1 - SELECT pg_stat_statements_reset() | 1 | 1 -(8 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + CREATE INDEX test_b ON test(b) | 1 | 0 + DROP FUNCTION IF EXISTS PLUS_ONE(INTEGER) | 1 | 0 + DROP FUNCTION PLUS_ONE(INTEGER) | 1 | 0 + DROP FUNCTION PLUS_TWO(INTEGER) | 1 | 0 + DROP TABLE IF EXISTS test | 3 | 0 + DROP TABLE test | 1 | 0 + SELECT $1 | 1 | 1 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 +(9 rows) -- -- Track user activity and reset them @@ -522,19 +528,20 @@ SELECT 1+1 AS "TWO"; RESET ROLE; SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows ------------------------------------+-------+------ - CREATE ROLE regress_stats_user1 | 1 | 0 - CREATE ROLE regress_stats_user2 | 1 | 0 - RESET ROLE | 2 | 0 - SELECT $1 AS "ONE" | 1 | 1 - SELECT $1 AS "ONE" | 1 | 1 - SELECT $1+$2 AS "TWO" | 1 | 1 - SELECT $1+$2 AS "TWO" | 1 | 1 - SELECT pg_stat_statements_reset() | 1 | 1 - SET ROLE regress_stats_user1 | 1 | 0 - SET ROLE regress_stats_user2 | 1 | 0 -(10 rows) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + CREATE ROLE regress_stats_user1 | 1 | 0 + CREATE ROLE regress_stats_user2 | 1 | 0 + RESET ROLE | 2 | 0 + SELECT $1 AS "ONE" | 1 | 1 + SELECT $1 AS "ONE" | 1 | 1 + SELECT $1+$2 AS "TWO" | 1 | 1 + SELECT $1+$2 AS "TWO" | 1 | 1 + SELECT pg_stat_statements_reset() | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 + SET ROLE regress_stats_user1 | 1 | 0 + SET ROLE regress_stats_user2 | 1 | 0 +(11 rows) -- -- Don't reset anything if any of the parameter is NULL @@ -557,7 +564,7 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; SELECT $1+$2 AS "TWO" | 1 | 1 SELECT pg_stat_statements_reset($1) | 1 | 1 SELECT pg_stat_statements_reset() | 1 | 1 - SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 1 | 10 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 1 | 11 SET ROLE regress_stats_user1 | 1 | 0 SET ROLE regress_stats_user2 | 1 | 0 (12 rows) @@ -592,7 +599,7 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; WHERE s.query = $2 LIMIT $3)) | | SELECT pg_stat_statements_reset($1) | 1 | 1 SELECT pg_stat_statements_reset() | 1 | 1 - SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 2 | 22 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 2 | 23 SET ROLE regress_stats_user1 | 1 | 0 SET ROLE regress_stats_user2 | 1 | 0 (12 rows) @@ -624,7 +631,7 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; SELECT pg_stat_statements_reset($1,$2,s.queryid) +| 1 | 2 FROM pg_stat_statements AS s WHERE s.query = $3 | | SELECT pg_stat_statements_reset() | 1 | 1 - SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 3 | 34 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 3 | 35 SET ROLE regress_stats_user1 | 1 | 0 SET ROLE regress_stats_user2 | 1 | 0 (11 rows) @@ -656,7 +663,7 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; SELECT pg_stat_statements_reset() | 1 | 1 SELECT pg_stat_statements_reset(r.oid) +| 1 | 1 FROM pg_roles AS r WHERE r.rolname = $1 | | - SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 4 | 45 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 4 | 46 SET ROLE regress_stats_user2 | 1 | 0 (10 rows) @@ -670,14 +677,80 @@ SELECT pg_stat_statements_reset(0,0,0); (1 row) SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; - query | calls | rows -----------------------------------------+-------+------ - SELECT pg_stat_statements_reset(0,0,0) | 1 | 1 -(1 row) + query | calls | rows +------------------------------------------------------------------------------+-------+------ + SELECT pg_stat_statements_reset(0,0,0) | 1 | 1 + SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 0 | 0 +(2 rows) -- -- cleanup -- 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 + SELECT query, plans, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C" | 1 | 0 | 0 +(6 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..5cf719ddc3 --- /dev/null +++ b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql @@ -0,0 +1,56 @@ +/* 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 min_plan_time float8, + OUT max_plan_time float8, + OUT mean_plan_time float8, + OUT stddev_plan_time float8, + OUT calls int8, + OUT total_exec_time float8, + OUT min_exec_time float8, + OUT max_exec_time float8, + OUT mean_exec_time float8, + OUT stddev_exec_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 20dc8c605b..adb63a6fe9 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 @@ -67,6 +68,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" @@ -109,6 +111,7 @@ static const uint32 PGSS_PG_MAJOR_VERSION = PG_VERSION_NUM / 100; #define USAGE_DECREASE_FACTOR (0.99) /* decreased every entry_dealloc */ #define STICKY_DECREASE_FACTOR (0.50) /* factor for sticky entries */ #define USAGE_DEALLOC_PERCENT 5 /* free this % of entries at once */ +#define IS_STICKY(c) ((c.calls[PGSS_PLAN] + c.calls[PGSS_EXEC]) == 0) #define JUMBLE_SIZE 1024 /* query serialization buffer size */ @@ -120,9 +123,22 @@ 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_PLAN and PGSS_EXEC must be respectively 0 and 1 as they're used to + * reference the underlying values in the arrays in the Counters struct, + * and this order is required in pg_stat_statements_internal(). + */ + PGSS_PLAN = 0, + PGSS_EXEC, + PGSS_JUMBLE, +} 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. @@ -144,12 +160,12 @@ typedef struct pgssHashKey */ typedef struct Counters { - int64 calls; /* # of times executed */ - double total_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 calls[2]; /* # of times planned/executed */ + double total_time[2]; /* total planning/execution time, in msec */ + double min_time[2]; /* minimum planning/execution time in msec */ + double max_time[2]; /* maximum planning/execution time in msec */ + double mean_time[2]; /* mean planning/execution time in msec */ + double sum_var_time[2]; /* sum of variances in planning/execution 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 +254,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 +285,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 +311,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 +334,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, @@ -341,6 +366,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); /* @@ -399,6 +425,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, @@ -425,6 +462,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; @@ -448,6 +487,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; @@ -602,7 +642,7 @@ pgss_shmem_startup(void) buffer[temp.query_len] = '\0'; /* Skip loading "sticky" entries */ - if (temp.counters.calls == 0) + if (IS_STICKY(temp.counters)) continue; /* Store the query text */ @@ -838,12 +878,83 @@ 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; + + /* We need to track buffer usage as the planner can access them. */ + bufusage_start = pgBufferUsage; + if (pgss_enabled() && pgss_track_planning + && parse->queryId != UINT64CONST(0)) + { + 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); + + pgss_store(query_text, + parse->queryId, + parse->stmt_location, + parse->stmt_len, + PGSS_PLAN, + 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 */ @@ -941,6 +1052,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) queryId, queryDesc->plannedstmt->stmt_location, queryDesc->plannedstmt->stmt_len, + PGSS_EXEC, queryDesc->totaltime->total * 1000.0, /* convert to msec */ queryDesc->estate->es_processed, &queryDesc->totaltime->bufusage, @@ -1016,35 +1128,13 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, rows = (qc && qc->commandTag == CMDTAG_COPY) ? qc->nprocessed : 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, INSTR_TIME_GET_MILLISEC(duration), rows, &bufusage, @@ -1083,12 +1173,17 @@ 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. timing, rows, bufusage are ignored in this case. + * + * If kind is PGSS_PLAN or PGSS_EXEC, its value is used as the array position + * for the arrays in the Counters field. */ 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) { @@ -1176,8 +1271,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, @@ -1234,19 +1331,22 @@ pgss_store(const char *query, uint64 queryId, */ volatile pgssEntry *e = (volatile pgssEntry *) entry; + Assert(kind == PGSS_PLAN || kind == PGSS_EXEC); + SpinLockAcquire(&e->mutex); /* "Unstick" entry if it was previously sticky */ - if (e->counters.calls == 0) + if (IS_STICKY(e->counters)) e->counters.usage = USAGE_INIT; - e->counters.calls += 1; - e->counters.total_time += total_time; - if (e->counters.calls == 1) + e->counters.calls[kind] += 1; + e->counters.total_time[kind] += timing; + + if (e->counters.calls[kind] == 1) { - e->counters.min_time = total_time; - e->counters.max_time = total_time; - e->counters.mean_time = total_time; + e->counters.min_time[kind] = timing; + e->counters.max_time[kind] = timing; + e->counters.mean_time[kind] = timing; } else { @@ -1254,18 +1354,18 @@ pgss_store(const char *query, uint64 queryId, * Welford's method for accurately computing variance. See * */ - double old_mean = e->counters.mean_time; + double old_mean = e->counters.mean_time[kind]; - 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); + e->counters.mean_time[kind] += + (timing - old_mean) / e->counters.calls[kind]; + e->counters.sum_var_time[kind] += + (timing - old_mean) * (timing - e->counters.mean_time[kind]); /* 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; + if (e->counters.min_time[kind] > timing) + e->counters.min_time[kind] = timing; + if (e->counters.max_time[kind] < timing) + e->counters.max_time[kind] = timing; } e->counters.rows += rows; e->counters.shared_blks_hit += bufusage->shared_blks_hit; @@ -1280,7 +1380,7 @@ pgss_store(const char *query, uint64 queryId, 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); + e->counters.usage += USAGE_EXEC(timing); SpinLockRelease(&e->mutex); } @@ -1328,7 +1428,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 29 +#define PG_STAT_STATEMENTS_COLS 29 /* maximum of above */ /* * Retrieve statement statistics. @@ -1340,6 +1441,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) { @@ -1445,6 +1556,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"); } @@ -1600,29 +1715,39 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, } /* Skip entry if unexecuted (ie, it's a pending "sticky" entry) */ - if (tmp.calls == 0) + if (IS_STICKY(tmp)) continue; - values[i++] = Int64GetDatumFast(tmp.calls); - values[i++] = Float8GetDatumFast(tmp.total_time); - if (api_version >= PGSS_V1_3) + /* Note that we rely on PGSS_PLAN being 0 and PGSS_EXEC being 1. */ + for (int kind=0; kind < 2; kind++) { - values[i++] = Float8GetDatumFast(tmp.min_time); - values[i++] = Float8GetDatumFast(tmp.max_time); - values[i++] = Float8GetDatumFast(tmp.mean_time); + if (kind == PGSS_EXEC || api_version >= PGSS_V1_8) + { + values[i++] = Int64GetDatumFast(tmp.calls[kind]); + values[i++] = Float8GetDatumFast(tmp.total_time[kind]); + } - /* - * Note we are calculating the population variance here, not the - * sample variance, as we have data for the whole population, so - * Bessel's correction is not used, and we don't divide by - * tmp.calls - 1. - */ - if (tmp.calls > 1) - stddev = sqrt(tmp.sum_var_time / tmp.calls); - else - stddev = 0.0; - values[i++] = Float8GetDatumFast(stddev); + if ( (kind == PGSS_EXEC && api_version >= PGSS_V1_3) || + api_version >= PGSS_V1_8) + { + values[i++] = Float8GetDatumFast(tmp.min_time[kind]); + values[i++] = Float8GetDatumFast(tmp.max_time[kind]); + values[i++] = Float8GetDatumFast(tmp.mean_time[kind]); + + /* + * Note we are calculating the population variance here, not the + * sample variance, as we have data for the whole population, so + * Bessel's correction is not used, and we don't divide by + * tmp.calls - 1. + */ + if (tmp.calls[kind] > 1) + stddev = sqrt(tmp.sum_var_time[kind] / tmp.calls[kind]); + else + stddev = 0.0; + values[i++] = Float8GetDatumFast(stddev); + } } + values[i++] = Int64GetDatumFast(tmp.rows); values[i++] = Int64GetDatumFast(tmp.shared_blks_hit); values[i++] = Int64GetDatumFast(tmp.shared_blks_read); @@ -1646,6 +1771,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); @@ -1781,7 +1907,7 @@ entry_dealloc(void) { entries[i++] = entry; /* "Sticky" entries get a different usage decay rate. */ - if (entry->counters.calls == 0) + if (IS_STICKY(entry->counters)) entry->counters.usage *= STICKY_DECREASE_FACTOR; else entry->counters.usage *= USAGE_DECREASE_FACTOR; @@ -3249,3 +3375,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 8b527070d4..e36e64f633 100644 --- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql +++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql @@ -290,4 +290,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 @@ 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 the statement was planned + + + + total_plan_time + double precision + + Total time spent planning the statement, in milliseconds + + calls bigint @@ -89,39 +104,46 @@ Number of times executed + + total_exec_time + double precision + + Total time spent executing the statement, in milliseconds + + total_time double precision - Total time spent in the statement, in milliseconds + Total time spent planning and executing the statement, in milliseconds min_time double precision - Minimum time spent in the statement, in milliseconds + Minimum time spent executing the statement, in milliseconds max_time double precision - Maximum time spent in the statement, in milliseconds + Maximum time spent executing the statement, in milliseconds mean_time double precision - Mean time spent in the statement, in milliseconds + Mean time spent executing the statement, in milliseconds stddev_time double precision - Population standard deviation of time spent in the statement, in milliseconds + Population standard deviation of time spent executing the statement, in milliseconds @@ -431,6 +453,21 @@ + + + pg_stat_statements.track_planning (boolean) + + + + + pg_stat_statements.track_planning controls whether + planning operations and duration are tracked by the module. + The default value is on. + Only superusers can change this setting. + + + + pg_stat_statements.track_utility (boolean) -- 2.20.1