On Wed, 16 Jun 2021 10:49:36 -0400 Gregory Smith <gregsmithpg...@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 <nag...@sraoss.co.jp>
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index d7479925cb..2be0c62cab 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -3778,7 +3778,6 @@ doLog(TState *thread, CState *st, StatsData *agg, bool skipped, double latency, double lag) { FILE *logfile = thread->logfile; - pg_time_usec_t now = pg_time_now(); Assert(use_log); @@ -3793,6 +3792,8 @@ doLog(TState *thread, CState *st, /* should we aggregate the results or not? */ if (agg_interval > 0) { + pg_time_usec_t now = pg_time_now(); + /* * Loop until we reach the interval of the current moment, and print * any empty intervals in between (this may happen with very low tps, @@ -3830,16 +3831,21 @@ doLog(TState *thread, CState *st, } else { + struct timeval tv; + + gettimeofday(&tv, NULL); + /* no, print raw transactions */ 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, + (long) tv.tv_sec, (long) tv.tv_usec); else fprintf(logfile, "%d " INT64_FORMAT " %.0f %d " INT64_FORMAT " " INT64_FORMAT, st->id, st->cnt, latency, st->use_file, - now / 1000000, now % 1000000); + (long) tv.tv_sec, (long) tv.tv_usec); if (throttle_delay) fprintf(logfile, " %.0f", lag); fputc('\n', logfile); @@ -5455,7 +5461,16 @@ printProgressReport(TState *threads, int64 test_start, pg_time_usec_t now, if (progress_timestamp) { - snprintf(tbuf, sizeof(tbuf), "%.3f s", PG_TIME_GET_DOUBLE(now)); + /* + * On some platforms the current system timestamp is available in + * now_time, but rather than get entangled with that, we just eat the + * cost of an extra syscall in all cases. + */ + struct timeval tv; + + gettimeofday(&tv, NULL); + snprintf(tbuf, sizeof(tbuf), "%ld.%03ld s", + (long) tv.tv_sec, (long) (tv.tv_usec / 1000)); } else {