diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile index 14a50380dcb0..d21e9a83a32a 100644 --- a/contrib/pg_stat_statements/Makefile +++ b/contrib/pg_stat_statements/Makefile @@ -4,10 +4,10 @@ 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.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 \ +DATA = pg_stat_statements--1.6.sql \ + pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \ + pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \ + pg_stat_statements--1.1--1.2.sql pg_stat_statements--1.0--1.1.sql \ pg_stat_statements--unpackaged--1.0.sql PGFILEDESC = "pg_stat_statements - execution statistics of SQL statements" diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql b/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql index 4f8c7f7ee8a0..3cb6eec081ee 100644 --- a/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql +++ b/contrib/pg_stat_statements/pg_stat_statements--1.5--1.6.sql @@ -3,5 +3,47 @@ -- complain if script is sourced in psql, rather than via ALTER EXTENSION \echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.6'" to load this file. \quit --- Execution is only allowed for superusers, fixing issue with 1.5. -REVOKE EXECUTE ON FUNCTION pg_stat_statements_reset() FROM pg_read_all_stats; +/* First we have to remove them from the extension */ +ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements; +ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean); + +/* Then we can drop them */ +DROP VIEW pg_stat_statements; +DROP FUNCTION pg_stat_statements(boolean); + +/* Now redefine */ +CREATE FUNCTION pg_stat_statements(IN showtext boolean, + OUT userid oid, + OUT dbid oid, + OUT queryid bigint, + OUT query text, + OUT plans int8, + OUT planning_time float8, + OUT calls int8, + OUT total_time float8, + OUT min_time float8, + OUT max_time float8, + OUT mean_time float8, + OUT stddev_time float8, + OUT rows int8, + OUT shared_blks_hit int8, + OUT shared_blks_read int8, + OUT shared_blks_dirtied int8, + OUT shared_blks_written int8, + OUT local_blks_hit int8, + OUT local_blks_read int8, + OUT local_blks_dirtied int8, + OUT local_blks_written int8, + OUT temp_blks_read int8, + OUT temp_blks_written int8, + OUT blk_read_time float8, + OUT blk_write_time float8 +) +RETURNS SETOF record +AS 'MODULE_PATHNAME', 'pg_stat_statements_1_4' +LANGUAGE C STRICT VOLATILE PARALLEL SAFE; + +CREATE VIEW pg_stat_statements AS + SELECT * FROM pg_stat_statements(true); + +GRANT SELECT ON pg_stat_statements TO PUBLIC; diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 33f9a79f5429..c16cb4b5f4f3 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" @@ -120,7 +121,8 @@ typedef enum pgssVersion PGSS_V1_0 = 0, PGSS_V1_1, PGSS_V1_2, - PGSS_V1_3 + PGSS_V1_3, + PGSS_V1_4 } pgssVersion; /* @@ -150,6 +152,8 @@ typedef struct Counters double max_time; /* maximum execution time in msec */ double mean_time; /* mean execution time in msec */ double sum_var_time; /* sum of variances in execution time in msec */ + int64 plans; /* # of times planned */ + double planning_time; /* total planning time, in msec */ int64 rows; /* total # of retrieved or affected rows */ int64 shared_blks_hit; /* # of shared buffer hits */ int64 shared_blks_read; /* # of shared disk blocks read */ @@ -238,6 +242,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; @@ -292,10 +297,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, @@ -310,7 +319,9 @@ static void pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, static uint64 pgss_hash_string(const char *str, int len); static void pgss_store(const char *query, uint64 queryId, int query_location, int query_len, - double total_time, uint64 rows, + double total_time, + double planning_time, + uint64 rows, const BufferUsage *bufusage, pgssJumbleState *jstate); static void pg_stat_statements_internal(FunctionCallInfo fcinfo, @@ -423,6 +434,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; @@ -446,6 +459,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; @@ -642,19 +656,19 @@ pgss_shmem_startup(void) read_error: ereport(LOG, (errcode_for_file_access(), - errmsg("could not read file \"%s\": %m", + errmsg("could not read pg_stat_statement file \"%s\": %m", PGSS_DUMP_FILE))); goto fail; data_error: ereport(LOG, (errcode(ERRCODE_INVALID_PARAMETER_VALUE), - errmsg("ignoring invalid data in file \"%s\"", + errmsg("ignoring invalid data in pg_stat_statement file \"%s\"", PGSS_DUMP_FILE))); goto fail; write_error: ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); fail: if (buffer) @@ -761,7 +775,7 @@ pgss_shmem_shutdown(int code, Datum arg) error: ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_DUMP_FILE ".tmp"))); if (qbuffer) free(qbuffer); @@ -771,6 +785,91 @@ pgss_shmem_shutdown(int code, Datum arg) 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; + BufferUsage bufusage_start, + bufusage; + + bufusage_start = pgBufferUsage; + 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); + + /* 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); + + pgss_store("", + parse->queryId, /* signal that it's a utility stmt */ + -1, + 0, + 0, + INSTR_TIME_GET_MILLISEC(duration), + 0, + &bufusage, + NULL); + } + 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 */ @@ -831,13 +930,13 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query) * the normalized string would be the same as the query text anyway, so * there's no need for an early entry. */ - if (jstate.clocations_count > 0) pgss_store(pstate->p_sourcetext, query->queryId, query->stmt_location, query->stmt_len, 0, 0, + 0, NULL, &jstate); } @@ -944,6 +1043,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) queryDesc->plannedstmt->stmt_location, queryDesc->plannedstmt->stmt_len, queryDesc->totaltime->total * 1000.0, /* convert to msec */ + 0, queryDesc->estate->es_processed, &queryDesc->totaltime->bufusage, NULL); @@ -975,8 +1075,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. */ @@ -1055,6 +1154,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, pstmt->stmt_location, pstmt->stmt_len, INSTR_TIME_GET_MILLISEC(duration), + 0, rows, &bufusage, NULL); @@ -1097,7 +1197,9 @@ pgss_hash_string(const char *str, int len) static void pgss_store(const char *query, uint64 queryId, int query_location, int query_len, - double total_time, uint64 rows, + double total_time, + double planning_time, + uint64 rows, const BufferUsage *bufusage, pgssJumbleState *jstate) { @@ -1239,15 +1341,19 @@ pgss_store(const char *query, uint64 queryId, if (e->counters.calls == 0) e->counters.usage = USAGE_INIT; - e->counters.calls += 1; - e->counters.total_time += total_time; - if (e->counters.calls == 1) + if (planning_time == 0) + { + e->counters.calls += 1; + e->counters.total_time += total_time; + } + + if (e->counters.calls == 1 && planning_time == 0) { e->counters.min_time = total_time; e->counters.max_time = total_time; e->counters.mean_time = total_time; } - else + else if(planning_time == 0) { /* * Welford's method for accurately computing variance. See @@ -1266,6 +1372,9 @@ pgss_store(const char *query, uint64 queryId, if (e->counters.max_time < total_time) e->counters.max_time = total_time; } + if (planning_time > 0) + e->counters.plans += 1; + e->counters.planning_time += planning_time; e->counters.rows += rows; e->counters.shared_blks_hit += bufusage->shared_blks_hit; e->counters.shared_blks_read += bufusage->shared_blks_read; @@ -1311,7 +1420,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. @@ -1323,6 +1433,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) { @@ -1429,6 +1549,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"); } @@ -1587,6 +1711,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, if (tmp.calls == 0) continue; + if (api_version >= PGSS_V1_4) + { + values[i++] = Int64GetDatumFast(tmp.plans); + values[i++] = Float8GetDatumFast(tmp.planning_time); + } values[i++] = Int64GetDatumFast(tmp.calls); values[i++] = Float8GetDatumFast(tmp.total_time); if (api_version >= PGSS_V1_3) @@ -1630,6 +1759,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); @@ -1799,6 +1929,12 @@ entry_dealloc(void) } pfree(entries); + + /* trace when evicting entries, if appening too often this can slow queries ... + * increasing pg_stat_statements.max value could help */ + ereport(WARNING, + (errmsg("pg_stat_statements evicting %d entries", nvictims), + errhidecontext(true), errhidestmt(true))); } /* @@ -1871,7 +2007,7 @@ qtext_store(const char *query, int query_len, error: ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); if (fd >= 0) @@ -1913,7 +2049,7 @@ qtext_load_file(Size *buffer_size) if (errno != ENOENT) ereport(LOG, (errcode_for_file_access(), - errmsg("could not read file \"%s\": %m", + errmsg("could not read pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); return NULL; } @@ -1923,7 +2059,7 @@ qtext_load_file(Size *buffer_size) { ereport(LOG, (errcode_for_file_access(), - errmsg("could not stat file \"%s\": %m", + errmsg("could not stat pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); CloseTransientFile(fd); return NULL; @@ -1939,7 +2075,7 @@ qtext_load_file(Size *buffer_size) ereport(LOG, (errcode(ERRCODE_OUT_OF_MEMORY), errmsg("out of memory"), - errdetail("Could not allocate enough memory to read file \"%s\".", + errdetail("Could not allocate enough memory to read pg_stat_statement file \"%s\".", PGSS_TEXT_FILE))); CloseTransientFile(fd); return NULL; @@ -1958,7 +2094,7 @@ qtext_load_file(Size *buffer_size) if (errno) ereport(LOG, (errcode_for_file_access(), - errmsg("could not read file \"%s\": %m", + errmsg("could not read pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); free(buf); CloseTransientFile(fd); @@ -2088,7 +2224,7 @@ gc_qtexts(void) { ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); goto gc_fail; } @@ -2118,7 +2254,7 @@ gc_qtexts(void) { ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); hash_seq_term(&hash_seq); goto gc_fail; @@ -2136,14 +2272,14 @@ gc_qtexts(void) if (ftruncate(fileno(qfile), extent) != 0) ereport(LOG, (errcode_for_file_access(), - errmsg("could not truncate file \"%s\": %m", + errmsg("could not truncate pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); if (FreeFile(qfile)) { ereport(LOG, (errcode_for_file_access(), - errmsg("could not write file \"%s\": %m", + errmsg("could not write pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); qfile = NULL; goto gc_fail; @@ -2203,7 +2339,7 @@ gc_qtexts(void) if (qfile == NULL) ereport(LOG, (errcode_for_file_access(), - errmsg("could not recreate file \"%s\": %m", + errmsg("could not write new pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); else FreeFile(qfile); @@ -2255,7 +2391,7 @@ entry_reset(void) { ereport(LOG, (errcode_for_file_access(), - errmsg("could not create file \"%s\": %m", + errmsg("could not create pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); goto done; } @@ -2264,7 +2400,7 @@ entry_reset(void) if (ftruncate(fileno(qfile), 0) != 0) ereport(LOG, (errcode_for_file_access(), - errmsg("could not truncate file \"%s\": %m", + errmsg("could not truncate pg_stat_statement file \"%s\": %m", PGSS_TEXT_FILE))); FreeFile(qfile);