Re: pgbench logging broken by time logic changes

On Wed, 16 Jun 2021 10:49:36 -0400
Gregory Smith <gregsmithpgsql@gmail.com> wrote:

> A lot of things are timed in pgbench now so I appreciate the idea.  Y'all
> started that whole big thread about sync on my birthday though and I didn't
> follow the details of what that was reviewed against.  For the logging use
> case I suspect it's just broken everywhere.  The two platforms I tested
> were PGDG Ubuntu beta1 apt install and Mac git build.  Example:
> 
>     $ createdb pgbench
>     $ pgbench -i -s 1 pgbench
>     $ pgbench -S -T 1 -l pgbench
>     $ head pgbench_log.*
>     0 1 1730 0 1537380 70911
>     0 2 541 0 1537380 71474
> 
> The epoch time is the 5th column in the output, and this week it should
> look like this:
> 
>     0 1 1411 0 1623767029 732926
>     0 2 711 0 1623767029 733660
> 
> If you're not an epoch guru who recognizes what's wrong already, you might
> grab https://github.com/gregs1104/pgbench-tools/ and party like it's 1970
> to see it:
> 
>     $ ~/repos/pgbench-tools/log-to-csv 1 local < pgbench_log* | head
>     1970-01-18 14:03:00.070911,0,1.73,1,local
>     1970-01-18 14:03:00.071474,0,0.541,1,local

After the commit, pgbench tries to get the current timestamp by calling
pg_time_now(). This uses INSTR_TIME_SET_CURRENT in it, but this macro
can call clock_gettime(CLOCK_MONOTONIC[_RAW], ) instead of gettimeofday
or clock_gettime(CLOCK_REALTIME, ). When CLOCK_MONOTONIC[_RAW] is used,
clock_gettime doesn't return epoch time. Therefore, we can use
INSTR_TIME_SET_CURRENT aiming to calculate a duration, but we should
not have used this to get the current timestamp.

I think we can fix this issue by using gettimeofday for logging as before
this was changed. I attached the patch.

Regards,
Yugo Nagata

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