From: Fabien COELHO <coelho@cri.ensmp.fr>
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: nagata@sraoss.co.jp
Cc: gregsmithpgsql@gmail.com
Cc: pgsql-hackers@postgresql.org
Cc: david.christensen@crunchydata.com
Subject: Re: pgbench logging broken by time logic changes
Date: Thu, 17 Jun 2021 09:15:37 +0200 (CEST)
Message-ID: <alpine.DEB.2.22.394.2106170901100.2693553@pseudo> (raw)
In-Reply-To: <20210617.141756.654908256727895408.horikyota.ntt@gmail.com>
References: <20210617025138.04a35c3ae9a6cd40c077cea0@sraoss.co.jp>
<alpine.DEB.2.22.394.2106162102030.2407635@pseudo>
<20210617122342.74aa8e65b186a7f2e0034533@sraoss.co.jp>
<20210617.141756.654908256727895408.horikyota.ntt@gmail.com>
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.
Attachments:pgbench-epoch-4.patch (text/x-diff, 1.3K) downloaddiff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex 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]);
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: coelho@cri.ensmp.fr, horikyota.ntt@gmail.com, nagata@sraoss.co.jp, gregsmithpgsql@gmail.com, david.christensen@crunchydata.com
Subject: Re: pgbench logging broken by time logic changes
In-Reply-To: <alpine.DEB.2.22.394.2106170901100.2693553@pseudo>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox