Fix pgbench timestamp bugs.

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

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 4aeccd93af87abe8bd6091372237afd07da85034..364b5a2e47d01885d746fb83ed15798a9696d523 100644 (file)
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -343,6 +343,12 @@ typedef struct StatsData
        SimpleStats lag;
 } 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.
  */
@@ -3772,16 +3778,17 @@ executeMetaCommand(CState *st, pg_time_usec_t *now)
  * Print log entry after completing one transaction.
  *
  * We print Unix-epoch timestamps in the log, so that entries can be
- * correlated against other logs.  On some platforms this could be obtained
- * from the caller, but rather than get entangled with that, we just eat
- * the cost of an extra syscall in all cases.
+ * correlated against other logs.
+ *
+ * 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
 doLog(TState *thread, CState *st,
          StatsData *agg, bool skipped, double latency, double lag)
 {
        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);
 
@@ -3796,17 +3803,19 @@ doLog(TState *thread, CState *st,
        /* should we aggregate the results or not? */
        if (agg_interval > 0)
        {
+               pg_time_usec_t next;
+
                /*
                 * Loop until we reach the interval of the current moment, and print
                 * any empty intervals in between (this may happen with very low tps,
                 * 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 */
                        fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
-                                       agg->start_time,
+                                       agg->start_time / 1000000,      /* seconds since Unix epoch */
                                        agg->cnt,
                                        agg->latency.sum,
                                        agg->latency.sum2,
@@ -3825,7 +3834,7 @@ doLog(TState *thread, CState *st,
                        fputc('\n', logfile);
 
                        /* reset data and move to next interval */
-                       initStats(agg, agg->start_time + agg_interval);
+                       initStats(agg, next);
                }
 
                /* accumulate the current transaction */
@@ -5458,7 +5467,8 @@ printProgressReport(TState *threads, int64 test_start, pg_time_usec_t now,
 
        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
        {
@@ -5808,6 +5818,14 @@ main(int argc, char **argv)
        char       *env;
 
        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]);
        progname = get_progname(argv[0]);
@@ -6637,7 +6655,14 @@ threadRun(void *arg)
        thread->bench_start = 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;
 
        /* loop till all clients have terminated */