From: Chao Li <li.evan.chao@gmail.com>
Message-Id: <CDC22691-F63E-4FD3-865A-2982E3B56DCA@gmail.com>
Content-Type: multipart/mixed;
	boundary="Apple-Mail=_30FA8343-7DFC-431D-86FB-32E42F0D23F8"
Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3864.400.21\))
Subject: Re: pg_test_timing: fix unit typo and widen diff type
Date: Wed, 8 Apr 2026 12:06:07 +0800
In-Reply-To: <D83C0F3F-0CD8-4D1D-B59C-F2AFBB9B2974@gmail.com>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>,
 Tom Lane <tgl@sss.pgh.pa.us>,
 Hannu Krosing <hannuk@google.com>
To: Lukas Fittl <lukas@fittl.com>
References: <F780CEEB-A237-4302-9F55-60E9D8B6533D@gmail.com>
 <CAP53PkwEZ+UMmwA8cbUSUdE6phXi+xWmn5t-YAnvKf0qoBnOvg@mail.gmail.com>
 <D83C0F3F-0CD8-4D1D-B59C-F2AFBB9B2974@gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/CDC22691-F63E-4FD3-865A-2982E3B56DCA%40gmail.com>
Precedence: bulk


--Apple-Mail=_30FA8343-7DFC-431D-86FB-32E42F0D23F8
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
	charset=utf-8


> On Apr 2, 2026, at 15:28, Chao Li <li.evan.chao@gmail.com> wrote:
>=20
>=20
>=20
>> On Apr 2, 2026, at 12:17, Lukas Fittl <lukas@fittl.com> wrote:
>>=20
>> Hi Chao,
>>=20
>> On Wed, Apr 1, 2026 at 8:10=E2=80=AFPM Chao Li =
<li.evan.chao@gmail.com> wrote:
>>>=20
>>> Hi,
>>>=20
>>> 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 mistake in an error message. The relevant code is like:
>>> ```
>>> diff =3D INSTR_TIME_GET_NANOSEC(diff_time);
>>>=20
>>> fprintf(stderr, _("Time warp: %d ms\n"), diff);
>>> ```
>>>=20
>>> Here, =E2=80=9Cdiff" is in nanoseconds, but the error message prints =
ms as the unit, which is incorrect.
>>=20
>> Good catch!
>>=20
>> 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.
>>=20
>> 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.
>>=20
>>>=20
>>> To fix that, I think there are two possible options:
>>>=20
>>> 1. Use INSTR_TIME_GET_MILLISEC to get =E2=80=9Cdiff"
>>> 2. Change =E2=80=9Cms" to =E2=80=9Cns" in the error message
>>>=20
>>> After reading through the whole file, I think option 2 is the right =
fix. While doing that, I also noticed another issue.
>>>=20
>>> =E2=80=9Cdiff" is currently defined as int32. Although one might =
think that is enough for a time delta, I believe it should be int64 for =
two reasons:
>>>=20
>>> * INSTR_TIME_GET_NANOSEC() explicitly returns int64:
>>> ```
>>> #define INSTR_TIME_GET_NANOSEC(t) \
>>>              ((int64) (t).ticks)
>>> ```
>>>=20
>>> * 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 value 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 misleading.
>>=20
>> 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.
>=20
> You are right. Changed to pg_leftmost_one_pos64 in v2.
>=20
>>=20
>> Maybe we should error out if the diff is larger than an int32, noting
>> a positive time drift?
>=20
> I agree we should warn/fail upon clock forwards drift. But I doubt =
int32 is too big (~2.14 seconds), I consider 1 second could be a too big =
threshold. Let=E2=80=99s wait for more voices on this.
>=20
>>=20
>> 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.
>>=20
>=20
> Given the error should rarely happen, I personally feel that might not =
be super helpful. Also, if the drift is just beyond the threshold, =
bumping to microsecond or millisecond might print just 0.
>=20
> PFA v2 - updated 0002 for pg_leftmost_one_pos64.
>=20
> Best regards,
> --
> Chao Li (Evan)
> HighGo Software Co., Ltd.
> https://www.highgo.com/
>=20
>=20
>=20
>=20
> =
<v2-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch><v2-0002-=
pg_test_timing-use-int64-for-largest-observed-tim.patch>

PFA v3: Fixed a CI failure.

Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/


