Re: pgbench logging broken by time logic changes

On Wed, 16 Jun 2021 10:49:36 -0400
Gregory Smith <gregsmithpgsql(at)gmail(dot)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(at)sraoss(dot)co(dot)jp>