Skip to content

Commit 957d08c

Browse files
tglsfdctglsfdc
committed
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.
1 parent 57b82bf commit 957d08c

File tree

9 files changed

+104
-47
lines changed

9 files changed

+104
-47
lines changed

‎src/backend/access/transam/xact.c

+33-4
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@
1010
*
1111
*
1212
* IDENTIFICATION
13-
* $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.240 2007/04/26 23:24:44 tgl Exp $
13+
* $PostgreSQL: pgsql/src/backend/access/transam/xact.c,v 1.241 2007/04/30 03:23:48 tgl Exp $
1414
*
1515
*-------------------------------------------------------------------------
1616
*/
@@ -160,11 +160,13 @@ static CommandId currentCommandId;
160160
/*
161161
* xactStartTimestamp is the value of transaction_timestamp().
162162
* stmtStartTimestamp is the value of statement_timestamp().
163+
* xactStopTimestamp is the time at which we log a commit or abort WAL record.
163164
* These do not change as we enter and exit subtransactions, so we don't
164165
* keep them inside the TransactionState stack.
165166
*/
166167
static TimestampTz xactStartTimestamp;
167168
static TimestampTz stmtStartTimestamp;
169+
static TimestampTz xactStopTimestamp;
168170

169171
/*
170172
* GID to be used for preparing the current transaction. This is also
@@ -435,6 +437,20 @@ GetCurrentStatementStartTimestamp(void)
435437
return stmtStartTimestamp;
436438
}
437439

440+
/*
441+
* GetCurrentTransactionStopTimestamp
442+
*
443+
* We return current time if the transaction stop time hasn't been set
444+
* (which can happen if we decide we don't need to log an XLOG record).
445+
*/
446+
TimestampTz
447+
GetCurrentTransactionStopTimestamp(void)
448+
{
449+
if (xactStopTimestamp != 0)
450+
return xactStopTimestamp;
451+
return GetCurrentTimestamp();
452+
}
453+
438454
/*
439455
* SetCurrentStatementStartTimestamp
440456
*/
@@ -444,6 +460,15 @@ SetCurrentStatementStartTimestamp(void)
444460
stmtStartTimestamp = GetCurrentTimestamp();
445461
}
446462

463+
/*
464+
* SetCurrentTransactionStopTimestamp
465+
*/
466+
static inline void
467+
SetCurrentTransactionStopTimestamp(void)
468+
{
469+
xactStopTimestamp = GetCurrentTimestamp();
470+
}
471+
447472
/*
448473
* GetCurrentTransactionNestLevel
449474
*
@@ -747,7 +772,8 @@ RecordTransactionCommit(void)
747772
*/
748773
MyProc->inCommit = true;
749774

750-
xlrec.xtime = time(NULL);
775+
SetCurrentTransactionStopTimestamp();
776+
xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp);
751777
xlrec.nrels = nrels;
752778
xlrec.nsubxacts = nchildren;
753779
rdata[0].data = (char *) (&xlrec);
@@ -1042,7 +1068,8 @@ RecordTransactionAbort(void)
10421068
xl_xact_abort xlrec;
10431069
XLogRecPtr recptr;
10441070

1045-
xlrec.xtime = time(NULL);
1071+
SetCurrentTransactionStopTimestamp();
1072+
xlrec.xtime = timestamptz_to_time_t(xactStopTimestamp);
10461073
xlrec.nrels = nrels;
10471074
xlrec.nsubxacts = nchildren;
10481075
rdata[0].data = (char *) (&xlrec);
@@ -1415,9 +1442,11 @@ StartTransaction(void)
14151442
/*
14161443
* set transaction_timestamp() (a/k/a now()). We want this to be the same
14171444
* as the first command's statement_timestamp(), so don't do a fresh
1418-
* GetCurrentTimestamp() call (which'd be expensive anyway).
1445+
* GetCurrentTimestamp() call (which'd be expensive anyway). Also,
1446+
* mark xactStopTimestamp as unset.
14191447
*/
14201448
xactStartTimestamp = stmtStartTimestamp;
1449+
xactStopTimestamp = 0;
14211450
pgstat_report_txn_timestamp(xactStartTimestamp);
14221451