--Apple-Mail=_30FA8343-7DFC-431D-86FB-32E42F0D23F8
Content-Disposition: attachment;
	filename=v3-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch
Content-Type: application/octet-stream;
	x-unix-mode=0644;
	name="v3-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch"
Content-Transfer-Encoding: quoted-printable

=46rom=200b4419bd6318f29a56ec263de7d4be042b55a6d8=20Mon=20Sep=2017=20=
00:00:00=202001=0AFrom:=20"Chao=20Li=20(Evan)"=20<lic@highgo.com>=0A=
Date:=20Thu,=202=20Apr=202026=2010:21:40=20+0800=0ASubject:=20[PATCH=20=
v3=201/2]=20pg_test_timing:=20fix=20unit=20in=20backward-clock=20warning=0A=
=0Apg_test_timing=20measures=20timing=20differences=20in=20nanoseconds=20=
via=0AINSTR_TIME_GET_NANOSEC(),=20but=20the=20backward-clock=20warning=20=
incorrectly=0Areported=20the=20value=20as=20milliseconds.=20Fix=20the=20=
message=20to=20use=20"ns"=20so=0Athat=20it=20matches=20the=20actual=20=
unit=20of=20diff.=0A=0AAuthor:=20Chao=20Li=20<lic@highgo.com>=0A=
Reviewed-by:=20Lukas=20Fittl=20<lukas@fittl.com>=0ADiscussion:=20=
https://postgr.es/m/F780CEEB-A237-4302-9F55-60E9D8B6533D@gmail.com=0A---=0A=
=20src/bin/pg_test_timing/pg_test_timing.c=20|=202=20+-=0A=201=20file=20=
changed,=201=20insertion(+),=201=20deletion(-)=0A=0Adiff=20--git=20=
a/src/bin/pg_test_timing/pg_test_timing.c=20=
b/src/bin/pg_test_timing/pg_test_timing.c=0Aindex=20=
2afb0e6a410..944b25df1f2=20100644=0A---=20=
a/src/bin/pg_test_timing/pg_test_timing.c=0A+++=20=
b/src/bin/pg_test_timing/pg_test_timing.c=0A@@=20-281,7=20+281,7=20@@=20=
test_timing(unsigned=20int=20duration,=20TimingClockSourceType=20source,=20=
bool=20fast_timin=0A=20=09=09if=20(unlikely(diff=20<=200))=0A=20=09=09{=0A=
=20=09=09=09fprintf(stderr,=20_("Detected=20clock=20going=20backwards=20=
in=20time.\n"));=0A-=09=09=09fprintf(stderr,=20_("Time=20warp:=20%d=20=
ms\n"),=20diff);=0A+=09=09=09fprintf(stderr,=20_("Time=20warp:=20%d=20=
ns\n"),=20diff);=0A=20=09=09=09exit(1);=0A=20=09=09}=0A=20=0A--=20=0A=
2.50.1=20(Apple=20Git-155)=0A=0A=

--Apple-Mail=_30FA8343-7DFC-431D-86FB-32E42F0D23F8
Content-Disposition: attachment;
	filename=v3-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch
Content-Type: application/octet-stream;
	x-unix-mode=0644;
	name="v3-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch"
Content-Transfer-Encoding: quoted-printable

=46rom=20e193672cc7cd5736290af81a1ce8acd2f4237224=20Mon=20Sep=2017=20=
00:00:00=202001=0AFrom:=20"Chao=20Li=20(Evan)"=20<lic@highgo.com>=0A=
Date:=20Thu,=202=20Apr=202026=2010:29:06=20+0800=0ASubject:=20[PATCH=20=
v3=202/2]=20pg_test_timing:=20use=20int64=20for=20largest=20observed=20=
time=0A=20delta=0A=0Apg_test_timing=20obtains=20timing=20deltas=20with=20=
INSTR_TIME_GET_NANOSEC(),=0Awhich=20returns=20a=20nanosecond=20value=20=
that=20should=20be=20stored=20in=20int64.=20Adjust=0Adiff=20and=20=
largest_diff=20to=20use=20int64=20accordingly.=0A=0AAlso=20fix=20the=20=
corresponding=20printf=20format=20specifiers=20so=20these=20values=20are=0A=
printed=20correctly.=0A=0AAuthor:=20Chao=20Li=20<lic@highgo.com>=0A=
Reviewed-by:=20Lukas=20Fittl=20<lukas@fittl.com>=0ADiscussion:=20=
https://postgr.es/m/F780CEEB-A237-4302-9F55-60E9D8B6533D@gmail.com=0A---=0A=
=20src/bin/pg_test_timing/pg_test_timing.c=20|=2014=20+++++++-------=0A=20=
1=20file=20changed,=207=20insertions(+),=207=20deletions(-)=0A=0Adiff=20=
--git=20a/src/bin/pg_test_timing/pg_test_timing.c=20=
b/src/bin/pg_test_timing/pg_test_timing.c=0Aindex=20=
944b25df1f2..ce4c54256e3=20100644=0A---=20=
a/src/bin/pg_test_timing/pg_test_timing.c=0A+++=20=
b/src/bin/pg_test_timing/pg_test_timing.c=0A@@=20-25,7=20+25,7=20@@=20=
static=20long=20long=20int=20histogram[32];=0A=20static=20long=20long=20=
int=20direct_histogram[NUM_DIRECT];=0A=20=0A=20/*=20separately=20record=20=
highest=20observed=20duration=20*/=0A-static=20int32=20largest_diff;=0A=
+static=20int64=20largest_diff;=0A=20static=20long=20long=20int=20=
largest_diff_count;=0A=20=0A=20=0A@@=20-262,8=20+262,8=20@@=20=
test_timing(unsigned=20int=20duration,=20TimingClockSourceType=20source,=20=
bool=20fast_timin=0A=20=0A=20=09while=20(INSTR_TIME_GT(end_time,=20cur))=0A=
=20=09{=0A-=09=09int32=09=09diff,=0A-=09=09=09=09=09bits;=0A+=09=09int64=09=
=09diff;=0A+=09=09int32=09=09bits;=0A=20=09=09instr_time=09diff_time;=0A=20=
=0A=20=09=09prev=20=3D=20cur;=0A@@=20-281,13=20+281,13=20@@=20=
test_timing(unsigned=20int=20duration,=20TimingClockSourceType=20source,=20=
bool=20fast_timin=0A=20=09=09if=20(unlikely(diff=20<=200))=0A=20=09=09{=0A=
=20=09=09=09fprintf(stderr,=20_("Detected=20clock=20going=20backwards=20=
in=20time.\n"));=0A-=09=09=09fprintf(stderr,=20_("Time=20warp:=20%d=20=
ns\n"),=20diff);=0A+=09=09=09fprintf(stderr,=20_("Time=20warp:=20"=20=
INT64_FORMAT=20"=20ns\n"),=20diff);=0A=20=09=09=09exit(1);=0A=20=09=09}=0A=
=20=0A=20=09=09/*=20What=20is=20the=20highest=20bit=20in=20the=20time=20=
diff?=20*/=0A=20=09=09if=20(diff=20>=200)=0A-=09=09=09bits=20=3D=20=
pg_leftmost_one_pos32(diff)=20+=201;=0A+=09=09=09bits=20=3D=20=
pg_leftmost_one_pos64(diff)=20+=201;=0A=20=09=09else=0A=20=09=09=09bits=20=
=3D=200;=0A=20=0A@@=20-409,8=20+409,8=20@@=20output(uint64=20loop_count)=0A=
=20=09=09double=09=09prct=20=3D=20(double)=20largest_diff_count=20*=20=
100=20/=20loop_count;=0A=20=0A=20=09=09printf("...\n");=0A-=09=09=
printf("%*d=20=20=20%*.4f=20%*.4f=20%*lld\n",=0A-=09=09=09=20=20=20len1,=20=
largest_diff,=0A+=09=09printf("%*lld=20=20=20%*.4f=20%*.4f=20%*lld\n",=0A=
+=09=09=09=20=20=20len1,=20(long=20long)=20largest_diff,=0A=20=09=09=09=20=
=20=20len2,=20prct,=0A=20=09=09=09=20=20=20len3,=20100.0,=0A=20=09=09=09=20=
=20=20len4,=20largest_diff_count);=0A--=20=0A2.50.1=20(Apple=20Git-155)=0A=
=0A=

--Apple-Mail=_30FA8343-7DFC-431D-86FB-32E42F0D23F8--