Re: pgbench logging broken by time logic changes

Hello Yugo-san,

>>> I think we can fix this issue by using gettimeofday for logging as before
>>> this was changed. I attached the patch.
>>
>> 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?
>
> 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.

Ok, I was thinking that it was possible that there was this kind of 
implication. Now, does it matter that much if a few transactions are 
skewed by NTP from time to time? Having to deal with different time 
functions in the same file seems painful.

> The commit 547f04e7 changed all of INSTR_TIME_SET_CURRENT, gettimeofday(), and
> time() to pg_now_time() which calls INSTR_TIME_SET_CURRENT in it. So, my patch
> intented to revert these changes only about gettimeofday() and time(), and remain
> changes about INSTR_TIME_SET_CURRENT.

Hmmm.

> pg_time_now(bool use_epoch)
> {
>     if (use_epoch)
>      {
>        struct timeval tv;
>        gettimeofday(&tv, NULL);
>        return tv.tv_sec * 1000000 + tv.tv_usec;
>       }
>     else
>       {
>         instr_time      now;
>         INSTR_TIME_SET_CURRENT(now);
>         return (pg_time_usec_t) INSTR_TIME_GET_MICROSEC(now);
>       }
> }
>
> or making an additional function that returns epoch time.

Yes, but when to call which version? How to avoid confusion? After giving 
it some thoughts, ISTM that the best short-term decision is just to have 
epoch everywhere, i.e. having now() to rely on gettimeofday, because:

  - at least one user is unhappy with not having epoch in the log file,
    and indeed it makes sense to be unhappy about that if they want to
    correlated logs. So I agree to undo that, or provide an option to undo
    it.

  - having different times with different origins at different point in
    the code makes it really hard to understand and maintain, and if we
    trade maintainability for precision it should really be worth it, and
    I'm not sure that working around NTP adjustment is worth it right now.

In the not so short term, I'd say that the best approach would be use 
relative time internally and just to offset these with a global epoch 
start time when displaying a timestamp.

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

The INSTR_TIME macros are pretty ugly and inefficient, especially when 
time arithmetic is involved because they re-implements 64 bits operations 
based on 32 bit ints. I really wanted to get rid of that as much as 
possible. From a database benchmarking perspective ISTM that µs is the 
right smallest unit, given that a transaction implies significant delays 
such as networks communications, parsing, and so on. So I do not think we 
should ever need nanos.

In conclusion, ISTM that it is enough to simply change now to call 
gettimeofday to fix the issue raised by Greg. This is patch v1 on the 
thread.

-- 
Fabien.