Hi,
This patch implements $subject only when ANALYZE and VERBOSE are on.
I made it that way because for years nobody seemed interested in this
info (at least no one did it) so i decided that maybe is to much
information for most people (actually btree indexes are normally very
fast).
But because we have GiST and GIN this became an interested piece of
data (there are other cases even when using btree).
Current patch doesn't have docs yet i will add them soon.
--
Jaime Casanova www.2ndQuadrant.com
Professional PostgreSQL: Soporte 24x7 y capacitación
Phone: +593 4 5107566 Cell: +593 987171157
From be4d94a7ca49b176d9f67476f2edde9e1f3d2a21 Mon Sep 17 00:00:00 2001
From: Jaime Casanova <ja...@2ndquadrant.com>
Date: Wed, 7 May 2014 18:28:46 -0500
Subject: [PATCH] Make EXPLAIN show measurements of updating indexes.
This adds a line in the output of EXPLAIN ANALYZE VERBOSE
showing the time that took to update indexes in INSERT/UPDATE
operations.
Also, add that info in auto_explain module using a new
variable auto_explain.log_indexes.
---
contrib/auto_explain/auto_explain.c | 14 ++++++
src/backend/catalog/indexing.c | 2 +-
src/backend/commands/copy.c | 6 +--
src/backend/commands/explain.c | 75 ++++++++++++++++++++++++++++++++
src/backend/executor/execUtils.c | 19 +++++++-
src/backend/executor/nodeModifyTable.c | 6 +--
src/include/commands/explain.h | 1 +
src/include/executor/executor.h | 4 +-
src/include/nodes/execnodes.h | 2 +
9 files changed, 118 insertions(+), 11 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c8ca7c4..f2c11e5 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -25,6 +25,7 @@ static int auto_explain_log_min_duration = -1; /* msec or -1 */
static bool auto_explain_log_analyze = false;
static bool auto_explain_log_verbose = false;
static bool auto_explain_log_buffers = false;
+static bool auto_explain_log_indexes = false;
static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = false;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
@@ -114,6 +115,17 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("auto_explain.log_indexes",
+ "Include index statistics in plans.",
+ "This has no effect unless log_analyze is also set.",
+ &auto_explain_log_indexes,
+ false,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomBoolVariable("auto_explain.log_triggers",
"Include trigger statistics in plans.",
"This has no effect unless log_analyze is also set.",
@@ -307,6 +319,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
ExplainBeginOutput(&es);
ExplainQueryText(&es, queryDesc);
ExplainPrintPlan(&es, queryDesc);
+ if (es.analyze && auto_explain_log_indexes)
+ ExplainPrintIndexes(&es, queryDesc);
if (es.analyze && auto_explain_log_triggers)
ExplainPrintTriggers(&es, queryDesc);
ExplainEndOutput(&es);
diff --git a/src/backend/catalog/indexing.c b/src/backend/catalog/indexing.c
index 4bf412f..b2d3a1e 100644
--- a/src/backend/catalog/indexing.c
+++ b/src/backend/catalog/indexing.c
@@ -46,7 +46,7 @@ CatalogOpenIndexes(Relation heapRel)
resultRelInfo->ri_RelationDesc = heapRel;
resultRelInfo->ri_TrigDesc = NULL; /* we don't fire triggers */
- ExecOpenIndices(resultRelInfo);
+ ExecOpenIndices(resultRelInfo, 0);
return resultRelInfo;
}
diff --git a/src/backend/commands/copy.c b/src/backend/commands/copy.c
index 70ee7e5..fbb1f13 100644
--- a/src/backend/commands/copy.c
+++ b/src/backend/commands/copy.c
@@ -2179,7 +2179,7 @@ CopyFrom(CopyState cstate)
1, /* dummy rangetable index */
0);
- ExecOpenIndices(resultRelInfo);
+ ExecOpenIndices(resultRelInfo, 0);
estate->es_result_relations = resultRelInfo;
estate->es_num_result_relations = 1;
@@ -2333,7 +2333,7 @@ CopyFrom(CopyState cstate)
if (resultRelInfo->ri_NumIndices > 0)
recheckIndexes = ExecInsertIndexTuples(slot, &(tuple->t_self),
- estate);
+ estate, NULL);
/* AFTER ROW INSERT Triggers */
ExecARInsertTriggers(estate, resultRelInfo, tuple,
@@ -2440,7 +2440,7 @@ CopyFromInsertBatch(CopyState cstate, EState *estate, CommandId mycid,
ExecStoreTuple(bufferedTuples[i], myslot, InvalidBuffer, false);
recheckIndexes =
ExecInsertIndexTuples(myslot, &(bufferedTuples[i]->t_self),
- estate);
+ estate, NULL);
ExecARInsertTriggers(estate, resultRelInfo,
bufferedTuples[i],
recheckIndexes);
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 08f3167..8e2b10d 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -502,6 +502,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
ExplainPropertyFloat("Planning Time", 1000.0 * plantime, 3, es);
}
+ /* Print info about runtime to update indexes */
+ if (es->analyze && es->verbose)
+ ExplainPrintIndexes(es, queryDesc);
+
/* Print info about runtime of triggers */
if (es->analyze)
ExplainPrintTriggers(es, queryDesc);
@@ -597,6 +601,77 @@ ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
}
/*
+ * ExplainPrintIndexes -
+
+ * convert a QueryDesc's index statistics to text and append it to
+ * es->str
+ *
+ * The caller should have set up the options fields of *es, as well as
+ * initializing the output buffer es->str. Other fields in *es are
+ * initialized here.
+ */
+void
+ExplainPrintIndexes(ExplainState *es, QueryDesc *queryDesc)
+{
+ ResultRelInfo *rInfo;
+ int numrels = queryDesc->estate->es_num_result_relations;
+ int nr;
+
+ ExplainOpenGroup("Indexes", "Indexes", false, es);
+
+ rInfo = queryDesc->estate->es_result_relations;
+
+ for (nr = 0; nr < numrels; rInfo++, nr++)
+ {
+ int ni;
+ RelationPtr idxreldesc;
+ IndexInfo **indexInfoArray;
+
+ if (rInfo->ri_NumIndices == 0)
+ continue;
+
+ idxreldesc = rInfo->ri_IndexRelationDescs;
+ indexInfoArray = rInfo->ri_IndexRelationInfo;
+
+ for (ni = 0; ni < rInfo->ri_NumIndices; ni++)
+ {
+ IndexInfo *idxinfo = indexInfoArray[ni];
+ Instrumentation *instr = rInfo->ri_IndexInstrument + ni;
+ char *relname = RelationGetRelationName(rInfo->ri_RelationDesc);
+ const char *idxname = explain_get_index_name(idxreldesc[ni]->rd_index->indexrelid);
+
+ /* Must clean up instrumentation state */
+ InstrEndLoop(instr);
+
+ /* If the index is marked as read-only, ignore it */
+ if (!idxinfo->ii_ReadyForInserts)
+ continue;
+
+ ExplainOpenGroup("Index", NULL, true, es);
+
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ appendStringInfo(es->str, "Index %s on %s: time=%.3f rows=%.0f\n",
+ idxname, relname,
+ 1000.0 * instr->total,
+ instr->ntuples);
+ }
+ else
+ {
+ ExplainPropertyText("Index Name", idxname, es);
+ ExplainPropertyText("Relation", relname, es);
+ ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
+ ExplainPropertyFloat("Rows", instr->ntuples, 0, es);
+ }
+
+ ExplainCloseGroup("Index", NULL, true, es);
+ }
+ }
+
+ ExplainCloseGroup("Indexes", "Indexes", false, es);
+}
+
+/*
* ExplainQueryText -
* add a "Query Text" node that contains the actual text of the query
*
diff --git a/src/backend/executor/execUtils.c b/src/backend/executor/execUtils.c
index fc71d85..759c15a 100644
--- a/src/backend/executor/execUtils.c
+++ b/src/backend/executor/execUtils.c
@@ -885,7 +885,7 @@ ExecCloseScanRelation(Relation scanrel)
* ----------------------------------------------------------------
*/
void
-ExecOpenIndices(ResultRelInfo *resultRelInfo)
+ExecOpenIndices(ResultRelInfo *resultRelInfo, int instrument_options)
{
Relation resultRelation = resultRelInfo->ri_RelationDesc;
List *indexoidlist;
@@ -918,6 +918,7 @@ ExecOpenIndices(ResultRelInfo *resultRelInfo)
resultRelInfo->ri_NumIndices = len;
resultRelInfo->ri_IndexRelationDescs = relationDescs;
resultRelInfo->ri_IndexRelationInfo = indexInfoArray;
+ resultRelInfo->ri_IndexInstrument = InstrAlloc(len, instrument_options);
/*
* For each index, open the index relation and save pg_index info. We
@@ -1000,7 +1001,8 @@ ExecCloseIndices(ResultRelInfo *resultRelInfo)
List *
ExecInsertIndexTuples(TupleTableSlot *slot,
ItemPointer tupleid,
- EState *estate)
+ EState *estate,
+ Instrumentation *instr)
{
List *result = NIL;
ResultRelInfo *resultRelInfo;
@@ -1074,6 +1076,12 @@ ExecInsertIndexTuples(TupleTableSlot *slot,
}
/*
+ * If doing EXPLAIN ANALYZE, start charging time to this index.
+ */
+ if (instr)
+ InstrStartNode(instr + i);
+
+ /*
* FormIndexDatum fills in its values and isnull parameters with the
* appropriate values for the column(s) of the index.
*/
@@ -1141,6 +1149,13 @@ ExecInsertIndexTuples(TupleTableSlot *slot,
*/
result = lappend_oid(result, RelationGetRelid(indexRelation));
}
+
+ /*
+ * If doing EXPLAIN ANALYZE, stop charging time to this index, and count
+ * one "tuple returned"
+ */
+ if (instr)
+ InstrStopNode(instr + i, 1);
}
return result;
diff --git a/src/backend/executor/nodeModifyTable.c b/src/backend/executor/nodeModifyTable.c
index fca7a25..cb7b90c 100644
--- a/src/backend/executor/nodeModifyTable.c
+++ b/src/backend/executor/nodeModifyTable.c
@@ -272,7 +272,7 @@ ExecInsert(TupleTableSlot *slot,
*/
if (resultRelInfo->ri_NumIndices > 0)
recheckIndexes = ExecInsertIndexTuples(slot, &(tuple->t_self),
- estate);
+ estate, resultRelInfo->ri_IndexInstrument);
}
if (canSetTag)
@@ -768,7 +768,7 @@ lreplace:;
*/
if (resultRelInfo->ri_NumIndices > 0 && !HeapTupleIsHeapOnly(tuple))
recheckIndexes = ExecInsertIndexTuples(slot, &(tuple->t_self),
- estate);
+ estate, resultRelInfo->ri_IndexInstrument);
}
if (canSetTag)
@@ -1134,7 +1134,7 @@ ExecInitModifyTable(ModifyTable *node, EState *estate, int eflags)
if (resultRelInfo->ri_RelationDesc->rd_rel->relhasindex &&
operation != CMD_DELETE &&
resultRelInfo->ri_IndexRelationDescs == NULL)
- ExecOpenIndices(resultRelInfo);
+ ExecOpenIndices(resultRelInfo, estate->es_instrument);
/* Now init the plan for this result rel */
estate->es_result_relation_info = resultRelInfo;
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3488be3..a84f847 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -72,6 +72,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
+extern void ExplainPrintIndexes(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h
index eb78776..363f439 100644
--- a/src/include/executor/executor.h
+++ b/src/include/executor/executor.h
@@ -346,10 +346,10 @@ extern bool ExecRelationIsTargetRelation(EState *estate, Index scanrelid);
extern Relation ExecOpenScanRelation(EState *estate, Index scanrelid, int eflags);
extern void ExecCloseScanRelation(Relation scanrel);
-extern void ExecOpenIndices(ResultRelInfo *resultRelInfo);
+extern void ExecOpenIndices(ResultRelInfo *resultRelInfo, int instrument_options);
extern void ExecCloseIndices(ResultRelInfo *resultRelInfo);
extern List *ExecInsertIndexTuples(TupleTableSlot *slot, ItemPointer tupleid,
- EState *estate);
+ EState *estate, Instrumentation *instr);
extern bool check_exclusion_constraint(Relation heap, Relation index,
IndexInfo *indexInfo,
ItemPointer tupleid,
diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h
index a301a08..ffa2902 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -297,6 +297,7 @@ typedef struct JunkFilter
* NumIndices # of indices existing on result relation
* IndexRelationDescs array of relation descriptors for indices
* IndexRelationInfo array of key/attr info for indices
+ * IndexInstrument optional runtime measurements for indexes
* TrigDesc triggers to be fired, if any
* TrigFunctions cached lookup info for trigger functions
* TrigWhenExprs array of trigger WHEN expr states
@@ -318,6 +319,7 @@ typedef struct ResultRelInfo
int ri_NumIndices;
RelationPtr ri_IndexRelationDescs;
IndexInfo **ri_IndexRelationInfo;
+ Instrumentation *ri_IndexInstrument;
TriggerDesc *ri_TrigDesc;
FmgrInfo *ri_TrigFunctions;
List **ri_TrigWhenExprs;
--
1.7.10.4
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
