On 01/17/2012 11:13 AM, Joel Jacobson wrote:
> Since you only care about the parentfuncid in one level, it looks like
> you will only be able to get a total call graph of all possible
> function calls, and not each unique call graph per transaction.

True, for my purposes (function dependencies and performance analysis)
the global graph is sufficient.

> Also, why remove the parent oid when uploading the statistics to the 
> collector?
> It would be nice to have the statistics for each function per parent,
> to see where you have a bottleneck which might only be occurring in a
> function when called from a specific parent.

I guess I was just lazy at the time I wrote it. But it shouldn't be too
much of an effort to store the global call graph in statistics
collector. Unique call graphs would be somewhat more complicated I
guess.

>> There is a patch for this and we do use it in production for occasional
>> troubleshooting and dependency analysis. Can't attach immediately
>> though -- it has some extra cruft in it that needs to be cleaned up.
> 
> I would highly appreciate a patch, don't worry about cleaning up, I
> can do that, unless it's some code you can't share for other reasons.
> 

Patch attached. It was developed against 9.1, but also applies to
HEAD but gives some fuzz and offsets.

It adds 2 GUC variables: log_function_calls and log_usage_stats. The
first just output function statistics to log (with no parent info).
With log_usage_stats enabled, it also outputs detailed function usage
plus relation usage. So you basically get output such as:

# select * from pgq.get_consumer_info();
LOG:  duration: 11.153 ms  statement: select * from pgq.get_consumer_info();
LOG:  function call: pgq.get_consumer_info(0) calls=1 time=9726
self_time=536
LOG:  USAGE STATISTICS
DETAIL:  ! object access stats:
! F 1892464226 0 pgq.get_consumer_info(0) calls=1 time=9726 self_time=536
! F 1892464228 1892464226 pgq.get_consumer_info(2) calls=1 time=9190
self_time=9190
! r 167558000 pgq.queue: blks_read=28 blks_hit=28
! r 167557988 pgq.consumer: blks_read=56 blks_hit=56
! r 167558021 pgq.subscription: blks_read=54 blks_hit=50
! r 167558050 pgq.tick: blks_read=103 blks_hit=102
! i 1892464189 pgq.queue_pkey: scans=1 tup_ret=37 tup_fetch=37
blks_read=2 blks_hit=2
! i 167557995 pgq.consumer_pkey: scans=56 tup_ret=56 tup_fetch=56
blks_read=57 blks_hit=56
! i 1892464195 pgq.subscription_pkey: scans=37 tup_ret=156 tup_fetch=56
blks_read=127 blks_hit=123
! i 167558058 pgq.tick_pkey: scans=112 tup_ret=103 tup_fetch=103
blks_read=367 blks_hit=366

> funcid->parentfuncid might be sufficient for performance
> optimizations, but to automatically generate directional graphs of all
> unique call graphs in run-time, you would need all the unique pairs of
> funcid->parentfuncid as a singel column, probably a sorted array of
> oids[][], example: [[1,2],[1,3],[2,4],[2,5]] if the call craph would
> be {1->2, 1->3, 2->4, 2->5}.
> 

Hmm, array would probably work, although I wonder if there is a
more elegant solution ...

regards,
Martin
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index 5ed6e83..2e66020 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -42,6 +42,7 @@
 #include "access/twophase_rmgr.h"
 #include "access/xact.h"
 #include "catalog/pg_database.h"
+#include "catalog/pg_namespace.h"
 #include "catalog/pg_proc.h"
 #include "libpq/ip.h"
 #include "libpq/libpq.h"
@@ -63,7 +64,8 @@
 #include "utils/ps_status.h"
 #include "utils/rel.h"
 #include "utils/tqual.h"
