Re: pgbench logging broken by time logic changes

At Thu, 17 Jun 2021 12:23:42 +0900, Yugo NAGATA <nagata@sraoss.co.jp> wrote in 
> On Wed, 16 Jun 2021 21:11:41 +0200 (CEST)
> Fabien COELHO <coelho@cri.ensmp.fr> wrote:
> > I cannot say that I'm thrilled by having multiple tv stuff back in several 
> > place. I can be okay with one, though. What about the attached? Does it 
> > make sense?

+1 The patch rounds down sd->start_time from ms to s but it seems to
me a degradation.

> At first, I also thought of fixing pg_time_now() to use gettimeofday() instead
> of INSTR_TIME_SET_CURRENT, but I noticed that using INSTR_TIME_SET_CURRENT is
> proper to measure time interval.  I mean, this macro uses
> lock_gettime(CLOCK_MONOTONIC, ) if avilable, which give reliable interval
> timing even in the face of changes to the system clock due to NTP.

If I understand the op correctly, the problem here is the time values
in pgbench log file are based on a bogus epoch. If it's the only issue
here and and if we just want to show the time based on the unix epoch
time, just recording the difference would work as I scketched in the
attached.  (Precisely theepoch would move if we set the system clock
but I don't think that matters:p)

> By the way, there is another advantage of using clock_gettime(). That is, this
> returns precise results in nanoseconds. However, we can not benefit from it because
> pg_time_now() converts the value to uint64 by using INSTR_TIME_GET_MICROSEC. So,
> if we would like more precious statistics in pgbench, it might be better to use
> INSTR_TIME_GET_MICROSEC instead of pg_time_now in other places.

I'm not sure we have transaction lasts for very short time that
nanoseconds matters.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index d7479925cb..0ce9315a2b 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -342,6 +342,8 @@ typedef struct StatsData
     SimpleStats lag;
 } StatsData;
 
+pg_time_usec_t epoch_shift;
+
 /*
  * Struct to keep random state.
  */
@@ -3803,7 +3805,7 @@ doLog(TState *thread, CState *st,
         {
             /* print aggregated report to logfile */
             fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
-                    agg->start_time,
+                    agg->start_time + epoch_shift,
                     agg->cnt,
                     agg->latency.sum,
                     agg->latency.sum2,
@@ -3834,12 +3836,12 @@ doLog(TState *thread, CState *st,
         if (skipped)
             fprintf(logfile, "%d " INT64_FORMAT " skipped %d " INT64_FORMAT " "
                     INT64_FORMAT,
-                    st->id, st->cnt, st->use_file, now / 1000000, now % 1000000);
+                    st->id, st->cnt, st->use_file, (now + epoch_shift) / 1000000, (now + epoch_shift) % 1000000);
         else
             fprintf(logfile, "%d " INT64_FORMAT " %.0f %d " INT64_FORMAT " "
                     INT64_FORMAT,
                     st->id, st->cnt, latency, st->use_file,
-                    now / 1000000, now % 1000000);
+                    (now + epoch_shift) / 1000000, (now + epoch_shift) % 1000000);
         if (throttle_delay)
             fprintf(logfile, " %.0f", lag);
         fputc('\n', logfile);
@@ -5775,7 +5777,12 @@ main(int argc, char **argv)
     char       *env;
 
     int            exit_code = 0;
+    struct timeval tv;
 
+    gettimeofday(&tv, NULL);
+    
+    epoch_shift = tv.tv_sec * 1000000 + tv.tv_usec - pg_time_now();
+        
     pg_logging_init(argv[0]);
     progname = get_progname(argv[0]);