From 957d08c81f9cc277725c83b9381c5154b6318a5e Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Mon, 30 Apr 2007 03:23:49 +0000 Subject: [PATCH] Implement rate-limiting logic on how often backends will attempt to send messages to the stats collector. This avoids the problem that enabling stats_row_level for autovacuum has a significant overhead for short read-only transactions, as noted by Arjen van der Meijden. We can avoid an extra gettimeofday call by piggybacking on the one done for WAL-logging xact commit or abort (although that doesn't help read-only transactions, since they don't WAL-log anything). In my proposal for this, I noted that we could change the WAL log entries for commit/abort to record full TimestampTz precision, instead of only time_t as at present. That's not done in this patch, but will be committed separately. --- src/backend/access/transam/xact.c | 37 +++++++++++++++++++++++++---- src/backend/commands/analyze.c | 22 ++++------------- src/backend/commands/vacuumlazy.c | 22 ++++------------- src/backend/postmaster/pgstat.c | 27 +++++++++++++++++---- src/backend/utils/adt/timestamp.c | 23 +++++++++++++++++- src/include/access/xact.h | 3 ++- src/include/utils/timestamp.h | 5 +++- src/test/regress/expected/stats.out | 8 +++++++ src/test/regress/sql/stats.sql | 4 ++++ 9 files changed, 104 insertions(+), 47 deletions(-) diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c index d705d7a5c1..e3f16d38a5 100644 --- a/src/backend/access/transam/xact.c +++ b/src/backend/access/transam/xact.c @@ -10,7 +10,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.240 2007/04/26 23:24:44 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.241 2007/04/30 03:23:48 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -160,11 +160,13 @@ static CommandId currentCommandId; /* * xactStartTimestamp is the value of transaction_timestamp(). * stmtStartTimestamp is the value of statement_timestamp(). + * xactStopTimestamp is the time at which we log a commit or abort WAL record. * These do not change as we enter and exit subtransactions, so we don't * keep them inside the TransactionState stack. */ static TimestampTz xactStartTimestamp; static TimestampTz stmtStartTimestamp; +static TimestampTz xactStopTimestamp; /* * GID to be used for preparing the current transaction. This is also @@ -435,6 +437,20 @@ GetCurrentStatementStartTimestamp(void) return stmtStartTimestamp; } +/* + * GetCurrentTransactionStopTimestamp + * + * We return current time if the transaction stop time hasn't been set + * (which can happen if we decide we don't need to log an XLOG record). + */ +TimestampTz +GetCurrentTransactionStopTimestamp(void) +{ + if (xactStopTimestamp != 0) + return xactStopTimestamp; + return GetCurrentTimestamp(); +} + /* * SetCurrentStatementStartTimestamp */ @@ -444,6 +460,15 @@ SetCurrentStatementStartTimestamp(void) stmtStartTimestamp = GetCurrentTimestamp(); } +/* + * SetCurrentTransactionStopTimestamp + */ +static inline void +SetCurrentTransactionStopTimestamp(void) +{ + xactStopTimestamp = GetCurrentTimestamp(); +} + /* * GetCurrentTransactionNestLevel * @@ -747,7 +772,8 @@ RecordTransactionCommit(void) */ MyProc->inCommit = true; - xlrec.xtime = time(NULL); + SetCurrentTransactionStopTimestamp(); + xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp); xlrec.nrels = nrels; xlrec.nsubxacts = nchildren; rdata[0].data = (char *) (&xlrec); @@ -1042,7 +1068,8 @@ RecordTransactionAbort(void) xl_xact_abort xlrec; XLogRecPtr recptr; - xlrec.xtime = time(NULL); + SetCurrentTransactionStopTimestamp(); + xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp); xlrec.nrels = nrels; xlrec.nsubxacts = nchildren; rdata[0].data = (char *) (&xlrec); @@ -1415,9 +1442,11 @@ StartTransaction(void) /* * set transaction_timestamp() (a/k/a now()). We want this to be the same * as the first command's statement_timestamp(), so don't do a fresh - * GetCurrentTimestamp() call (which'd be expensive anyway). + * GetCurrentTimestamp() call (which'd be expensive anyway). Also, + * mark xactStopTimestamp as unset. */ xactStartTimestamp = stmtStartTimestamp; + xactStopTimestamp = 0; pgstat_report_txn_timestamp(xactStartTimestamp); /* diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 700137ec24..2754a6db6a 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.106 2007/04/19 16:26:44 alvherre Exp $ + * $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.107 2007/04/30 03:23:48 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -468,29 +468,15 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt) /* Log the action if appropriate */ if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0) { - long diff = 0L; - - if (Log_autovacuum > 0) - { - TimestampTz endtime; - int usecs; - long secs; - - endtime = GetCurrentTimestamp(); - TimestampDifference(starttime, endtime, &secs, &usecs); - - diff = secs * 1000 + usecs / 1000; - } - - if (Log_autovacuum == 0 || diff >= Log_autovacuum) - { + if (Log_autovacuum == 0 || + TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(), + Log_autovacuum)) ereport(LOG, (errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s", get_database_name(MyDatabaseId), get_namespace_name(RelationGetNamespace(onerel)), RelationGetRelationName(onerel), pg_rusage_show(&ru0)))); - } } } diff --git a/src/backend/commands/vacuumlazy.c b/src/backend/commands/vacuumlazy.c index 0b04cfb7b2..2b6d8a07f7 100644 --- a/src/backend/commands/vacuumlazy.c +++ b/src/backend/commands/vacuumlazy.c @@ -36,7 +36,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.87 2007/04/19 16:26:44 alvherre Exp $ + * $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.88 2007/04/30 03:23:48 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -217,22 +217,9 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt) /* and log the action if appropriate */ if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0) { - long diff = 0L; - - if (Log_autovacuum > 0) - { - TimestampTz endtime; - int usecs; - long secs; - - endtime = GetCurrentTimestamp(); - TimestampDifference(starttime, endtime, &secs, &usecs); - - diff = secs * 1000 + usecs / 1000; - } - - if (Log_autovacuum == 0 || diff >= Log_autovacuum) - { + if (Log_autovacuum == 0 || + TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(), + Log_autovacuum)) ereport(LOG, (errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n" "pages: %d removed, %d remain\n" @@ -245,7 +232,6 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt) vacrelstats->pages_removed, vacrelstats->rel_pages, vacrelstats->tuples_deleted, vacrelstats->rel_tuples, pg_rusage_show(&ru0)))); - } } } diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index be9b236d54..ad5b490a27 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -13,7 +13,7 @@ * * Copyright (c) 2001-2007, PostgreSQL Global Development Group * - * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.153 2007/04/21 04:10:53 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.154 2007/04/30 03:23:49 tgl Exp $ * ---------- */ #include "postgres.h" @@ -608,15 +608,34 @@ void allow_immediate_pgstat_restart(void) /* ---------- * pgstat_report_tabstat() - * - * Called from tcop/postgres.c to send the so far collected - * per table access statistics to the collector. + * 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(void) { + static TimestampTz last_report = 0; + TimestampTz now; + + /* Don't expend a clock check if nothing to do */ + if (RegularTabStat.tsa_used == 0 && + SharedTabStat.tsa_used == 0) + return; + /* - * For each message buffer used during the last query set the header + * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL + * msec since we last sent one. + */ + now = GetCurrentTransactionStopTimestamp(); + if (!TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL)) + return; + last_report = now; + + /* + * For each message buffer used during the last queries, set the header * fields and send it out; then mark the entries unused. */ pgstat_report_one_tabstat(&RegularTabStat, MyDatabaseId); diff --git a/src/backend/utils/adt/timestamp.c b/src/backend/utils/adt/timestamp.c index e9d1efe3ed..2a83ae96b2 100644 --- a/src/backend/utils/adt/timestamp.c +++ b/src/backend/utils/adt/timestamp.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.174 2007/02/27 23:48:09 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.175 2007/04/30 03:23:49 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -1238,6 +1238,27 @@ TimestampDifference(TimestampTz start_time, TimestampTz stop_time, } } +/* + * TimestampDifferenceExceeds -- report whether the difference between two + * timestamps is >= a threshold (expressed in milliseconds) + * + * Both inputs must be ordinary finite timestamps (in current usage, + * they'll be results from GetCurrentTimestamp()). + */ +bool +TimestampDifferenceExceeds(TimestampTz start_time, + TimestampTz stop_time, + int msec) +{ + TimestampTz diff = stop_time - start_time; + +#ifdef HAVE_INT64_TIMESTAMP + return (diff >= msec * INT64CONST(1000)); +#else + return (diff * 1000.0 >= msec); +#endif +} + /* * Convert a time_t to TimestampTz. * diff --git a/src/include/access/xact.h b/src/include/access/xact.h index 760b432456..8ec834676d 100644 --- a/src/include/access/xact.h +++ b/src/include/access/xact.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/access/xact.h,v 1.85 2007/03/13 00:33:42 tgl Exp $ + * $PostgreSQL: pgsql/src/include/access/xact.h,v 1.86 2007/04/30 03:23:49 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -142,6 +142,7 @@ extern SubTransactionId GetCurrentSubTransactionId(void); extern CommandId GetCurrentCommandId(void); extern TimestampTz GetCurrentTransactionStartTimestamp(void); extern TimestampTz GetCurrentStatementStartTimestamp(void); +extern TimestampTz GetCurrentTransactionStopTimestamp(void); extern void SetCurrentStatementStartTimestamp(void); extern int GetCurrentTransactionNestLevel(void); extern bool TransactionIdIsCurrentTransactionId(TransactionId xid); diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.h index 0d31cc0294..594cd61e88 100644 --- a/src/include/utils/timestamp.h +++ b/src/include/utils/timestamp.h @@ -6,7 +6,7 @@ * Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.67 2007/02/16 03:39:45 momjian Exp $ + * $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.68 2007/04/30 03:23:49 tgl Exp $ * *------------------------------------------------------------------------- */ @@ -311,6 +311,9 @@ extern TimestampTz GetCurrentTimestamp(void); extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time, long *secs, int *microsecs); +extern bool TimestampDifferenceExceeds(TimestampTz start_time, + TimestampTz stop_time, + int msec); extern TimestampTz time_t_to_timestamptz(time_t tm); extern time_t timestamptz_to_time_t(TimestampTz t); diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out index fc76d14225..af0f630a8d 100644 --- a/src/test/regress/expected/stats.out +++ b/src/test/regress/expected/stats.out @@ -73,6 +73,14 @@ SELECT count(*) FROM tenk2 WHERE unique1 = 1; 1 (1 row) +-- force the rate-limiting logic in pgstat_report_tabstat() to time out +-- and send a message +SELECT pg_sleep(1.0); + pg_sleep +---------- + +(1 row) + -- wait for stats collector to update SELECT wait_for_stats(); wait_for_stats diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql index cde38b3a37..9900b9114a 100644 --- a/src/test/regress/sql/stats.sql +++ b/src/test/regress/sql/stats.sql @@ -60,6 +60,10 @@ SELECT count(*) FROM tenk2; -- do an indexscan SELECT count(*) FROM tenk2 WHERE unique1 = 1; +-- force the rate-limiting logic in pgstat_report_tabstat() to time out +-- and send a message +SELECT pg_sleep(1.0); + -- wait for stats collector to update SELECT wait_for_stats();