-
+#include "utils/syscache.h"
+#include "utils/lsyscache.h"
 
 /* ----------
  * Paths for the statistics files (relative to installation's $PGDATA).
@@ -113,6 +115,12 @@ bool		pgstat_track_counts = false;
 int			pgstat_track_functions = TRACK_FUNC_OFF;
 int			pgstat_track_activity_query_size = 1024;
 
+/*
+ * Last function call parent. InvalidOid is used to indicate
+ * top-level functions.
+ */
+Oid current_function_parent = InvalidOid;
+
 /* ----------
  * Built from GUC parameter
  * ----------
@@ -258,8 +266,11 @@ static void pgstat_read_current_status(void);
 static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg);
 static void pgstat_send_funcstats(void);
 static HTAB *pgstat_collect_oids(Oid catalogid);
+static void pgstat_report_functions(void);
+static void pgstat_report_usage(void);
 
 static PgStat_TableStatus *get_tabstat_entry(Oid rel_id, bool isshared);
+static PgStat_TableStatus *new_tsa_entry(TabStatusArray *entry, Oid rel_id, bool isshared);
 
 static void pgstat_setup_memcxt(void);
 
@@ -697,6 +708,12 @@ pgstat_report_stat(bool force)
 	last_report = now;
 
 	/*
+	 * First report function calls and object usage.
+	 */
+	pgstat_report_functions();
+	pgstat_report_usage();
+
+	/*
 	 * Scan through the TabStatusArray struct(s) to find tables that actually
 	 * have counts, and build messages to send.  We have to separate shared
 	 * relations from regular ones because the databaseid field in the message
@@ -804,9 +821,6 @@ pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg)
 static void
 pgstat_send_funcstats(void)
 {
-	/* we assume this inits to all zeroes: */
-	static const PgStat_FunctionCounts all_zeroes;
-
 	PgStat_MsgFuncstat msg;
 	PgStat_BackendFunctionEntry *entry;
 	HASH_SEQ_STATUS fstat;
@@ -818,37 +832,31 @@ pgstat_send_funcstats(void)
 	msg.m_databaseid = MyDatabaseId;
 	msg.m_nentries = 0;
 
+	/*
+	 * Pack the function stats into message structures and send
+	 * them to the collector. Don't bother merging the stats for
+	 * the same function with different parents -- just send the
+	 * entries individually and let the collector sum it up.
+	 */
 	hash_seq_init(&fstat, pgStatFunctions);
-	while ((entry = (PgStat_BackendFunctionEntry *) hash_seq_search(&fstat)) != NULL)
+	while ((entry = hash_seq_search(&fstat)) != NULL)
 	{
-		PgStat_FunctionEntry *m_ent;
+			msg.m_entry[msg.m_nentries].f_id = entry->f_key.f_id;
+			msg.m_entry[msg.m_nentries].f_counts = entry->counts;
 
-		/* Skip it if no counts accumulated since last time */
-		if (memcmp(&entry->f_counts, &all_zeroes,
-				   sizeof(PgStat_FunctionCounts)) == 0)
-			continue;
-
-		/* need to convert format of time accumulators */
-		m_ent = &msg.m_entry[msg.m_nentries];
-		m_ent->f_id = entry->f_id;
-		m_ent->f_numcalls = entry->f_counts.f_numcalls;
-		m_ent->f_time = INSTR_TIME_GET_MICROSEC(entry->f_counts.f_time);
-		m_ent->f_time_self = INSTR_TIME_GET_MICROSEC(entry->f_counts.f_time_self);
-
-		if (++msg.m_nentries >= PGSTAT_NUM_FUNCENTRIES)
-		{
-			pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) +
-						msg.m_nentries * sizeof(PgStat_FunctionEntry));
-			msg.m_nentries = 0;
-		}
+			memset(&entry->counts, 0, sizeof(PgStat_FunctionCounts));
 
-		/* reset the entry's counts */
-		MemSet(&entry->f_counts, 0, sizeof(PgStat_FunctionCounts));
+			if (++msg.m_nentries >= PGSTAT_NUM_FUNCENTRIES)
+			{
+				pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) +
+					msg.m_nentries * sizeof(PgStat_MsgFunctionEntry));
+				msg.m_nentries = 0;
+			}
 	}
 
 	if (msg.m_nentries > 0)
 		pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) +
