Hello,
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?
+1 The patch rounds down sd->start_time from ms to s but it seems to
me a degradation.
Yes, please we should not use time.
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.
If I understand the op correctly, the problem here is the time values
in pgbench log file are based on a bogus epoch.
It is not "bogus", but is not necessary epoch depending on the underlying
function called behind by INSTR_TIME macros, and people are entitled to
expect epoch for log correlations.
If it's the only issue
here and and if we just want to show the time based on the unix epoch
time, just recording the difference would work as I scketched in the
attached. (Precisely theepoch would move if we set the system clock
but I don't think that matters:p)
I do like the approach.
I'm hesitant to promote it for fixing the beta, but the code impact is
small enough, so I'd say yes. Maybe there is a similar issue with progress
which should probably use the same approach. I think that aligning the
implementations can wait for pg15.
The patch as white space issues. Attached an updated version which fixes
that, adds comments and simplify the code a little bit.
I'm not sure we have transaction lasts for very short time that
nanoseconds matters.
Indeed.
--
Fabien.
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index d7479925cb..876c5a4547 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -342,6 +342,12 @@ typedef struct StatsData
SimpleStats lag;
} StatsData;
+/*
+ * For displaying epoch timestamp, as some time functions may have
+ * another reference.
+ */
+pg_time_usec_t epoch_shift;
+
/*
* Struct to keep random state.
*/
@@ -3803,7 +3809,7 @@ doLog(TState *thread, CState *st,
{
/* print aggregated report to logfile */
fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
- agg->start_time,
+ agg->start_time + epoch_shift,
agg->cnt,
agg->latency.sum,
agg->latency.sum2,
@@ -3830,6 +3836,9 @@ doLog(TState *thread, CState *st,
}
else
{
+ /* switch to epoch for displaying the timestamp */
+ now += epoch_shift;
+
/* no, print raw transactions */
if (skipped)
fprintf(logfile, "%d " INT64_FORMAT " skipped %d " INT64_FORMAT " "
@@ -5775,6 +5784,11 @@ main(int argc, char **argv)
char *env;
int exit_code = 0;
+ struct timeval tv;
+
+ /* record shift between epoch and now() */
+ gettimeofday(&tv, NULL);
+ epoch_shift = tv.tv_sec * 1000000 + tv.tv_usec - pg_time_now();
pg_logging_init(argv[0]);
progname = get_progname(argv[0]);
