Add support for tracking call counts and elapsed runtime for user-defined

functions.

Note that because this patch changes FmgrInfo, any external C functions
you might be testing with 8.4 will need to be recompiled.

Patch by Martin Pihlak, some editorialization by me (principally, removing
tracking of getrusage() numbers)

doc/src/sgml/config.sgml

-<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.177 2008/05/02 21:26:09 tgl Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.178 2008/05/15 00:17:39 tgl Exp $ -->
 
 <chapter Id="runtime-config">
   <title>Server Configuration</title>
@@ -3342,6 +3342,22 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-functions" xreflabel="track_functions">
+      <term><varname>track_functions</varname> (<type>string</type>)</term>
+      <indexterm>
+       <primary><varname>track_functions</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        Enables tracking of function call counts and time used. Specify
+        <literal>pl</literal> to count only procedural language functions,
+        <literal>all</literal> to also track SQL and C language functions.
+        The default is <literal>none</literal>.
+        Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-update-process-title" xreflabel="update_process_title">
       <term><varname>update_process_title</varname> (<type>boolean</type>)</term>
       <indexterm>

doc/src/sgml/monitoring.sgml

-<!-- $PostgreSQL: pgsql/doc/src/sgml/monitoring.sgml,v 1.58 2008/05/07 14:41:55 mha Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/monitoring.sgml,v 1.59 2008/05/15 00:17:39 tgl Exp $ -->
 
 <chapter id="monitoring">
  <title>Monitoring Database Activity</title>
@@ -119,7 +119,8 @@ postgres: <replaceable>user</> <replaceable>database</> <replaceable>host</> <re
    server activity.  Presently, the collector can count accesses to tables
    and indexes in both disk-block and individual-row terms.  It also tracks
    total numbers of rows in each table, and the last vacuum and analyze times
-   for each table.
+   for each table.  It can also count calls to user-defined functions and
+   the total time spent in each one.
   </para>
 
   <para>
@@ -141,8 +142,12 @@ postgres: <replaceable>user</> <replaceable>database</> <replaceable>host</> <re
 
   <para>
    The parameter <xref linkend="guc-track-counts"> controls whether
-   information is actually sent to the collector process and thus determines
-   whether any run-time overhead occurs for event counting.
+   statistics are collected about table and index accesses.
+  </para>
+
+  <para>
+   The parameter <xref linkend="guc-track-functions"> enables tracking of
+   usage of user-defined functions.
   </para>
 
   <para>
@@ -370,6 +375,16 @@ postgres: <replaceable>user</> <replaceable>database</> <replaceable>host</> <re
       <entry>Same as <structname>pg_statio_all_sequences</>, except that only
       user sequences are shown.</entry>
      </row>
+
+     <row>
+      <entry><structname>pg_stat_user_functions</></entry>
+      <entry>For all tracked functions, function OID, schema, name, number
+      of calls, total time, and self time.  Self time is the
+      amount of time spent in the function itself, total time includes the
+      time spent in functions it called. Time values are in milliseconds.
+     </entry>
+     </row>
+
     </tbody>
    </tgroup>
   </table>
@@ -429,8 +444,9 @@ postgres: <replaceable>user</> <replaceable>database</> <replaceable>host</> <re
    linkend="monitoring-stats-funcs-table">.  The per-database access
    functions take a database OID as argument to identify which
    database to report on.  The per-table and per-index functions take
-   a table or index OID.  (Note that only tables and indexes in the
-   current database can be seen with these functions.)  The
+   a table or index OID.  The functions for function-call statistics
+   take a function OID.  (Note that only tables, indexes, and functions
+   in the current database can be seen with these functions.)  The
    per-server-process access functions take a server process
    number, which ranges from one to the number of currently active
    server processes.
@@ -674,6 +690,32 @@ postgres: <replaceable>user</> <replaceable>database</> <replaceable>host</> <re
       </entry>
      </row>
 
+     <row>
+      <entry><literal><function>pg_stat_get_function_calls</function>(<type>oid</type>)</literal></entry>
+      <entry><type>bigint</type></entry>
+      <entry>
+       Number of times the function has been called.
+      </entry>
+     </row>
+
+     <row>
+      <entry><literal><function>pg_stat_get_function_time</function>(<type>oid</type>)</literal></entry>
+      <entry><type>bigint</type></entry>
+      <entry>
+       Total wall clock time spent in the function, in microseconds.  Includes
+       the time spent in functions called by this one.
+      </entry>
+     </row>
+
+     <row>
+      <entry><literal><function>pg_stat_get_function_self_time</function>(<type>oid</type>)</literal></entry>
+      <entry><type>bigint</type></entry>
+      <entry>
+       Time spent in only this function. Time spent in called functions
+       is excluded.
+      </entry>
+     </row>
+
      <row>
       <entry><literal><function>pg_stat_get_backend_idset</function>()</literal></entry>
       <entry><type>setof integer</type></entry>

src/backend/catalog/system_views.sql

@@ -3,7 +3,7 @@
  *
  * Copyright (c) 1996-2008, PostgreSQL Global Development Group
  *
- * $PostgreSQL: pgsql/src/backend/catalog/system_views.sql,v 1.51 2008/05/08 08:58:59 mha Exp $
+ * $PostgreSQL: pgsql/src/backend/catalog/system_views.sql,v 1.52 2008/05/15 00:17:39 tgl Exp $
  */
 
 CREATE VIEW pg_roles AS 
@@ -374,6 +374,18 @@ CREATE VIEW pg_stat_database AS
             pg_stat_get_db_tuples_deleted(D.oid) AS tup_deleted
     FROM pg_database D;
 