-					msg.m_nentries * sizeof(PgStat_FunctionEntry));
+			msg.m_nentries * sizeof(PgStat_MsgFunctionEntry));
 
 	have_function_stats = false;
 }
@@ -1079,6 +1087,163 @@ pgstat_collect_oids(Oid catalogid)
 
 
 /* ----------
+ * pgstat_report_functions() -
+ *
+ *	Report top-level function calls to system log.
+ * ----------
+ */
+static void
+pgstat_report_functions(void)
+{
+	PgStat_BackendFunctionEntry	   *entry;
+	HASH_SEQ_STATUS 				fstat;
+
+	if (!log_function_calls || IsAutoVacuumWorkerProcess())
+		return;
+
+	/*
+	 * Go through the functions that have stats. Dump only the
+	 * top-level calls.
+	 */
+	if (pgStatFunctions != NULL)
+	{
+		hash_seq_init(&fstat, pgStatFunctions);
+		while ((entry = hash_seq_search(&fstat)) != NULL)
+		{
+			/* log top-level function calls if so requested */
+			if (entry->counts.f_numcalls > 0 && !OidIsValid(entry->f_key.f_parent))
+				elog(LOG, "function call: %s.%s(%d) calls=" UINT64_FORMAT
+				          " time=" UINT64_FORMAT " self_time=" UINT64_FORMAT,
+					 entry->f_schema,
+					 entry->f_name,
+					 entry->f_nargs,
+					 entry->counts.f_numcalls,
+					 INSTR_TIME_GET_MICROSEC(entry->counts.f_time),
+					 INSTR_TIME_GET_MICROSEC(entry->counts.f_time_self));
+		}
+	}
+}
+
+/* ----------
+ * pgstat_report_usage() -
+ *
+ *	Report relation and function usage for the client. The report is
+ *	formatted similarly to log_executor_stats.
+ * ----------
+ */
+static void
+pgstat_report_usage(void)
+{
+	static const PgStat_TableCounts	tc_all_zeroes;
+	PgStat_BackendFunctionEntry	   *entry;
+	HASH_SEQ_STATUS 				fstat;
+	TabStatusArray				   *tsa;
+	StringInfoData					str;
+	bool							log_usage = false;
+	int								i;
+
+	if (!log_usage_stats || IsAutoVacuumWorkerProcess())
+		return;
+
+	initStringInfo(&str);
+	appendStringInfo(&str, "! object access stats:\n");
+
+	/*
+	 * Go through the functions that have stats. We produce as many
+	 * detail rows as necessary to list all the invocations by different
+	 * parents of the function. This is verbose, but allows for more
+	 * fine-grained performance analysis later.
+	 */
+	if (pgStatFunctions != NULL)
+	{
+		hash_seq_init(&fstat, pgStatFunctions);
+		while ((entry = hash_seq_search(&fstat)) != NULL)
+		{
+			if (!entry->counts.f_numcalls > 0)
+				/* nothing to do */
+				continue;
+
+			appendStringInfo(&str, "! F %u %u %s.%s(%d) calls=" UINT64_FORMAT
+							 " time=" UINT64_FORMAT
+							 " self_time=" UINT64_FORMAT "\n",
+							 entry->f_key.f_id,
+							 entry->f_key.f_parent,
+							 entry->f_schema,
+							 entry->f_name,
+							 entry->f_nargs,
+							 entry->counts.f_numcalls,
+							 INSTR_TIME_GET_MICROSEC(entry->counts.f_time),
+							 INSTR_TIME_GET_MICROSEC(entry->counts.f_time_self));
+
+			log_usage = true;
+		}
+	}
+
+	/*
+	 * Now the tables. Here we actually report any relations that have
+	 * stats counters, use relkind to distinguish.
+	 */
+	if (log_usage_stats && pgStatTabList->tsa_used > 0)
+	{
+		for (tsa = pgStatTabList; tsa != NULL; tsa = tsa->tsa_next)
+		{
+			for (i = 0; i < tsa->tsa_used; i++)
+			{
+				PgStat_TableStatus *entry = &tsa->tsa_entries[i];
+				PgStat_TableCounts *tc = &entry->t_counts;
+
+				if (entry->t_system)
+					/* Don't report system tables */
+					continue;
+				if (memcmp(tc, &tc_all_zeroes, sizeof(*tc)) == 0)
+					/* All zeroes, nothing to report */
+					continue;
+
+#define REPORT_TC_COUNTER(field,label) \
+	if (tc->field) \
+		appendStringInfo(&str, " %s=" UINT64_FORMAT, (label), tc->field)
+
+				appendStringInfo(&str, "! %c %u %s.%s:",
+								 entry->t_relkind,
+								 entry->t_id,
+								 entry->t_schema,
+								 entry->t_name);
+
+				REPORT_TC_COUNTER(t_numscans, "scans");
+				REPORT_TC_COUNTER(t_tuples_returned, "tup_ret");
+				REPORT_TC_COUNTER(t_tuples_fetched, "tup_fetch");
+				REPORT_TC_COUNTER(t_tuples_inserted, "n_tup_ins");
+				REPORT_TC_COUNTER(t_tuples_updated, "n_tup_upd");
+				REPORT_TC_COUNTER(t_tuples_deleted, "n_tup_del");
+				REPORT_TC_COUNTER(t_tuples_hot_updated, "n_tup_hot_upd");
+				REPORT_TC_COUNTER(t_delta_live_tuples, "n_delta_live_tuples");
+				REPORT_TC_COUNTER(t_delta_dead_tuples, "n_delta_dead_tuples");
+				REPORT_TC_COUNTER(t_changed_tuples, "n_changed_tuples");
+				REPORT_TC_COUNTER(t_blocks_fetched, "blks_read");
+				REPORT_TC_COUNTER(t_blocks_hit, "blks_hit");
+
+				appendStringInfo(&str, "\n");
+				log_usage = true;
+			}
+		}
+	}
+
+	/*
+	 * Found something to report - spit it out.
+	 */
+	if (log_usage)
+	{
+		str.data[--str.len] = '\0';
+		ereport(LOG,
+				(errmsg_internal("%s", "USAGE STATISTICS"),
+				errdetail("%s", str.data)));
+	}
+
+	pfree(str.data);
+}
+
+
+/* ----------
  * pgstat_drop_database() -
  *
  *	Tell the collector that we just dropped a database.
@@ -1380,8 +1545,10 @@ void
 pgstat_init_function_usage(FunctionCallInfoData *fcinfo,
 						   PgStat_FunctionCallUsage *fcu)
 {
-	PgStat_BackendFunctionEntry *htabent;
 	bool		found;
+	Oid             funcid;
+	MemoryContext	oldcontext;
+	FunctionStatKey	key;
 
 	if (pgstat_track_functions <= fcinfo->flinfo->fn_stats)
 	{
@@ -1390,15 +1557,19 @@ pgstat_init_function_usage(FunctionCallInfoData *fcinfo,
 		return;
 	}
 
+	memset(&fcu->counts, 0, sizeof(fcu->counts));
+	funcid = fcinfo->flinfo->fn_oid;
+	oldcontext = MemoryContextSwitchTo(TopMemoryContext);
+
 	if (!pgStatFunctions)
 	{
 		/* First time through - initialize function stat table */
 		HASHCTL		hash_ctl;
 
 		memset(&hash_ctl, 0, sizeof(hash_ctl));