14231452
/*

‎src/backend/commands/analyze.c

+4-18
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.106 2007/04/19 16:26:44 alvherre Exp $
11+
* $PostgreSQL: pgsql/src/backend/commands/analyze.c,v 1.107 2007/04/30 03:23:48 tgl Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -468,29 +468,15 @@ analyze_rel(Oid relid, VacuumStmt *vacstmt)
468468
/* Log the action if appropriate */
469469
if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
470470
{
471-
long diff = 0L;
472-
473-
if (Log_autovacuum > 0)
474-
{
475-
TimestampTz endtime;
476-
int usecs;
477-
long secs;
478-
479-
endtime = GetCurrentTimestamp();
480-
TimestampDifference(starttime, endtime, &secs, &usecs);
481-
482-
diff = secs * 1000 + usecs / 1000;
483-
}
484-
485-
if (Log_autovacuum == 0 || diff >= Log_autovacuum)
486-
{
471+
if (Log_autovacuum == 0 ||
472+
TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(),
473+
Log_autovacuum))
487474
ereport(LOG,
488475
(errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s",
489476
get_database_name(MyDatabaseId),
490477
get_namespace_name(RelationGetNamespace(onerel)),
491478
RelationGetRelationName(onerel),
492479
pg_rusage_show(&ru0))));
493-
}
494480
}
495481
}
496482

‎src/backend/commands/vacuumlazy.c

+4-18
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,7 @@
3636
*
3737
*
3838
* IDENTIFICATION
39-
* $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.87 2007/04/19 16:26:44 alvherre Exp $
39+
* $PostgreSQL: pgsql/src/backend/commands/vacuumlazy.c,v 1.88 2007/04/30 03:23:48 tgl Exp $
4040
*
4141
*-------------------------------------------------------------------------
4242
*/
@@ -217,22 +217,9 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
217217
/* and log the action if appropriate */
218218
if (IsAutoVacuumWorkerProcess() && Log_autovacuum >= 0)
219219
{
220-
long diff = 0L;
221-
222-
if (Log_autovacuum > 0)
223-
{
224-
TimestampTz endtime;
225-
int usecs;
226-
long secs;
227-
228-
endtime = GetCurrentTimestamp();
229-
TimestampDifference(starttime, endtime, &secs, &usecs);
230-
231-
diff = secs * 1000 + usecs / 1000;
232-
}
233-
234-
if (Log_autovacuum == 0 || diff >= Log_autovacuum)
235-
{
220+
if (Log_autovacuum == 0 ||
221+
TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(),
222+
Log_autovacuum))
236223
ereport(LOG,
237224
(errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n"
238225
"pages: %d removed, %d remain\n"
@@ -245,7 +232,6 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt)
245232
vacrelstats->pages_removed, vacrelstats->rel_pages,
246233
vacrelstats->tuples_deleted, vacrelstats->rel_tuples,
247234
pg_rusage_show(&ru0))));
248-
}
249235
}
250236
}
251237

‎src/backend/postmaster/pgstat.c

+23-4
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313
*
1414
* Copyright (c) 2001-2007, PostgreSQL Global Development Group
1515
*
16-
* $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.153 2007/04/21 04:10:53 tgl Exp $
16+
* $PostgreSQL: pgsql/src/backend/postmaster/pgstat.c,v 1.154 2007/04/30 03:23:49 tgl Exp $
1717
* ----------
1818
*/
1919
#include "postgres.h"
@@ -608,15 +608,34 @@ void allow_immediate_pgstat_restart(void)
608608
/* ----------
609609
* pgstat_report_tabstat() -
610610
*
611-
* Called from tcop/postgres.c to send the so far collected
612-
* per table access statistics to the collector.
611+
* Called from tcop/postgres.c to send the so far collected per-table
612+
* access statistics to the collector. Note that this is called only
613+
* when not within a transaction, so it is fair to use transaction stop
614+
* time as an approximation of current time.
613615
* ----------
614616
*/
615617
void
616618
pgstat_report_tabstat(void)
617619
{
620+
static TimestampTz last_report = 0;
621+
TimestampTz now;
622+
623+
/* Don't expend a clock check if nothing to do */
624+
if (RegularTabStat.tsa_used == 0 &&
625+
SharedTabStat.tsa_used == 0)
626+
return;
627+
628+
/*
629+
* Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL
630+
* msec since we last sent one.
631+
*/
632+
now = GetCurrentTransactionStopTimestamp();
633+
if (!TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL))
634+
return;
635+
last_report = now;
636+
618637
/*
619-
* For each message buffer used during the last query set the header
638+
* For each message buffer used during the last queries, set the header
620639
* fields and send it out; then mark the entries unused.
621640
*/
622641
pgstat_report_one_tabstat(&RegularTabStat, MyDatabaseId);

