mirrors/postgres
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Fix pgbench timestamp bugs.

Browse Source 
Commit 547f04e changed pgbench to use microsecond accounting, but
introduced a couple of logging and aggregation bugs:

1.  We print Unix epoch timestamps so that you can correlate them with
other logs, but these were inadvertently changed to use a
system-dependent reference epoch.  Compute Unix timestamps, and begin
aggregation intervals on the boundaries of whole Unix epoch seconds, as
before.

2.  The user-supplied aggregation interval needed to be scaled.

Back-patch to 14.

Author: Fabien COELHO <coelho@cri.ensmp.fr>
Author: Yugo NAGATA <nagata@sraoss.co.jp>
Author: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Reported-by: YoungHwan Joo <rulyox@gmail.com>
Reported-by: Gregory Smith <gregsmithpgsql@gmail.com>
Discussion: https://postgr.es/m/CAF7igB1r6wRfSCEAB-iZBKxkowWY6%2BdFF2jObSdd9%2BiVK%2BvHJg%40mail.gmail.com
Discussion: https://postgr.es/m/CAHLJuCW_8Vpcr0%3Dt6O_gozrg3wXXWXZXDioYJd3NhvKriqgpfQ%40mail.gmail.com
This commit is contained in:
Thomas Munro 2021-07-11 19:50:55 +12:00
parent 10a07973cf
commit 5614a0f78e
1 changed files with 34 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

43
src/bin/pgbench/pgbench.c
View File

@ -343,6 +343,12 @@ typedef struct StatsData
SimpleStats lag; SimpleStats lag;
} StatsData; } StatsData;
/*
* For displaying Unix epoch timestamps, as some time functions may have
* another reference.
*/
pg_time_usec_t epoch_shift;
/* /*
* Struct to keep random state. * Struct to keep random state.
*/ */
@ -3772,16 +3778,17 @@ executeMetaCommand(CState *st, pg_time_usec_t *now)
* Print log entry after completing one transaction. * Print log entry after completing one transaction.
* *
* We print Unix-epoch timestamps in the log, so that entries can be * We print Unix-epoch timestamps in the log, so that entries can be
* correlated against other logs. On some platforms this could be obtained * correlated against other logs.
* from the caller, but rather than get entangled with that, we just eat *
* the cost of an extra syscall in all cases. * XXX We could obtain the time from the caller and just shift it here, to
* avoid the cost of an extra call to pg_time_now().
*/ */
static void static void
doLog(TState *thread, CState *st, doLog(TState *thread, CState *st,
StatsData *agg, bool skipped, double latency, double lag) StatsData *agg, bool skipped, double latency, double lag)
{ {
FILE *logfile = thread->logfile; FILE *logfile = thread->logfile;
pg_time_usec_t now = pg_time_now(); pg_time_usec_t now = pg_time_now() + epoch_shift;
Assert(use_log); Assert(use_log);
@ -3796,17 +3803,19 @@ doLog(TState *thread, CState *st,
/* should we aggregate the results or not? */ /* should we aggregate the results or not? */
if (agg_interval > 0) if (agg_interval > 0)
{ {
pg_time_usec_t next;
/* /*
* Loop until we reach the interval of the current moment, and print * Loop until we reach the interval of the current moment, and print
* any empty intervals in between (this may happen with very low tps, * any empty intervals in between (this may happen with very low tps,
* e.g. --rate=0.1). * e.g. --rate=0.1).
*/ */
while (agg->start_time + agg_interval <= now) while ((next = agg->start_time + agg_interval * INT64CONST(1000000)) <= now)
{ {
/* print aggregated report to logfile */ /* print aggregated report to logfile */
fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f", fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
agg->start_time, agg->start_time / 1000000, /* seconds since Unix epoch */
agg->cnt, agg->cnt,
agg->latency.sum, agg->latency.sum,
agg->latency.sum2, agg->latency.sum2,
@ -3825,7 +3834,7 @@ doLog(TState *thread, CState *st,
fputc('\n', logfile); fputc('\n', logfile);
/* reset data and move to next interval */ /* reset data and move to next interval */
initStats(agg, agg->start_time + agg_interval); initStats(agg, next);
} }
/* accumulate the current transaction */ /* accumulate the current transaction */
@ -5458,7 +5467,8 @@ printProgressReport(TState *threads, int64 test_start, pg_time_usec_t now,
if (progress_timestamp) if (progress_timestamp)
{ {
snprintf(tbuf, sizeof(tbuf), "%.3f s", PG_TIME_GET_DOUBLE(now)); snprintf(tbuf, sizeof(tbuf), "%.3f s",
PG_TIME_GET_DOUBLE(now + epoch_shift));
} }
else else
{ {
@ -5808,6 +5818,14 @@ main(int argc, char **argv)
char *env; char *env;
int exit_code = 0; int exit_code = 0;
struct timeval tv;
/*
* Record difference between Unix time and instr_time time. We'll use
* this for logging and aggregation.
*/
gettimeofday(&tv, NULL);
epoch_shift = tv.tv_sec * INT64CONST(1000000) + tv.tv_usec - pg_time_now();
pg_logging_init(argv[0]); pg_logging_init(argv[0]);
progname = get_progname(argv[0]); progname = get_progname(argv[0]);
@ -6637,7 +6655,14 @@ threadRun(void *arg)
thread->bench_start = start; thread->bench_start = start;
thread->throttle_trigger = start; thread->throttle_trigger = start;
initStats(&aggs, start); /*
* The log format currently has Unix epoch timestamps with whole numbers
* of seconds. Round the first aggregate's start time down to the nearest
* Unix epoch second (the very first aggregate might really have started a
* fraction of a second later, but later aggregates are measured from the
* whole number time that is actually logged).
*/
initStats(&aggs, (start + epoch_shift) / 1000000 * 1000000);
last = aggs; last = aggs;
/* loop till all clients have terminated */ /* loop till all clients have terminated */