+CREATE VIEW pg_stat_user_functions AS 
+    SELECT
+            P.oid AS funcid, 
+            N.nspname AS schemaname,
+            P.proname AS funcname,
+            pg_stat_get_function_calls(P.oid) AS calls,
+            pg_stat_get_function_time(P.oid) / 1000 AS total_time,
+            pg_stat_get_function_self_time(P.oid) / 1000 AS self_time
+    FROM pg_proc P LEFT JOIN pg_namespace N ON (N.oid = P.pronamespace)
+    WHERE P.prolang != 12  -- fast check to eliminate built-in functions   
+          AND pg_stat_get_function_calls(P.oid) IS NOT NULL;
+
 CREATE VIEW pg_stat_bgwriter AS
     SELECT
         pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed,

src/backend/commands/trigger.c

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/trigger.c,v 1.233 2008/05/12 20:01:59 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/trigger.c,v 1.234 2008/05/15 00:17:39 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -32,6 +32,7 @@
 #include "miscadmin.h"
 #include "nodes/makefuncs.h"
 #include "parser/parse_func.h"
+#include "pgstat.h"
 #include "storage/bufmgr.h"
 #include "tcop/utility.h"
 #include "utils/acl.h"
@@ -1566,6 +1567,7 @@ ExecCallTriggerFunc(TriggerData *trigdata,
 					MemoryContext per_tuple_context)
 {
 	FunctionCallInfoData fcinfo;
+	PgStat_FunctionCallUsage fcusage;
 	Datum		result;
 	MemoryContext oldContext;
 
@@ -1599,8 +1601,12 @@ ExecCallTriggerFunc(TriggerData *trigdata,
 	 */
 	InitFunctionCallInfoData(fcinfo, finfo, 0, (Node *) trigdata, NULL);
 
+	pgstat_init_function_usage(&fcinfo, &fcusage);
+
 	result = FunctionCallInvoke(&fcinfo);
 
+	pgstat_end_function_usage(&fcusage, true);
+
 	MemoryContextSwitchTo(oldContext);
 
 	/*

src/backend/commands/vacuum.c

@@ -13,7 +13,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/commands/vacuum.c,v 1.373 2008/05/12 20:02:00 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/commands/vacuum.c,v 1.374 2008/05/15 00:17:39 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -323,7 +323,7 @@ vacuum(VacuumStmt *vacstmt, List *relids,
 	 * in autovacuum --- autovacuum.c does this for itself.
 	 */
 	if (vacstmt->vacuum && !IsAutoVacuumWorkerProcess())
-		pgstat_vacuum_tabstat();
+		pgstat_vacuum_stat();
 
 	/*
 	 * Create special memory context for cross-transaction storage.

src/backend/executor/execQual.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/executor/execQual.c,v 1.230 2008/05/12 00:00:48 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/executor/execQual.c,v 1.231 2008/05/15 00:17:39 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -46,6 +46,7 @@
 #include "nodes/makefuncs.h"
 #include "optimizer/planmain.h"
 #include "parser/parse_expr.h"
+#include "pgstat.h"
 #include "utils/acl.h"
 #include "utils/builtins.h"
 #include "utils/lsyscache.h"
@@ -1147,6 +1148,7 @@ ExecMakeFunctionResult(FuncExprState *fcache,
 	List	   *arguments = fcache->args;
 	Datum		result;
 	FunctionCallInfoData fcinfo;
+	PgStat_FunctionCallUsage fcusage;
 	ReturnSetInfo rsinfo;		/* for functions returning sets */
 	ExprDoneCond argDone;
 	bool		hasSetArg;
@@ -1250,11 +1252,16 @@ ExecMakeFunctionResult(FuncExprState *fcache,
 
 			if (callit)
 			{
+				pgstat_init_function_usage(&fcinfo, &fcusage);
+
 				fcinfo.isnull = false;
 				rsinfo.isDone = ExprSingleResult;
 				result = FunctionCallInvoke(&fcinfo);
 				*isNull = fcinfo.isnull;
 				*isDone = rsinfo.isDone;
+
+				pgstat_end_function_usage(&fcusage,
+										  rsinfo.isDone != ExprMultipleResult);
 			}
 			else
 			{
@@ -1346,9 +1353,14 @@ ExecMakeFunctionResult(FuncExprState *fcache,
 				}
 			}
 		}
+
+		pgstat_init_function_usage(&fcinfo, &fcusage);
+
 		fcinfo.isnull = false;
 		result = FunctionCallInvoke(&fcinfo);
 		*isNull = fcinfo.isnull;
+
+		pgstat_end_function_usage(&fcusage, true);
 	}
 
 	return result;
@@ -1369,6 +1381,7 @@ ExecMakeFunctionResultNoSets(FuncExprState *fcache,
 	ListCell   *arg;
 	Datum		result;
 	FunctionCallInfoData fcinfo;
+	PgStat_FunctionCallUsage fcusage;
 	int			i;
 
 	/* Guard against stack overflow due to overly complex expressions */
@@ -1407,10 +1420,15 @@ ExecMakeFunctionResultNoSets(FuncExprState *fcache,
 			}
 		}
 	}
+
+	pgstat_init_function_usage(&fcinfo, &fcusage);
+
 	/* fcinfo.isnull = false; */	/* handled by InitFunctionCallInfoData */
 	result = FunctionCallInvoke(&fcinfo);
 	*isNull = fcinfo.isnull;
 
+	pgstat_end_function_usage(&fcusage, true);
+
 	return result;
 }
 