-		hash_ctl.keysize = sizeof(Oid);
+		hash_ctl.keysize = sizeof(key);
 		hash_ctl.entrysize = sizeof(PgStat_BackendFunctionEntry);
-		hash_ctl.hash = oid_hash;
+		hash_ctl.hash = tag_hash;
 		pgStatFunctions = hash_create("Function stat entries",
 									  PGSTAT_FUNCTION_HASH_SIZE,
 									  &hash_ctl,
@@ -1406,21 +1577,45 @@ pgstat_init_function_usage(FunctionCallInfoData *fcinfo,
 	}
 
 	/* Get the stats entry for this function, create if necessary */
-	htabent = hash_search(pgStatFunctions, &fcinfo->flinfo->fn_oid,
-						  HASH_ENTER, &found);
+	key.f_id = funcid;
+	key.f_parent = current_function_parent;
+	fcu->fs = hash_search(pgStatFunctions, &key, HASH_ENTER, &found);
+
 	if (!found)
-		MemSet(&htabent->f_counts, 0, sizeof(PgStat_FunctionCounts));
+	{
+		Form_pg_proc functup;
+		HeapTuple	tp;
 
-	fcu->fs = &htabent->f_counts;
+		tp = SearchSysCache(PROCOID, ObjectIdGetDatum(funcid), 0, 0, 0);
+		if (!HeapTupleIsValid(tp))
+			ereport(ERROR,
+				(errcode(ERRCODE_UNDEFINED_OBJECT),
+				errmsg("function \"%u\" does not exist", funcid)));
+
+		functup = (Form_pg_proc) GETSTRUCT(tp);
+
+		memset(fcu->fs, 0, sizeof(*fcu->fs));
+		fcu->fs->f_key = key;
+		fcu->fs->f_name = pstrdup(NameStr(functup->proname));
+		fcu->fs->f_schema = get_namespace_name(functup->pronamespace);
+		fcu->fs->f_nargs = functup->pronargs;
+
+		ReleaseSysCache(tp);
+	}
+
+	/* Make this function the current */
+	current_function_parent = funcid;
 
 	/* save stats for this function, later used to compensate for recursion */
-	fcu->save_f_time = htabent->f_counts.f_time;
+	fcu->save_counts = fcu->fs->counts;
 
 	/* save current backend-wide total time */
 	fcu->save_total = total_func_time;
 
 	/* get clock time as of function start */
 	INSTR_TIME_SET_CURRENT(fcu->f_start);
+
+	MemoryContextSwitchTo(oldcontext);
 }
 
 /*
@@ -1452,13 +1647,12 @@ find_funcstat_entry(Oid func_id)
 void
 pgstat_end_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize)
 {
-	PgStat_FunctionCounts *fs = fcu->fs;
 	instr_time	f_total;
 	instr_time	f_others;
 	instr_time	f_self;
 
 	/* stats not wanted? */
