Re: Planning counters in pg_stat_statements (using pgss_store)
Julien Rouhaud <[email protected]>
| Newsgroups | gmane.comp.db.postgresql.devel.general |
|---|---|
| Message-ID | <CAOBaU_bKDoMxEWLqJue8ZS-kamcwKS2zUROONjEtp_sHmbBegg@mail.gmail.com> |
On Fri, Nov 22, 2019 at 11:23 AM [email protected] <[email protected]> wrote: > > On Wed, Nov 20, 2019 at 4:55 PM, Julien Rouhaud wrote: > > On Wed, Nov 20, 2019 at 2:06 AM [email protected] <[email protected]> wrote: > > > > > > On Tue, Nov 19, 2019 at 2:27 PM, Julien Rouhaud wrote: > > > > On Fri, Nov 15, 2019 at 2:00 AM [email protected] <[email protected]> wrote: > > > > > > > > > > Actually I also don't have strong opinion but I thought someone > > > > > would complain about renaming of those columns and > > > > also some tools like monitoring which use those columns will not > > > > work. If we use {total, min, max, mean, stddev}_time, someone might > > > > mistakenly understand {total, min, max, mean, stddev}_time mean {total, min, max, mean, stddev} of planning and > > execution. > > > > > If I need to choose {total, min, max, mean, stddev}_time or > > > > > {total, min, max, mean, stddev}_exec_time, I choose former > > > > one because choosing best name is not worth destructing the existing scripts or tools. > > > > > > > > We could definitely keep (plan|exec)_time for the SRF, and have the > > > > {total, min, max, mean, stddev}_time created by the view to be a sum > > > > of planning + execution for each counter > > > > > > I might misunderstand but if we define {total, min, max, mean, > > > stddev}_time is just a sum of planning + execution for each counter > > > like "select total_plan_time + total_exec_time as total_time from > > > pg_stat_statements", I wonder we can calculate stddev_time correctly. > > > If we prepare variables in the codes to calculate those values, yes, > > > we can correctly calculate those values even for the total_stddev. > > > > Yes you're right, this can't possibly work for most of the counters. > > And also, since there's no guarantee that each execution will follow a planning, providing such global counters for > > min/max/mean and stddev wouldn't make much sense. > > Ah, I see. Planning counts and execution counts differ. > It might be difficult to redefine the meaning of {min, max, mean, stddev}_time precisely, and even if we can redefine it correctly, it would not be intuitive. Thomas' automatic patch tester just warned me that the patchset is broken since 3fd40b628c7db4, which removed the queryString from ExecCreateTableAs. New patch version that re-add the queryString, no changes otherwise.
0001-Pass-query-string-to-the-planner-v3.patch
(application/octet-stream, 11.9 KB)
From 5ca152cecb4207178f1aa6d0f203bca0be5eb942 Mon Sep 17 00:00:00 2001 From: Julien Rouhaud <[email protected]> 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 | 5 +++-- 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/tcop/utility.c | 3 ++- src/backend/utils/cache/plancache.c | 3 ++- src/include/commands/createas.h | 4 +++- src/include/optimizer/optimizer.h | 3 ++- src/include/optimizer/planner.h | 4 +++- src/include/tcop/tcopprot.h | 6 ++++-- 15 files changed, 40 insertions(+), 23 deletions(-) diff --git a/src/backend/commands/copy.c b/src/backend/commands/copy.c index c93a788798..3719beeb98 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 9f387b5f5f..3fe65a6c5d 100644 --- a/src/backend/commands/createas.c +++ b/src/backend/commands/createas.c @@ -225,7 +225,7 @@ create_ctas_nodata(List *tlist, IntoClause *into) ObjectAddress ExecCreateTableAs(ParseState *pstate, CreateTableAsStmt *stmt, ParamListInfo params, QueryEnvironment *queryEnv, - char *completionTag) + const char *queryString, char *completionTag) { Query *query = castNode(Query, stmt->query); IntoClause *into = stmt->into; @@ -329,7 +329,8 @@ ExecCreateTableAs(ParseState *pstate, CreateTableAsStmt *stmt, 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 d189b8d573..7a04d0396c 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -363,7 +363,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 01de398dcb..f1590e1b89 100644 --- a/src/backend/commands/extension.c +++ b/src/backend/commands/extension.c @@ -740,7 +740,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 1ee37c1aeb..dfb6cf72e2 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 7e5c805a1e..dd749ebc33 100644 --- a/src/backend/commands/portalcmds.c +++ b/src/backend/commands/portalcmds.c @@ -90,7 +90,7 @@ PerformCursorOpen(ParseState *pstate, DeclareCursorStmt *cstmt, ParamListInfo pa 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 query string into its memory. diff --git a/src/backend/executor/functions.c b/src/backend/executor/functions.c index ac298c0295..8dd01995ad 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 d6f2153593..bb76dda576 100644 --- a/src/backend/optimizer/plan/planner.c +++ b/src/backend/optimizer/plan/planner.c @@ -264,19 +264,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 0a6f80963b..e7ac8036f1 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -854,7 +854,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; @@ -871,7 +872,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"); @@ -939,7 +940,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; @@ -961,7 +963,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); @@ -1152,7 +1155,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/tcop/utility.c b/src/backend/tcop/utility.c index b2c58bf862..5229411fd7 100644 --- a/src/backend/tcop/utility.c +++ b/src/backend/tcop/utility.c @@ -1492,7 +1492,8 @@ ProcessUtilitySlow(ParseState *pstate, case T_CreateTableAsStmt: address = ExecCreateTableAs(pstate, (CreateTableAsStmt *) parsetree, - params, queryEnv, completionTag); + params, queryEnv, queryString, + completionTag); break; case T_RefreshMatViewStmt: diff --git a/src/backend/utils/cache/plancache.c b/src/backend/utils/cache/plancache.c index c47be0ba4c..47122dfc7c 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/commands/createas.h b/src/include/commands/createas.h index 7743851a38..7a863dba0b 100644 --- a/src/include/commands/createas.h +++ b/src/include/commands/createas.h @@ -22,7 +22,9 @@ extern ObjectAddress ExecCreateTableAs(ParseState *pstate, CreateTableAsStmt *stmt, - ParamListInfo params, QueryEnvironment *queryEnv, char *completionTag); + ParamListInfo params, QueryEnvironment + *queryEnv, const char *queryString, + char *completionTag); extern int GetIntoRelEFlags(IntoClause *intoClause); diff --git a/src/include/optimizer/optimizer.h b/src/include/optimizer/optimizer.h index 5283995df8..302e47aa58 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 93df62d136..22bcf9c1e8 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 750ba4a3e2..69c7b16ac7 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.20.1
0002-Add-planning-counters-to-pg_stat_statements-v3.patch
(application/octet-stream, 45.5 KB)
From 652a36834643a73cce2fef5f88d5f7f21c305db5 Mon Sep 17 00:00:00 2001 From: Julien Rouhaud <[email protected]> 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 | 231 +++++++++----- .../pg_stat_statements--1.7--1.8.sql | 56 ++++ .../pg_stat_statements/pg_stat_statements.c | 301 +++++++++++++----- .../pg_stat_statements.control | 2 +- .../sql/pg_stat_statements.sql | 16 + doc/src/sgml/pgstatstatements.sgml | 49 ++- 7 files changed, 497 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 5bbe054367..ad9ac5dd45 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 6f82a671ee..bad535db2d 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" @@ -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,82 @@ 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) + { + 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 +1051,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, @@ -1021,35 +1132,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, INSTR_TIME_GET_MILLISEC(duration), rows, &bufusage, @@ -1088,12 +1177,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) { @@ -1181,8 +1275,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, @@ -1239,19 +1335,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 { @@ -1259,18 +1358,18 @@ pgss_store(const char *query, uint64 queryId, * Welford's method for accurately computing variance. See * <http://www.johndcook.com/blog/standard_deviation/> */ - 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; @@ -1285,7 +1384,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); } @@ -1333,7 +1432,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. @@ -1345,6 +1445,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) { @@ -1450,6 +1560,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"); } @@ -1605,29 +1719,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); @@ -1651,6 +1775,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); @@ -1786,7 +1911,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; @@ -3257,3 +3382,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 @@ <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.20.1