Re: pgbench logging broken by time logic changes

On Thu, 17 Jun 2021 14:17:56 +0900 (JST)
Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:

> 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.

I don't think that's matter because sd->start_time is used only for
log aggregation and aggregate-interval is specified in seconds, though.

> > 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)

That makes sense. If the system clock is shifted due to NTP (for example)
it would not affect the measurement although timestamps in logs could be shifted
because gettimeofday is called only once.

If we fix it in this way, we should fix also printProgressReport().

     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));
     }

> > 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.

I thought it might affect the accuracy when statistics are accumulated
through a huge numbers of transactions, but I am fine with it if no one
cares it.

Regards,
Yugo Nagata

-- 
Yugo NAGATA <nagata@sraoss.co.jp>