-	if (fs == NULL)
+	if (fcu->fs == NULL)
 		return;
 
 	/* total elapsed time in this function call */
@@ -1481,13 +1675,17 @@ pgstat_end_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize)
 	 * similar kluge for self time, since that already excludes any recursive
 	 * calls.)
 	 */
-	INSTR_TIME_ADD(f_total, fcu->save_f_time);
+	INSTR_TIME_ADD(f_total, fcu->save_counts.f_time);
 
 	/* update counters in function stats table */
 	if (finalize)
-		fs->f_numcalls++;
-	fs->f_time = f_total;
-	INSTR_TIME_ADD(fs->f_time_self, f_self);
+		fcu->fs->counts.f_numcalls++;
+
+	fcu->fs->counts.f_time = f_total;
+	INSTR_TIME_ADD(fcu->fs->counts.f_time_self, f_self);
+
+	/* restore the previous parent */
+	current_function_parent = fcu->fs->f_key.f_parent;
 
 	/* indicate that we have something to send */
 	have_function_stats = true;
@@ -1542,6 +1740,60 @@ pgstat_initstats(Relation rel)
 }
 
 /*
+ * new_tsa_entry - fill in PgStat_TableStatus structure.
+ */
+PgStat_TableStatus *
+new_tsa_entry(TabStatusArray *tsa, Oid rel_id, bool isshared)
+{
+	HeapTuple	tp;
+	MemoryContext oldcontext;
+	Form_pg_class reltup;
+
+	PgStat_TableStatus *entry = &tsa->tsa_entries[tsa->tsa_used++];
+	entry->t_id = rel_id;
+	entry->t_shared = isshared;
+	entry->t_name = NULL;
+	entry->t_schema = NULL;
+	entry->t_relkind = ' ';
+
+	if (rel_id < FirstNormalObjectId)
+	{
+		/* 
+		 * Skip name lookups for system tables. As a sideeffect this also
+		 * takes care of the cases where pgstat_initstats is called without
+		 * a transaction (e.g. autovacuum launcher or pg_hba role check).
+		 */
+		entry->t_system = TRUE;
+		return entry;
+	}
+
+	tp = SearchSysCache(RELOID, ObjectIdGetDatum(rel_id), 0, 0, 0);
+
+	if (!HeapTupleIsValid(tp))
+		ereport(ERROR,
+			(errcode(ERRCODE_UNDEFINED_OBJECT),
+			errmsg("relation \"%u\" does not exist", rel_id)));
+
+	oldcontext = MemoryContextSwitchTo(TopMemoryContext);
+	reltup = (Form_pg_class) GETSTRUCT(tp);
+
+	entry->t_name = pstrdup(NameStr(reltup->relname));
+	entry->t_relkind = reltup->relkind;
+
+	/* Additional check for system objects */
+	if (reltup->relnamespace == PG_CATALOG_NAMESPACE
+		|| reltup->relnamespace == PG_TOAST_NAMESPACE)
+		entry->t_system = TRUE;
+	else
+		entry->t_schema = get_namespace_name(reltup->relnamespace);
+
+	MemoryContextSwitchTo(oldcontext);
+	ReleaseSysCache(tp);
+
+	return entry;
+}
+
+/*
  * get_tabstat_entry - find or create a PgStat_TableStatus entry for rel
  */
 static PgStat_TableStatus *