@@ -1434,6 +1452,7 @@ ExecMakeTableFunctionResult(ExprState *funcexpr,
 	bool		returnsTuple;
 	bool		returnsSet = false;
 	FunctionCallInfoData fcinfo;
+	PgStat_FunctionCallUsage fcusage;
 	ReturnSetInfo rsinfo;
 	HeapTupleData tmptup;
 	MemoryContext callerContext;
@@ -1559,9 +1578,14 @@ ExecMakeTableFunctionResult(ExprState *funcexpr,
 		/* Call the function or expression one time */
 		if (direct_function_call)
 		{
+			pgstat_init_function_usage(&fcinfo, &fcusage);
+
 			fcinfo.isnull = false;
 			rsinfo.isDone = ExprSingleResult;
 			result = FunctionCallInvoke(&fcinfo);
+
+			pgstat_end_function_usage(&fcusage,
+									  rsinfo.isDone != ExprMultipleResult);
 		}
 		else
 		{

src/backend/postmaster/autovacuum.c

@@ -55,7 +55,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/postmaster/autovacuum.c,v 1.77 2008/05/12 00:00:50 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/postmaster/autovacuum.c,v 1.78 2008/05/15 00:17:40 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1857,7 +1857,7 @@ do_autovacuum(void)
 	 * want to do this exactly once per DB-processing cycle, even if we find
 	 * nothing worth vacuuming in the database.
 	 */
-	pgstat_vacuum_tabstat();
+	pgstat_vacuum_stat();
 
 	/*
 	 * Find the pg_database entry and select the default freeze_min_age. We

src/backend/tcop/postgres.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.552 2008/05/12 20:02:01 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.553 2008/05/15 00:17:40 tgl Exp $
  *
  * NOTES
  *	  this is the "main" module of the postgres backend and
@@ -3502,7 +3502,7 @@ PostgresMain(int argc, char *argv[], const char *username)
 			}
 			else
 			{
-				pgstat_report_tabstat(false);
+				pgstat_report_stat(false);
 
 				set_ps_display("idle", false);
 				pgstat_report_activity("<IDLE>");

src/backend/utils/adt/pgstatfuncs.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/adt/pgstatfuncs.c,v 1.51 2008/05/12 00:00:51 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/adt/pgstatfuncs.c,v 1.52 2008/05/15 00:17:40 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -39,6 +39,10 @@ extern Datum pg_stat_get_last_autovacuum_time(PG_FUNCTION_ARGS);
 extern Datum pg_stat_get_last_analyze_time(PG_FUNCTION_ARGS);
 extern Datum pg_stat_get_last_autoanalyze_time(PG_FUNCTION_ARGS);
 
+extern Datum pg_stat_get_function_calls(PG_FUNCTION_ARGS);
+extern Datum pg_stat_get_function_time(PG_FUNCTION_ARGS);
+extern Datum pg_stat_get_function_self_time(PG_FUNCTION_ARGS);
+
 extern Datum pg_stat_get_backend_idset(PG_FUNCTION_ARGS);
 extern Datum pg_stat_get_activity(PG_FUNCTION_ARGS);
 extern Datum pg_backend_pid(PG_FUNCTION_ARGS);
@@ -325,6 +329,39 @@ pg_stat_get_last_autoanalyze_time(PG_FUNCTION_ARGS)
 		PG_RETURN_TIMESTAMPTZ(result);
 }
 
+Datum
+pg_stat_get_function_calls(PG_FUNCTION_ARGS)
+{
+	Oid	funcid = PG_GETARG_OID(0);
+	PgStat_StatFuncEntry *funcentry;
+
+	if ((funcentry = pgstat_fetch_stat_funcentry(funcid)) == NULL)
+		PG_RETURN_NULL();
+	PG_RETURN_INT64(funcentry->f_numcalls);
+}
+
+Datum
+pg_stat_get_function_time(PG_FUNCTION_ARGS)
+{
+	Oid	funcid = PG_GETARG_OID(0);
+	PgStat_StatFuncEntry *funcentry;
+
+	if ((funcentry = pgstat_fetch_stat_funcentry(funcid)) == NULL)
+		PG_RETURN_NULL();
+	PG_RETURN_INT64(funcentry->f_time);
+}
+
+Datum
+pg_stat_get_function_self_time(PG_FUNCTION_ARGS)
+{
+	Oid	funcid = PG_GETARG_OID(0);
+	PgStat_StatFuncEntry *funcentry;
+
+	if ((funcentry = pgstat_fetch_stat_funcentry(funcid)) == NULL)
+		PG_RETURN_NULL();
+	PG_RETURN_INT64(funcentry->f_time_self);
+}
+
 Datum
 pg_stat_get_backend_idset(PG_FUNCTION_ARGS)
 {

src/backend/utils/fmgr/README

-$PostgreSQL: pgsql/src/backend/utils/fmgr/README,v 1.12 2008/04/21 00:26:45 tgl Exp $
+$PostgreSQL: pgsql/src/backend/utils/fmgr/README,v 1.13 2008/05/15 00:17:40 tgl Exp $
 
 Function Manager
 ================
@@ -70,6 +70,7 @@ typedef struct
     short       fn_nargs;   /* 0..FUNC_MAX_ARGS, or -1 if variable arg count */
     bool        fn_strict;  /* function is "strict" (NULL in => NULL out) */
     bool        fn_retset;  /* function returns a set (over multiple calls) */
+    unsigned char fn_stats; /* collect stats if track_functions > this */
     void       *fn_extra;   /* extra space for use by handler */
     MemoryContext fn_mcxt;  /* memory context to store fn_extra in */
     Node       *fn_expr;    /* expression parse tree for call, or NULL */
@@ -86,10 +87,11 @@ a function handler could set it to avoid making repeated lookups of its
 own when the same FmgrInfo is used repeatedly during a query.)  fn_nargs
 is the number of arguments expected by the function, fn_strict is its
 strictness flag, and fn_retset shows whether it returns a set; all of
-these values come from the function's pg_proc entry.  If the function is
-being called as part of a SQL expression, fn_expr will point to the
-expression parse tree for the function call; this can be used to extract
-parse-time knowledge about the actual arguments.
+these values come from the function's pg_proc entry.  fn_stats is also
+set up to control whether or not to track runtime statistics for calling
+this function.  If the function is being called as part of a SQL expression,
+fn_expr will point to the expression parse tree for the function call; this
+can be used to extract parse-time knowledge about the actual arguments.
 
 FmgrInfo already exists in the current code, but has fewer fields.  This
 change should be transparent at the source-code level.

src/backend/utils/fmgr/fmgr.c

@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/fmgr/fmgr.c,v 1.118 2008/05/12 00:00:52 alvherre Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/fmgr/fmgr.c,v 1.119 2008/05/15 00:17:40 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -21,6 +21,7 @@
 #include "executor/functions.h"
 #include "miscadmin.h"
 #include "parser/parse_expr.h"
+#include "pgstat.h"
 #include "utils/builtins.h"
 #include "utils/fmgrtab.h"
 #include "utils/guc.h"
@@ -165,8 +166,7 @@ fmgr_info_cxt(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt)
 
 /*
  * This one does the actual work.  ignore_security is ordinarily false
- * but is set to true by fmgr_security_definer to avoid infinite
- * recursive lookups.
+ * but is set to true by fmgr_security_definer to avoid recursion.
  */
 static void
 fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
@@ -197,6 +197,7 @@ fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
 		finfo->fn_nargs = fbp->nargs;
 		finfo->fn_strict = fbp->strict;
 		finfo->fn_retset = fbp->retset;
+		finfo->fn_stats = TRACK_FUNC_ALL;	/* ie, never track */
 		finfo->fn_addr = fbp->func;
 		finfo->fn_oid = functionId;
 		return;
@@ -216,13 +217,23 @@ fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
 
 	/*
 	 * If it has prosecdef set, or non-null proconfig, use
-	 * fmgr_security_definer call handler.
+	 * fmgr_security_definer call handler --- unless we are being called
+	 * again by fmgr_security_definer.
+	 *
+	 * When using fmgr_security_definer, function stats tracking is always
+	 * disabled at the outer level, and instead we set the flag properly
+	 * in fmgr_security_definer's private flinfo and implement the tracking
+	 * inside fmgr_security_definer.  This loses the ability to charge the
+	 * overhead of fmgr_security_definer to the function, but gains the
+	 * ability to set the track_functions GUC as a local GUC parameter of
+	 * an interesting function and have the right things happen.
 	 */
 	if (!ignore_security &&
 		(procedureStruct->prosecdef ||
 		 !heap_attisnull(procedureTuple, Anum_pg_proc_proconfig)))
 	{
 		finfo->fn_addr = fmgr_security_definer;
+		finfo->fn_stats = TRACK_FUNC_ALL;	/* ie, never track */
 		finfo->fn_oid = functionId;
 		ReleaseSysCache(procedureTuple);
 		return;
@@ -255,18 +266,23 @@ fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
 			pfree(prosrc);
 			/* Should we check that nargs, strict, retset match the table? */
 			finfo->fn_addr = fbp->func;
+			/* note this policy is also assumed in fast path above */
+			finfo->fn_stats = TRACK_FUNC_ALL;	/* ie, never track */
 			break;
 
 		case ClanguageId:
 			fmgr_info_C_lang(functionId, finfo, procedureTuple);
+			finfo->fn_stats = TRACK_FUNC_PL;	/* ie, track if ALL */
 			break;
 
 		case SQLlanguageId:
 			finfo->fn_addr = fmgr_sql;
+			finfo->fn_stats = TRACK_FUNC_PL;	/* ie, track if ALL */
 			break;
 
 		default:
 			fmgr_info_other_lang(functionId, finfo, procedureTuple);
+			finfo->fn_stats = TRACK_FUNC_OFF;	/* ie, track if not OFF */
 			break;
 	}
 
@@ -862,6 +878,7 @@ fmgr_security_definer(PG_FUNCTION_ARGS)
 	Oid			save_userid;
 	bool		save_secdefcxt;
 	volatile int save_nestlevel;
+	PgStat_FunctionCallUsage fcusage;
 
 	if (!fcinfo->flinfo->fn_extra)
 	{
@@ -934,7 +951,19 @@ fmgr_security_definer(PG_FUNCTION_ARGS)
 	{
 		fcinfo->flinfo = &fcache->flinfo;
 
+		/* See notes in fmgr_info_cxt_security */
+		pgstat_init_function_usage(fcinfo, &fcusage);
+
 		result = FunctionCallInvoke(fcinfo);
+
+		/*
+		 * We could be calling either a regular or a set-returning function,
+		 * so we have to test to see what finalize flag to use.
+		 */
+		pgstat_end_function_usage(&fcusage,
+								  (fcinfo->resultinfo == NULL ||
+								   !IsA(fcinfo->resultinfo, ReturnSetInfo) ||
+								   ((ReturnSetInfo *) fcinfo->resultinfo)->isDone != ExprMultipleResult));
 	}
 	PG_CATCH();
 	{

src/backend/utils/misc/guc.c

@@ -10,7 +10,7 @@
  * Written by Peter Eisentraut <peter_e@gmx.net>.
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.453 2008/05/12 08:35:05 mha Exp $
+ *	  $PostgreSQL: pgsql/src/backend/utils/misc/guc.c,v 1.454 2008/05/15 00:17:40 tgl Exp $
  *
  *--------------------------------------------------------------------
  */
@@ -169,7 +169,6 @@ static char *config_enum_get_options(struct config_enum *record,
 									 const char *prefix, const char *suffix);
 
 
-
 /*
  * Options for enum values defined in this module.
  */
@@ -241,6 +240,13 @@ static const struct config_enum_entry syslog_facility_options[] = {
 };
 #endif
 
+static const struct config_enum_entry track_function_options[] = {
+	{"none", TRACK_FUNC_OFF},
+	{"pl", TRACK_FUNC_PL},
+	{"all", TRACK_FUNC_ALL},
+	{NULL, 0}
+};
+
 static const struct config_enum_entry xmlbinary_options[] = {
 	{"base64", XMLBINARY_BASE64},
 	{"hex", XMLBINARY_HEX},
@@ -2524,6 +2530,15 @@ static struct config_enum ConfigureNamesEnum[] =
 		assign_session_replication_role, NULL
 	},
 
+	{
+		{"track_functions", PGC_SUSET, STATS_COLLECTOR,
+			gettext_noop("Collects function-level statistics on database activity."),
+			gettext_noop("Valid values are: NONE, PL, and ALL.")
+		},
+		&pgstat_track_functions,
+		TRACK_FUNC_OFF, track_function_options, NULL, NULL
+	},
+
 	{
 		{"wal_sync_method", PGC_SIGHUP, WAL_SETTINGS,
 			gettext_noop("Selects the method used for forcing WAL updates to disk."),

src/backend/utils/misc/postgresql.conf.sample

@@ -363,6 +363,7 @@
 
 #track_activities = on
 #track_counts = on
+#track_functions = none			# none, pl, all
 #update_process_title = on
 
 

src/include/catalog/catversion.h

@@ -37,7 +37,7 @@
  * Portions Copyright (c) 1996-2008, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/catalog/catversion.h,v 1.458 2008/05/09 23:32:04 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/catalog/catversion.h,v 1.459 2008/05/15 00:17:40 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -53,6 +53,6 @@
  */
 
 /*							yyyymmddN */
-#define CATALOG_VERSION_NO	200805091
+#define CATALOG_VERSION_NO	200805141
 
 #endif

src/include/catalog/pg_proc.h

@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1996-2008, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/catalog/pg_proc.h,v 1.498 2008/05/08 08:58:59 mha Exp $
+ * $PostgreSQL: pgsql/src/include/catalog/pg_proc.h,v 1.499 2008/05/15 00:17:40 tgl Exp $
  *
  * NOTES
  *	  The script catalog/genbki.sh reads this file and generates .bki
@@ -2963,6 +2963,13 @@ DESCR("statistics: number of buffers written by backends");
 DATA(insert OID = 2859 ( pg_stat_get_buf_alloc			PGNSP PGUID 12 1 0 f f t f s 0 20 "" _null_ _null_ _null_ pg_stat_get_buf_alloc - _null_ _null_ ));
 DESCR("statistics: number of buffer allocations");
 
+DATA(insert OID = 2978 (  pg_stat_get_function_calls		PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_calls - _null_ _null_ ));
+DESCR("statistics: number of function calls");
+DATA(insert OID = 2979 (  pg_stat_get_function_time			PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_time - _null_ _null_ ));
+DESCR("statistics: execution time of function");
+DATA(insert OID = 2980 (  pg_stat_get_function_self_time	PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_self_time - _null_ _null_ ));
+DESCR("statistics: self execution time of function");
+
 DATA(insert OID = 2230 (  pg_stat_clear_snapshot		PGNSP PGUID 12 1 0 f f f f v 0 2278  "" _null_ _null_ _null_	pg_stat_clear_snapshot - _null_ _null_ ));
 DESCR("statistics: discard current transaction's statistics snapshot");
 DATA(insert OID = 2274 (  pg_stat_reset					PGNSP PGUID 12 1 0 f f f f v 0 2278  "" _null_ _null_ _null_	pg_stat_reset - _null_ _null_ ));

src/include/fmgr.h

@@ -11,7 +11,7 @@
  * Portions Copyright (c) 1996-2008, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
- * $PostgreSQL: pgsql/src/include/fmgr.h,v 1.58 2008/04/21 00:26:46 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/fmgr.h,v 1.59 2008/05/15 00:17:41 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -49,6 +49,7 @@ typedef struct FmgrInfo
 								 * count */
 	bool		fn_strict;		/* function is "strict" (NULL in => NULL out) */
 	bool		fn_retset;		/* function returns a set */
+	unsigned char fn_stats;		/* collect stats if track_functions > this */
 	void	   *fn_extra;		/* extra space for use by handler */
 	MemoryContext fn_mcxt;		/* memory context to store fn_extra in */
 	fmNodePtr	fn_expr;		/* expression parse tree for call, or NULL */

src/include/pgstat.h

@@ -5,18 +5,27 @@
  *
  *	Copyright (c) 2001-2008, PostgreSQL Global Development Group
  *
- *	$PostgreSQL: pgsql/src/include/pgstat.h,v 1.74 2008/04/03 16:27:25 tgl Exp $
+ *	$PostgreSQL: pgsql/src/include/pgstat.h,v 1.75 2008/05/15 00:17:41 tgl Exp $
  * ----------
  */
 #ifndef PGSTAT_H
 #define PGSTAT_H
 
 #include "libpq/pqcomm.h"
+#include "portability/instr_time.h"
 #include "utils/hsearch.h"
 #include "utils/rel.h"
 #include "utils/timestamp.h"
 
 
+/* Values for track_functions GUC variable --- order is significant! */
+typedef enum TrackFunctionsLevel
+{
+	TRACK_FUNC_OFF,
+	TRACK_FUNC_PL,
+	TRACK_FUNC_ALL
+} TrackFunctionsLevel;
+
 /* ----------
  * The types of backend -> collector messages
  * ----------
@@ -31,7 +40,9 @@ typedef enum StatMsgType
 	PGSTAT_MTYPE_AUTOVAC_START,
 	PGSTAT_MTYPE_VACUUM,
 	PGSTAT_MTYPE_ANALYZE,
-	PGSTAT_MTYPE_BGWRITER
+	PGSTAT_MTYPE_BGWRITER,
+	PGSTAT_MTYPE_FUNCSTAT,
+	PGSTAT_MTYPE_FUNCPURGE
 } StatMsgType;
 
 /* ----------
@@ -299,6 +310,80 @@ typedef struct PgStat_MsgBgWriter
 } PgStat_MsgBgWriter;
 
 
+/* ----------
+ * PgStat_FunctionCounts	The actual per-function counts kept by a backend
+ *
+ * This struct should contain only actual event counters, because we memcmp
+ * it against zeroes to detect whether there are any counts to transmit.
+ *
+ * Note that the time counters are in instr_time format here.  We convert to
+ * microseconds in PgStat_Counter format when transmitting to the collector.
+ * ----------
+ */
+typedef struct PgStat_FunctionCounts
+{
+	PgStat_Counter f_numcalls;
+	instr_time	f_time;
+	instr_time	f_time_self;
+} PgStat_FunctionCounts;
+
+/* ----------
+ * PgStat_BackendFunctionEntry	Entry in backend's per-function hash table
+ * ----------
+ */
+typedef struct PgStat_BackendFunctionEntry
+{
+	Oid			f_id;
+	PgStat_FunctionCounts f_counts;
+} PgStat_BackendFunctionEntry;
+
+/* ----------
+ * PgStat_FunctionEntry			Per-function info in a MsgFuncstat
+ * ----------
+ */
+typedef struct PgStat_FunctionEntry
+{
+	Oid			f_id;
+	PgStat_Counter f_numcalls;
+	PgStat_Counter f_time;		/* times in microseconds */
+	PgStat_Counter f_time_self;
+} PgStat_FunctionEntry;
+
+/* ----------
+ * PgStat_MsgFuncstat			Sent by the backend to report function
+ *								usage statistics.
+ * ----------
+ */
+#define PGSTAT_NUM_FUNCENTRIES  \
+	((PGSTAT_MSG_PAYLOAD - sizeof(Oid) - sizeof(int))  \
+	 / sizeof(PgStat_FunctionEntry))
+
+typedef struct PgStat_MsgFuncstat
+{
+	PgStat_MsgHdr m_hdr;
+	Oid			m_databaseid;
+	int			m_nentries;
+	PgStat_FunctionEntry m_entry[PGSTAT_NUM_FUNCENTRIES];
+} PgStat_MsgFuncstat;
+
+/* ----------
+ * PgStat_MsgFuncpurge			Sent by the backend to tell the collector
+ *								about dead functions.
+ * ----------
+ */
+#define PGSTAT_NUM_FUNCPURGE  \
+	((PGSTAT_MSG_PAYLOAD - sizeof(Oid) - sizeof(int))  \
+	 / sizeof(Oid))
+
+typedef struct PgStat_MsgFuncpurge
+{
+	PgStat_MsgHdr m_hdr;
+	Oid			m_databaseid;
+	int			m_nentries;
+	Oid			m_functionid[PGSTAT_NUM_FUNCPURGE];
+} PgStat_MsgFuncpurge;
+
+
 /* ----------
  * PgStat_Msg					Union over all possible messages.
  * ----------
@@ -315,6 +400,8 @@ typedef union PgStat_Msg
 	PgStat_MsgVacuum msg_vacuum;
 	PgStat_MsgAnalyze msg_analyze;
 	PgStat_MsgBgWriter msg_bgwriter;
+	PgStat_MsgFuncstat msg_funcstat;
+	PgStat_MsgFuncpurge msg_funcpurge;
 } PgStat_Msg;
 
 
@@ -347,10 +434,11 @@ typedef struct PgStat_StatDBEntry
 	TimestampTz last_autovac_time;
 
 	/*
-	 * tables must be last in the struct, because we don't write the pointer
-	 * out to the stats file.
+	 * tables and functions must be last in the struct, because we don't
+	 * write the pointers out to the stats file.
 	 */
 	HTAB	   *tables;
+	HTAB	   *functions;
 } PgStat_StatDBEntry;
 
 
@@ -386,6 +474,21 @@ typedef struct PgStat_StatTabEntry
 } PgStat_StatTabEntry;
 
 
+/* ----------
+ * PgStat_StatFuncEntry			The collector's data per function
+ * ----------
+ */
+typedef struct PgStat_StatFuncEntry
+{
+	Oid			functionid;
+
+	PgStat_Counter f_numcalls;
+
+	PgStat_Counter f_time;		/* times in microseconds */
+	PgStat_Counter f_time_self;
+} PgStat_StatFuncEntry;
+
+
 /*
  * Global statistics kept in the stats collector
  */
@@ -451,6 +554,22 @@ typedef struct PgBackendStatus
 	char		st_activity[PGBE_ACTIVITY_SIZE];
 } PgBackendStatus;
 
+/*
+ * Working state needed to accumulate per-function-call timing statistics.
+ */
+typedef struct PgStat_FunctionCallUsage
+{
+	/* Link to function's hashtable entry (must still be there at exit!) */
+	/* NULL means we are not tracking the current function call */
+	PgStat_FunctionCounts *fs;
+	/* Total time previously charged to function, as of function start */
+	instr_time		save_f_time;
+	/* Backend-wide total time as of function start */
+	instr_time		save_total;
+	/* system clock as of function start */
+	instr_time		f_start;
+} PgStat_FunctionCallUsage;
+
 
 /* ----------
  * GUC parameters
@@ -458,6 +577,7 @@ typedef struct PgBackendStatus
  */
 extern bool pgstat_track_activities;
 extern bool pgstat_track_counts;
+extern int	pgstat_track_functions;
 
 /*
  * BgWriter statistics counters are updated directly by bgwriter and bufmgr
@@ -487,8 +607,8 @@ extern void PgstatCollectorMain(int argc, char *argv[]);
  */
 extern void pgstat_ping(void);
 
-extern void pgstat_report_tabstat(bool force);
-extern void pgstat_vacuum_tabstat(void);
+extern void pgstat_report_stat(bool force);
+extern void pgstat_vacuum_stat(void);
 extern void pgstat_drop_database(Oid databaseid);
 
 extern void pgstat_clear_snapshot(void);
@@ -554,6 +674,11 @@ extern void pgstat_count_heap_update(Relation rel, bool hot);
 extern void pgstat_count_heap_delete(Relation rel);
 extern void pgstat_update_heap_dead_tuples(Relation rel, int delta);
 
+extern void pgstat_init_function_usage(FunctionCallInfoData *fcinfo,
+									   PgStat_FunctionCallUsage *fcu);
+extern void pgstat_end_function_usage(PgStat_FunctionCallUsage *fcu,
+									  bool finalize);
+
 extern void AtEOXact_PgStat(bool isCommit);
 extern void AtEOSubXact_PgStat(bool isCommit, int nestDepth);
 
@@ -575,6 +700,7 @@ extern void pgstat_send_bgwriter(void);
 extern PgStat_StatDBEntry *pgstat_fetch_stat_dbentry(Oid dbid);
 extern PgStat_StatTabEntry *pgstat_fetch_stat_tabentry(Oid relid);
 extern PgBackendStatus *pgstat_fetch_stat_beentry(int beid);
+extern PgStat_StatFuncEntry *pgstat_fetch_stat_funcentry(Oid funcid);
 extern int	pgstat_fetch_stat_numbackends(void);
 extern PgStat_GlobalStats *pgstat_fetch_global(void);
 

src/include/portability/instr_time.h

@@ -20,6 +20,8 @@
  *
  * INSTR_TIME_SET_CURRENT(t)		set t to current time
  *
+ * INSTR_TIME_ADD(x, y)				x += y
+ *
  * INSTR_TIME_SUBTRACT(x, y)		x -= y
  *
  * INSTR_TIME_ACCUM_DIFF(x, y, z)	x += (y - z)
@@ -35,15 +37,15 @@
  * only useful on intervals.
  *
  * When summing multiple measurements, it's recommended to leave the
- * running sum in instr_time form (ie, use INSTR_TIME_ACCUM_DIFF) and
- * convert to a result format only at the end.
+ * running sum in instr_time form (ie, use INSTR_TIME_ADD or
+ * INSTR_TIME_ACCUM_DIFF) and convert to a result format only at the end.
  *
  * Beware of multiple evaluations of the macro arguments.
  *
  *
  * Copyright (c) 2001-2008, PostgreSQL Global Development Group
  *
- * $PostgreSQL: pgsql/src/include/portability/instr_time.h,v 1.1 2008/05/14 19:10:29 tgl Exp $
+ * $PostgreSQL: pgsql/src/include/portability/instr_time.h,v 1.2 2008/05/15 00:17:41 tgl Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -62,6 +64,18 @@ typedef struct timeval instr_time;
 
 #define INSTR_TIME_SET_CURRENT(t)	gettimeofday(&(t), NULL)
 
+#define INSTR_TIME_ADD(x,y) \
+	do { \
+		(x).tv_sec += (y).tv_sec; \
+		(x).tv_usec += (y).tv_usec; \
+		/* Normalize */ \
+		while ((x).tv_usec >= 1000000) \
+		{ \
+			(x).tv_usec -= 1000000; \
+			(x).tv_sec++; \
+		} \
+	} while (0)
+
 #define INSTR_TIME_SUBTRACT(x,y) \
 	do { \
 		(x).tv_sec -= (y).tv_sec; \
@@ -110,6 +124,9 @@ typedef LARGE_INTEGER instr_time;
 
 #define INSTR_TIME_SET_CURRENT(t)	QueryPerformanceCounter(&(t))
 
+#define INSTR_TIME_ADD(x,y) \
+	((x).QuadPart += (y).QuadPart)
+
 #define INSTR_TIME_SUBTRACT(x,y) \
 	((x).QuadPart -= (y).QuadPart)
 

src/test/regress/expected/rules.out

@@ -1296,6 +1296,7 @@ SELECT viewname, definition FROM pg_views WHERE schemaname <> 'information_schem
  pg_stat_database         | SELECT d.oid AS datid, d.datname, pg_stat_get_db_numbackends(d.oid) AS numbackends, pg_stat_get_db_xact_commit(d.oid) AS xact_commit, pg_stat_get_db_xact_rollback(d.oid) AS xact_rollback, (pg_stat_get_db_blocks_fetched(d.oid) - pg_stat_get_db_blocks_hit(d.oid)) AS blks_read, pg_stat_get_db_blocks_hit(d.oid) AS blks_hit, pg_stat_get_db_tuples_returned(d.oid) AS tup_returned, pg_stat_get_db_tuples_fetched(d.oid) AS tup_fetched, pg_stat_get_db_tuples_inserted(d.oid) AS tup_inserted, pg_stat_get_db_tuples_updated(d.oid) AS tup_updated, pg_stat_get_db_tuples_deleted(d.oid) AS tup_deleted FROM pg_database d;
  pg_stat_sys_indexes      | SELECT pg_stat_all_indexes.relid, pg_stat_all_indexes.indexrelid, pg_stat_all_indexes.schemaname, pg_stat_all_indexes.relname, pg_stat_all_indexes.indexrelname, pg_stat_all_indexes.idx_scan, pg_stat_all_indexes.idx_tup_read, pg_stat_all_indexes.idx_tup_fetch FROM pg_stat_all_indexes WHERE ((pg_stat_all_indexes.schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (pg_stat_all_indexes.schemaname ~ '^pg_toast'::text));
  pg_stat_sys_tables       | SELECT pg_stat_all_tables.relid, pg_stat_all_tables.schemaname, pg_stat_all_tables.relname, pg_stat_all_tables.seq_scan, pg_stat_all_tables.seq_tup_read, pg_stat_all_tables.idx_scan, pg_stat_all_tables.idx_tup_fetch, pg_stat_all_tables.n_tup_ins, pg_stat_all_tables.n_tup_upd, pg_stat_all_tables.n_tup_del, pg_stat_all_tables.n_tup_hot_upd, pg_stat_all_tables.n_live_tup, pg_stat_all_tables.n_dead_tup, pg_stat_all_tables.last_vacuum, pg_stat_all_tables.last_autovacuum, pg_stat_all_tables.last_analyze, pg_stat_all_tables.last_autoanalyze FROM pg_stat_all_tables WHERE ((pg_stat_all_tables.schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (pg_stat_all_tables.schemaname ~ '^pg_toast'::text));
+ pg_stat_user_functions   | SELECT p.oid AS funcid, n.nspname AS schemaname, p.proname AS funcname, pg_stat_get_function_calls(p.oid) AS calls, (pg_stat_get_function_time(p.oid) / 1000) AS total_time, (pg_stat_get_function_self_time(p.oid) / 1000) AS self_time FROM (pg_proc p LEFT JOIN pg_namespace n ON ((n.oid = p.pronamespace))) WHERE ((p.prolang <> (12)::oid) AND (pg_stat_get_function_calls(p.oid) IS NOT NULL));
  pg_stat_user_indexes     | SELECT pg_stat_all_indexes.relid, pg_stat_all_indexes.indexrelid, pg_stat_all_indexes.schemaname, pg_stat_all_indexes.relname, pg_stat_all_indexes.indexrelname, pg_stat_all_indexes.idx_scan, pg_stat_all_indexes.idx_tup_read, pg_stat_all_indexes.idx_tup_fetch FROM pg_stat_all_indexes WHERE ((pg_stat_all_indexes.schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (pg_stat_all_indexes.schemaname !~ '^pg_toast'::text));
  pg_stat_user_tables      | SELECT pg_stat_all_tables.relid, pg_stat_all_tables.schemaname, pg_stat_all_tables.relname, pg_stat_all_tables.seq_scan, pg_stat_all_tables.seq_tup_read, pg_stat_all_tables.idx_scan, pg_stat_all_tables.idx_tup_fetch, pg_stat_all_tables.n_tup_ins, pg_stat_all_tables.n_tup_upd, pg_stat_all_tables.n_tup_del, pg_stat_all_tables.n_tup_hot_upd, pg_stat_all_tables.n_live_tup, pg_stat_all_tables.n_dead_tup, pg_stat_all_tables.last_vacuum, pg_stat_all_tables.last_autovacuum, pg_stat_all_tables.last_analyze, pg_stat_all_tables.last_autoanalyze FROM pg_stat_all_tables WHERE ((pg_stat_all_tables.schemaname <> ALL (ARRAY['pg_catalog'::name, 'information_schema'::name])) AND (pg_stat_all_tables.schemaname !~ '^pg_toast'::text));
  pg_statio_all_indexes    | SELECT c.oid AS relid, i.oid AS indexrelid, n.nspname AS schemaname, c.relname, i.relname AS indexrelname, (pg_stat_get_blocks_fetched(i.oid) - pg_stat_get_blocks_hit(i.oid)) AS idx_blks_read, pg_stat_get_blocks_hit(i.oid) AS idx_blks_hit FROM (((pg_class c JOIN pg_index x ON ((c.oid = x.indrelid))) JOIN pg_class i ON ((i.oid = x.indexrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) WHERE (c.relkind = ANY (ARRAY['r'::"char", 't'::"char"]));
@@ -1327,7 +1328,7 @@ SELECT viewname, definition FROM pg_views WHERE schemaname <> 'information_schem
  shoelace_obsolete        | SELECT shoelace.sl_name, shoelace.sl_avail, shoelace.sl_color, shoelace.sl_len, shoelace.sl_unit, shoelace.sl_len_cm FROM shoelace WHERE (NOT (EXISTS (SELECT shoe.shoename FROM shoe WHERE (shoe.slcolor = shoelace.sl_color))));
  street                   | SELECT r.name, r.thepath, c.cname FROM ONLY road r, real_city c WHERE (c.outline ## r.thepath);
  toyemp                   | SELECT emp.name, emp.age, emp.location, (12 * emp.salary) AS annualsal FROM emp;
-(49 rows)
+(50 rows)
 
 SELECT tablename, rulename, definition FROM pg_rules 
 	ORDER BY tablename, rulename;