Commit adb1a6e9 authored by Tom Lane's avatar Tom Lane

Improve EXPLAIN ANALYZE to show the time spent in each trigger when

executing a statement that fires triggers.  Formerly this time was
included in "Total runtime" but not otherwise accounted for.
As a side benefit, we avoid re-opening relations when firing non-deferred
AFTER triggers, because the trigger code can re-use the main executor's
ResultRelInfo data structure.
parent 08890b40
<!--
$PostgreSQL: pgsql/doc/src/sgml/perform.sgml,v 1.50 2005/02/03 07:12:37 neilc Exp $
$PostgreSQL: pgsql/doc/src/sgml/perform.sgml,v 1.51 2005/03/25 21:57:57 tgl Exp $
-->
<chapter id="performance-tips">
......@@ -320,16 +320,19 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50 AND t1
</para>
<para>
The <literal>Total runtime</literal> shown by <command>EXPLAIN ANALYZE</command> includes
executor start-up and shut-down time, as well as time spent processing
the result rows. It does not include parsing, rewriting, or planning
time. For a <command>SELECT</> query, the total run time will normally be just a
little larger than the total time reported for the top-level plan node.
For <command>INSERT</>, <command>UPDATE</>, and <command>DELETE</> commands, the total run time may be
considerably larger, because it includes the time spent processing the
result rows. In these commands, the time for the top plan node
essentially is the time spent computing the new rows and/or locating
the old ones, but it doesn't include the time spent making the changes.
The <literal>Total runtime</literal> shown by <command>EXPLAIN
ANALYZE</command> includes executor start-up and shut-down time, as well
as time spent processing the result rows. It does not include parsing,
rewriting, or planning time. For a <command>SELECT</> query, the total
run time will normally be just a little larger than the total time
reported for the top-level plan node. For <command>INSERT</>,
<command>UPDATE</>, and <command>DELETE</> commands, the total run time
may be considerably larger, because it includes the time spent processing
the result rows. In these commands, the time for the top plan node
essentially is the time spent computing the new rows and/or locating the
old ones, but it doesn't include the time spent making the changes.
Time spent firing triggers, if any, is also outside the top plan node,
and is shown separately for each trigger.
</para>
<para>
......
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/catalog/pg_constraint.c,v 1.22 2004/12/31 21:59:38 pgsql Exp $
* $PostgreSQL: pgsql/src/backend/catalog/pg_constraint.c,v 1.23 2005/03/25 21:57:57 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -21,12 +21,14 @@
#include "catalog/dependency.h"
#include "catalog/indexing.h"
#include "catalog/pg_constraint.h"
#include "catalog/pg_depend.h"
#include "catalog/pg_type.h"
#include "commands/defrem.h"
#include "miscadmin.h"
#include "utils/array.h"
#include "utils/builtins.h"
#include "utils/fmgroids.h"
#include "utils/lsyscache.h"
#include "utils/syscache.h"
......@@ -510,3 +512,95 @@ RemoveConstraintById(Oid conId)
systable_endscan(conscan);
heap_close(conDesc, RowExclusiveLock);
}
/*
* GetConstraintNameForTrigger
* Get the name of the constraint owning a trigger, if any
*
* Returns a palloc'd string, or NULL if no constraint can be found
*/
char *
GetConstraintNameForTrigger(Oid triggerId)
{
char *result;
Oid constraintId = InvalidOid;
Oid pg_trigger_id;
Oid pg_constraint_id;
Relation depRel;
Relation conRel;
ScanKeyData key[2];
SysScanDesc scan;
HeapTuple tup;
pg_trigger_id = get_system_catalog_relid(TriggerRelationName);
pg_constraint_id = get_system_catalog_relid(ConstraintRelationName);
/*
* We must grovel through pg_depend to find the owning constraint.
* Perhaps pg_trigger should have a column for the owning constraint ...
* but right now this is not performance-critical code.
*/
depRel = heap_openr(DependRelationName, AccessShareLock);
ScanKeyInit(&key[0],
Anum_pg_depend_classid,
BTEqualStrategyNumber, F_OIDEQ,
ObjectIdGetDatum(pg_trigger_id));
ScanKeyInit(&key[1],
Anum_pg_depend_objid,
BTEqualStrategyNumber, F_OIDEQ,
ObjectIdGetDatum(triggerId));
/* assume we can ignore objsubid for a trigger */
scan = systable_beginscan(depRel, DependDependerIndex, true,
SnapshotNow, 2, key);
while (HeapTupleIsValid(tup = systable_getnext(scan)))
{
Form_pg_depend foundDep = (Form_pg_depend) GETSTRUCT(tup);
if (foundDep->refclassid == pg_constraint_id &&
foundDep->deptype == DEPENDENCY_INTERNAL)
{
constraintId = foundDep->refobjid;
break;
}
}
systable_endscan(scan);
heap_close(depRel, AccessShareLock);
if (!OidIsValid(constraintId))
return NULL; /* no owning constraint found */
conRel = heap_openr(ConstraintRelationName, AccessShareLock);
ScanKeyInit(&key[0],
ObjectIdAttributeNumber,
BTEqualStrategyNumber, F_OIDEQ,
ObjectIdGetDatum(constraintId));
scan = systable_beginscan(conRel, ConstraintOidIndex, true,
SnapshotNow, 1, key);
tup = systable_getnext(scan);
if (HeapTupleIsValid(tup))
{
Form_pg_constraint con = (Form_pg_constraint) GETSTRUCT(tup);
result = pstrdup(NameStr(con->conname));
}
else
{
/* This arguably should be an error, but we'll just return NULL */
result = NULL;
}
systable_endscan(scan);
heap_close(conRel, AccessShareLock);
return result;
}
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.238 2005/03/16 21:38:05 tgl Exp $
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.239 2005/03/25 21:57:57 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -1510,6 +1510,10 @@ CopyFrom(Relation rel, List *attnumlist, bool binary, bool oids,
resultRelInfo->ri_RangeTableIndex = 1; /* dummy */
resultRelInfo->ri_RelationDesc = rel;
resultRelInfo->ri_TrigDesc = CopyTriggerDesc(rel->trigdesc);
if (resultRelInfo->ri_TrigDesc)
resultRelInfo->ri_TrigFunctions = (FmgrInfo *)
palloc0(resultRelInfo->ri_TrigDesc->numtriggers * sizeof(FmgrInfo));
resultRelInfo->ri_TrigInstrument = NULL;
ExecOpenIndices(resultRelInfo);
......@@ -1974,7 +1978,7 @@ CopyFrom(Relation rel, List *attnumlist, bool binary, bool oids,
/*
* Handle queued AFTER triggers
*/
AfterTriggerEndQuery();
AfterTriggerEndQuery(estate);
pfree(values);
pfree(nulls);
......
......@@ -7,7 +7,7 @@
* Portions Copyright (c) 1994-5, Regents of the University of California
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.130 2005/03/20 22:27:51 tgl Exp $
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.131 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -15,6 +15,7 @@
#include "access/genam.h"
#include "access/heapam.h"
#include "catalog/pg_constraint.h"
#include "catalog/pg_type.h"
#include "commands/explain.h"
#include "commands/prepare.h"
......@@ -272,16 +273,76 @@ ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt,
}
/*
* Close down the query and free resources; also run any queued
* AFTER triggers. Include time for this in the total runtime.
* If we ran the command, run any AFTER triggers it queued. (Note this
* will not include DEFERRED triggers; since those don't run until end of
* transaction, we can't measure them.) Include into total runtime.
*/
if (stmt->analyze)
{
INSTR_TIME_SET_CURRENT(starttime);
AfterTriggerEndQuery(queryDesc->estate);
totaltime += elapsed_time(&starttime);
}
/* Print info about runtime of triggers */
if (es->printAnalyze)
{
ResultRelInfo *rInfo;
int numrels = queryDesc->estate->es_num_result_relations;
int nr;
rInfo = queryDesc->estate->es_result_relations;
for (nr = 0; nr < numrels; rInfo++, nr++)
{
int nt;
if (!rInfo->ri_TrigDesc)
continue;
for (nt = 0; nt < rInfo->ri_TrigDesc->numtriggers; nt++)
{
Trigger *trig = rInfo->ri_TrigDesc->triggers + nt;
Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
char *conname;
/* Must clean up instrumentation state */
InstrEndLoop(instr);
/*
* We ignore triggers that were never invoked; they likely
* aren't relevant to the current query type.
*/
if (instr->ntuples == 0)
continue;
if (trig->tgisconstraint &&
(conname = GetConstraintNameForTrigger(trig->tgoid)) != NULL)
{
appendStringInfo(str, "Trigger for constraint %s",
conname);
pfree(conname);
}
else
appendStringInfo(str, "Trigger %s", trig->tgname);
if (numrels > 1)
appendStringInfo(str, " on %s",
RelationGetRelationName(rInfo->ri_RelationDesc));
appendStringInfo(str, ": time=%.3f calls=%.0f\n",
1000.0 * instr->total,
instr->ntuples);
}
}
}
/*
* Close down the query and free resources. Include time for this
* in the total runtime (although it should be pretty minimal).
*/
INSTR_TIME_SET_CURRENT(starttime);
ExecutorEnd(queryDesc);
if (stmt->analyze)
AfterTriggerEndQuery();
FreeQueryDesc(queryDesc);
/* We need a CCI just in case query expanded to multiple plans */
......
......@@ -14,7 +14,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.38 2004/12/31 21:59:41 pgsql Exp $
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.39 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -281,8 +281,8 @@ PortalCleanup(Portal portal)
PG_TRY();
{
CurrentResourceOwner = portal->resowner;
ExecutorEnd(queryDesc);
/* we do not need AfterTriggerEndQuery() here */
ExecutorEnd(queryDesc);
}
PG_CATCH();
{
......@@ -382,8 +382,8 @@ PersistHoldablePortal(Portal portal)
* Now shut down the inner executor.
*/
portal->queryDesc = NULL; /* prevent double shutdown */
ExecutorEnd(queryDesc);
/* we do not need AfterTriggerEndQuery() here */
ExecutorEnd(queryDesc);
/*
* Reset the position in the result set: ideally, this could be
......
This diff is collapsed.
......@@ -26,7 +26,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.243 2005/03/20 23:40:25 neilc Exp $
* $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.244 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -39,6 +39,7 @@
#include "commands/trigger.h"
#include "executor/execdebug.h"
#include "executor/execdefs.h"
#include "executor/instrument.h"
#include "miscadmin.h"
#include "optimizer/clauses.h"
#include "optimizer/var.h"
......@@ -69,7 +70,8 @@ static void InitPlan(QueryDesc *queryDesc, bool explainOnly);
static void initResultRelInfo(ResultRelInfo *resultRelInfo,
Index resultRelationIndex,
List *rangeTable,
CmdType operation);
CmdType operation,
bool doInstrument);
static TupleTableSlot *ExecutePlan(EState *estate, PlanState *planstate,
CmdType operation,
long numberTuples,
......@@ -508,7 +510,8 @@ InitPlan(QueryDesc *queryDesc, bool explainOnly)
initResultRelInfo(resultRelInfo,
lfirst_int(l),
rangeTable,
operation);
operation,
estate->es_instrument);
resultRelInfo++;
}
}
......@@ -523,7 +526,8 @@ InitPlan(QueryDesc *queryDesc, bool explainOnly)
initResultRelInfo(resultRelInfos,
parseTree->resultRelation,
rangeTable,
operation);
operation,
estate->es_instrument);
}
estate->es_result_relations = resultRelInfos;
......@@ -798,7 +802,8 @@ static void
initResultRelInfo(ResultRelInfo *resultRelInfo,
Index resultRelationIndex,
List *rangeTable,
CmdType operation)
CmdType operation,
bool doInstrument)
{
Oid resultRelationOid;
Relation resultRelationDesc;
......@@ -837,7 +842,22 @@ initResultRelInfo(ResultRelInfo *resultRelInfo,
resultRelInfo->ri_IndexRelationInfo = NULL;
/* make a copy so as not to depend on relcache info not changing... */
resultRelInfo->ri_TrigDesc = CopyTriggerDesc(resultRelationDesc->trigdesc);
resultRelInfo->ri_TrigFunctions = NULL;
if (resultRelInfo->ri_TrigDesc)
{
int n = resultRelInfo->ri_TrigDesc->numtriggers;
resultRelInfo->ri_TrigFunctions = (FmgrInfo *)
palloc0(n * sizeof(FmgrInfo));
if (doInstrument)
resultRelInfo->ri_TrigInstrument = InstrAlloc(n);
else
resultRelInfo->ri_TrigInstrument = NULL;
}
else
{
resultRelInfo->ri_TrigFunctions = NULL;
resultRelInfo->ri_TrigInstrument = NULL;
}
resultRelInfo->ri_ConstraintExprs = NULL;
resultRelInfo->ri_junkFilter = NULL;
......
......@@ -12,7 +12,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.46 2004/12/31 21:59:45 pgsql Exp $
* $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.47 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -252,7 +252,7 @@ ExecInitNode(Plan *node, EState *estate)
/* Set up instrumentation for this node if requested */
if (estate->es_instrument)
result->instrument = InstrAlloc();
result->instrument = InstrAlloc(1);
return result;
}
......
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.92 2005/03/16 21:38:07 tgl Exp $
* $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.93 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -399,8 +399,8 @@ postquel_end(execution_state *es, SQLFunctionCachePtr fcache)
{
ActiveSnapshot = es->qd->snapshot;
AfterTriggerEndQuery(es->qd->estate);
ExecutorEnd(es->qd);
AfterTriggerEndQuery();
}
PG_CATCH();
{
......
......@@ -7,7 +7,7 @@
* Copyright (c) 2001-2005, PostgreSQL Global Development Group
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.10 2005/03/20 22:27:51 tgl Exp $
* $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.11 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -18,13 +18,13 @@
#include "executor/instrument.h"
/* Allocate new instrumentation structure */
/* Allocate new instrumentation structure(s) */
Instrumentation *
InstrAlloc(void)
InstrAlloc(int n)
{
Instrumentation *instr = palloc(sizeof(Instrumentation));
Instrumentation *instr = palloc0(n * sizeof(Instrumentation));
memset(instr, 0, sizeof(Instrumentation));
/* we don't need to do any initialization except zero 'em */
return instr;
}
......
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.135 2005/03/16 21:38:08 tgl Exp $
* $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.136 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -1546,10 +1546,10 @@ _SPI_pquery(QueryDesc *queryDesc, int tcount)
elog(ERROR, "consistency check on SPI tuple count failed");
}
ExecutorEnd(queryDesc);
/* Take care of any queued AFTER triggers */
AfterTriggerEndQuery();
AfterTriggerEndQuery(queryDesc->estate);
ExecutorEnd(queryDesc);
if (queryDesc->dest->mydest == SPI)
{
......
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.92 2005/03/16 21:38:08 tgl Exp $
* $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.93 2005/03/25 21:57:58 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -206,14 +206,14 @@ ProcessQuery(Query *parsetree,
}
}
/* Now take care of any queued AFTER triggers */
AfterTriggerEndQuery(queryDesc->estate);
/*
* Now, we close down all the scans and free allocated resources.
*/
ExecutorEnd(queryDesc);
/* And take care of any queued AFTER triggers */
AfterTriggerEndQuery();
FreeQueryDesc(queryDesc);
FreeSnapshot(ActiveSnapshot);
......
......@@ -8,7 +8,7 @@
* Portions Copyright (c) 1996-2005, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
* $PostgreSQL: pgsql/src/include/catalog/pg_constraint.h,v 1.14 2004/12/31 22:03:24 pgsql Exp $
* $PostgreSQL: pgsql/src/include/catalog/pg_constraint.h,v 1.15 2005/03/25 21:57:59 tgl Exp $
*
* NOTES
* the genbki.sh script reads this file and generates .bki
......@@ -181,4 +181,6 @@ extern char *ChooseConstraintName(const char *name1, const char *name2,
const char *label, Oid namespace,
List *others);
extern char *GetConstraintNameForTrigger(Oid triggerId);
#endif /* PG_CONSTRAINT_H */
......@@ -6,7 +6,7 @@
* Portions Copyright (c) 1996-2005, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
* $PostgreSQL: pgsql/src/include/commands/trigger.h,v 1.51 2004/12/31 22:03:28 pgsql Exp $
* $PostgreSQL: pgsql/src/include/commands/trigger.h,v 1.52 2005/03/25 21:57:59 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -156,7 +156,7 @@ extern void ExecARUpdateTriggers(EState *estate,
extern void AfterTriggerBeginXact(void);
extern void AfterTriggerBeginQuery(void);
extern void AfterTriggerEndQuery(void);
extern void AfterTriggerEndQuery(EState *estate);
extern void AfterTriggerEndXact(void);
extern void AfterTriggerAbortXact(void);
extern void AfterTriggerBeginSubXact(void);
......
......@@ -6,7 +6,7 @@
*
* Copyright (c) 2001-2005, PostgreSQL Global Development Group
*
* $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.9 2005/03/20 22:27:52 tgl Exp $
* $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.10 2005/03/25 21:57:59 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -70,7 +70,7 @@ typedef struct Instrumentation
double nloops; /* # of run cycles for this node */
} Instrumentation;
extern Instrumentation *InstrAlloc(void);
extern Instrumentation *InstrAlloc(int n);
extern void InstrStartNode(Instrumentation *instr);
extern void InstrStopNode(Instrumentation *instr, bool returnedTuple);
extern void InstrEndLoop(Instrumentation *instr);
......
......@@ -7,7 +7,7 @@
* Portions Copyright (c) 1996-2005, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
* $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.124 2005/03/16 21:38:10 tgl Exp $
* $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.125 2005/03/25 21:58:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -261,6 +261,7 @@ typedef struct JunkFilter
* IndexRelationInfo array of key/attr info for indices
* TrigDesc triggers to be fired, if any
* TrigFunctions cached lookup info for trigger functions
* TrigInstrument optional runtime measurements for triggers
* ConstraintExprs array of constraint-checking expr states
* junkFilter for removing junk attributes from tuples
* ----------------
......@@ -275,6 +276,7 @@ typedef struct ResultRelInfo
IndexInfo **ri_IndexRelationInfo;
TriggerDesc *ri_TrigDesc;
FmgrInfo *ri_TrigFunctions;
struct Instrumentation *ri_TrigInstrument;
List **ri_ConstraintExprs;
JunkFilter *ri_junkFilter;
} ResultRelInfo;
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment