Skip to content

Commit adb1a6e

Browse files
tglsfdctglsfdc
committed
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.
1 parent 08890b4 commit adb1a6e

File tree

16 files changed

+406
-146
lines changed

16 files changed

+406
-146
lines changed

‎doc/src/sgml/perform.sgml

Lines changed: 14 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
<!--
2-
$PostgreSQL: pgsql/doc/src/sgml/perform.sgml,v 1.50 2005/02/03 07:12:37 neilc Exp $
2+
$PostgreSQL: pgsql/doc/src/sgml/perform.sgml,v 1.51 2005/03/25 21:57:57 tgl Exp $
33
-->
44

55
<chapter id="performance-tips">
@@ -320,16 +320,19 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 &lt; 50 AND t1
320320
</para>
321321

322322
<para>
323-
The <literal>Total runtime</literal> shown by <command>EXPLAIN ANALYZE</command> includes
324-
executor start-up and shut-down time, as well as time spent processing
325-
the result rows. It does not include parsing, rewriting, or planning
326-
time. For a <command>SELECT</> query, the total run time will normally be just a
327-
little larger than the total time reported for the top-level plan node.
328-
For <command>INSERT</>, <command>UPDATE</>, and <command>DELETE</> commands, the total run time may be
329-
considerably larger, because it includes the time spent processing the
330-
result rows. In these commands, the time for the top plan node
331-
essentially is the time spent computing the new rows and/or locating
332-
the old ones, but it doesn't include the time spent making the changes.
323+
The <literal>Total runtime</literal> shown by <command>EXPLAIN
324+
ANALYZE</command> includes executor start-up and shut-down time, as well
325+
as time spent processing the result rows. It does not include parsing,
326+
rewriting, or planning time. For a <command>SELECT</> query, the total
327+
run time will normally be just a little larger than the total time
328+
reported for the top-level plan node. For <command>INSERT</>,
329+
<command>UPDATE</>, and <command>DELETE</> commands, the total run time
330+
may be considerably larger, because it includes the time spent processing
331+
the result rows. In these commands, the time for the top plan node
332+
essentially is the time spent computing the new rows and/or locating the
333+
old ones, but it doesn't include the time spent making the changes.
334+
Time spent firing triggers, if any, is also outside the top plan node,
335+
and is shown separately for each trigger.
333336
</para>
334337

335338
<para>

‎src/backend/catalog/pg_constraint.c

Lines changed: 95 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/catalog/pg_constraint.c,v 1.22 2004/12/31 21:59:38 pgsql Exp $
11+
* $PostgreSQL: pgsql/src/backend/catalog/pg_constraint.c,v 1.23 2005/03/25 21:57:57 tgl Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -21,12 +21,14 @@
2121
#include "catalog/dependency.h"
2222
#include "catalog/indexing.h"
2323
#include "catalog/pg_constraint.h"
24+
#include "catalog/pg_depend.h"
2425
#include "catalog/pg_type.h"
2526
#include "commands/defrem.h"
2627
#include "miscadmin.h"
2728
#include "utils/array.h"
2829
#include "utils/builtins.h"
2930
#include "utils/fmgroids.h"
31+
#include "utils/lsyscache.h"
3032
#include "utils/syscache.h"
3133

3234

@@ -510,3 +512,95 @@ RemoveConstraintById(Oid conId)
510512
systable_endscan(conscan);
511513
heap_close(conDesc, RowExclusiveLock);
512514
}
515+
516+
/*
517+
* GetConstraintNameForTrigger
518+
* Get the name of the constraint owning a trigger, if any
519+
*
520+
* Returns a palloc'd string, or NULL if no constraint can be found
521+
*/
522+
char *
523+
GetConstraintNameForTrigger(Oid triggerId)
524+
{
525+
char *result;
526+
Oid constraintId = InvalidOid;
527+
Oid pg_trigger_id;
528+
Oid pg_constraint_id;
529+
Relation depRel;
530+
Relation conRel;
531+
ScanKeyData key[2];
532+
SysScanDesc scan;
533+
HeapTuple tup;
534+
535+
pg_trigger_id = get_system_catalog_relid(TriggerRelationName);
536+
pg_constraint_id = get_system_catalog_relid(ConstraintRelationName);
537+
538+
/*
539+
* We must grovel through pg_depend to find the owning constraint.
540+
* Perhaps pg_trigger should have a column for the owning constraint ...
541+
* but right now this is not performance-critical code.
542+
*/
543+
depRel = heap_openr(DependRelationName, AccessShareLock);
544+
545+
ScanKeyInit(&key[0],
546+
Anum_pg_depend_classid,
547+
BTEqualStrategyNumber, F_OIDEQ,
548+
ObjectIdGetDatum(pg_trigger_id));
549+
ScanKeyInit(&key[1],
550+
Anum_pg_depend_objid,
551+
BTEqualStrategyNumber, F_OIDEQ,
552+
ObjectIdGetDatum(triggerId));
553+
/* assume we can ignore objsubid for a trigger */
554+
555+
scan = systable_beginscan(depRel, DependDependerIndex, true,
556+
SnapshotNow, 2, key);
557+
558+
while (HeapTupleIsValid(tup = systable_getnext(scan)))
559+
{
560+
Form_pg_depend foundDep = (Form_pg_depend) GETSTRUCT(tup);
561+
562+
if (foundDep->refclassid == pg_constraint_id &&
563+
foundDep->deptype == DEPENDENCY_INTERNAL)
564+
{
565+
constraintId = foundDep->refobjid;
566+
break;
567+
}
568+
}
569+
570+
systable_endscan(scan);
571+
572+
heap_close(depRel, AccessShareLock);
573+
574+
if (!OidIsValid(constraintId))
575+
return NULL; /* no owning constraint found */
576+
577+
conRel = heap_openr(ConstraintRelationName, AccessShareLock);
578+
579+
ScanKeyInit(&key[0],
580+
ObjectIdAttributeNumber,
581+
BTEqualStrategyNumber, F_OIDEQ,
582+
ObjectIdGetDatum(constraintId));
583+
584+
scan = systable_beginscan(conRel, ConstraintOidIndex, true,
585+
SnapshotNow, 1, key);
586+
587+
tup = systable_getnext(scan);
588+
589+
if (HeapTupleIsValid(tup))
590+
{
591+
Form_pg_constraint con = (Form_pg_constraint) GETSTRUCT(tup);
592+
593+
result = pstrdup(NameStr(con->conname));
594+
}
595+
else
596+
{
597+
/* This arguably should be an error, but we'll just return NULL */
598+
result = NULL;
599+
}
600+
601+
systable_endscan(scan);
602+
603+
heap_close(conRel, AccessShareLock);
604+
605+
return result;
606+
}

