From 93c701edc6c6f065cd25f77f63ab31aff085d6ac Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Thu, 15 May 2008 00:17:41 +0000 Subject: [PATCH] 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 | 18 +- doc/src/sgml/monitoring.sgml | 56 ++- src/backend/catalog/system_views.sql | 14 +- src/backend/commands/trigger.c | 8 +- src/backend/commands/vacuum.c | 4 +- src/backend/executor/execQual.c | 26 +- src/backend/postmaster/autovacuum.c | 4 +- src/backend/postmaster/pgstat.c | 471 +++++++++++++++++- src/backend/tcop/postgres.c | 4 +- src/backend/utils/adt/pgstatfuncs.c | 41 +- src/backend/utils/fmgr/README | 12 +- src/backend/utils/fmgr/fmgr.c | 39 +- src/backend/utils/misc/guc.c | 19 +- src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/catalog/catversion.h | 4 +- src/include/catalog/pg_proc.h | 9 +- src/include/fmgr.h | 3 +- src/include/pgstat.h | 138 ++++- src/include/portability/instr_time.h | 23 +- src/test/regress/expected/rules.out | 3 +- 20 files changed, 830 insertions(+), 67 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a3fecc4934..1961d28893 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -1,4 +1,4 @@ - + Server Configuration @@ -3342,6 +3342,22 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; + + track_functions (string) + + track_functions configuration parameter + + + + Enables tracking of function call counts and time used. Specify + pl to count only procedural language functions, + all to also track SQL and C language functions. + The default is none. + Only superusers can change this setting. + + + + update_process_title (boolean) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 069bad8dc1..5018b17c59 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -1,4 +1,4 @@ - + Monitoring Database Activity @@ -119,7 +119,8 @@ postgres: user database host @@ -141,15 +142,19 @@ postgres: user database host The parameter 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. + + + + The parameter enables tracking of + usage of user-defined functions. The parameter enables monitoring of the current command being executed by any server process. - + Normally these parameters are set in postgresql.conf so that they apply to all server processes, but it is possible to turn @@ -370,6 +375,16 @@ postgres: user database host Same as pg_statio_all_sequences, except that only user sequences are shown. + + + pg_stat_user_functions + 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. + + + @@ -429,8 +444,9 @@ postgres: user database host . 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: user database host + + pg_stat_get_function_calls(oid) + bigint + + Number of times the function has been called. + + + + + pg_stat_get_function_time(oid) + bigint + + Total wall clock time spent in the function, in microseconds. Includes + the time spent in functions called by this one. + + + + + pg_stat_get_function_self_time(oid) + bigint + + Time spent in only this function. Time spent in called functions + is excluded. + + + pg_stat_get_backend_idset() setof integer diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index ad1d5272d7..d9ac50b429 100644 --- a/src/backend/catalog/system_views.sql +++ b/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, diff --git a/src/backend/commands/trigger.c b/src/backend/commands/trigger.c index 7685906aeb..76a373343d 100644 --- a/src/backend/commands/trigger.c +++ b/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); /* diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c index c5793231f2..f8b8c5b064 100644 --- a/src/backend/commands/vacuum.c +++ b/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. diff --git a/src/backend/executor/execQual.c b/src/backend/executor/execQual.c index 02267fa0d2..7761485d7c 100644 --- a/src/backend/executor/execQual.c +++ b/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 { diff --git a/src/backend/postmaster/autovacuum.c b/src/backend/postmaster/autovacuum.c index 093004f5bf..5711093d9e 100644 --- a/src/backend/postmaster/autovacuum.c +++ b/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 diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index c9720a6310..590ee8a5e3 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -13,7 +13,7 @@ * * Copyright (c) 2001-2008, PostgreSQL Global Development Group * - * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.173 2008/04/03 16:27:25 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.174 2008/05/15 00:17:40 tgl Exp $ * ---------- */ #include "postgres.h" @@ -42,6 +42,7 @@ #include "access/twophase_rmgr.h" #include "access/xact.h" #include "catalog/pg_database.h" +#include "catalog/pg_proc.h" #include "libpq/ip.h" #include "libpq/libpq.h" #include "libpq/pqsignal.h" @@ -89,6 +90,7 @@ */ #define PGSTAT_DB_HASH_SIZE 16 #define PGSTAT_TAB_HASH_SIZE 512 +#define PGSTAT_FUNCTION_HASH_SIZE 512 /* ---------- @@ -97,6 +99,7 @@ */ bool pgstat_track_activities = false; bool pgstat_track_counts = false; +int pgstat_track_functions = TRACK_FUNC_OFF; /* * BgWriter global statistics counters (unused in other processes). @@ -139,6 +142,12 @@ typedef struct TabStatusArray static TabStatusArray *pgStatTabList = NULL; +/* + * Backends store per-function info that's waiting to be sent to the collector + * in this hash table (indexed by function OID). + */ +static HTAB *pgStatFunctions = NULL; + /* * Tuple insertion/deletion counts for an open transaction can't be propagated * into PgStat_TableStatus counters until we know if it is going to commit @@ -185,6 +194,13 @@ static PgStat_GlobalStats globalStats; static volatile bool need_exit = false; static volatile bool need_statwrite = false; +/* + * Total time charged to functions so far in the current backend. + * We use this to help separate "self" and "other" time charges. + * (We assume this initializes to zero.) + */ +static instr_time total_func_time; + /* ---------- * Local function forward declarations @@ -206,6 +222,7 @@ static void backend_read_statsfile(void); 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 PgStat_TableStatus *get_tabstat_entry(Oid rel_id, bool isshared); @@ -223,6 +240,8 @@ static void pgstat_recv_autovac(PgStat_MsgAutovacStart *msg, int len); static void pgstat_recv_vacuum(PgStat_MsgVacuum *msg, int len); static void pgstat_recv_analyze(PgStat_MsgAnalyze *msg, int len); static void pgstat_recv_bgwriter(PgStat_MsgBgWriter *msg, int len); +static void pgstat_recv_funcstat(PgStat_MsgFuncstat *msg, int len); +static void pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len); /* ------------------------------------------------------------ @@ -601,16 +620,16 @@ allow_immediate_pgstat_restart(void) /* ---------- - * pgstat_report_tabstat() - + * pgstat_report_stat() - * * Called from tcop/postgres.c to send the so far collected per-table - * access statistics to the collector. Note that this is called only - * when not within a transaction, so it is fair to use transaction stop - * time as an approximation of current time. + * and function usage statistics to the collector. Note that this is + * called only when not within a transaction, so it is fair to use + * transaction stop time as an approximation of current time. * ---------- */ void -pgstat_report_tabstat(bool force) +pgstat_report_stat(bool force) { /* we assume this inits to all zeroes: */ static const PgStat_TableCounts all_zeroes; @@ -623,6 +642,7 @@ pgstat_report_tabstat(bool force) int i; /* Don't expend a clock check if nothing to do */ + /* Note: we ignore pending function stats in this test ... OK? */ if (pgStatTabList == NULL || pgStatTabList->tsa_used == 0) return; @@ -696,10 +716,13 @@ pgstat_report_tabstat(bool force) pgstat_send_tabstat(®ular_msg); if (shared_msg.m_nentries > 0) pgstat_send_tabstat(&shared_msg); + + /* Now, send function statistics */ + pgstat_send_funcstats(); } /* - * Subroutine for pgstat_report_tabstat: finish and send a tabstat message + * Subroutine for pgstat_report_stat: finish and send a tabstat message */ static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg) @@ -736,21 +759,76 @@ pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg) pgstat_send(tsmsg, len); } +/* + * Subroutine for pgstat_report_stat: populate and send a function stat message + */ +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; + + if (pgStatFunctions == NULL) + return; + + pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_FUNCSTAT); + msg.m_databaseid = MyDatabaseId; + msg.m_nentries = 0; + + hash_seq_init(&fstat, pgStatFunctions); + while ((entry = (PgStat_BackendFunctionEntry *) hash_seq_search(&fstat)) != NULL) + { + PgStat_FunctionEntry *m_ent; + + /* 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; + } + + /* reset the entry's counts */ + MemSet(&entry->f_counts, 0, sizeof(PgStat_FunctionCounts)); + } + + if (msg.m_nentries > 0) + pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) + + msg.m_nentries * sizeof(PgStat_FunctionEntry)); +} + /* ---------- - * pgstat_vacuum_tabstat() - + * pgstat_vacuum_stat() - * * Will tell the collector about objects he can get rid of. * ---------- */ void -pgstat_vacuum_tabstat(void) +pgstat_vacuum_stat(void) { HTAB *htab; PgStat_MsgTabpurge msg; + PgStat_MsgFuncpurge f_msg; HASH_SEQ_STATUS hstat; PgStat_StatDBEntry *dbentry; PgStat_StatTabEntry *tabentry; + PgStat_StatFuncEntry *funcentry; int len; if (pgStatSock < 0) @@ -855,15 +933,66 @@ pgstat_vacuum_tabstat(void) /* Clean up */ hash_destroy(htab); + + /* + * Now repeat the above steps for functions. + */ + htab = pgstat_collect_oids(ProcedureRelationId); + + pgstat_setheader(&f_msg.m_hdr, PGSTAT_MTYPE_FUNCPURGE); + f_msg.m_databaseid = MyDatabaseId; + f_msg.m_nentries = 0; + + hash_seq_init(&hstat, dbentry->functions); + while ((funcentry = (PgStat_StatFuncEntry *) hash_seq_search(&hstat)) != NULL) + { + Oid funcid = funcentry->functionid; + + CHECK_FOR_INTERRUPTS(); + + if (hash_search(htab, (void *) &funcid, HASH_FIND, NULL) != NULL) + continue; + + /* + * Not there, so add this function's Oid to the message + */ + f_msg.m_functionid[f_msg.m_nentries++] = funcid; + + /* + * If the message is full, send it out and reinitialize to empty + */ + if (f_msg.m_nentries >= PGSTAT_NUM_FUNCPURGE) + { + len = offsetof(PgStat_MsgFuncpurge, m_functionid[0]) + +f_msg.m_nentries * sizeof(Oid); + + pgstat_send(&f_msg, len); + + f_msg.m_nentries = 0; + } + } + + /* + * Send the rest + */ + if (f_msg.m_nentries > 0) + { + len = offsetof(PgStat_MsgFuncpurge, m_functionid[0]) + +f_msg.m_nentries * sizeof(Oid); + + pgstat_send(&f_msg, len); + } + + hash_destroy(htab); } /* ---------- * pgstat_collect_oids() - * - * Collect the OIDs of either all databases or all tables, according to - * the parameter, into a temporary hash table. Caller should hash_destroy - * the result when done with it. + * Collect the OIDs of all objects listed in the specified system catalog + * into a temporary hash table. Caller should hash_destroy the result + * when done with it. * ---------- */ static HTAB * @@ -906,7 +1035,7 @@ pgstat_collect_oids(Oid catalogid) * * Tell the collector that we just dropped a database. * (If the message gets lost, we will still clean the dead DB eventually - * via future invocations of pgstat_vacuum_tabstat().) + * via future invocations of pgstat_vacuum_stat().) * ---------- */ void @@ -928,10 +1057,10 @@ pgstat_drop_database(Oid databaseid) * * Tell the collector that we just dropped a relation. * (If the message gets lost, we will still clean the dead entry eventually - * via future invocations of pgstat_vacuum_tabstat().) + * via future invocations of pgstat_vacuum_stat().) * * Currently not used for lack of any good place to call it; we rely - * entirely on pgstat_vacuum_tabstat() to clean out stats for dead rels. + * entirely on pgstat_vacuum_stat() to clean out stats for dead rels. * ---------- */ #ifdef NOT_USED @@ -1100,6 +1229,107 @@ pgstat_ping(void) pgstat_send(&msg, sizeof(msg)); } +/* + * Initialize function call usage data. + * Called by the executor before invoking a function. + */ +void +pgstat_init_function_usage(FunctionCallInfoData *fcinfo, + PgStat_FunctionCallUsage *fcu) +{ + PgStat_BackendFunctionEntry *htabent; + bool found; + + if (pgstat_track_functions <= fcinfo->flinfo->fn_stats) + { + /* stats not wanted */ + fcu->fs = NULL; + return; + } + + 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.entrysize = sizeof(PgStat_BackendFunctionEntry); + hash_ctl.hash = oid_hash; + pgStatFunctions = hash_create("Function stat entries", + PGSTAT_FUNCTION_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION); + } + + /* Get the stats entry for this function, create if necessary */ + htabent = hash_search(pgStatFunctions, &fcinfo->flinfo->fn_oid, + HASH_ENTER, &found); + if (!found) + MemSet(&htabent->f_counts, 0, sizeof(PgStat_FunctionCounts)); + + fcu->fs = &htabent->f_counts; + + /* save stats for this function, later used to compensate for recursion */ + fcu->save_f_time = htabent->f_counts.f_time; + + /* 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); +} + +/* + * Calculate function call usage and update stat counters. + * Called by the executor after invoking a function. + * + * In the case of a set-returning function that runs in value-per-call mode, + * we will see multiple pgstat_init_function_usage/pgstat_end_function_usage + * calls for what the user considers a single call of the function. The + * finalize flag should be TRUE on the last call. + */ +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) + return; + + /* total elapsed time in this function call */ + INSTR_TIME_SET_CURRENT(f_total); + INSTR_TIME_SUBTRACT(f_total, fcu->f_start); + + /* self usage: elapsed minus anything already charged to other calls */ + f_others = total_func_time; + INSTR_TIME_SUBTRACT(f_others, fcu->save_total); + f_self = f_total; + INSTR_TIME_SUBTRACT(f_self, f_others); + + /* update backend-wide total time */ + INSTR_TIME_ADD(total_func_time, f_self); + + /* + * Compute the new total f_time as the total elapsed time added to the + * pre-call value of f_time. This is necessary to avoid double-counting + * any time taken by recursive calls of myself. (We do not need any + * similar kluge for self time, since that already excludes any + * recursive calls.) + */ + INSTR_TIME_ADD(f_total, fcu->save_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); +} + /* ---------- * pgstat_initstats() - @@ -1689,6 +1919,35 @@ pgstat_fetch_stat_tabentry(Oid relid) } +/* ---------- + * pgstat_fetch_stat_funcentry() - + * + * Support function for the SQL-callable pgstat* functions. Returns + * the collected statistics for one function or NULL. + * ---------- + */ +PgStat_StatFuncEntry * +pgstat_fetch_stat_funcentry(Oid func_id) +{ + PgStat_StatDBEntry *dbentry; + PgStat_StatFuncEntry *funcentry = NULL; + + /* load the stats file if needed */ + backend_read_statsfile(); + + /* Lookup our database, then find the requested function. */ + dbentry = pgstat_fetch_stat_dbentry(MyDatabaseId); + if (dbentry != NULL && dbentry->functions != NULL) + { + funcentry = (PgStat_StatFuncEntry *) hash_search(dbentry->functions, + (void *) &func_id, + HASH_FIND, NULL); + } + + return funcentry; +} + + /* ---------- * pgstat_fetch_stat_beentry() - * @@ -1888,7 +2147,7 @@ pgstat_beshutdown_hook(int code, Datum arg) { volatile PgBackendStatus *beentry = MyBEEntry; - pgstat_report_tabstat(true); + pgstat_report_stat(true); /* * Clear my status entry, following the protocol of bumping st_changecount @@ -2469,6 +2728,14 @@ PgstatCollectorMain(int argc, char *argv[]) pgstat_recv_bgwriter((PgStat_MsgBgWriter *) &msg, len); break; + case PGSTAT_MTYPE_FUNCSTAT: + pgstat_recv_funcstat((PgStat_MsgFuncstat *) &msg, len); + break; + + case PGSTAT_MTYPE_FUNCPURGE: + pgstat_recv_funcpurge((PgStat_MsgFuncpurge *) &msg, len); + break; + default: break; } @@ -2547,6 +2814,7 @@ pgstat_get_db_entry(Oid databaseid, bool create) HASHCTL hash_ctl; result->tables = NULL; + result->functions = NULL; result->n_xact_commit = 0; result->n_xact_rollback = 0; result->n_blocks_fetched = 0; @@ -2566,6 +2834,14 @@ pgstat_get_db_entry(Oid databaseid, bool create) PGSTAT_TAB_HASH_SIZE, &hash_ctl, HASH_ELEM | HASH_FUNCTION); + + hash_ctl.keysize = sizeof(Oid); + hash_ctl.entrysize = sizeof(PgStat_StatFuncEntry); + hash_ctl.hash = oid_hash; + result->functions = hash_create("Per-database function", + PGSTAT_FUNCTION_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION); } return result; @@ -2583,8 +2859,10 @@ pgstat_write_statsfile(void) { HASH_SEQ_STATUS hstat; HASH_SEQ_STATUS tstat; + HASH_SEQ_STATUS fstat; PgStat_StatDBEntry *dbentry; PgStat_StatTabEntry *tabentry; + PgStat_StatFuncEntry *funcentry; FILE *fpout; int32 format_id; @@ -2620,8 +2898,8 @@ pgstat_write_statsfile(void) { /* * Write out the DB entry including the number of live backends. We - * don't write the tables pointer since it's of no use to any other - * process. + * don't write the tables or functions pointers, since they're of + * no use to any other process. */ fputc('D', fpout); fwrite(dbentry, offsetof(PgStat_StatDBEntry, tables), 1, fpout); @@ -2636,6 +2914,16 @@ pgstat_write_statsfile(void) fwrite(tabentry, sizeof(PgStat_StatTabEntry), 1, fpout); } + /* + * Walk through the database's function stats table. + */ + hash_seq_init(&fstat, dbentry->functions); + while ((funcentry = (PgStat_StatFuncEntry *) hash_seq_search(&fstat)) != NULL) + { + fputc('F', fpout); + fwrite(funcentry, sizeof(PgStat_StatFuncEntry), 1, fpout); + } + /* * Mark the end of this DB */ @@ -2691,9 +2979,12 @@ pgstat_read_statsfile(Oid onlydb) PgStat_StatDBEntry dbbuf; PgStat_StatTabEntry *tabentry; PgStat_StatTabEntry tabbuf; + PgStat_StatFuncEntry funcbuf; + PgStat_StatFuncEntry *funcentry; HASHCTL hash_ctl; HTAB *dbhash; HTAB *tabhash = NULL; + HTAB *funchash = NULL; FILE *fpin; int32 format_id; bool found; @@ -2759,8 +3050,8 @@ pgstat_read_statsfile(Oid onlydb) { /* * 'D' A PgStat_StatDBEntry struct describing a database - * follows. Subsequently, zero to many 'T' entries will follow - * until a 'd' is encountered. + * follows. Subsequently, zero to many 'T' and 'F' entries + * will follow until a 'd' is encountered. */ case 'D': if (fread(&dbbuf, 1, offsetof(PgStat_StatDBEntry, tables), @@ -2787,6 +3078,7 @@ pgstat_read_statsfile(Oid onlydb) memcpy(dbentry, &dbbuf, sizeof(PgStat_StatDBEntry)); dbentry->tables = NULL; + dbentry->functions = NULL; /* * Don't collect tables if not the requested DB (or the @@ -2809,11 +3101,20 @@ pgstat_read_statsfile(Oid onlydb) &hash_ctl, HASH_ELEM | HASH_FUNCTION | HASH_CONTEXT); + hash_ctl.keysize = sizeof(Oid); + hash_ctl.entrysize = sizeof(PgStat_StatFuncEntry); + hash_ctl.hash = oid_hash; + hash_ctl.hcxt = pgStatLocalContext; + dbentry->functions = hash_create("Per-database function", + PGSTAT_FUNCTION_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION | HASH_CONTEXT); /* - * Arrange that following 'T's add entries to this database's - * tables hash table. + * Arrange that following records add entries to this + * database's hash tables. */ tabhash = dbentry->tables; + funchash = dbentry->functions; break; /* @@ -2821,6 +3122,7 @@ pgstat_read_statsfile(Oid onlydb) */ case 'd': tabhash = NULL; + funchash = NULL; break; /* @@ -2855,6 +3157,38 @@ pgstat_read_statsfile(Oid onlydb) memcpy(tabentry, &tabbuf, sizeof(tabbuf)); break; + /* + * 'F' A PgStat_StatFuncEntry follows. + */ + case 'F': + if (fread(&funcbuf, 1, sizeof(PgStat_StatFuncEntry), + fpin) != sizeof(PgStat_StatFuncEntry)) + { + ereport(pgStatRunningInCollector ? LOG : WARNING, + (errmsg("corrupted pgstat.stat file"))); + goto done; + } + + /* + * Skip if function belongs to a not requested database. + */ + if (funchash == NULL) + break; + + funcentry = (PgStat_StatFuncEntry *) hash_search(funchash, + (void *) &funcbuf.functionid, + HASH_ENTER, &found); + + if (found) + { + ereport(pgStatRunningInCollector ? LOG : WARNING, + (errmsg("corrupted pgstat.stat file"))); + goto done; + } + + memcpy(funcentry, &funcbuf, sizeof(funcbuf)); + break; + /* * 'E' The EOF marker of a complete stats file. */ @@ -3087,6 +3421,8 @@ pgstat_recv_dropdb(PgStat_MsgDropdb *msg, int len) { if (dbentry->tables != NULL) hash_destroy(dbentry->tables); + if (dbentry->functions != NULL) + hash_destroy(dbentry->functions); if (hash_search(pgStatDBHash, (void *) &(dbentry->databaseid), @@ -3124,8 +3460,11 @@ pgstat_recv_resetcounter(PgStat_MsgResetcounter *msg, int len) */ if (dbentry->tables != NULL) hash_destroy(dbentry->tables); + if (dbentry->functions != NULL) + hash_destroy(dbentry->functions); dbentry->tables = NULL; + dbentry->functions = NULL; dbentry->n_xact_commit = 0; dbentry->n_xact_rollback = 0; dbentry->n_blocks_fetched = 0; @@ -3139,6 +3478,14 @@ pgstat_recv_resetcounter(PgStat_MsgResetcounter *msg, int len) PGSTAT_TAB_HASH_SIZE, &hash_ctl, HASH_ELEM | HASH_FUNCTION); + + hash_ctl.keysize = sizeof(Oid); + hash_ctl.entrysize = sizeof(PgStat_StatFuncEntry); + hash_ctl.hash = oid_hash; + dbentry->functions = hash_create("Per-database function", + PGSTAT_FUNCTION_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION); } /* ---------- @@ -3271,3 +3618,83 @@ pgstat_recv_bgwriter(PgStat_MsgBgWriter *msg, int len) globalStats.buf_written_backend += msg->m_buf_written_backend; globalStats.buf_alloc += msg->m_buf_alloc; } + +/* ---------- + * pgstat_recv_funcstat() - + * + * Count what the backend has done. + * ---------- + */ +static void +pgstat_recv_funcstat(PgStat_MsgFuncstat *msg, int len) +{ + PgStat_FunctionEntry *funcmsg = &(msg->m_entry[0]); + PgStat_StatDBEntry *dbentry; + PgStat_StatFuncEntry *funcentry; + int i; + bool found; + + dbentry = pgstat_get_db_entry(msg->m_databaseid, true); + + /* + * Process all function entries in the message. + */ + for (i = 0; i < msg->m_nentries; i++, funcmsg++) + { + funcentry = (PgStat_StatFuncEntry *) hash_search(dbentry->functions, + (void *) &(funcmsg->f_id), + HASH_ENTER, &found); + + if (!found) + { + /* + * 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; + } + 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; + } + } +} + +/* ---------- + * pgstat_recv_funcpurge() - + * + * Arrange for dead function removal. + * ---------- + */ +static void +pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len) +{ + PgStat_StatDBEntry *dbentry; + int i; + + dbentry = pgstat_get_db_entry(msg->m_databaseid, false); + + /* + * No need to purge if we don't even know the database. + */ + if (!dbentry || !dbentry->functions) + return; + + /* + * Process all function entries in the message. + */ + for (i = 0; i < msg->m_nentries; i++) + { + /* Remove from hashtable if present; we don't care if it's not. */ + (void) hash_search(dbentry->functions, + (void *) &(msg->m_functionid[i]), + HASH_REMOVE, NULL); + } +} diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index d212eb9449..c6d6e1b55d 100644 --- a/src/backend/tcop/postgres.c +++ b/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(""); diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 0750041ce5..3e0877c7a4 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/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) { @@ -401,7 +438,7 @@ pg_stat_get_activity(PG_FUNCTION_ARGS) } else { - /* + /* * Get one backend - locate by pid. * * We lookup the backend early, so we can return zero rows if it doesn't diff --git a/src/backend/utils/fmgr/README b/src/backend/utils/fmgr/README index 730830a84c..7cdb69418c 100644 --- a/src/backend/utils/fmgr/README +++ b/src/backend/utils/fmgr/README @@ -1,4 +1,4 @@ -$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. diff --git a/src/backend/utils/fmgr/fmgr.c b/src/backend/utils/fmgr/fmgr.c index 8398305519..481278703a 100644 --- a/src/backend/utils/fmgr/fmgr.c +++ b/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(); { @@ -2089,7 +2118,7 @@ float4 DatumGetFloat4(Datum X) { union { - int32 value; + int32 value; float4 retval; } myunion; diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index c4b07aad2a..f4466ddb14 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -10,7 +10,7 @@ * Written by Peter Eisentraut . * * 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."), diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index ce78453083..fdc6f39fc2 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/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 diff --git a/src/include/catalog/catversion.h b/src/include/catalog/catversion.h index fcc9c6c234..e0bd027fda 100644 --- a/src/include/catalog/catversion.h +++ b/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 diff --git a/src/include/catalog/pg_proc.h b/src/include/catalog/pg_proc.h index 685b77aca3..cc1d5db786 100644 --- a/src/include/catalog/pg_proc.h +++ b/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_ )); diff --git a/src/include/fmgr.h b/src/include/fmgr.h index ec3261b081..f0cc26f531 100644 --- a/src/include/fmgr.h +++ b/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 */ diff --git a/src/include/pgstat.h b/src/include/pgstat.h index fc0173c6f3..3cda489b35 100644 --- a/src/include/pgstat.h +++ b/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); diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h index 666d495f20..7f4a0923b6 100644 --- a/src/include/portability/instr_time.h +++ b/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) diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index f6b9405e43..99f240f1f0 100644 --- a/src/test/regress/expected/rules.out +++ b/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; -- 2.40.0