On Wed, 16 Jun 2021 10:49:36 -0400
Gregory Smith <[email protected]> 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 <[email protected]>
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
{
