MIME-Version: 1.0
References: <F780CEEB-A237-4302-9F55-60E9D8B6533D@gmail.com>
In-Reply-To: <F780CEEB-A237-4302-9F55-60E9D8B6533D@gmail.com>
From: Lukas Fittl <lukas@fittl.com>
Date: Wed, 1 Apr 2026 21:17:35 -0700
Message-ID: 
 <CAP53PkwEZ+UMmwA8cbUSUdE6phXi+xWmn5t-YAnvKf0qoBnOvg@mail.gmail.com>
Subject: Re: pg_test_timing: fix unit typo and widen diff type
To: Chao Li <li.evan.chao@gmail.com>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>,
 Tom Lane <tgl@sss.pgh.pa.us>,
	Hannu Krosing <hannuk@google.com>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAP53PkwEZ%2BUMmwA8cbUSUdE6phXi%2BxWmn5t-YAnvKf0qoBnOvg%40mail.gmail.com>
Precedence: bulk

Hi Chao,

On Wed, Apr 1, 2026 at 8:10=E2=80=AFPM Chao Li <li.evan.chao@gmail.com> wro=
te:
>
> Hi,
>
> This morning, as part of my usual routine, I synced the master branch and=
 read through the recent commits. While reading 82c0cb4e672, I noticed a mi=
stake in an error message. The relevant code is like:
> ```
> diff =3D INSTR_TIME_GET_NANOSEC(diff_time);
>
> fprintf(stderr, _("Time warp: %d ms\n"), diff);
> ```
>
> Here, =E2=80=9Cdiff" is in nanoseconds, but the error message prints ms a=
s the unit, which is incorrect.

Good catch!

It looks like the use of nanoseconds for "diff" got introduced last
year in 0b096e379e6f9bd49 (as you note later in the email, today's
commit didn't actually change that part), CCing Tom and Hannu as
authors of that earlier change.

That said, its a bit odd that we were using INSTR_TIME_GET_MICROSEC
there before that earlier commit, but called it "ms" (i.e.
milliseconds) in the error message.

>
> To fix that, I think there are two possible options:
>
> 1. Use INSTR_TIME_GET_MILLISEC to get =E2=80=9Cdiff"
> 2. Change =E2=80=9Cms" to =E2=80=9Cns" in the error message
>
> After reading through the whole file, I think option 2 is the right fix. =
While doing that, I also noticed another issue.
>
> =E2=80=9Cdiff" is currently defined as int32. Although one might think th=
at is enough for a time delta, I believe it should be int64 for two reasons=
:
>
> * INSTR_TIME_GET_NANOSEC() explicitly returns int64:
> ```
> #define INSTR_TIME_GET_NANOSEC(t) \
>                ((int64) (t).ticks)
> ```
>
> * The current code has a sanity check for backward clock drift:
> ```
>         /* Did time go backwards? */
>         if (unlikely(diff < 0))
>         {
>             fprintf(stderr, _("Detected clock going backwards in time.\n"=
));
>             fprintf(stderr, _("Time warp: %d ms\n"), diff);
>             exit(1);
>         }
> ```
> Clock jumping forward is also possible, and a forward jump of about 2.14 =
seconds would overflow int32 when expressed in nanoseconds, making the valu=
e appear negative. In that case, the code could report a =E2=80=9Cbackwards=
=E2=80=9D clock jump when the actual jump was forwards, which would be misl=
eading.

I agree it doesn't seem sound to use an int32 for storing the result
of INSTR_TIME_GET_NANOSEC. It looks like we may also need to adjust
the call to pg_leftmost_one_pos32 though if we actually accept that
large a "diff" value, as in your patch.

Maybe we should error out if the diff is larger than an int32, noting
a positive time drift?

Independently of that, its worth noting we could easily emit the diff
in a larger unit (micro or milliseconds) for easier interpretation, by
just calling INSTR_TIME_GET_MICROSEC / INSTR_TIME_GET_MILLISEC on the
"diff_time" again.

Thanks,
Lukas


--
Lukas Fittl