From be4d94a7ca49b176d9f67476f2edde9e1f3d2a21 Mon Sep 17 00:00:00 2001 From: Jaime Casanova 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