@@ -1572,10 +1824,7 @@ get_tabstat_entry(Oid rel_id, bool isshared)
 			 * let's use this one.  We assume the entry was already zeroed,
 			 * either at creation or after last use.
 			 */
-			entry = &tsa->tsa_entries[tsa->tsa_used++];
-			entry->t_id = rel_id;
-			entry->t_shared = isshared;
-			return entry;
+			return new_tsa_entry(tsa, rel_id, isshared);
 		}
 	}
 
@@ -1589,13 +1838,7 @@ get_tabstat_entry(Oid rel_id, bool isshared)
 	else
 		pgStatTabList = tsa;
 
-	/*
-	 * Use the first entry of the new TabStatusArray.
-	 */
-	entry = &tsa->tsa_entries[tsa->tsa_used++];
-	entry->t_id = rel_id;
-	entry->t_shared = isshared;
-	return entry;
+    return new_tsa_entry(tsa, rel_id, isshared);
 }
 
 /*
@@ -4349,18 +4592,18 @@ pgstat_recv_funcstat(PgStat_MsgFuncstat *msg, int len)
 			 * If it's a new function entry, initialize counters to the values
 			 * we just got.
 			 */
-			funcentry->f_numcalls = funcmsg->f_numcalls;
-			funcentry->f_time = funcmsg->f_time;
-			funcentry->f_time_self = funcmsg->f_time_self;
+			funcentry->f_numcalls = funcmsg->f_counts.f_numcalls;
+			funcentry->f_time = funcmsg->f_counts.f_time;
+			funcentry->f_time_self = funcmsg->f_counts.f_time_self;
 		}
 		else
 		{
 			/*
 			 * Otherwise add the values to the existing entry.
 			 */
-			funcentry->f_numcalls += funcmsg->f_numcalls;
-			funcentry->f_time += funcmsg->f_time;
-			funcentry->f_time_self += funcmsg->f_time_self;
+			funcentry->f_numcalls += funcmsg->f_counts.f_numcalls;
+			INSTR_TIME_ADD(funcentry->f_time, funcmsg->f_counts.f_time);
+			INSTR_TIME_ADD(funcentry->f_time_self, funcmsg->f_counts.f_time_self);
 		}
 	}
 }
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index a07661f..b7c102f 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3783,6 +3783,11 @@ PostgresMain(int argc, char *argv[], const char *username)
 		debug_query_string = NULL;
 
 		/*
+		 * Reset the current function parent.
+		 */
+		current_function_parent = InvalidOid;
+
+		/*
 		 * Abort the current transaction in order to recover.
 		 */
 		AbortCurrentTransaction();
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index f811245..a245a31 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -438,7 +438,7 @@ pg_stat_get_function_time(PG_FUNCTION_ARGS)
 
 	if ((funcentry = pgstat_fetch_stat_funcentry(funcid)) == NULL)
 		PG_RETURN_NULL();
