Thread: stored procedure stats in collector
Attached is a patch that enables tracking function calls through the stats subsystem. Original discussion: http://archives.postgresql.org/pgsql-hackers/2007-07/msg00377.php Introduces new guc variable - track_functions. Possible values are: none - no collection, default pl - tracks procedural language functions all - tracks procedural, SQL and C (not internal) functions The results are visible from pg_stat_get_function_* functions and pg_stat_user_functions view. regards, Martin *** ./doc/src/sgml/config.sgml.orig 2008-03-22 20:15:30.000000000 +0200 --- ./doc/src/sgml/config.sgml 2008-03-23 15:00:27.000000000 +0200 *************** *** 3322,3327 **** --- 3322,3343 ---- </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 time and cpu usage of stored procedures. 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.orig 2008-03-23 13:20:25.000000000 +0200 --- ./doc/src/sgml/monitoring.sgml 2008-03-23 14:55:28.000000000 +0200 *************** *** 151,156 **** --- 151,161 ---- </para> <para> + The parameter <xref linkend="guc-track-functions"> enables tracking of + stored procedure usage. + </para> + + <para> Normally these parameters are set in <filename>postgresql.conf</> so that they apply to all server processes, but it is possible to turn them on or off in individual sessions using the <xref *************** *** 370,375 **** --- 375,390 ---- <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 called functions, function OID, schema, name, number + of calls, total time, total cpu, self time and cpu. Self time is the + amount of time spent in the function itself, total time includes the + time spent in child functions. Time values in milliseconds. + </entry> + </row> + </tbody> </tgroup> </table> *************** *** 655,660 **** --- 670,733 ---- </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_rtime</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 by child functions. + </entry> + </row> + + <row> + <entry><literal><function>pg_stat_get_function_stime</function>(<type>oid</type>)</literal></entry> + <entry><type>bigint</type></entry> + <entry> + Total system mode CPU time spent in the function. + </entry> + </row> + + <row> + <entry><literal><function>pg_stat_get_function_utime</function>(<type>oid</type>)</literal></entry> + <entry><type>bigint</type></entry> + <entry> + Total user mode CPU time spent in the function. + </entry> + </row> + + <row> + <entry><literal><function>pg_stat_get_function_self_rtime</function>(<type>oid</type>)</literal></entry> + <entry><type>bigint</type></entry> + <entry> + Time spent by only this function. Time spent in child functions + is excluded. + </entry> + </row> + + <row> + <entry><literal><function>pg_stat_get_function_self_stime</function>(<type>oid</type>)</literal></entry> + <entry><type>bigint</type></entry> + <entry> + System mode CPU spent by this function. + </entry> + </row> + + <row> + <entry><literal><function>pg_stat_get_function_self_utime</function>(<type>oid</type>)</literal></entry> + <entry><type>bigint</type></entry> + <entry> + User mode CPU spent by this function. + </entry> + </row> + + <row> <entry><literal><function>pg_stat_get_backend_idset</function>()</literal></entry> <entry><type>setof integer</type></entry> <entry> *** ./src/backend/catalog/system_views.sql.orig 2008-03-20 10:13:23.000000000 +0200 --- ./src/backend/catalog/system_views.sql 2008-03-22 16:27:38.000000000 +0200 *************** *** 376,381 **** --- 376,395 ---- pg_stat_get_db_tuples_deleted(D.oid) AS tup_deleted FROM pg_database D; + CREATE OR REPLACE 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_rtime(P.oid)/1000 AS total_time, + (pg_stat_get_function_utime(P.oid) + pg_stat_get_function_stime(P.oid)) /1000 AS total_cpu, + pg_stat_get_function_self_rtime(P.oid)/1000 AS self_time, + (pg_stat_get_function_self_utime(P.oid) + pg_stat_get_function_self_stime(P.oid)) /1000 AS self_cpu + FROM pg_proc P LEFT JOIN pg_namespace N ON (N.oid = P.pronamespace) + WHERE + 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.orig 2008-03-20 10:15:41.000000000 +0200 --- ./src/backend/commands/trigger.c 2008-03-23 18:42:39.000000000 +0200 *************** *** 13,18 **** --- 13,19 ---- */ #include "postgres.h" + #include "pgstat.h" #include "access/genam.h" #include "access/heapam.h" #include "access/xact.h" *************** *** 1541,1546 **** --- 1542,1548 ---- MemoryContext per_tuple_context) { FunctionCallInfoData fcinfo; + PgStat_FunctionCallUsage fcusage; Datum result; MemoryContext oldContext; *************** *** 1574,1580 **** --- 1576,1584 ---- */ InitFunctionCallInfoData(fcinfo, finfo, 0, (Node *) trigdata, NULL); + pgstat_init_function_usage(&fcinfo, &fcusage); result = FunctionCallInvoke(&fcinfo); + pgstat_update_function_usage(&fcusage, TRUE); MemoryContextSwitchTo(oldContext); *** ./src/backend/commands/vacuum.c.orig 2008-03-21 19:26:48.000000000 +0200 --- ./src/backend/commands/vacuum.c 2008-03-22 11:21:08.000000000 +0200 *************** *** 319,325 **** * in autovacuum --- autovacuum.c does this for itself. */ if (vacstmt->vacuum && !IsAutoVacuumWorkerProcess()) ! pgstat_vacuum_tabstat(); /* * Create special memory context for cross-transaction storage. --- 319,325 ---- * in autovacuum --- autovacuum.c does this for itself. */ if (vacstmt->vacuum && !IsAutoVacuumWorkerProcess()) ! pgstat_vacuum_stat(); /* * Create special memory context for cross-transaction storage. *** ./src/backend/executor/execQual.c.orig 2008-03-20 10:18:39.000000000 +0200 --- ./src/backend/executor/execQual.c 2008-03-23 18:43:00.000000000 +0200 *************** *** 36,41 **** --- 36,42 ---- #include "postgres.h" + #include "pgstat.h" #include "access/heapam.h" #include "access/nbtree.h" #include "catalog/pg_type.h" *************** *** 1148,1153 **** --- 1149,1155 ---- List *arguments = fcache->args; Datum result; FunctionCallInfoData fcinfo; + PgStat_FunctionCallUsage fcusage; ReturnSetInfo rsinfo; /* for functions returning sets */ ExprDoneCond argDone; bool hasSetArg; *************** *** 1206,1211 **** --- 1208,1215 ---- rsinfo.setDesc = NULL; } + pgstat_init_function_usage(&fcinfo, &fcusage); + /* * now return the value gotten by calling the function manager, passing * the function the evaluated parameter values. *************** *** 1316,1321 **** --- 1320,1326 ---- * argument. */ } + pgstat_update_function_usage(&fcusage, *isDone == ExprEndResult); } else { *************** *** 1350,1355 **** --- 1355,1361 ---- fcinfo.isnull = false; result = FunctionCallInvoke(&fcinfo); *isNull = fcinfo.isnull; + pgstat_update_function_usage(&fcusage, TRUE); } return result; *************** *** 1370,1375 **** --- 1376,1382 ---- ListCell *arg; Datum result; FunctionCallInfoData fcinfo; + PgStat_FunctionCallUsage fcusage; int i; /* Guard against stack overflow due to overly complex expressions */ *************** *** 1392,1397 **** --- 1399,1405 ---- } InitFunctionCallInfoData(fcinfo, &(fcache->func), i, NULL, NULL); + pgstat_init_function_usage(&fcinfo, &fcusage); /* * If function is strict, and there are any NULL arguments, skip calling *************** *** 1412,1417 **** --- 1420,1427 ---- result = FunctionCallInvoke(&fcinfo); *isNull = fcinfo.isnull; + pgstat_update_function_usage(&fcusage, TRUE); + return result; } *************** *** 1435,1440 **** --- 1445,1451 ---- bool returnsTuple; bool returnsSet = false; FunctionCallInfoData fcinfo; + PgStat_FunctionCallUsage fcusage; ReturnSetInfo rsinfo; HeapTupleData tmptup; MemoryContext callerContext; *************** *** 1535,1540 **** --- 1546,1553 ---- direct_function_call = false; } + pgstat_init_function_usage(&fcinfo, &fcusage); + /* * Switch to short-lived context for calling the function or expression. */ *************** *** 1685,1690 **** --- 1698,1705 ---- first_time = false; } + pgstat_update_function_usage(&fcusage, TRUE); + no_function_result: /* *** ./src/backend/postmaster/autovacuum.c.orig 2008-03-21 19:26:40.000000000 +0200 --- ./src/backend/postmaster/autovacuum.c 2008-03-22 11:21:24.000000000 +0200 *************** *** 1855,1861 **** * want to do this exactly once per DB-processing cycle, even if we find * nothing worth vacuuming in the database. */ ! pgstat_vacuum_tabstat(); /* * Find the pg_database entry and select the default freeze_min_age. We --- 1855,1861 ---- * want to do this exactly once per DB-processing cycle, even if we find * nothing worth vacuuming in the database. */ ! pgstat_vacuum_stat(); /* * Find the pg_database entry and select the default freeze_min_age. We *** ./src/backend/postmaster/pgstat.c.orig 2008-03-20 10:29:52.000000000 +0200 --- ./src/backend/postmaster/pgstat.c 2008-03-23 18:43:33.000000000 +0200 *************** *** 42,47 **** --- 42,48 ---- #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" *************** *** 88,93 **** --- 89,95 ---- */ #define PGSTAT_DB_HASH_SIZE 16 #define PGSTAT_TAB_HASH_SIZE 512 + #define PGSTAT_FUNCTION_HASH_SIZE 512 /* ---------- *************** *** 96,101 **** --- 98,104 ---- */ bool pgstat_track_activities = false; bool pgstat_track_counts = false; + int pgstat_track_functions = 0; /* * BgWriter global statistics counters (unused in other processes). *************** *** 138,143 **** --- 141,150 ---- static TabStatusArray *pgStatTabList = NULL; + /* Function stat entries */ + 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 *************** *** 184,189 **** --- 191,200 ---- static volatile bool need_exit = false; static volatile bool need_statwrite = false; + /* Helper variables for function self time calculations. */ + static uint64 total_stime = 0; + static uint64 total_utime = 0; + static uint64 total_rtime = 0; /* ---------- * Local function forward declarations *************** *** 205,210 **** --- 216,222 ---- 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); *************** *** 216,221 **** --- 228,235 ---- static void pgstat_recv_tabstat(PgStat_MsgTabstat *msg, int len); static void pgstat_recv_tabpurge(PgStat_MsgTabpurge *msg, int len); + static void pgstat_recv_funcstat(PgStat_MsgFuncstat *msg, int len); + static void pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len); static void pgstat_recv_dropdb(PgStat_MsgDropdb *msg, int len); static void pgstat_recv_resetcounter(PgStat_MsgResetcounter *msg, int len); static void pgstat_recv_autovac(PgStat_MsgAutovacStart *msg, int len); *************** *** 600,615 **** /* ---------- ! * pgstat_report_tabstat() - * * 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. * ---------- */ void ! pgstat_report_tabstat(bool force) { /* we assume this inits to all zeroes: */ static const PgStat_TableCounts all_zeroes; --- 614,629 ---- /* ---------- ! * pgstat_report_stat() - * * Called from tcop/postgres.c to send the so far collected per-table ! * and function 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. * ---------- */ void ! pgstat_report_stat(bool force) { /* we assume this inits to all zeroes: */ static const PgStat_TableCounts all_zeroes; *************** *** 695,704 **** pgstat_send_tabstat(®ular_msg); if (shared_msg.m_nentries > 0) pgstat_send_tabstat(&shared_msg); } /* ! * Subroutine for pgstat_report_tabstat: finish and send a tabstat message */ static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg) --- 709,721 ---- pgstat_send_tabstat(®ular_msg); if (shared_msg.m_nentries > 0) pgstat_send_tabstat(&shared_msg); + + /* Now, send the functions */ + pgstat_send_funcstats(); } /* ! * Subroutine for pgstat_report_stat: finish and send a tabstat message */ static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg) *************** *** 735,755 **** pgstat_send(tsmsg, len); } /* ---------- ! * pgstat_vacuum_tabstat() - * * Will tell the collector about objects he can get rid of. * ---------- */ void ! pgstat_vacuum_tabstat(void) { HTAB *htab; PgStat_MsgTabpurge msg; HASH_SEQ_STATUS hstat; PgStat_StatDBEntry *dbentry; PgStat_StatTabEntry *tabentry; int len; if (pgStatSock < 0) --- 752,812 ---- pgstat_send(tsmsg, len); } + /* + * Subroutine for pgstat_report_stat: populate and send a function stat message. + */ + void + pgstat_send_funcstats(void) + { + PgStat_MsgFuncstat msg; + PgStat_FunctionEntry *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_FunctionEntry *)hash_seq_search(&fstat)) != NULL) + { + msg.m_entry[msg.m_nentries] = *entry; + + /* clear the entry, but retain Oid */ + memset(entry, 0, sizeof(PgStat_FunctionEntry)); + entry->f_id = msg.m_entry[msg.m_nentries].f_id; + + 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; + } + } + + if (msg.m_nentries > 0) + pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) + + msg.m_nentries * sizeof(PgStat_FunctionEntry)); + } /* ---------- ! * pgstat_vacuum_stat() - * * Will tell the collector about objects he can get rid of. * ---------- */ 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) *************** *** 854,861 **** /* Clean up */ hash_destroy(htab); - } /* ---------- * pgstat_collect_oids() - --- 911,965 ---- /* Clean up */ hash_destroy(htab); + /* + * Done with the tables, now repeat the above steps for functions. + */ + htab = pgstat_collect_oids(ProcedureRelationId); + + pgstat_setheader(&f_msg.m_hdr, PGSTAT_MTYPE_FUNCPURGE); + f_msg.m_nentries = 0; + f_msg.m_databaseid = MyDatabaseId; + + /* + * Check for all functions listed in stats hashtable if they still exist. + */ + 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) + /* still exists, move on */ + continue; + + 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_TABPURGE) + { + len = offsetof(PgStat_MsgFuncpurge, m_functionid[0]) + +f_msg.m_nentries * sizeof(Oid); + + pgstat_send(&f_msg, len); + f_msg.m_nentries = 0; + } + } + + 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() - *************** *** 905,911 **** * * 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().) * ---------- */ void --- 1009,1015 ---- * * 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_stat().) * ---------- */ void *************** *** 927,936 **** * * 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().) * * 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. * ---------- */ #ifdef NOT_USED --- 1031,1040 ---- * * 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_stat().) * * Currently not used for lack of any good place to call it; we rely ! * entirely on pgstat_vacuum_stat() to clean out stats for dead rels. * ---------- */ #ifdef NOT_USED *************** *** 1073,1078 **** --- 1177,1294 ---- pgstat_send(&msg, sizeof(msg)); } + /* + * Initialize function call usage structures. Called by the executor before + * invoking a function. + */ + void + pgstat_init_function_usage(FunctionCallInfoData *fcinfo, PgStat_FunctionCallUsage *fcu) + { + HASHCTL hash_ctl; + bool found; + + fcu->fn_oid = InvalidOid; + + if (!pgstat_track_functions || !fcinfo->flinfo) { + /* We are not collecting or we don't have oid of the function (got rewritten?)*/ + return; + } + + if (!fcinfo->flinfo->fn_stats) { + /* stats not needed */ + return; + } + + gettimeofday(&fcu->t_start, NULL); + getrusage(RUSAGE_SELF, &fcu->r_start); + fcu->rtime_us = fcu->self_rtime = 0; + fcu->utime_us = fcu->self_utime = 0; + fcu->stime_us = fcu->self_stime = 0; + fcu->fn_oid = fcinfo->flinfo->fn_oid; + + if (!pgStatFunctions) { + /* First time - initialize function stat table */ + memset(&hash_ctl, 0, sizeof(hash_ctl)); + hash_ctl.keysize = sizeof(Oid); + hash_ctl.entrysize = sizeof(PgStat_FunctionEntry); + 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 */ + fcu->fs = hash_search(pgStatFunctions, &fcu->fn_oid, HASH_ENTER, &found); + if (!found) { + memset(fcu->fs, 0, sizeof(PgStat_FunctionEntry)); + fcu->fs->f_id = fcu->fn_oid; + } + + /* save stats for this function, later used to compensate for recursion */ + fcu->save_fs = *fcu->fs; + + /* save totals for 'self' calculation */ + fcu->save_stime = total_stime; + fcu->save_utime = total_utime; + fcu->save_rtime = total_rtime; + } + + /* + * Calculate function call usage and update stat counters. Called by the + * executor when its done with the function. Might be called several times + * by set returning functions, last invocation should then have finalize + * set to TRUE. + */ + void + pgstat_update_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize) + { + struct timeval t1; + struct rusage r1; + + if (!pgstat_track_functions || fcu->fn_oid == InvalidOid) + return; + + getrusage(RUSAGE_SELF, &r1); + gettimeofday(&t1, NULL); + + /* total elapsed */ + fcu->utime_us += r1.ru_utime.tv_sec*1000000 + r1.ru_utime.tv_usec - + (fcu->r_start.ru_utime.tv_sec*1000000 + fcu->r_start.ru_utime.tv_usec); + fcu->stime_us += r1.ru_stime.tv_sec*1000000 + r1.ru_stime.tv_usec - + (fcu->r_start.ru_stime.tv_sec*1000000 + fcu->r_start.ru_stime.tv_usec); + fcu->rtime_us += t1.tv_sec*1000000 + t1.tv_usec - + (fcu->t_start.tv_sec*1000000 + fcu->t_start.tv_usec); + + /* extract self usage */ + fcu->self_stime = (fcu->save_stime + fcu->stime_us) - total_stime; + fcu->self_utime = (fcu->save_utime + fcu->utime_us) - total_utime; + fcu->self_rtime = (fcu->save_rtime + fcu->rtime_us) - total_rtime; + + /* subtract recursive calls of myself */ + fcu->utime_us -= fcu->fs->f_utime - fcu->save_fs.f_utime; + fcu->stime_us -= fcu->fs->f_stime - fcu->save_fs.f_stime; + fcu->rtime_us -= fcu->fs->f_rtime - fcu->save_fs.f_rtime; + + elog(DEBUG5, "pgstat_update_function_usage: rtime start=%llu end=%llu\n", fcu->save_fs.f_rtime, fcu->fs->f_rtime); + + total_stime += fcu->self_stime; + total_utime += fcu->self_utime; + total_rtime += fcu->self_rtime; + + if (finalize) + pgstat_count_function_calls(fcu->fs); + + /* update the calculated values in function stats table */ + pgstat_count_function_rtime(fcu->fs, fcu->rtime_us, fcu->self_rtime); + pgstat_count_function_utime(fcu->fs, fcu->utime_us, fcu->self_utime); + pgstat_count_function_stime(fcu->fs, fcu->stime_us, fcu->self_stime); + + elog(DEBUG5, "pgstat_update_function_usage %u %s: real=%llu user=%llu sys=%llu us [self %llu %llu %llu us]", + fcu->fn_oid, finalize ? "final" : "contemporary", + fcu->rtime_us, fcu->utime_us, fcu->stime_us, + fcu->self_rtime, fcu->self_utime, fcu->self_stime); + } /* ---------- * pgstat_initstats() - *************** *** 1661,1666 **** --- 1877,1909 ---- return NULL; } + /* ---------- + * 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() - *************** *** 1861,1867 **** { volatile PgBackendStatus *beentry = MyBEEntry; ! pgstat_report_tabstat(true); /* * Clear my status entry, following the protocol of bumping st_changecount --- 2104,2110 ---- { volatile PgBackendStatus *beentry = MyBEEntry; ! pgstat_report_stat(true); /* * Clear my status entry, following the protocol of bumping st_changecount *************** *** 2343,2348 **** --- 2586,2599 ---- pgstat_recv_tabpurge((PgStat_MsgTabpurge *) &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; + case PGSTAT_MTYPE_DROPDB: pgstat_recv_dropdb((PgStat_MsgDropdb *) &msg, len); break; *************** *** 2446,2451 **** --- 2697,2703 ---- HASHCTL hash_ctl; result->tables = NULL; + result->functions = NULL; result->n_xact_commit = 0; result->n_xact_rollback = 0; result->n_blocks_fetched = 0; *************** *** 2465,2470 **** --- 2717,2728 ---- PGSTAT_TAB_HASH_SIZE, &hash_ctl, HASH_ELEM | HASH_FUNCTION); + + hash_ctl.entrysize = sizeof(PgStat_FunctionEntry); + result->functions = hash_create("Per-database function", + PGSTAT_TAB_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION); } return result; *************** *** 2482,2489 **** --- 2740,2749 ---- { 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; *************** *** 2536,2541 **** --- 2796,2814 ---- } /* + * Walk through the database's function stats table. + */ + hash_seq_init(&fstat, dbentry->functions); + while ((funcentry = (PgStat_StatFuncEntry *) hash_seq_search(&fstat)) != NULL) + { + if (funcentry->numcalls > 0) + { + fputc('F', fpout); + fwrite(funcentry, sizeof(PgStat_StatFuncEntry), 1, fpout); + } + } + + /* * Mark the end of this DB */ fputc('d', fpout); *************** *** 2590,2598 **** --- 2863,2874 ---- 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; *************** *** 2686,2691 **** --- 2962,2968 ---- memcpy(dbentry, &dbbuf, sizeof(PgStat_StatDBEntry)); dbentry->tables = NULL; + dbentry->functions = NULL; /* * Don't collect tables if not the requested DB (or the *************** *** 2708,2718 **** --- 2985,3001 ---- &hash_ctl, HASH_ELEM | HASH_FUNCTION | HASH_CONTEXT); + hash_ctl.entrysize = sizeof(PgStat_FunctionEntry); + 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. */ tabhash = dbentry->tables; + funchash = dbentry->functions; break; /* *************** *** 2720,2725 **** --- 3003,3009 ---- */ case 'd': tabhash = NULL; + funchash = NULL; break; /* *************** *** 2755,2760 **** --- 3039,3076 ---- break; /* + * 'F' A PgStat_FunctionEntry 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 table 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. */ case 'E': *************** *** 2962,2967 **** --- 3278,3367 ---- } } + /* ---------- + * 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++) + { + funcentry = (PgStat_StatFuncEntry *) hash_search(dbentry->functions, + (void *) &(funcmsg[i].f_id), + HASH_ENTER, &found); + + if (!found) + { + /* + * If it's a new function entry, initialize counters to the values we + * just got. + */ + funcentry->numcalls = funcmsg[i].f_numcalls; + funcentry->utime = funcmsg[i].f_utime; + funcentry->stime = funcmsg[i].f_stime; + funcentry->rtime = funcmsg[i].f_rtime; + funcentry->utime_self = funcmsg[i].f_utime_self; + funcentry->stime_self = funcmsg[i].f_stime_self; + funcentry->rtime_self = funcmsg[i].f_rtime_self; + } + else + { + /* + * Otherwise add the values to the existing entry. + */ + funcentry->numcalls += funcmsg[i].f_numcalls; + funcentry->utime += funcmsg[i].f_utime; + funcentry->stime += funcmsg[i].f_stime; + funcentry->rtime += funcmsg[i].f_rtime; + funcentry->utime_self += funcmsg[i].f_utime_self; + funcentry->stime_self += funcmsg[i].f_stime_self; + funcentry->rtime_self += funcmsg[i].f_rtime_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); + + if (!dbentry || !dbentry->tables) + return; + + /* + * Process all function entries in the message. + */ + for (i = 0; i < msg->m_nentries; i++) + { + (void) hash_search(dbentry->functions, + (void *) &(msg->m_functionid[i]), + HASH_REMOVE, NULL); + } + } /* ---------- * pgstat_recv_dropdb() - *************** *** 2986,2991 **** --- 3386,3393 ---- { if (dbentry->tables != NULL) hash_destroy(dbentry->tables); + if (dbentry->functions != NULL) + hash_destroy(dbentry->functions); if (hash_search(pgStatDBHash, (void *) &(dbentry->databaseid), *************** *** 3023,3030 **** --- 3425,3435 ---- */ 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; *************** *** 3038,3043 **** --- 3443,3454 ---- PGSTAT_TAB_HASH_SIZE, &hash_ctl, HASH_ELEM | HASH_FUNCTION); + + hash_ctl.entrysize = sizeof(PgStat_FunctionEntry); + dbentry->functions = hash_create("Per-database function", + PGSTAT_FUNCTION_HASH_SIZE, + &hash_ctl, + HASH_ELEM | HASH_FUNCTION); } /* ---------- *************** *** 3170,3172 **** --- 3581,3584 ---- globalStats.buf_written_backend += msg->m_buf_written_backend; globalStats.buf_alloc += msg->m_buf_alloc; } + *** ./src/backend/tcop/postgres.c.orig 2008-03-20 10:46:13.000000000 +0200 --- ./src/backend/tcop/postgres.c 2008-03-22 11:39:41.000000000 +0200 *************** *** 3488,3494 **** } else { ! pgstat_report_tabstat(false); set_ps_display("idle", false); pgstat_report_activity("<IDLE>"); --- 3488,3494 ---- } else { ! pgstat_report_stat(false); set_ps_display("idle", false); pgstat_report_activity("<IDLE>"); *** ./src/backend/utils/adt/pgstatfuncs.c.orig 2008-03-20 10:47:44.000000000 +0200 --- ./src/backend/utils/adt/pgstatfuncs.c 2008-03-20 10:51:10.000000000 +0200 *************** *** 38,43 **** --- 38,51 ---- 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_utime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_function_stime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_function_rtime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_function_self_utime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_function_self_stime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_function_self_rtime(PG_FUNCTION_ARGS); + extern Datum pg_stat_get_backend_idset(PG_FUNCTION_ARGS); extern Datum pg_backend_pid(PG_FUNCTION_ARGS); extern Datum pg_stat_get_backend_pid(PG_FUNCTION_ARGS); *************** *** 324,329 **** --- 332,420 ---- } 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->numcalls); + } + + Datum + pg_stat_get_function_utime(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->utime); + } + + Datum + pg_stat_get_function_stime(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->stime); + } + + Datum + pg_stat_get_function_rtime(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->rtime); + } + + Datum + pg_stat_get_function_self_utime(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->utime_self); + } + + Datum + pg_stat_get_function_self_stime(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->stime_self); + } + + Datum + pg_stat_get_function_self_rtime(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->rtime_self); + } + + Datum pg_stat_get_backend_idset(PG_FUNCTION_ARGS) { FuncCallContext *funcctx; *** ./src/backend/utils/fmgr/fmgr.c.orig 2008-03-20 10:51:21.000000000 +0200 --- ./src/backend/utils/fmgr/fmgr.c 2008-03-22 19:38:04.000000000 +0200 *************** *** 27,32 **** --- 27,33 ---- #include "utils/guc.h" #include "utils/lsyscache.h" #include "utils/syscache.h" + #include "pgstat.h" /* *************** *** 189,194 **** --- 190,196 ---- finfo->fn_extra = NULL; finfo->fn_mcxt = mcxt; finfo->fn_expr = NULL; /* caller may set this later */ + finfo->fn_stats = false; if ((fbp = fmgr_isbuiltin(functionId)) != NULL) { *************** *** 215,220 **** --- 217,236 ---- finfo->fn_strict = procedureStruct->proisstrict; finfo->fn_retset = procedureStruct->proretset; + /* check if we need stats for the function */ + switch (procedureStruct->prolang) { + case INTERNALlanguageId: + finfo->fn_stats = false; + break; + case ClanguageId: + case SQLlanguageId: + finfo->fn_stats = (pgstat_track_functions == TRACK_FUNC_ALL); + break; + default: + finfo->fn_stats = (pgstat_track_functions != TRACK_FUNC_OFF); + break; + } + /* * If it has prosecdef set, or non-null proconfig, use * fmgr_security_definer call handler. *** ./src/backend/utils/misc/guc.c.orig 2008-03-20 10:54:29.000000000 +0200 --- ./src/backend/utils/misc/guc.c 2008-03-23 14:56:59.000000000 +0200 *************** *** 208,213 **** --- 208,220 ---- {NULL, 0} }; + static const struct config_enum_entry track_function_options [] = { + {"none", TRACK_FUNC_OFF}, + {"pl", TRACK_FUNC_PL}, + {"all", TRACK_FUNC_ALL}, + {NULL, 0} + }; + /* * GUC option variables that are exported from this module */ *************** *** 2488,2493 **** --- 2495,2508 ---- LOGSTMT_NONE, log_statement_options, NULL, NULL }, + { + {"track_functions", PGC_USERSET, STATS_COLLECTOR, + gettext_noop("Collects function-level statistics on database activity."), + gettext_noop("Valid values are: pl, all and none.") + }, + &pgstat_track_functions, + TRACK_FUNC_OFF, track_function_options, NULL, NULL + }, *** ./src/backend/utils/misc/postgresql.conf.sample.orig 2008-03-20 11:00:32.000000000 +0200 --- ./src/backend/utils/misc/postgresql.conf.sample 2008-03-23 14:57:25.000000000 +0200 *************** *** 362,367 **** --- 362,368 ---- #track_activities = on #track_counts = on + #track_functions = none # none, pl, all #update_process_title = on *** ./src/include/catalog/pg_proc.h.orig 2008-03-20 11:01:01.000000000 +0200 --- ./src/include/catalog/pg_proc.h 2008-03-20 15:21:34.000000000 +0200 *************** *** 2949,2954 **** --- 2949,2969 ---- 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_utime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_utime- _null_ _null_ )); + DESCR("Statistics: User mode cpu usage of function"); + DATA(insert OID = 2980 ( pg_stat_get_function_stime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_stime- _null_ _null_ )); + DESCR("Statistics: System mode cpu usage of function"); + DATA(insert OID = 2981 ( pg_stat_get_function_rtime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_rtime- _null_ _null_ )); + DESCR("Statistics: Execution time of function"); + DATA(insert OID = 2982 ( pg_stat_get_function_self_utime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_self_utime- _null_ _null_ )); + DESCR("Statistics: Self user mode cpu usage of function"); + DATA(insert OID = 2983 ( pg_stat_get_function_self_stime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_self_stime- _null_ _null_ )); + DESCR("Statistics: Self system mode cpu usage of function"); + DATA(insert OID = 2984 ( pg_stat_get_function_self_rtime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_ pg_stat_get_function_self_rtime- _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.orig 2008-03-20 11:05:48.000000000 +0200 --- ./src/include/fmgr.h 2008-03-20 11:06:20.000000000 +0200 *************** *** 50,55 **** --- 50,56 ---- bool fn_strict; /* function is "strict" (NULL in => NULL out) */ bool fn_retset; /* function returns a set */ void *fn_extra; /* extra space for use by handler */ + bool fn_stats; /* collect function call stats */ MemoryContext fn_mcxt; /* memory context to store fn_extra in */ fmNodePtr fn_expr; /* expression parse tree for call, or NULL */ } FmgrInfo; *** ./src/include/pgstat.h.orig 2008-03-20 11:06:43.000000000 +0200 --- ./src/include/pgstat.h 2008-03-23 18:44:09.000000000 +0200 *************** *** 16,21 **** --- 16,30 ---- #include "utils/rel.h" #include "utils/timestamp.h" + #ifdef HAVE_SYS_RESOURCE_H + #include <sys/time.h> + #include <sys/resource.h> + #endif + + #ifndef HAVE_GETRUSAGE + #include "rusagestub.h" + #endif + /* ---------- * The types of backend -> collector messages *************** *** 31,39 **** PGSTAT_MTYPE_AUTOVAC_START, PGSTAT_MTYPE_VACUUM, PGSTAT_MTYPE_ANALYZE, ! PGSTAT_MTYPE_BGWRITER } StatMsgType; /* ---------- * The data type used for counters. * ---------- --- 40,56 ---- PGSTAT_MTYPE_AUTOVAC_START, PGSTAT_MTYPE_VACUUM, PGSTAT_MTYPE_ANALYZE, ! PGSTAT_MTYPE_BGWRITER, ! PGSTAT_MTYPE_FUNCSTAT, ! PGSTAT_MTYPE_FUNCPURGE } StatMsgType; + typedef enum { + TRACK_FUNC_OFF, + TRACK_FUNC_PL, + TRACK_FUNC_ALL + } TrackFunctionsLevel; + /* ---------- * The data type used for counters. * ---------- *************** *** 173,178 **** --- 190,214 ---- } PgStat_TableEntry; /* ---------- + * PgStat_FunctionEntry Per-function info in a MsgFuncstat + * + */ + typedef struct PgStat_FunctionEntry + { + Oid f_id; + + PgStat_Counter f_numcalls; + + PgStat_Counter f_utime; + PgStat_Counter f_stime; + PgStat_Counter f_rtime; + + PgStat_Counter f_utime_self; + PgStat_Counter f_stime_self; + PgStat_Counter f_rtime_self; + } PgStat_FunctionEntry; + + /* ---------- * PgStat_MsgTabstat Sent by the backend to report table * and buffer access statistics. * ---------- *************** *** 211,216 **** --- 247,286 ---- /* ---------- + * PgStat_MsgFuncstat Sent by the backend to report function + * access statistics. + * ---------- + */ + #define PGSTAT_NUM_FUNCENTRIES \ + ((PGSTAT_MSG_PAYLOAD - sizeof(Oid) - 3 * 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_MsgDropdb Sent by the backend to tell the collector * about a dropped database * ---------- *************** *** 309,314 **** --- 379,386 ---- PgStat_MsgDummy msg_dummy; PgStat_MsgTabstat msg_tabstat; PgStat_MsgTabpurge msg_tabpurge; + PgStat_MsgFuncstat msg_funcstat; + PgStat_MsgFuncpurge msg_funcpurge; PgStat_MsgDropdb msg_dropdb; PgStat_MsgResetcounter msg_resetcounter; PgStat_MsgAutovacStart msg_autovacuum; *************** *** 347,356 **** TimestampTz last_autovac_time; /* ! * tables must be last in the struct, because we don't write the pointer ! * out to the stats file. */ HTAB *tables; } PgStat_StatDBEntry; --- 419,429 ---- TimestampTz last_autovac_time; /* ! * tables and functions must be last in the struct, because we don't ! * write the pointer out to the stats file. */ HTAB *tables; + HTAB *functions; } PgStat_StatDBEntry; *************** *** 385,390 **** --- 458,481 ---- TimestampTz autovac_analyze_timestamp; /* autovacuum initiated */ } PgStat_StatTabEntry; + /* ---------- + * PgStat_StatFuncEntry The collector's data per function + * ---------- + */ + typedef struct PgStat_StatFuncEntry + { + Oid functionid; + + PgStat_Counter numcalls; + + PgStat_Counter utime; + PgStat_Counter stime; + PgStat_Counter rtime; + PgStat_Counter utime_self; + PgStat_Counter stime_self; + PgStat_Counter rtime_self; + } PgStat_StatFuncEntry ; + /* * Global statistics kept in the stats collector *************** *** 451,456 **** --- 542,568 ---- char st_activity[PGBE_ACTIVITY_SIZE]; } PgBackendStatus; + /* + * Function call cpu and time usage. + */ + typedef struct PgStat_FunctionCallUsage + { + Oid fn_oid; + struct rusage r_start; + struct timeval t_start; + uint64 rtime_us; + uint64 utime_us; + uint64 stime_us; + uint64 self_stime; + uint64 self_utime; + uint64 self_rtime; + PgStat_FunctionEntry *fs; + PgStat_FunctionEntry save_fs; + uint64 save_stime; + uint64 save_utime; + uint64 save_rtime; + } PgStat_FunctionCallUsage; + /* ---------- * GUC parameters *************** *** 458,463 **** --- 570,577 ---- */ 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 *************** *** 476,481 **** --- 590,601 ---- extern void pgstat_reset_all(void); extern void allow_immediate_pgstat_restart(void); + /* + * function call stats + */ + extern void pgstat_init_function_usage(FunctionCallInfoData *fcinfo, PgStat_FunctionCallUsage *fcu); + extern void pgstat_update_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize); + #ifdef EXEC_BACKEND extern void PgstatCollectorMain(int argc, char *argv[]); #endif *************** *** 487,494 **** */ extern void pgstat_ping(void); ! extern void pgstat_report_tabstat(bool force); ! extern void pgstat_vacuum_tabstat(void); extern void pgstat_drop_database(Oid databaseid); extern void pgstat_clear_snapshot(void); --- 607,614 ---- */ extern void pgstat_ping(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); *************** *** 547,552 **** --- 667,698 ---- if (pgstat_track_counts && (rel)->pgstat_info != NULL) \ (rel)->pgstat_info->t_counts.t_blocks_hit++; \ } while (0) + #define pgstat_count_function_calls(s) \ + do { \ + if (pgstat_track_functions && s != NULL) \ + s->f_numcalls++; \ + } while (0) + #define pgstat_count_function_rtime(s, n, self) \ + do { \ + if (pgstat_track_functions && s != NULL) { \ + s->f_rtime += (n); \ + s->f_rtime_self += (self); \ + } \ + } while (0) + #define pgstat_count_function_utime(s, n, self) \ + do { \ + if (pgstat_track_functions && s != NULL) { \ + s->f_utime += (n); \ + s->f_utime_self += (self); \ + } \ + } while (0) + #define pgstat_count_function_stime(s, n, self) \ + do { \ + if (pgstat_track_functions && s != NULL) { \ + s->f_stime += (n); \ + s->f_stime_self += (self); \ + } \ + } while (0) extern void pgstat_count_heap_insert(Relation rel); extern void pgstat_count_heap_update(Relation rel, bool hot); *************** *** 574,579 **** --- 720,726 ---- 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/test/regress/expected/rules.out.orig 2008-03-20 19:46:37.000000000 +0200 --- ./src/test/regress/expected/rules.out 2008-03-22 16:38:25.000000000 +0200 *************** *** 1296,1301 **** --- 1296,1302 ---- 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) ASblks_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_indexesWHERE ((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_rtime(p.oid) / 1000) AS total_time, ((pg_stat_get_function_utime(p.oid)+ pg_stat_get_function_stime(p.oid)) / 1000) AS total_cpu, (pg_stat_get_function_self_rtime(p.oid)/ 1000) AS self_time, ((pg_stat_get_function_self_utime(p.oid) + pg_stat_get_function_self_stime(p.oid))/ 1000) AS self_cpu FROM (pg_proc p LEFT JOIN pg_namespace n ON ((n.oid = p.pronamespace)))WHERE (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_indexesWHERE ((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 ASindexrelname, (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_classi 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,1333 **** 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) SELECT tablename, rulename, definition FROM pg_rules ORDER BY tablename, rulename; --- 1328,1334 ---- 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; ! (50 rows) SELECT tablename, rulename, definition FROM pg_rules ORDER BY tablename, rulename;
Hi, On Sun, 23 Mar 2008, Martin Pihlak <martin.pihlak@gmail.com> writes: > Attached is a patch that enables tracking function calls through > the stats subsystem. Original discussion: > http://archives.postgresql.org/pgsql-hackers/2007-07/msg00377.php > > Introduces new guc variable - track_functions. Possible values are: > none - no collection, default > pl - tracks procedural language functions > all - tracks procedural, SQL and C (not internal) functions I might have missed the discussion, but I'd love to see a more flexible interface for configuration parameters. For instance, it'd be great if we can specify which procedural languages to track in the `pl' GUC. Moreover, if it'd be possible to specify which specific functions we want to try, then that would be awesome as well. For instance, possible configuration combinations for track_functions can be: `pl:*' - Tracks procedural, SQL and C (not internal) functions in the `public' schema. `pl:pgsql' - Tracks only PL/pgSQL functions. `pl:scheme' - Tracks only PL/scheme functions. `foo(int, int)' - Tracks related `foo' function in the public schema. `stock.foo(int, int)' - Tracks related `foo' function in the `stock' schema. `pl:stock.*' - Tracks procedural, SQL and C (not internal) functions in the `stock' schema. Syntax can obviously be much more consistent. (These are just what I come up with for the very moment.) And I'm aware of the overhead and complexity(?) this sort of scheme will bring, but I really want to use such a useful feature with mentioned flexibilities. Regards.
On Mar 23, 2008, at 9:25 PM, Volkan YAZICI wrote:
Hi,On Sun, 23 Mar 2008, Martin Pihlak <martin.pihlak@gmail.com> writes:Attached is a patch that enables tracking function calls throughthe stats subsystem. Original discussion:Introduces new guc variable - track_functions. Possible values are:none - no collection, defaultpl - tracks procedural language functionsall - tracks procedural, SQL and C (not internal) functionsI might have missed the discussion, but I'd love to see a more flexibleinterface for configuration parameters. For instance, it'd be great ifwe can specify which procedural languages to track in the `pl' GUC.Moreover, if it'd be possible to specify which specific functions wewant to try, then that would be awesome as well.For instance, possible configuration combinations for track_functionscan be:`pl:*' - Tracks procedural, SQL and C (not internal)functions in the `public' schema.`pl:pgsql' - Tracks only PL/pgSQL functions.`pl:scheme' - Tracks only PL/scheme functions.`foo(int, int)' - Tracks related `foo' function in the publicschema.`stock.foo(int, int)' - Tracks related `foo' function in the `stock'schema.`pl:stock.*' - Tracks procedural, SQL and C (not internal)functions in the `stock' schema.Syntax can obviously be much more consistent. (These are just what Icome up with for the very moment.) And I'm aware of the overhead andcomplexity(?) this sort of scheme will bring, but I really want to usesuch a useful feature with mentioned flexibilities.
this patch is quite cool already.
it would be even cooler if we could define on a per-function basis.
eg. CREATE FUNCTION ... TRACK | NOTRACK
in addition to that we could define a GUC defining whether TRACK or NOTRACK is used as default.
in many cases you are only interested in a special set of functions anyway.
as every operator is basically a procedure in postgres, i am not quite happy about the per-language approach.
best regards,
hans
--
Cybertec Schönig & Schönig GmbH
PostgreSQL Solutions and Support
Gröhrmühlgasse 26, 2700 Wiener Neustadt
Tel: +43/1/205 10 35 / 340
www.postgresql-support.de, www.postgresql-support.com
Howdy,
> Moreover, if it'd be possible to specify which specific functions we
> want to try, then that would be awesome as well.
>
> For instance, possible configuration combinations for track_functions
> can be:
>
> `pl:*' - Tracks procedural, SQL and C (not internal)
It is probably more efficient to track all functions and then use filters
on the stats view. That way the filters can be arbitrarily complex and
are out of the way of critical code path.
Selective filtering could also be implemented using per-function guc
variables. For example, set "track_functions = none" system wide and
then for specific functions:
alter function foo() set track_functions = "all";
Now I just realized that the current patch doesn't handle this quite
correctly. Modified patch attached.
Hans, this should be equivalent to the TRACK / NOTRACK you proposed? If so,
then we can do without the grammar change and just use the per-function guc.
Regards,
Martin
*** ./doc/src/sgml/config.sgml.orig 2008-03-22 20:15:30.000000000 +0200
--- ./doc/src/sgml/config.sgml 2008-03-23 15:00:27.000000000 +0200
***************
*** 3322,3327 ****
--- 3322,3343 ----
</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 time and cpu usage of stored procedures. 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.orig 2008-03-23 13:20:25.000000000 +0200
--- ./doc/src/sgml/monitoring.sgml 2008-03-23 14:55:28.000000000 +0200
***************
*** 151,156 ****
--- 151,161 ----
</para>
<para>
+ The parameter <xref linkend="guc-track-functions"> enables tracking of
+ stored procedure usage.
+ </para>
+
+ <para>
Normally these parameters are set in <filename>postgresql.conf</> so
that they apply to all server processes, but it is possible to turn
them on or off in individual sessions using the <xref
***************
*** 370,375 ****
--- 375,390 ----
<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 called functions, function OID, schema, name, number
+ of calls, total time, total cpu, self time and cpu. Self time is the
+ amount of time spent in the function itself, total time includes the
+ time spent in child functions. Time values in milliseconds.
+ </entry>
+ </row>
+
</tbody>
</tgroup>
</table>
***************
*** 655,660 ****
--- 670,733 ----
</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_rtime</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 by child functions.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal><function>pg_stat_get_function_stime</function>(<type>oid</type>)</literal></entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ Total system mode CPU time spent in the function.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal><function>pg_stat_get_function_utime</function>(<type>oid</type>)</literal></entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ Total user mode CPU time spent in the function.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal><function>pg_stat_get_function_self_rtime</function>(<type>oid</type>)</literal></entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ Time spent by only this function. Time spent in child functions
+ is excluded.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal><function>pg_stat_get_function_self_stime</function>(<type>oid</type>)</literal></entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ System mode CPU spent by this function.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal><function>pg_stat_get_function_self_utime</function>(<type>oid</type>)</literal></entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ User mode CPU spent by this function.
+ </entry>
+ </row>
+
+ <row>
<entry><literal><function>pg_stat_get_backend_idset</function>()</literal></entry>
<entry><type>setof integer</type></entry>
<entry>
*** ./src/backend/catalog/system_views.sql.orig 2008-03-20 10:13:23.000000000 +0200
--- ./src/backend/catalog/system_views.sql 2008-03-22 16:27:38.000000000 +0200
***************
*** 376,381 ****
--- 376,395 ----
pg_stat_get_db_tuples_deleted(D.oid) AS tup_deleted
FROM pg_database D;
+ CREATE OR REPLACE 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_rtime(P.oid)/1000 AS total_time,
+ (pg_stat_get_function_utime(P.oid) + pg_stat_get_function_stime(P.oid)) /1000 AS total_cpu,
+ pg_stat_get_function_self_rtime(P.oid)/1000 AS self_time,
+ (pg_stat_get_function_self_utime(P.oid) + pg_stat_get_function_self_stime(P.oid)) /1000 AS self_cpu
+ FROM pg_proc P LEFT JOIN pg_namespace N ON (N.oid = P.pronamespace)
+ WHERE
+ 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.orig 2008-03-20 10:15:41.000000000 +0200
--- ./src/backend/commands/trigger.c 2008-03-23 18:42:39.000000000 +0200
***************
*** 13,18 ****
--- 13,19 ----
*/
#include "postgres.h"
+ #include "pgstat.h"
#include "access/genam.h"
#include "access/heapam.h"
#include "access/xact.h"
***************
*** 1541,1546 ****
--- 1542,1548 ----
MemoryContext per_tuple_context)
{
FunctionCallInfoData fcinfo;
+ PgStat_FunctionCallUsage fcusage;
Datum result;
MemoryContext oldContext;
***************
*** 1574,1580 ****
--- 1576,1584 ----
*/
InitFunctionCallInfoData(fcinfo, finfo, 0, (Node *) trigdata, NULL);
+ pgstat_init_function_usage(&fcinfo, &fcusage);
result = FunctionCallInvoke(&fcinfo);
+ pgstat_update_function_usage(&fcusage, TRUE);
MemoryContextSwitchTo(oldContext);
*** ./src/backend/commands/vacuum.c.orig 2008-03-21 19:26:48.000000000 +0200
--- ./src/backend/commands/vacuum.c 2008-03-22 11:21:08.000000000 +0200
***************
*** 319,325 ****
* in autovacuum --- autovacuum.c does this for itself.
*/
if (vacstmt->vacuum && !IsAutoVacuumWorkerProcess())
! pgstat_vacuum_tabstat();
/*
* Create special memory context for cross-transaction storage.
--- 319,325 ----
* in autovacuum --- autovacuum.c does this for itself.
*/
if (vacstmt->vacuum && !IsAutoVacuumWorkerProcess())
! pgstat_vacuum_stat();
/*
* Create special memory context for cross-transaction storage.
*** ./src/backend/executor/execQual.c.orig 2008-03-20 10:18:39.000000000 +0200
--- ./src/backend/executor/execQual.c 2008-03-23 18:43:00.000000000 +0200
***************
*** 36,41 ****
--- 36,42 ----
#include "postgres.h"
+ #include "pgstat.h"
#include "access/heapam.h"
#include "access/nbtree.h"
#include "catalog/pg_type.h"
***************
*** 1148,1153 ****
--- 1149,1155 ----
List *arguments = fcache->args;
Datum result;
FunctionCallInfoData fcinfo;
+ PgStat_FunctionCallUsage fcusage;
ReturnSetInfo rsinfo; /* for functions returning sets */
ExprDoneCond argDone;
bool hasSetArg;
***************
*** 1206,1211 ****
--- 1208,1215 ----
rsinfo.setDesc = NULL;
}
+ pgstat_init_function_usage(&fcinfo, &fcusage);
+
/*
* now return the value gotten by calling the function manager, passing
* the function the evaluated parameter values.
***************
*** 1316,1321 ****
--- 1320,1326 ----
* argument.
*/
}
+ pgstat_update_function_usage(&fcusage, *isDone == ExprEndResult);
}
else
{
***************
*** 1350,1355 ****
--- 1355,1361 ----
fcinfo.isnull = false;
result = FunctionCallInvoke(&fcinfo);
*isNull = fcinfo.isnull;
+ pgstat_update_function_usage(&fcusage, TRUE);
}
return result;
***************
*** 1370,1375 ****
--- 1376,1382 ----
ListCell *arg;
Datum result;
FunctionCallInfoData fcinfo;
+ PgStat_FunctionCallUsage fcusage;
int i;
/* Guard against stack overflow due to overly complex expressions */
***************
*** 1392,1397 ****
--- 1399,1405 ----
}
InitFunctionCallInfoData(fcinfo, &(fcache->func), i, NULL, NULL);
+ pgstat_init_function_usage(&fcinfo, &fcusage);
/*
* If function is strict, and there are any NULL arguments, skip calling
***************
*** 1412,1417 ****
--- 1420,1427 ----
result = FunctionCallInvoke(&fcinfo);
*isNull = fcinfo.isnull;
+ pgstat_update_function_usage(&fcusage, TRUE);
+
return result;
}
***************
*** 1435,1440 ****
--- 1445,1451 ----
bool returnsTuple;
bool returnsSet = false;
FunctionCallInfoData fcinfo;
+ PgStat_FunctionCallUsage fcusage;
ReturnSetInfo rsinfo;
HeapTupleData tmptup;
MemoryContext callerContext;
***************
*** 1535,1540 ****
--- 1546,1553 ----
direct_function_call = false;
}
+ pgstat_init_function_usage(&fcinfo, &fcusage);
+
/*
* Switch to short-lived context for calling the function or expression.
*/
***************
*** 1685,1690 ****
--- 1698,1705 ----
first_time = false;
}
+ pgstat_update_function_usage(&fcusage, TRUE);
+
no_function_result:
/*
*** ./src/backend/postmaster/autovacuum.c.orig 2008-03-21 19:26:40.000000000 +0200
--- ./src/backend/postmaster/autovacuum.c 2008-03-22 11:21:24.000000000 +0200
***************
*** 1855,1861 ****
* want to do this exactly once per DB-processing cycle, even if we find
* nothing worth vacuuming in the database.
*/
! pgstat_vacuum_tabstat();
/*
* Find the pg_database entry and select the default freeze_min_age. We
--- 1855,1861 ----
* want to do this exactly once per DB-processing cycle, even if we find
* nothing worth vacuuming in the database.
*/
! pgstat_vacuum_stat();
/*
* Find the pg_database entry and select the default freeze_min_age. We
*** ./src/backend/postmaster/pgstat.c.orig 2008-03-20 10:29:52.000000000 +0200
--- ./src/backend/postmaster/pgstat.c 2008-03-23 18:43:33.000000000 +0200
***************
*** 42,47 ****
--- 42,48 ----
#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"
***************
*** 88,93 ****
--- 89,95 ----
*/
#define PGSTAT_DB_HASH_SIZE 16
#define PGSTAT_TAB_HASH_SIZE 512
+ #define PGSTAT_FUNCTION_HASH_SIZE 512
/* ----------
***************
*** 96,101 ****
--- 98,104 ----
*/
bool pgstat_track_activities = false;
bool pgstat_track_counts = false;
+ int pgstat_track_functions = 0;
/*
* BgWriter global statistics counters (unused in other processes).
***************
*** 138,143 ****
--- 141,150 ----
static TabStatusArray *pgStatTabList = NULL;
+ /* Function stat entries */
+ 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
***************
*** 184,189 ****
--- 191,200 ----
static volatile bool need_exit = false;
static volatile bool need_statwrite = false;
+ /* Helper variables for function self time calculations. */
+ static uint64 total_stime = 0;
+ static uint64 total_utime = 0;
+ static uint64 total_rtime = 0;
/* ----------
* Local function forward declarations
***************
*** 205,210 ****
--- 216,222 ----
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);
***************
*** 216,221 ****
--- 228,235 ----
static void pgstat_recv_tabstat(PgStat_MsgTabstat *msg, int len);
static void pgstat_recv_tabpurge(PgStat_MsgTabpurge *msg, int len);
+ static void pgstat_recv_funcstat(PgStat_MsgFuncstat *msg, int len);
+ static void pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len);
static void pgstat_recv_dropdb(PgStat_MsgDropdb *msg, int len);
static void pgstat_recv_resetcounter(PgStat_MsgResetcounter *msg, int len);
static void pgstat_recv_autovac(PgStat_MsgAutovacStart *msg, int len);
***************
*** 600,615 ****
/* ----------
! * pgstat_report_tabstat() -
*
* 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.
* ----------
*/
void
! pgstat_report_tabstat(bool force)
{
/* we assume this inits to all zeroes: */
static const PgStat_TableCounts all_zeroes;
--- 614,629 ----
/* ----------
! * pgstat_report_stat() -
*
* Called from tcop/postgres.c to send the so far collected per-table
! * and function 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.
* ----------
*/
void
! pgstat_report_stat(bool force)
{
/* we assume this inits to all zeroes: */
static const PgStat_TableCounts all_zeroes;
***************
*** 695,704 ****
pgstat_send_tabstat(®ular_msg);
if (shared_msg.m_nentries > 0)
pgstat_send_tabstat(&shared_msg);
}
/*
! * Subroutine for pgstat_report_tabstat: finish and send a tabstat message
*/
static void
pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg)
--- 709,721 ----
pgstat_send_tabstat(®ular_msg);
if (shared_msg.m_nentries > 0)
pgstat_send_tabstat(&shared_msg);
+
+ /* Now, send the functions */
+ pgstat_send_funcstats();
}
/*
! * Subroutine for pgstat_report_stat: finish and send a tabstat message
*/
static void
pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg)
***************
*** 735,755 ****
pgstat_send(tsmsg, len);
}
/* ----------
! * pgstat_vacuum_tabstat() -
*
* Will tell the collector about objects he can get rid of.
* ----------
*/
void
! pgstat_vacuum_tabstat(void)
{
HTAB *htab;
PgStat_MsgTabpurge msg;
HASH_SEQ_STATUS hstat;
PgStat_StatDBEntry *dbentry;
PgStat_StatTabEntry *tabentry;
int len;
if (pgStatSock < 0)
--- 752,812 ----
pgstat_send(tsmsg, len);
}
+ /*
+ * Subroutine for pgstat_report_stat: populate and send a function stat message.
+ */
+ void
+ pgstat_send_funcstats(void)
+ {
+ PgStat_MsgFuncstat msg;
+ PgStat_FunctionEntry *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_FunctionEntry *)hash_seq_search(&fstat)) != NULL)
+ {
+ msg.m_entry[msg.m_nentries] = *entry;
+
+ /* clear the entry, but retain Oid */
+ memset(entry, 0, sizeof(PgStat_FunctionEntry));
+ entry->f_id = msg.m_entry[msg.m_nentries].f_id;
+
+ 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;
+ }
+ }
+
+ if (msg.m_nentries > 0)
+ pgstat_send(&msg, offsetof(PgStat_MsgFuncstat, m_entry[0]) +
+ msg.m_nentries * sizeof(PgStat_FunctionEntry));
+ }
/* ----------
! * pgstat_vacuum_stat() -
*
* Will tell the collector about objects he can get rid of.
* ----------
*/
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)
***************
*** 854,861 ****
/* Clean up */
hash_destroy(htab);
- }
/* ----------
* pgstat_collect_oids() -
--- 911,965 ----
/* Clean up */
hash_destroy(htab);
+ /*
+ * Done with the tables, now repeat the above steps for functions.
+ */
+ htab = pgstat_collect_oids(ProcedureRelationId);
+
+ pgstat_setheader(&f_msg.m_hdr, PGSTAT_MTYPE_FUNCPURGE);
+ f_msg.m_nentries = 0;
+ f_msg.m_databaseid = MyDatabaseId;
+
+ /*
+ * Check for all functions listed in stats hashtable if they still exist.
+ */
+ 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)
+ /* still exists, move on */
+ continue;
+
+ 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_TABPURGE)
+ {
+ len = offsetof(PgStat_MsgFuncpurge, m_functionid[0])
+ +f_msg.m_nentries * sizeof(Oid);
+
+ pgstat_send(&f_msg, len);
+ f_msg.m_nentries = 0;
+ }
+ }
+
+ 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() -
***************
*** 905,911 ****
*
* 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().)
* ----------
*/
void
--- 1009,1015 ----
*
* 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_stat().)
* ----------
*/
void
***************
*** 927,936 ****
*
* 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().)
*
* 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.
* ----------
*/
#ifdef NOT_USED
--- 1031,1040 ----
*
* 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_stat().)
*
* Currently not used for lack of any good place to call it; we rely
! * entirely on pgstat_vacuum_stat() to clean out stats for dead rels.
* ----------
*/
#ifdef NOT_USED
***************
*** 1073,1078 ****
--- 1177,1294 ----
pgstat_send(&msg, sizeof(msg));
}
+ /*
+ * Initialize function call usage structures. Called by the executor before
+ * invoking a function.
+ */
+ void
+ pgstat_init_function_usage(FunctionCallInfoData *fcinfo, PgStat_FunctionCallUsage *fcu)
+ {
+ HASHCTL hash_ctl;
+ bool found;
+
+ fcu->fn_oid = InvalidOid;
+
+ if (!pgstat_track_functions || !fcinfo->flinfo) {
+ /* We are not collecting or we don't have oid of the function (got rewritten?)*/
+ return;
+ }
+
+ if (!fcinfo->flinfo->fn_stats) {
+ /* stats not needed */
+ return;
+ }
+
+ gettimeofday(&fcu->t_start, NULL);
+ getrusage(RUSAGE_SELF, &fcu->r_start);
+ fcu->rtime_us = fcu->self_rtime = 0;
+ fcu->utime_us = fcu->self_utime = 0;
+ fcu->stime_us = fcu->self_stime = 0;
+ fcu->fn_oid = fcinfo->flinfo->fn_oid;
+
+ if (!pgStatFunctions) {
+ /* First time - initialize function stat table */
+ memset(&hash_ctl, 0, sizeof(hash_ctl));
+ hash_ctl.keysize = sizeof(Oid);
+ hash_ctl.entrysize = sizeof(PgStat_FunctionEntry);
+ 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 */
+ fcu->fs = hash_search(pgStatFunctions, &fcu->fn_oid, HASH_ENTER, &found);
+ if (!found) {
+ memset(fcu->fs, 0, sizeof(PgStat_FunctionEntry));
+ fcu->fs->f_id = fcu->fn_oid;
+ }
+
+ /* save stats for this function, later used to compensate for recursion */
+ fcu->save_fs = *fcu->fs;
+
+ /* save totals for 'self' calculation */
+ fcu->save_stime = total_stime;
+ fcu->save_utime = total_utime;
+ fcu->save_rtime = total_rtime;
+ }
+
+ /*
+ * Calculate function call usage and update stat counters. Called by the
+ * executor when its done with the function. Might be called several times
+ * by set returning functions, last invocation should then have finalize
+ * set to TRUE.
+ */
+ void
+ pgstat_update_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize)
+ {
+ struct timeval t1;
+ struct rusage r1;
+
+ if (!pgstat_track_functions || fcu->fn_oid == InvalidOid)
+ return;
+
+ getrusage(RUSAGE_SELF, &r1);
+ gettimeofday(&t1, NULL);
+
+ /* total elapsed */
+ fcu->utime_us += r1.ru_utime.tv_sec*1000000 + r1.ru_utime.tv_usec -
+ (fcu->r_start.ru_utime.tv_sec*1000000 + fcu->r_start.ru_utime.tv_usec);
+ fcu->stime_us += r1.ru_stime.tv_sec*1000000 + r1.ru_stime.tv_usec -
+ (fcu->r_start.ru_stime.tv_sec*1000000 + fcu->r_start.ru_stime.tv_usec);
+ fcu->rtime_us += t1.tv_sec*1000000 + t1.tv_usec -
+ (fcu->t_start.tv_sec*1000000 + fcu->t_start.tv_usec);
+
+ /* extract self usage */
+ fcu->self_stime = (fcu->save_stime + fcu->stime_us) - total_stime;
+ fcu->self_utime = (fcu->save_utime + fcu->utime_us) - total_utime;
+ fcu->self_rtime = (fcu->save_rtime + fcu->rtime_us) - total_rtime;
+
+ /* subtract recursive calls of myself */
+ fcu->utime_us -= fcu->fs->f_utime - fcu->save_fs.f_utime;
+ fcu->stime_us -= fcu->fs->f_stime - fcu->save_fs.f_stime;
+ fcu->rtime_us -= fcu->fs->f_rtime - fcu->save_fs.f_rtime;
+
+ elog(DEBUG5, "pgstat_update_function_usage: rtime start=%llu end=%llu\n", fcu->save_fs.f_rtime,
fcu->fs->f_rtime);
+
+ total_stime += fcu->self_stime;
+ total_utime += fcu->self_utime;
+ total_rtime += fcu->self_rtime;
+
+ if (finalize)
+ pgstat_count_function_calls(fcu->fs);
+
+ /* update the calculated values in function stats table */
+ pgstat_count_function_rtime(fcu->fs, fcu->rtime_us, fcu->self_rtime);
+ pgstat_count_function_utime(fcu->fs, fcu->utime_us, fcu->self_utime);
+ pgstat_count_function_stime(fcu->fs, fcu->stime_us, fcu->self_stime);
+
+ elog(DEBUG5, "pgstat_update_function_usage %u %s: real=%llu user=%llu sys=%llu us [self %llu %llu %llu us]",
+ fcu->fn_oid, finalize ? "final" : "contemporary",
+ fcu->rtime_us, fcu->utime_us, fcu->stime_us,
+ fcu->self_rtime, fcu->self_utime, fcu->self_stime);
+ }
/* ----------
* pgstat_initstats() -
***************
*** 1661,1666 ****
--- 1877,1909 ----
return NULL;
}
+ /* ----------
+ * 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() -
***************
*** 1861,1867 ****
{
volatile PgBackendStatus *beentry = MyBEEntry;
! pgstat_report_tabstat(true);
/*
* Clear my status entry, following the protocol of bumping st_changecount
--- 2104,2110 ----
{
volatile PgBackendStatus *beentry = MyBEEntry;
! pgstat_report_stat(true);
/*
* Clear my status entry, following the protocol of bumping st_changecount
***************
*** 2343,2348 ****
--- 2586,2599 ----
pgstat_recv_tabpurge((PgStat_MsgTabpurge *) &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;
+
case PGSTAT_MTYPE_DROPDB:
pgstat_recv_dropdb((PgStat_MsgDropdb *) &msg, len);
break;
***************
*** 2446,2451 ****
--- 2697,2703 ----
HASHCTL hash_ctl;
result->tables = NULL;
+ result->functions = NULL;
result->n_xact_commit = 0;
result->n_xact_rollback = 0;
result->n_blocks_fetched = 0;
***************
*** 2465,2470 ****
--- 2717,2728 ----
PGSTAT_TAB_HASH_SIZE,
&hash_ctl,
HASH_ELEM | HASH_FUNCTION);
+
+ hash_ctl.entrysize = sizeof(PgStat_FunctionEntry);
+ result->functions = hash_create("Per-database function",
+ PGSTAT_TAB_HASH_SIZE,
+ &hash_ctl,
+ HASH_ELEM | HASH_FUNCTION);
}
return result;
***************
*** 2482,2489 ****
--- 2740,2749 ----
{
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;
***************
*** 2536,2541 ****
--- 2796,2814 ----
}
/*
+ * Walk through the database's function stats table.
+ */
+ hash_seq_init(&fstat, dbentry->functions);
+ while ((funcentry = (PgStat_StatFuncEntry *) hash_seq_search(&fstat)) != NULL)
+ {
+ if (funcentry->numcalls > 0)
+ {
+ fputc('F', fpout);
+ fwrite(funcentry, sizeof(PgStat_StatFuncEntry), 1, fpout);
+ }
+ }
+
+ /*
* Mark the end of this DB
*/
fputc('d', fpout);
***************
*** 2590,2598 ****
--- 2863,2874 ----
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;
***************
*** 2686,2691 ****
--- 2962,2968 ----
memcpy(dbentry, &dbbuf, sizeof(PgStat_StatDBEntry));
dbentry->tables = NULL;
+ dbentry->functions = NULL;
/*
* Don't collect tables if not the requested DB (or the
***************
*** 2708,2718 ****
--- 2985,3001 ----
&hash_ctl,
HASH_ELEM | HASH_FUNCTION | HASH_CONTEXT);
+ hash_ctl.entrysize = sizeof(PgStat_FunctionEntry);
+ 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.
*/
tabhash = dbentry->tables;
+ funchash = dbentry->functions;
break;
/*
***************
*** 2720,2725 ****
--- 3003,3009 ----
*/
case 'd':
tabhash = NULL;
+ funchash = NULL;
break;
/*
***************
*** 2755,2760 ****
--- 3039,3076 ----
break;
/*
+ * 'F' A PgStat_FunctionEntry 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 table 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.
*/
case 'E':
***************
*** 2962,2967 ****
--- 3278,3367 ----
}
}
+ /* ----------
+ * 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++)
+ {
+ funcentry = (PgStat_StatFuncEntry *) hash_search(dbentry->functions,
+ (void *) &(funcmsg[i].f_id),
+ HASH_ENTER, &found);
+
+ if (!found)
+ {
+ /*
+ * If it's a new function entry, initialize counters to the values we
+ * just got.
+ */
+ funcentry->numcalls = funcmsg[i].f_numcalls;
+ funcentry->utime = funcmsg[i].f_utime;
+ funcentry->stime = funcmsg[i].f_stime;
+ funcentry->rtime = funcmsg[i].f_rtime;
+ funcentry->utime_self = funcmsg[i].f_utime_self;
+ funcentry->stime_self = funcmsg[i].f_stime_self;
+ funcentry->rtime_self = funcmsg[i].f_rtime_self;
+ }
+ else
+ {
+ /*
+ * Otherwise add the values to the existing entry.
+ */
+ funcentry->numcalls += funcmsg[i].f_numcalls;
+ funcentry->utime += funcmsg[i].f_utime;
+ funcentry->stime += funcmsg[i].f_stime;
+ funcentry->rtime += funcmsg[i].f_rtime;
+ funcentry->utime_self += funcmsg[i].f_utime_self;
+ funcentry->stime_self += funcmsg[i].f_stime_self;
+ funcentry->rtime_self += funcmsg[i].f_rtime_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);
+
+ if (!dbentry || !dbentry->tables)
+ return;
+
+ /*
+ * Process all function entries in the message.
+ */
+ for (i = 0; i < msg->m_nentries; i++)
+ {
+ (void) hash_search(dbentry->functions,
+ (void *) &(msg->m_functionid[i]),
+ HASH_REMOVE, NULL);
+ }
+ }
/* ----------
* pgstat_recv_dropdb() -
***************
*** 2986,2991 ****
--- 3386,3393 ----
{
if (dbentry->tables != NULL)
hash_destroy(dbentry->tables);
+ if (dbentry->functions != NULL)
+ hash_destroy(dbentry->functions);
if (hash_search(pgStatDBHash,
(void *) &(dbentry->databaseid),
***************
*** 3023,3030 ****
--- 3425,3435 ----
*/
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;
***************
*** 3038,3043 ****
--- 3443,3454 ----
PGSTAT_TAB_HASH_SIZE,
&hash_ctl,
HASH_ELEM | HASH_FUNCTION);
+
+ hash_ctl.entrysize = sizeof(PgStat_FunctionEntry);
+ dbentry->functions = hash_create("Per-database function",
+ PGSTAT_FUNCTION_HASH_SIZE,
+ &hash_ctl,
+ HASH_ELEM | HASH_FUNCTION);
}
/* ----------
***************
*** 3170,3172 ****
--- 3581,3584 ----
globalStats.buf_written_backend += msg->m_buf_written_backend;
globalStats.buf_alloc += msg->m_buf_alloc;
}
+
*** ./src/backend/tcop/postgres.c.orig 2008-03-20 10:46:13.000000000 +0200
--- ./src/backend/tcop/postgres.c 2008-03-22 11:39:41.000000000 +0200
***************
*** 3488,3494 ****
}
else
{
! pgstat_report_tabstat(false);
set_ps_display("idle", false);
pgstat_report_activity("<IDLE>");
--- 3488,3494 ----
}
else
{
! pgstat_report_stat(false);
set_ps_display("idle", false);
pgstat_report_activity("<IDLE>");
*** ./src/backend/utils/adt/pgstatfuncs.c.orig 2008-03-20 10:47:44.000000000 +0200
--- ./src/backend/utils/adt/pgstatfuncs.c 2008-03-20 10:51:10.000000000 +0200
***************
*** 38,43 ****
--- 38,51 ----
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_utime(PG_FUNCTION_ARGS);
+ extern Datum pg_stat_get_function_stime(PG_FUNCTION_ARGS);
+ extern Datum pg_stat_get_function_rtime(PG_FUNCTION_ARGS);
+ extern Datum pg_stat_get_function_self_utime(PG_FUNCTION_ARGS);
+ extern Datum pg_stat_get_function_self_stime(PG_FUNCTION_ARGS);
+ extern Datum pg_stat_get_function_self_rtime(PG_FUNCTION_ARGS);
+
extern Datum pg_stat_get_backend_idset(PG_FUNCTION_ARGS);
extern Datum pg_backend_pid(PG_FUNCTION_ARGS);
extern Datum pg_stat_get_backend_pid(PG_FUNCTION_ARGS);
***************
*** 324,329 ****
--- 332,420 ----
}
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->numcalls);
+ }
+
+ Datum
+ pg_stat_get_function_utime(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->utime);
+ }
+
+ Datum
+ pg_stat_get_function_stime(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->stime);
+ }
+
+ Datum
+ pg_stat_get_function_rtime(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->rtime);
+ }
+
+ Datum
+ pg_stat_get_function_self_utime(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->utime_self);
+ }
+
+ Datum
+ pg_stat_get_function_self_stime(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->stime_self);
+ }
+
+ Datum
+ pg_stat_get_function_self_rtime(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->rtime_self);
+ }
+
+ Datum
pg_stat_get_backend_idset(PG_FUNCTION_ARGS)
{
FuncCallContext *funcctx;
*** ./src/backend/utils/fmgr/fmgr.c.orig 2008-03-20 10:51:21.000000000 +0200
--- ./src/backend/utils/fmgr/fmgr.c 2008-03-25 14:05:38.000000000 +0200
***************
*** 27,32 ****
--- 27,33 ----
#include "utils/guc.h"
#include "utils/lsyscache.h"
#include "utils/syscache.h"
+ #include "pgstat.h"
/*
***************
*** 136,141 ****
--- 137,156 ----
}
/*
+ * Determine if function call tracking is enabled for this language.
+ */
+ static bool
+ need_function_stats(Oid prolang)
+ {
+ if (prolang == INTERNALlanguageId)
+ return false;
+ if (prolang == ClanguageId || prolang == SQLlanguageId)
+ return (pgstat_track_functions == TRACK_FUNC_ALL);
+
+ return (pgstat_track_functions != TRACK_FUNC_OFF);
+ }
+
+ /*
* This routine fills a FmgrInfo struct, given the OID
* of the function to be called.
*
***************
*** 189,194 ****
--- 204,210 ----
finfo->fn_extra = NULL;
finfo->fn_mcxt = mcxt;
finfo->fn_expr = NULL; /* caller may set this later */
+ finfo->fn_stats = false;
if ((fbp = fmgr_isbuiltin(functionId)) != NULL)
{
***************
*** 273,278 ****
--- 289,295 ----
}
finfo->fn_oid = functionId;
+ finfo->fn_stats = need_function_stats(procedureStruct->prolang);
ReleaseSysCache(procedureTuple);
}
***************
*** 844,849 ****
--- 861,867 ----
{
FmgrInfo flinfo; /* lookup info for target function */
Oid userid; /* userid to set, or InvalidOid */
+ Oid prolang; /* need this to re-evaluate stats requirements */
ArrayType *proconfig; /* GUC values to set, or NULL */
};
***************
*** 866,871 ****
--- 884,890 ----
Oid save_userid;
bool save_secdefcxt;
volatile int save_nestlevel;
+ PgStat_FunctionCallUsage fcusage;
if (!fcinfo->flinfo->fn_extra)
{
***************
*** 893,898 ****
--- 912,919 ----
if (procedureStruct->prosecdef)
fcache->userid = procedureStruct->proowner;
+ fcache->prolang = procedureStruct->prolang;
+
datum = SysCacheGetAttr(PROCOID, tuple, Anum_pg_proc_proconfig,
&isnull);
if (!isnull)
***************
*** 938,944 ****
--- 959,970 ----
{
fcinfo->flinfo = &fcache->flinfo;
+ /* re-evaluate our need for stats */
+ fcinfo->flinfo->fn_stats = need_function_stats(fcache->prolang);
+
+ pgstat_init_function_usage(fcinfo, &fcusage);
result = FunctionCallInvoke(fcinfo);
+ pgstat_update_function_usage(&fcusage, true);
}
PG_CATCH();
{
*** ./src/backend/utils/misc/guc.c.orig 2008-03-20 10:54:29.000000000 +0200
--- ./src/backend/utils/misc/guc.c 2008-03-23 14:56:59.000000000 +0200
***************
*** 208,213 ****
--- 208,220 ----
{NULL, 0}
};
+ static const struct config_enum_entry track_function_options [] = {
+ {"none", TRACK_FUNC_OFF},
+ {"pl", TRACK_FUNC_PL},
+ {"all", TRACK_FUNC_ALL},
+ {NULL, 0}
+ };
+
/*
* GUC option variables that are exported from this module
*/
***************
*** 2488,2493 ****
--- 2495,2508 ----
LOGSTMT_NONE, log_statement_options, NULL, NULL
},
+ {
+ {"track_functions", PGC_USERSET, STATS_COLLECTOR,
+ gettext_noop("Collects function-level statistics on database activity."),
+ gettext_noop("Valid values are: pl, all and none.")
+ },
+ &pgstat_track_functions,
+ TRACK_FUNC_OFF, track_function_options, NULL, NULL
+ },
*** ./src/backend/utils/misc/postgresql.conf.sample.orig 2008-03-20 11:00:32.000000000 +0200
--- ./src/backend/utils/misc/postgresql.conf.sample 2008-03-23 14:57:25.000000000 +0200
***************
*** 362,367 ****
--- 362,368 ----
#track_activities = on
#track_counts = on
+ #track_functions = none # none, pl, all
#update_process_title = on
*** ./src/include/catalog/pg_proc.h.orig 2008-03-20 11:01:01.000000000 +0200
--- ./src/include/catalog/pg_proc.h 2008-03-20 15:21:34.000000000 +0200
***************
*** 2949,2954 ****
--- 2949,2969 ----
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_utime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_utime- _null_ _null_ ));
+ DESCR("Statistics: User mode cpu usage of function");
+ DATA(insert OID = 2980 ( pg_stat_get_function_stime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_stime- _null_ _null_ ));
+ DESCR("Statistics: System mode cpu usage of function");
+ DATA(insert OID = 2981 ( pg_stat_get_function_rtime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_rtime- _null_ _null_ ));
+ DESCR("Statistics: Execution time of function");
+ DATA(insert OID = 2982 ( pg_stat_get_function_self_utime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_self_utime- _null_ _null_ ));
+ DESCR("Statistics: Self user mode cpu usage of function");
+ DATA(insert OID = 2983 ( pg_stat_get_function_self_stime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_self_stime- _null_ _null_ ));
+ DESCR("Statistics: Self system mode cpu usage of function");
+ DATA(insert OID = 2984 ( pg_stat_get_function_self_rtime PGNSP PGUID 12 1 0 f f t f s 1 20 "26" _null_ _null_ _null_
pg_stat_get_function_self_rtime- _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.orig 2008-03-20 11:05:48.000000000 +0200
--- ./src/include/fmgr.h 2008-03-20 11:06:20.000000000 +0200
***************
*** 50,55 ****
--- 50,56 ----
bool fn_strict; /* function is "strict" (NULL in => NULL out) */
bool fn_retset; /* function returns a set */
void *fn_extra; /* extra space for use by handler */
+ bool fn_stats; /* collect function call stats */
MemoryContext fn_mcxt; /* memory context to store fn_extra in */
fmNodePtr fn_expr; /* expression parse tree for call, or NULL */
} FmgrInfo;
*** ./src/include/pgstat.h.orig 2008-03-20 11:06:43.000000000 +0200
--- ./src/include/pgstat.h 2008-03-23 18:44:09.000000000 +0200
***************
*** 16,21 ****
--- 16,30 ----
#include "utils/rel.h"
#include "utils/timestamp.h"
+ #ifdef HAVE_SYS_RESOURCE_H
+ #include <sys/time.h>
+ #include <sys/resource.h>
+ #endif
+
+ #ifndef HAVE_GETRUSAGE
+ #include "rusagestub.h"
+ #endif
+
/* ----------
* The types of backend -> collector messages
***************
*** 31,39 ****
PGSTAT_MTYPE_AUTOVAC_START,
PGSTAT_MTYPE_VACUUM,
PGSTAT_MTYPE_ANALYZE,
! PGSTAT_MTYPE_BGWRITER
} StatMsgType;
/* ----------
* The data type used for counters.
* ----------
--- 40,56 ----
PGSTAT_MTYPE_AUTOVAC_START,
PGSTAT_MTYPE_VACUUM,
PGSTAT_MTYPE_ANALYZE,
! PGSTAT_MTYPE_BGWRITER,
! PGSTAT_MTYPE_FUNCSTAT,
! PGSTAT_MTYPE_FUNCPURGE
} StatMsgType;
+ typedef enum {
+ TRACK_FUNC_OFF,
+ TRACK_FUNC_PL,
+ TRACK_FUNC_ALL
+ } TrackFunctionsLevel;
+
/* ----------
* The data type used for counters.
* ----------
***************
*** 173,178 ****
--- 190,214 ----
} PgStat_TableEntry;
/* ----------
+ * PgStat_FunctionEntry Per-function info in a MsgFuncstat
+ *
+ */
+ typedef struct PgStat_FunctionEntry
+ {
+ Oid f_id;
+
+ PgStat_Counter f_numcalls;
+
+ PgStat_Counter f_utime;
+ PgStat_Counter f_stime;
+ PgStat_Counter f_rtime;
+
+ PgStat_Counter f_utime_self;
+ PgStat_Counter f_stime_self;
+ PgStat_Counter f_rtime_self;
+ } PgStat_FunctionEntry;
+
+ /* ----------
* PgStat_MsgTabstat Sent by the backend to report table
* and buffer access statistics.
* ----------
***************
*** 211,216 ****
--- 247,286 ----
/* ----------
+ * PgStat_MsgFuncstat Sent by the backend to report function
+ * access statistics.
+ * ----------
+ */
+ #define PGSTAT_NUM_FUNCENTRIES \
+ ((PGSTAT_MSG_PAYLOAD - sizeof(Oid) - 3 * 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_MsgDropdb Sent by the backend to tell the collector
* about a dropped database
* ----------
***************
*** 309,314 ****
--- 379,386 ----
PgStat_MsgDummy msg_dummy;
PgStat_MsgTabstat msg_tabstat;
PgStat_MsgTabpurge msg_tabpurge;
+ PgStat_MsgFuncstat msg_funcstat;
+ PgStat_MsgFuncpurge msg_funcpurge;
PgStat_MsgDropdb msg_dropdb;
PgStat_MsgResetcounter msg_resetcounter;
PgStat_MsgAutovacStart msg_autovacuum;
***************
*** 347,356 ****
TimestampTz last_autovac_time;
/*
! * tables must be last in the struct, because we don't write the pointer
! * out to the stats file.
*/
HTAB *tables;
} PgStat_StatDBEntry;
--- 419,429 ----
TimestampTz last_autovac_time;
/*
! * tables and functions must be last in the struct, because we don't
! * write the pointer out to the stats file.
*/
HTAB *tables;
+ HTAB *functions;
} PgStat_StatDBEntry;
***************
*** 385,390 ****
--- 458,481 ----
TimestampTz autovac_analyze_timestamp; /* autovacuum initiated */
} PgStat_StatTabEntry;
+ /* ----------
+ * PgStat_StatFuncEntry The collector's data per function
+ * ----------
+ */
+ typedef struct PgStat_StatFuncEntry
+ {
+ Oid functionid;
+
+ PgStat_Counter numcalls;
+
+ PgStat_Counter utime;
+ PgStat_Counter stime;
+ PgStat_Counter rtime;
+ PgStat_Counter utime_self;
+ PgStat_Counter stime_self;
+ PgStat_Counter rtime_self;
+ } PgStat_StatFuncEntry ;
+
/*
* Global statistics kept in the stats collector
***************
*** 451,456 ****
--- 542,568 ----
char st_activity[PGBE_ACTIVITY_SIZE];
} PgBackendStatus;
+ /*
+ * Function call cpu and time usage.
+ */
+ typedef struct PgStat_FunctionCallUsage
+ {
+ Oid fn_oid;
+ struct rusage r_start;
+ struct timeval t_start;
+ uint64 rtime_us;
+ uint64 utime_us;
+ uint64 stime_us;
+ uint64 self_stime;
+ uint64 self_utime;
+ uint64 self_rtime;
+ PgStat_FunctionEntry *fs;
+ PgStat_FunctionEntry save_fs;
+ uint64 save_stime;
+ uint64 save_utime;
+ uint64 save_rtime;
+ } PgStat_FunctionCallUsage;
+
/* ----------
* GUC parameters
***************
*** 458,463 ****
--- 570,577 ----
*/
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
***************
*** 476,481 ****
--- 590,601 ----
extern void pgstat_reset_all(void);
extern void allow_immediate_pgstat_restart(void);
+ /*
+ * function call stats
+ */
+ extern void pgstat_init_function_usage(FunctionCallInfoData *fcinfo, PgStat_FunctionCallUsage *fcu);
+ extern void pgstat_update_function_usage(PgStat_FunctionCallUsage *fcu, bool finalize);
+
#ifdef EXEC_BACKEND
extern void PgstatCollectorMain(int argc, char *argv[]);
#endif
***************
*** 487,494 ****
*/
extern void pgstat_ping(void);
! extern void pgstat_report_tabstat(bool force);
! extern void pgstat_vacuum_tabstat(void);
extern void pgstat_drop_database(Oid databaseid);
extern void pgstat_clear_snapshot(void);
--- 607,614 ----
*/
extern void pgstat_ping(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);
***************
*** 547,552 ****
--- 667,698 ----
if (pgstat_track_counts && (rel)->pgstat_info != NULL) \
(rel)->pgstat_info->t_counts.t_blocks_hit++; \
} while (0)
+ #define pgstat_count_function_calls(s) \
+ do { \
+ if (pgstat_track_functions && s != NULL) \
+ s->f_numcalls++; \
+ } while (0)
+ #define pgstat_count_function_rtime(s, n, self) \
+ do { \
+ if (pgstat_track_functions && s != NULL) { \
+ s->f_rtime += (n); \
+ s->f_rtime_self += (self); \
+ } \
+ } while (0)
+ #define pgstat_count_function_utime(s, n, self) \
+ do { \
+ if (pgstat_track_functions && s != NULL) { \
+ s->f_utime += (n); \
+ s->f_utime_self += (self); \
+ } \
+ } while (0)
+ #define pgstat_count_function_stime(s, n, self) \
+ do { \
+ if (pgstat_track_functions && s != NULL) { \
+ s->f_stime += (n); \
+ s->f_stime_self += (self); \
+ } \
+ } while (0)
extern void pgstat_count_heap_insert(Relation rel);
extern void pgstat_count_heap_update(Relation rel, bool hot);
***************
*** 574,579 ****
--- 720,726 ----
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/test/regress/expected/rules.out.orig 2008-03-20 19:46:37.000000000 +0200
--- ./src/test/regress/expected/rules.out 2008-03-22 16:38:25.000000000 +0200
***************
*** 1296,1301 ****
--- 1296,1302 ----
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)
ASblks_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_indexesWHERE ((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_rtime(p.oid) / 1000) AS total_time,
((pg_stat_get_function_utime(p.oid)+ pg_stat_get_function_stime(p.oid)) / 1000) AS total_cpu,
(pg_stat_get_function_self_rtime(p.oid)/ 1000) AS self_time, ((pg_stat_get_function_self_utime(p.oid) +
pg_stat_get_function_self_stime(p.oid))/ 1000) AS self_cpu FROM (pg_proc p LEFT JOIN pg_namespace n ON ((n.oid =
p.pronamespace)))WHERE (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_indexesWHERE ((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
ASindexrelname, (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_classi 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,1333 ****
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)
SELECT tablename, rulename, definition FROM pg_rules
ORDER BY tablename, rulename;
--- 1328,1334 ----
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;
! (50 rows)
SELECT tablename, rulename, definition FROM pg_rules
ORDER BY tablename, rulename;
Martin Pihlak <martin.pihlak@gmail.com> writes:
> Now I just realized that the current patch doesn't handle this quite
> correctly. Modified patch attached.
I'm starting to look through this now, and I notice that the various
code paths in execQual.c are not too consistent about whether it counts
as a call if a strict function is skipped over because of NULL
arguments. I'm inclined to make it uniformly say that that's not a call
and is not included in the stats --- any objections?
regards, tom lane
I wrote:
> I'm starting to look through this now,
I found another fairly big problem, which is that this stuff isn't even
going to begin to compile on Windows.
What I think we should do about that is forget tracking getrusage()'s
user/system/real time and just track elapsed time. We have the
technology to get that in a portable fashion (cf the well-proven
instrument.c code). Such a decision would also alleviate two of the
biggest negatives of this patch, which are the runtime overhead and
the extent to which it's going to bloat the pgstats file.
Thoughts?
regards, tom lane
Tom Lane wrote: > I wrote: >> I'm starting to look through this now, > > I found another fairly big problem, which is that this stuff isn't even > going to begin to compile on Windows. Where exactly is taht problem? In getrusage()? We have a getrusage() in src/port that works fine on Windows, no? > What I think we should do about that is forget tracking getrusage()'s > user/system/real time and just track elapsed time. We have the > technology to get that in a portable fashion (cf the well-proven > instrument.c code). Such a decision would also alleviate two of the > biggest negatives of this patch, which are the runtime overhead and > the extent to which it's going to bloat the pgstats file. Those argument makes a lot of sense, though. A bloated pgstats file can be a real problem. And I don't see that information as being all that helpful anyway. //Magnus
Magnus Hagander <magnus@hagander.net> writes:
> Tom Lane wrote:
>> I found another fairly big problem, which is that this stuff isn't even
>> going to begin to compile on Windows.
> Where exactly is taht problem? In getrusage()? We have a getrusage() in
> src/port that works fine on Windows, no?
Huh ... I'd forgotten about that ... although it seems to work only for
rather small values of "work", since the WIN32 code path isn't paying
attention to the "who" argument.
>> What I think we should do about that is forget tracking getrusage()'s
>> user/system/real time and just track elapsed time.
> Those argument makes a lot of sense, though.
Yeah, the real bottom line here is whether we are buying anything that's
worth another two kernel calls per function. Given all the buffering
and offloading of I/O to bgwriter that we try to do, it's hard to argue
that stime/utime measurements for the current backend really mean a lot.
regards, tom lane
Tom Lane wrote: > Magnus Hagander <magnus@hagander.net> writes: >> Tom Lane wrote: >>> I found another fairly big problem, which is that this stuff isn't even >>> going to begin to compile on Windows. > >> Where exactly is taht problem? In getrusage()? We have a getrusage() in >> src/port that works fine on Windows, no? > > Huh ... I'd forgotten about that ... although it seems to work only for > rather small values of "work", since the WIN32 code path isn't paying > attention to the "who" argument. True, but it works for this case :-) >>> What I think we should do about that is forget tracking getrusage()'s >>> user/system/real time and just track elapsed time. > >> Those argument makes a lot of sense, though. > > Yeah, the real bottom line here is whether we are buying anything that's > worth another two kernel calls per function. Given all the buffering > and offloading of I/O to bgwriter that we try to do, it's hard to argue > that stime/utime measurements for the current backend really mean a lot. Agreed. //Magnus
Magnus Hagander <magnus@hagander.net> writes:
> Tom Lane wrote:
>> Huh ... I'd forgotten about that ... although it seems to work only for
>> rather small values of "work", since the WIN32 code path isn't paying
>> attention to the "who" argument.
> True, but it works for this case :-)
Shouldn't we at least make it fail with EINVAL if "who" doesn't match
whichever semantics this code is able to implement?
[ not relevant to the immediate patch, I suppose, but it might save some
tears later. ]
regards, tom lane
Tom Lane wrote: > Magnus Hagander <magnus@hagander.net> writes: >> Tom Lane wrote: >>> Huh ... I'd forgotten about that ... although it seems to work only for >>> rather small values of "work", since the WIN32 code path isn't paying >>> attention to the "who" argument. > >> True, but it works for this case :-) > > Shouldn't we at least make it fail with EINVAL if "who" doesn't match > whichever semantics this code is able to implement? > > [ not relevant to the immediate patch, I suppose, but it might save some > tears later. ] Yeah, we only ever call it asking for our own process, but I guess we might at some point in the future change that, so it can't hurt.. Want me to do it, or will you? //Magnus
Magnus Hagander <magnus@hagander.net> writes:
> Tom Lane wrote:
>> Shouldn't we at least make it fail with EINVAL if "who" doesn't match
>> whichever semantics this code is able to implement?
> Yeah, we only ever call it asking for our own process, but I guess we
> might at some point in the future change that, so it can't hurt.. Want
> me to do it, or will you?
Please do, I'm going to bed ...
regards, tom lane
Tom Lane wrote: > Magnus Hagander <magnus@hagander.net> writes: >> Tom Lane wrote: >>> Shouldn't we at least make it fail with EINVAL if "who" doesn't match >>> whichever semantics this code is able to implement? > >> Yeah, we only ever call it asking for our own process, but I guess we >> might at some point in the future change that, so it can't hurt.. Want >> me to do it, or will you? > > Please do, I'm going to bed ... Done. //Magnus
> What I think we should do about that is forget tracking getrusage()'s > user/system/real time and just track elapsed time. We have the > technology to get that in a portable fashion (cf the well-proven > instrument.c code). Such a decision would also alleviate two of the > biggest negatives of this patch, which are the runtime overhead and > the extent to which it's going to bloat the pgstats file. > I find the utime/stime quite useful, compared with the actual time it enables us to distinguish waiters (remote calls, sleeps, etc) from the actual CPU hogs. The difference is also very visible for IO bound functions. At least in our case it is a very useful tool for diagnosing performance issues and the overhead is not really visible. Perhaps the track_functions should just be set to none, or enabled selectively (session, function guc, user guc) for the environments where getrusage() is particularly expensive? Maybe a note in the docs that tracking is potentially expensive, and should be used carefully in production env. Regards, Martin
Martin Pihlak <martin.pihlak@gmail.com> writes:
> Now I just realized that the current patch doesn't handle this quite
> correctly. Modified patch attached.
Applied with revisions as per discussion.
regards, tom lane