‎src/backend/commands/copy.c

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.238 2005/03/16 21:38:05 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.239 2005/03/25 21:57:57 tgl Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -1510,6 +1510,10 @@ CopyFrom(Relation rel, List *attnumlist, bool binary, bool oids,
15101510
resultRelInfo->ri_RangeTableIndex = 1; /* dummy */
15111511
resultRelInfo->ri_RelationDesc = rel;
15121512
resultRelInfo->ri_TrigDesc = CopyTriggerDesc(rel->trigdesc);
1513+
if (resultRelInfo->ri_TrigDesc)
1514+
resultRelInfo->ri_TrigFunctions = (FmgrInfo *)
1515+
palloc0(resultRelInfo->ri_TrigDesc->numtriggers * sizeof(FmgrInfo));
1516+
resultRelInfo->ri_TrigInstrument = NULL;
15131517

15141518
ExecOpenIndices(resultRelInfo);
15151519

@@ -1974,7 +1978,7 @@ CopyFrom(Relation rel, List *attnumlist, bool binary, bool oids,
19741978
/*
19751979
* Handle queued AFTER triggers
19761980
*/
1977-
AfterTriggerEndQuery();
1981+
AfterTriggerEndQuery(estate);
19781982

19791983
pfree(values);
19801984
pfree(nulls);

‎src/backend/commands/explain.c

Lines changed: 67 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -7,14 +7,15 @@
77
* Portions Copyright (c) 1994-5, Regents of the University of California
88
*
99
* IDENTIFICATION
10-
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.130 2005/03/20 22:27:51 tgl Exp $
10+
* $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.131 2005/03/25 21:57:58 tgl Exp $
1111
*
1212
*-------------------------------------------------------------------------
1313
*/
1414
#include "postgres.h"
1515

1616
#include "access/genam.h"
1717
#include "access/heapam.h"
18+
#include "catalog/pg_constraint.h"
1819
#include "catalog/pg_type.h"
1920
#include "commands/explain.h"
2021
#include "commands/prepare.h"
@@ -272,16 +273,76 @@ ExplainOnePlan(QueryDesc *queryDesc, ExplainStmt *stmt,
272273
}
273274

274275
/*
275-
* Close down the query and free resources; also run any queued
276-
* AFTER triggers. Include time for this in the total runtime.
276+
* If we ran the command, run any AFTER triggers it queued. (Note this
277+
* will not include DEFERRED triggers; since those don't run until end of
278+
* transaction, we can't measure them.) Include into total runtime.
279+
*/
280+
if (stmt->analyze)
281+
{
282+
INSTR_TIME_SET_CURRENT(starttime);
283+
AfterTriggerEndQuery(queryDesc->estate);
284+
totaltime += elapsed_time(&starttime);
285+
}
286+
287+
/* Print info about runtime of triggers */
288+
if (es->printAnalyze)
289+
{
290+
ResultRelInfo *rInfo;
291+
int numrels = queryDesc->estate->es_num_result_relations;
292+
int nr;
293+
294+
rInfo = queryDesc->estate->es_result_relations;
295+
for (nr = 0; nr < numrels; rInfo++, nr++)
296+
{
297+
int nt;
298+
299+
if (!rInfo->ri_TrigDesc)
300+
continue;
301+
for (nt = 0; nt < rInfo->ri_TrigDesc->numtriggers; nt++)
302+
{
303+
Trigger *trig = rInfo->ri_TrigDesc->triggers + nt;
304+
Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
305+
char *conname;
306+
307+
/* Must clean up instrumentation state */
308+
InstrEndLoop(instr);
309+
310+
/*
311+
* We ignore triggers that were never invoked; they likely
312+
* aren't relevant to the current query type.
313+
*/
314+
if (instr->ntuples == 0)
315+
continue;
316+
317+
if (trig->tgisconstraint &&
318+
(conname = GetConstraintNameForTrigger(trig->tgoid)) != NULL)
319+
{
320+
appendStringInfo(str, "Trigger for constraint %s",
321+
conname);
322+
pfree(conname);
323+
}
324+
else
325+
appendStringInfo(str, "Trigger %s", trig->tgname);
326+
327+
if (numrels > 1)
328+
appendStringInfo(str, " on %s",
329+
RelationGetRelationName(rInfo->ri_RelationDesc));
330+
331+
appendStringInfo(str, ": time=%.3f calls=%.0f\n",
332+
1000.0 * instr->total,
333+
instr->ntuples);
334+
}
335+
}
336+
}
337+
338+
/*
339+
* Close down the query and free resources. Include time for this
340+
* in the total runtime (although it should be pretty minimal).
277341
*/
278342
INSTR_TIME_SET_CURRENT(starttime);
279343

280344
ExecutorEnd(queryDesc);
281345

282-
if (stmt->analyze)
283-
AfterTriggerEndQuery();
284-
285346
FreeQueryDesc(queryDesc);
286347

287348
/* We need a CCI just in case query expanded to multiple plans */

‎src/backend/commands/portalcmds.c

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@
1414
*
1515
*
1616
* IDENTIFICATION
17-
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.38 2004/12/31 21:59:41 pgsql Exp $
17+
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.39 2005/03/25 21:57:58 tgl Exp $
1818
*
1919
*-------------------------------------------------------------------------
2020
*/
@@ -281,8 +281,8 @@ PortalCleanup(Portal portal)
281281
PG_TRY();
282282
{
283283
CurrentResourceOwner = portal->resowner;
284-
ExecutorEnd(queryDesc);
285284
/* we do not need AfterTriggerEndQuery() here */
285+
ExecutorEnd(queryDesc);
286286
}
287287
PG_CATCH();
288288
{
@@ -382,8 +382,8 @@ PersistHoldablePortal(Portal portal)
382382
* Now shut down the inner executor.
383383
*/
384384
portal->queryDesc = NULL; /* prevent double shutdown */
385-
ExecutorEnd(queryDesc);
386385
/* we do not need AfterTriggerEndQuery() here */
386+
ExecutorEnd(queryDesc);
387387

388388
/*
389389
* Reset the position in the result set: ideally, this could be

0 commit comments

Comments
 (0)