-	PG_RETURN_INT64(funcentry->f_time);
+	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->f_time));
 }
 
 Datum
@@ -449,7 +449,7 @@ pg_stat_get_function_self_time(PG_FUNCTION_ARGS)
 
 	if ((funcentry = pgstat_fetch_stat_funcentry(funcid)) == NULL)
 		PG_RETURN_NULL();
-	PG_RETURN_INT64(funcentry->f_time_self);
+	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->f_time_self));
 }
 
 Datum
@@ -1487,7 +1487,7 @@ pg_stat_get_xact_function_calls(PG_FUNCTION_ARGS)
 
 	if ((funcentry = find_funcstat_entry(funcid)) == NULL)
 		PG_RETURN_NULL();
-	PG_RETURN_INT64(funcentry->f_counts.f_numcalls);
+	PG_RETURN_INT64(funcentry->counts.f_numcalls);
 }
 
 Datum
@@ -1498,7 +1498,7 @@ pg_stat_get_xact_function_time(PG_FUNCTION_ARGS)
 
 	if ((funcentry = find_funcstat_entry(funcid)) == NULL)
 		PG_RETURN_NULL();
-	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->f_counts.f_time));
+	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->counts.f_time));
 }
 
 Datum
@@ -1509,7 +1509,7 @@ pg_stat_get_xact_function_self_time(PG_FUNCTION_ARGS)
 
 	if ((funcentry = find_funcstat_entry(funcid)) == NULL)
 		PG_RETURN_NULL();
-	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->f_counts.f_time_self));
+	PG_RETURN_INT64(INSTR_TIME_GET_MICROSEC(funcentry->counts.f_time_self));
 }
 
 
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 92391ed..7f1dfea 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -412,6 +412,9 @@ bool		log_statement_stats = false;		/* this is sort of all three
 												 * above together */
 bool		log_btree_build_stats = false;
 
+bool		log_usage_stats = false;
+bool		log_function_calls = false;
+
 bool		check_function_bodies = true;
 bool		default_with_oids = false;
 bool		SQL_inheritance = true;
@@ -976,6 +979,22 @@ static struct config_bool ConfigureNamesBool[] =
 		false,
 		check_log_stats, NULL, NULL
 	},
