Hi,
pg_stat_statements is basically very helpful to find out slow queries.
But since it doesn't report the time spent in the planner, we cannot
find out slow queries which take most time to do query planning, from
pg_stat_statements. Is there any reason why pg_stat_statements doesn't
collect the planning time?
Attached patch extends pg_stat_statements so that it reports the
planning time. Thought?
In the patch, I didn't change the column name "total_time" meaning
the time spent in the executor because of the backward compatibility.
But once new column "plan_time" is added, "total_time" is confusing and
ISTM it should be renamed...
Regards,
--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center
*** a/contrib/pg_stat_statements/pg_stat_statements--1.0--1.1.sql
--- b/contrib/pg_stat_statements/pg_stat_statements--1.0--1.1.sql
***************
*** 17,22 **** CREATE FUNCTION pg_stat_statements(
--- 17,23 ----
OUT dbid oid,
OUT query text,
OUT calls int8,
+ OUT plan_time float8,
OUT total_time float8,
OUT rows int8,
OUT shared_blks_hit int8,
*** a/contrib/pg_stat_statements/pg_stat_statements--1.1.sql
--- b/contrib/pg_stat_statements/pg_stat_statements--1.1.sql
***************
*** 14,19 **** CREATE FUNCTION pg_stat_statements(
--- 14,20 ----
OUT dbid oid,
OUT query text,
OUT calls int8,
+ OUT plan_time float8,
OUT total_time float8,
OUT rows int8,
OUT shared_blks_hit int8,
*** a/contrib/pg_stat_statements/pg_stat_statements.c
--- b/contrib/pg_stat_statements/pg_stat_statements.c
***************
*** 1,7 ****
/*-------------------------------------------------------------------------
*
* pg_stat_statements.c
! * Track statement execution times across a whole database cluster.
*
* Note about locking issues: to create or delete an entry in the shared
* hashtable, one must hold pgss->lock exclusively. Modifying any field
--- 1,7 ----
/*-------------------------------------------------------------------------
*
* pg_stat_statements.c
! * Track statement planning and execution times across a whole database cluster.
*
* Note about locking issues: to create or delete an entry in the shared
* hashtable, one must hold pgss->lock exclusively. Modifying any field
***************
*** 27,32 ****
--- 27,33 ----
#include "funcapi.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
+ #include "optimizer/planner.h"
#include "pgstat.h"
#include "storage/fd.h"
#include "storage/ipc.h"
***************
*** 73,78 **** typedef struct pgssHashKey
--- 74,80 ----
typedef struct Counters
{
int64 calls; /* # of times executed */
+ double plan_time; /* total planning time in seconds */
double total_time; /* total execution time in seconds */
int64 rows; /* total # of retrieved or affected rows */
int64 shared_blks_hit; /* # of shared buffer hits */
***************
*** 118,123 **** static int nested_level = 0;
--- 120,126 ----
/* 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 ExecutorStart_hook_type prev_ExecutorStart = NULL;
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
***************
*** 168,173 **** PG_FUNCTION_INFO_V1(pg_stat_statements);
--- 171,178 ----
static void pgss_shmem_startup(void);
static void pgss_shmem_shutdown(int code, Datum arg);
+ static PlannedStmt *pgss_planner(Query *parse, int cursorOptions,
+ ParamListInfo boundParams);
static void pgss_ExecutorStart(QueryDesc *queryDesc, int eflags);
static void pgss_ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction,
***************
*** 179,186 **** static void pgss_ProcessUtility(Node *parsetree,
DestReceiver *dest, char *completionTag);
static uint32 pgss_hash_fn(const void *key, Size keysize);
static int pgss_match_fn(const void *key1, const void *key2, Size keysize);
! static void pgss_store(const char *query, double total_time, uint64 rows,
! const BufferUsage *bufusage);
static Size pgss_memsize(void);
static pgssEntry *entry_alloc(pgssHashKey *key);
static void entry_dealloc(void);
--- 184,191 ----
DestReceiver *dest, char *completionTag);
static uint32 pgss_hash_fn(const void *key, Size keysize);
static int pgss_match_fn(const void *key1, const void *key2, Size keysize);
! static void pgss_store(const char *query, double plan_time, double total_time,
! uint64 rows, const BufferUsage *bufusage);
static Size pgss_memsize(void);
static pgssEntry *entry_alloc(pgssHashKey *key);
static void entry_dealloc(void);
***************
*** 269,274 **** _PG_init(void)
--- 274,281 ----
*/
prev_shmem_startup_hook = shmem_startup_hook;
shmem_startup_hook = pgss_shmem_startup;
+ prev_planner_hook = planner_hook;
+ planner_hook = pgss_planner;
prev_ExecutorStart = ExecutorStart_hook;
ExecutorStart_hook = pgss_ExecutorStart;
prev_ExecutorRun = ExecutorRun_hook;
***************
*** 289,294 **** _PG_fini(void)
--- 296,302 ----
{
/* Uninstall hooks. */
shmem_startup_hook = prev_shmem_startup_hook;
+ planner_hook = prev_planner_hook;
ExecutorStart_hook = prev_ExecutorStart;
ExecutorRun_hook = prev_ExecutorRun;
ExecutorFinish_hook = prev_ExecutorFinish;
***************
*** 505,510 **** error:
--- 513,565 ----
}
/*
+ * planner hook
+ */
+ static PlannedStmt *
+ pgss_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
+ {
+ PlannedStmt *result;
+
+ if (pgss_enabled())
+ {
+ instr_time start;
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(start);
+
+ nested_level++;
+ PG_TRY();
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ nested_level--;
+ }
+ PG_CATCH();
+ {
+ nested_level--;
+ PG_RE_THROW();
+ }
+ PG_END_TRY();
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+
+ result->plan_time = INSTR_TIME_GET_DOUBLE(duration);
+ }
+ else
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, cursorOptions, boundParams);
+ else
+ result = standard_planner(parse, cursorOptions, boundParams);
+ }
+
+ return result;
+ }
+
+ /*
* ExecutorStart hook: start up tracking if needed
*/
static void
***************
*** 594,599 **** pgss_ExecutorEnd(QueryDesc *queryDesc)
--- 649,655 ----
InstrEndLoop(queryDesc->totaltime);
pgss_store(queryDesc->sourceText,
+ queryDesc->plannedstmt->plan_time,
queryDesc->totaltime->total,
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage);
***************
*** 671,677 **** pgss_ProcessUtility(Node *parsetree, const char *queryString,
bufusage.temp_blks_written =
pgBufferUsage.temp_blks_written - bufusage.temp_blks_written;
! pgss_store(queryString, INSTR_TIME_GET_DOUBLE(duration), rows,
&bufusage);
}
else
--- 727,734 ----
bufusage.temp_blks_written =
pgBufferUsage.temp_blks_written - bufusage.temp_blks_written;
! /* planning time is always 0 because utility commands have no plans */
! pgss_store(queryString, 0, INSTR_TIME_GET_DOUBLE(duration), rows,
&bufusage);
}
else
***************
*** 723,730 **** pgss_match_fn(const void *key1, const void *key2, Size keysize)
* Store some statistics for a statement.
*/
static void
! pgss_store(const char *query, double total_time, uint64 rows,
! const BufferUsage *bufusage)
{
pgssHashKey key;
double usage;
--- 780,787 ----
* Store some statistics for a statement.
*/
static void
! pgss_store(const char *query, double plan_time, double total_time,
! uint64 rows, const BufferUsage *bufusage)
{
pgssHashKey key;
double usage;
***************
*** 768,773 **** pgss_store(const char *query, double total_time, uint64 rows,
--- 825,831 ----
SpinLockAcquire(&e->mutex);
e->counters.calls += 1;
+ e->counters.plan_time += plan_time;
e->counters.total_time += total_time;
e->counters.rows += rows;
e->counters.shared_blks_hit += bufusage->shared_blks_hit;
***************
*** 802,808 **** pg_stat_statements_reset(PG_FUNCTION_ARGS)
}
#define PG_STAT_STATEMENTS_COLS_V1_0 14
! #define PG_STAT_STATEMENTS_COLS 16
/*
* Retrieve statement statistics.
--- 860,866 ----
}
#define PG_STAT_STATEMENTS_COLS_V1_0 14
! #define PG_STAT_STATEMENTS_COLS 17
/*
* Retrieve statement statistics.
***************
*** 895,900 **** pg_stat_statements(PG_FUNCTION_ARGS)
--- 953,959 ----
}
values[i++] = Int64GetDatumFast(tmp.calls);
+ values[i++] = Float8GetDatumFast(tmp.plan_time);
values[i++] = Float8GetDatumFast(tmp.total_time);
values[i++] = Int64GetDatumFast(tmp.rows);
values[i++] = Int64GetDatumFast(tmp.shared_blks_hit);
*** a/doc/src/sgml/pgstatstatements.sgml
--- b/doc/src/sgml/pgstatstatements.sgml
***************
*** 9,15 ****
<para>
The <filename>pg_stat_statements</filename> module provides a means for
! tracking execution statistics of all SQL statements executed by a server.
</para>
<para>
--- 9,15 ----
<para>
The <filename>pg_stat_statements</filename> module provides a means for
! tracking planning and execution statistics of all SQL statements executed by a server.
</para>
<para>
***************
*** 72,81 ****
</row>
<row>
<entry><structfield>total_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
! <entry>Total time spent in the statement, in seconds</entry>
</row>
<row>
--- 72,88 ----
</row>
<row>
+ <entry><structfield>plan_time</structfield></entry>
+ <entry><type>double precision</type></entry>
+ <entry></entry>
+ <entry>Total planning time spent in the statement, in seconds</entry>
+ </row>
+
+ <row>
<entry><structfield>total_time</structfield></entry>
<entry><type>double precision</type></entry>
<entry></entry>
! <entry>Total execution time spent in the statement, in seconds</entry>
</row>
<row>
*** a/src/backend/nodes/copyfuncs.c
--- b/src/backend/nodes/copyfuncs.c
***************
*** 93,98 **** _copyPlannedStmt(const PlannedStmt *from)
--- 93,99 ----
COPY_NODE_FIELD(relationOids);
COPY_NODE_FIELD(invalItems);
COPY_SCALAR_FIELD(nParamExec);
+ COPY_SCALAR_FIELD(plan_time);
return newnode;
}
*** a/src/backend/nodes/outfuncs.c
--- b/src/backend/nodes/outfuncs.c
***************
*** 257,262 **** _outPlannedStmt(StringInfo str, const PlannedStmt *node)
--- 257,263 ----
WRITE_NODE_FIELD(relationOids);
WRITE_NODE_FIELD(invalItems);
WRITE_INT_FIELD(nParamExec);
+ WRITE_FLOAT_FIELD(plan_time, "%.0f");
}
/*
*** a/src/backend/optimizer/plan/planner.c
--- b/src/backend/optimizer/plan/planner.c
***************
*** 240,245 **** standard_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
--- 240,246 ----
result->relationOids = glob->relationOids;
result->invalItems = glob->invalItems;
result->nParamExec = list_length(glob->paramlist);
+ result->plan_time = 0;
return result;
}
*** a/src/include/nodes/plannodes.h
--- b/src/include/nodes/plannodes.h
***************
*** 67,72 **** typedef struct PlannedStmt
--- 67,75 ----
List *invalItems; /* other dependencies, as PlanInvalItems */
int nParamExec; /* number of PARAM_EXEC Params used */
+
+ /* This is always set 0 by the core system, but plugins can change it */
+ double plan_time; /* total time spent in planner */
} PlannedStmt;
/* macro for fetching the Plan associated with a SubPlan node */
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