‎src/backend/utils/adt/timestamp.c

+22-1
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.174 2007/02/27 23:48:09 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/utils/adt/timestamp.c,v 1.175 2007/04/30 03:23:49 tgl Exp $
1212
*
1313
*-------------------------------------------------------------------------
1414
*/
@@ -1238,6 +1238,27 @@ TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
12381238
}
12391239
}
12401240

1241+
/*
1242+
* TimestampDifferenceExceeds -- report whether the difference between two
1243+
* timestamps is >= a threshold (expressed in milliseconds)
1244+
*
1245+
* Both inputs must be ordinary finite timestamps (in current usage,
1246+
* they'll be results from GetCurrentTimestamp()).
1247+
*/
1248+
bool
1249+
TimestampDifferenceExceeds(TimestampTz start_time,
1250+
TimestampTz stop_time,
1251+
int msec)
1252+
{
1253+
TimestampTz diff = stop_time - start_time;
1254+
1255+
#ifdef HAVE_INT64_TIMESTAMP
1256+
return (diff >= msec * INT64CONST(1000));
1257+
#else
1258+
return (diff * 1000.0 >= msec);
1259+
#endif
1260+
}
1261+
12411262
/*
12421263
* Convert a time_t to TimestampTz.
12431264
*

‎src/include/access/xact.h

+2-1
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@
77
* Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
88
* Portions Copyright (c) 1994, Regents of the University of California
99
*
10-
* $PostgreSQL: pgsql/src/include/access/xact.h,v 1.85 2007/03/13 00:33:42 tgl Exp $
10+
* $PostgreSQL: pgsql/src/include/access/xact.h,v 1.86 2007/04/30 03:23:49 tgl Exp $
1111
*
1212
*-------------------------------------------------------------------------
1313
*/
@@ -142,6 +142,7 @@ extern SubTransactionId GetCurrentSubTransactionId(void);
142142
extern CommandId GetCurrentCommandId(void);
143143
extern TimestampTz GetCurrentTransactionStartTimestamp(void);
144144
extern TimestampTz GetCurrentStatementStartTimestamp(void);
145+
extern TimestampTz GetCurrentTransactionStopTimestamp(void);
145146
extern void SetCurrentStatementStartTimestamp(void);
146147
extern int GetCurrentTransactionNestLevel(void);
147148
extern bool TransactionIdIsCurrentTransactionId(TransactionId xid);

‎src/include/utils/timestamp.h

+4-1
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@
66
* Portions Copyright (c) 1996-2007, PostgreSQL Global Development Group
77
* Portions Copyright (c) 1994, Regents of the University of California
88
*
9-
* $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.67 2007/02/16 03:39:45 momjian Exp $
9+
* $PostgreSQL: pgsql/src/include/utils/timestamp.h,v 1.68 2007/04/30 03:23:49 tgl Exp $
1010
*
1111
*-------------------------------------------------------------------------
1212
*/
@@ -311,6 +311,9 @@ extern TimestampTz GetCurrentTimestamp(void);
311311

312312
extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
313313
long *secs, int *microsecs);
314+
extern bool TimestampDifferenceExceeds(TimestampTz start_time,
315+
TimestampTz stop_time,
316+
int msec);
314317

315318
extern TimestampTz time_t_to_timestamptz(time_t tm);
316319
extern time_t timestamptz_to_time_t(TimestampTz t);

‎src/test/regress/expected/stats.out

+8
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,14 @@ SELECT count(*) FROM tenk2 WHERE unique1 = 1;
7373
1
7474
(1 row)
7575

76+
-- force the rate-limiting logic in pgstat_report_tabstat() to time out
77+
-- and send a message
78+
SELECT pg_sleep(1.0);
79+
pg_sleep
80+
----------
81+
82+
(1 row)
83+
7684
-- wait for stats collector to update
7785
SELECT wait_for_stats();
7886
wait_for_stats

‎src/test/regress/sql/stats.sql

+4
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,10 @@ SELECT count(*) FROM tenk2;
6060
-- do an indexscan
6161
SELECT count(*) FROM tenk2 WHERE unique1 = 1;
6262

63+
-- force the rate-limiting logic in pgstat_report_tabstat() to time out
64+
-- and send a message
65+
SELECT pg_sleep(1.0);
66+
6367
-- wait for stats collector to update
6468
SELECT wait_for_stats();
6569

0 commit comments

Comments
 (0)