+	{
+		{"log_usage_stats", PGC_SUSET, STATS_MONITORING,
+			gettext_noop("Writes table and function access statistics to the server log."),
+			NULL
+		},
+		&log_usage_stats,
+		false, NULL, NULL
+	},
+	{
+		{"log_function_calls", PGC_SUSET, STATS_MONITORING,
+			gettext_noop("Writes top level function call stats to the server log."),
+			NULL
+		},
+		&log_function_calls,
+		false, NULL, NULL
+	},
 #ifdef BTREE_BUILD_STATS
 	{
 		{"log_btree_build_stats", PGC_SUSET, DEVELOPER_OPTIONS,
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index f04be95..1eca1f2 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -134,6 +134,10 @@ typedef struct PgStat_TableStatus
 {
 	Oid			t_id;			/* table's OID */
 	bool		t_shared;		/* is it a shared catalog? */
+	bool		t_system;		/* is it a system table? */
+	char		t_relkind;		/* table, index, ... */
+	char		*t_schema;
+	char		*t_name;
 	struct PgStat_TableXactStatus *trans;		/* lowest subxact's counts */
 	PgStat_TableCounts t_counts;	/* event counts to be sent */
 } PgStat_TableStatus;
@@ -395,13 +399,35 @@ typedef struct PgStat_FunctionCounts
 } PgStat_FunctionCounts;
 
 /* ----------
- * PgStat_BackendFunctionEntry	Entry in backend's per-function hash table
+ * PgStat_MsgFunctionEntry			Per-function info in a stat message.
  * ----------
  */
-typedef struct PgStat_BackendFunctionEntry
+typedef struct PgStat_MsgFunctionEntry
 {
 	Oid			f_id;
 	PgStat_FunctionCounts f_counts;
+} PgStat_MsgFunctionEntry;
+
+/* Hash key for the function stats */
+typedef struct FunctionStatKey
+{
+	Oid				f_id;
+	Oid				f_parent;
+} FunctionStatKey;
+
+/* ----------
+ * PgStat_BackendFunctionEntry	Entry in backend's per-function hash table
+ * ----------
+ */
+typedef struct PgStat_BackendFunctionEntry
+{
+	FunctionStatKey f_key;
+	int				f_nargs;
+	char		   *f_schema;
+	char		   *f_name;
+
+	PgStat_FunctionCounts	counts;
+
 } PgStat_BackendFunctionEntry;
 
 /* ----------
@@ -411,9 +437,7 @@ typedef struct PgStat_BackendFunctionEntry
 typedef struct PgStat_FunctionEntry
 {
 	Oid			f_id;
-	PgStat_Counter f_numcalls;
-	PgStat_Counter f_time;		/* times in microseconds */
-	PgStat_Counter f_time_self;
+	PgStat_FunctionCounts f_counts;
 } PgStat_FunctionEntry;
 
 /* ----------
@@ -566,8 +590,8 @@ typedef struct PgStat_StatFuncEntry
 
 	PgStat_Counter f_numcalls;
 
-	PgStat_Counter f_time;		/* times in microseconds */
-	PgStat_Counter f_time_self;
+	instr_time f_time;		/* times in microseconds */
+	instr_time f_time_self;
 } PgStat_StatFuncEntry;
 
 
@@ -647,9 +671,9 @@ 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;
+	PgStat_BackendFunctionEntry *fs;
+	PgStat_FunctionCounts counts;
+	PgStat_FunctionCounts save_counts;
 	/* Backend-wide total time as of function start */
 	instr_time	save_total;
 	/* system clock as of function start */
@@ -669,6 +693,11 @@ extern char *pgstat_stat_tmpname;
 extern char *pgstat_stat_filename;
 
 /*
+ * The current function call parent for dependency tracking.
+ */
+extern Oid current_function_parent;
+
+/*
  * BgWriter statistics counters are updated directly by bgwriter and bufmgr
  */
 extern PgStat_MsgBgWriter BgWriterStats;
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index ee52cd7..310ec08 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -198,6 +198,8 @@ extern bool log_planner_stats;
 extern bool log_executor_stats;
 extern bool log_statement_stats;
 extern bool log_btree_build_stats;
+extern bool log_usage_stats;
+extern bool log_function_calls;
 
 extern PGDLLIMPORT bool check_function_bodies;
 extern bool default_with_oids;
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Reply via email to