public inbox for [email protected]
help / color / mirror / Atom feedpg_test_timing: fix unit typo and widen diff type
11+ messages / 4 participants
[nested] [flat]
* pg_test_timing: fix unit typo and widen diff type
@ 2026-04-02 03:09 Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Chao Li @ 2026-04-02 03:09 UTC (permalink / raw)
To: PostgreSQL Hackers <[email protected]>
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 mistake in an error message. The relevant code is like:
```
diff = INSTR_TIME_GET_NANOSEC(diff_time);
fprintf(stderr, _("Time warp: %d ms\n"), diff);
```
Here, “diff" is in nanoseconds, but the error message prints ms as the unit, which is incorrect.
To fix that, I think there are two possible options:
1. Use INSTR_TIME_GET_MILLISEC to get “diff"
2. Change “ms" to “ns" 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.
“diff" 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:
* 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 value appear negative. In that case, the code could report a “backwards” clock jump when the actual jump was forwards, which would be misleading.
To make the patch easier to process, I split it into two parts: 0001 fixes the unit in the error message, and 0002 changes the type of diff. If this gets accepted, I would be happy to squash them into one commit.
I should also note that although I noticed this while reading 82c0cb4e672, I do not think this was an oversight of that commit. More likely, because clock drift backwards is rare, this issue has simply gone unnoticed for many years.
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
Attachments:
[application/octet-stream] v1-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch (1.1K, 2-v1-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch)
download | inline diff:
From 0dc6d45322d60fb54c27a649f2b146242ed64f62 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:21:40 +0800
Subject: [PATCH v1 1/2] pg_test_timing: fix unit in backward-clock warning
pg_test_timing measures timing differences in nanoseconds via
INSTR_TIME_GET_NANOSEC(), but the backward-clock warning incorrectly
reported the value as milliseconds. Fix the message to use "ns" so
that it matches the actual unit of diff.
Author: Chao Li <[email protected]>
Reviewed-by:
Discussion: https://postgr.es/m/
---
src/bin/pg_test_timing/pg_test_timing.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index aee41dbe3f9..cbdc5af09d9 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -191,7 +191,7 @@ test_timing(unsigned int duration)
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d ns\n"), diff);
exit(1);
}
--
2.50.1 (Apple Git-155)
[application/octet-stream] v1-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch (1.9K, 3-v1-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch)
download | inline diff:
From e29ff7fef693e830b4929f9b7444cc943fd16516 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:29:06 +0800
Subject: [PATCH v1 2/2] pg_test_timing: use int64 for largest observed time
delta
pg_test_timing obtains timing deltas with INSTR_TIME_GET_NANOSEC(),
which returns a nanosecond value that should be stored in int64. Adjust
diff and largest_diff to use int64 accordingly.
Also fix the corresponding printf format specifiers so these values are
printed correctly.
Author: Chao Li <[email protected]>
Reviewed-by:
Discussion: https://postgr.es/m/
---
src/bin/pg_test_timing/pg_test_timing.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index cbdc5af09d9..07b98a6388d 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -25,7 +25,7 @@ static long long int histogram[32];
static long long int direct_histogram[NUM_DIRECT];
/* separately record highest observed duration */
-static int32 largest_diff;
+static int64 largest_diff;
static long long int largest_diff_count;
@@ -176,8 +176,8 @@ test_timing(unsigned int duration)
while (INSTR_TIME_GT(end_time, cur))
{
- int32 diff,
- bits;
+ int64 diff;
+ int32 bits;
instr_time diff_time;
prev = cur;
@@ -191,7 +191,7 @@ test_timing(unsigned int duration)
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ns\n"), diff);
+ fprintf(stderr, _("Time warp: %lld ns\n"), diff);
exit(1);
}
@@ -319,7 +319,7 @@ output(uint64 loop_count)
double prct = (double) largest_diff_count * 100 / loop_count;
printf("...\n");
- printf("%*d %*.4f %*.4f %*lld\n",
+ printf("%*lld %*.4f %*.4f %*lld\n",
len1, largest_diff,
len2, prct,
len3, 100.0,
--
2.50.1 (Apple Git-155)
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-02 04:17 Lukas Fittl <[email protected]>
parent: Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Lukas Fittl @ 2026-04-02 04:17 UTC (permalink / raw)
To: Chao Li <[email protected]>; +Cc: PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
Hi Chao,
On Wed, Apr 1, 2026 at 8:10 PM Chao Li <[email protected]> wrote:
>
> 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 mistake in an error message. The relevant code is like:
> ```
> diff = INSTR_TIME_GET_NANOSEC(diff_time);
>
> fprintf(stderr, _("Time warp: %d ms\n"), diff);
> ```
>
> Here, “diff" is in nanoseconds, but the error message prints ms as 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 “diff"
> 2. Change “ms" to “ns" 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.
>
> “diff" 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:
>
> * 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 value appear negative. In that case, the code could report a “backwards” clock jump when the actual jump was forwards, which would be misleading.
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-02 07:28 Chao Li <[email protected]>
parent: Lukas Fittl <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Chao Li @ 2026-04-02 07:28 UTC (permalink / raw)
To: Lukas Fittl <[email protected]>; +Cc: PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
> On Apr 2, 2026, at 12:17, Lukas Fittl <[email protected]> wrote:
>
> Hi Chao,
>
> On Wed, Apr 1, 2026 at 8:10 PM Chao Li <[email protected]> wrote:
>>
>> 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 mistake in an error message. The relevant code is like:
>> ```
>> diff = INSTR_TIME_GET_NANOSEC(diff_time);
>>
>> fprintf(stderr, _("Time warp: %d ms\n"), diff);
>> ```
>>
>> Here, “diff" is in nanoseconds, but the error message prints ms as 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 “diff"
>> 2. Change “ms" to “ns" 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.
>>
>> “diff" 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:
>>
>> * 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 value appear negative. In that case, the code could report a “backwards” clock jump when the actual jump was forwards, which would be misleading.
>
> 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.
You are right. Changed to pg_leftmost_one_pos64 in v2.
>
> Maybe we should error out if the diff is larger than an int32, noting
> a positive time drift?
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’s wait for more voices on this.
>
> 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.
>
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.
PFA v2 - updated 0002 for pg_leftmost_one_pos64.
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
Attachments:
[application/octet-stream] v2-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch (1.2K, 2-v2-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch)
download | inline diff:
From 5bb978b940a93c8f902aa4ea25ae39ef52eca3e3 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:21:40 +0800
Subject: [PATCH v2 1/2] pg_test_timing: fix unit in backward-clock warning
pg_test_timing measures timing differences in nanoseconds via
INSTR_TIME_GET_NANOSEC(), but the backward-clock warning incorrectly
reported the value as milliseconds. Fix the message to use "ns" so
that it matches the actual unit of diff.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index aee41dbe3f9..cbdc5af09d9 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -191,7 +191,7 @@ test_timing(unsigned int duration)
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d ns\n"), diff);
exit(1);
}
--
2.50.1 (Apple Git-155)
[application/octet-stream] v2-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch (2.2K, 3-v2-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch)
download | inline diff:
From d17974f31f8b11e240ffadaf0f134b4e82b7e2de Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:29:06 +0800
Subject: [PATCH v2 2/2] pg_test_timing: use int64 for largest observed time
delta
pg_test_timing obtains timing deltas with INSTR_TIME_GET_NANOSEC(),
which returns a nanosecond value that should be stored in int64. Adjust
diff and largest_diff to use int64 accordingly.
Also fix the corresponding printf format specifiers so these values are
printed correctly.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 12 ++++++------
1 file changed, 6 insertions(+), 6 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index cbdc5af09d9..323d98bbb61 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -25,7 +25,7 @@ static long long int histogram[32];
static long long int direct_histogram[NUM_DIRECT];
/* separately record highest observed duration */
-static int32 largest_diff;
+static int64 largest_diff;
static long long int largest_diff_count;
@@ -176,8 +176,8 @@ test_timing(unsigned int duration)
while (INSTR_TIME_GT(end_time, cur))
{
- int32 diff,
- bits;
+ int64 diff;
+ int32 bits;
instr_time diff_time;
prev = cur;
@@ -191,13 +191,13 @@ test_timing(unsigned int duration)
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ns\n"), diff);
+ fprintf(stderr, _("Time warp: %lld ns\n"), diff);
exit(1);
}
/* What is the highest bit in the time diff? */
if (diff > 0)
- bits = pg_leftmost_one_pos32(diff) + 1;
+ bits = pg_leftmost_one_pos64(diff) + 1;
else
bits = 0;
@@ -319,7 +319,7 @@ output(uint64 loop_count)
double prct = (double) largest_diff_count * 100 / loop_count;
printf("...\n");
- printf("%*d %*.4f %*.4f %*lld\n",
+ printf("%*lld %*.4f %*.4f %*lld\n",
len1, largest_diff,
len2, prct,
len3, 100.0,
--
2.50.1 (Apple Git-155)
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-08 04:06 Chao Li <[email protected]>
parent: Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Chao Li @ 2026-04-08 04:06 UTC (permalink / raw)
To: Lukas Fittl <[email protected]>; +Cc: PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
> On Apr 2, 2026, at 15:28, Chao Li <[email protected]> wrote:
>
>
>
>> On Apr 2, 2026, at 12:17, Lukas Fittl <[email protected]> wrote:
>>
>> Hi Chao,
>>
>> On Wed, Apr 1, 2026 at 8:10 PM Chao Li <[email protected]> wrote:
>>>
>>> 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 mistake in an error message. The relevant code is like:
>>> ```
>>> diff = INSTR_TIME_GET_NANOSEC(diff_time);
>>>
>>> fprintf(stderr, _("Time warp: %d ms\n"), diff);
>>> ```
>>>
>>> Here, “diff" is in nanoseconds, but the error message prints ms as 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 “diff"
>>> 2. Change “ms" to “ns" 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.
>>>
>>> “diff" 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:
>>>
>>> * 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 value appear negative. In that case, the code could report a “backwards” clock jump when the actual jump was forwards, which would be misleading.
>>
>> 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.
>
> You are right. Changed to pg_leftmost_one_pos64 in v2.
>
>>
>> Maybe we should error out if the diff is larger than an int32, noting
>> a positive time drift?
>
> 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’s wait for more voices on this.
>
>>
>> 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.
>>
>
> 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.
>
> PFA v2 - updated 0002 for pg_leftmost_one_pos64.
>
> Best regards,
> --
> Chao Li (Evan)
> HighGo Software Co., Ltd.
> https://www.highgo.com/
>
>
>
>
> <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/
Attachments:
[application/octet-stream] v3-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch (1.3K, 2-v3-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch)
download | inline diff:
From 0b4419bd6318f29a56ec263de7d4be042b55a6d8 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:21:40 +0800
Subject: [PATCH v3 1/2] pg_test_timing: fix unit in backward-clock warning
pg_test_timing measures timing differences in nanoseconds via
INSTR_TIME_GET_NANOSEC(), but the backward-clock warning incorrectly
reported the value as milliseconds. Fix the message to use "ns" so
that it matches the actual unit of diff.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 2afb0e6a410..944b25df1f2 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -281,7 +281,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d ns\n"), diff);
exit(1);
}
--
2.50.1 (Apple Git-155)
[application/octet-stream] v3-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch (2.4K, 3-v3-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch)
download | inline diff:
From e193672cc7cd5736290af81a1ce8acd2f4237224 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:29:06 +0800
Subject: [PATCH v3 2/2] pg_test_timing: use int64 for largest observed time
delta
pg_test_timing obtains timing deltas with INSTR_TIME_GET_NANOSEC(),
which returns a nanosecond value that should be stored in int64. Adjust
diff and largest_diff to use int64 accordingly.
Also fix the corresponding printf format specifiers so these values are
printed correctly.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 14 +++++++-------
1 file changed, 7 insertions(+), 7 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 944b25df1f2..ce4c54256e3 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -25,7 +25,7 @@ static long long int histogram[32];
static long long int direct_histogram[NUM_DIRECT];
/* separately record highest observed duration */
-static int32 largest_diff;
+static int64 largest_diff;
static long long int largest_diff_count;
@@ -262,8 +262,8 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
while (INSTR_TIME_GT(end_time, cur))
{
- int32 diff,
- bits;
+ int64 diff;
+ int32 bits;
instr_time diff_time;
prev = cur;
@@ -281,13 +281,13 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ns\n"), diff);
+ fprintf(stderr, _("Time warp: " INT64_FORMAT " ns\n"), diff);
exit(1);
}
/* What is the highest bit in the time diff? */
if (diff > 0)
- bits = pg_leftmost_one_pos32(diff) + 1;
+ bits = pg_leftmost_one_pos64(diff) + 1;
else
bits = 0;
@@ -409,8 +409,8 @@ output(uint64 loop_count)
double prct = (double) largest_diff_count * 100 / loop_count;
printf("...\n");
- printf("%*d %*.4f %*.4f %*lld\n",
- len1, largest_diff,
+ printf("%*lld %*.4f %*.4f %*lld\n",
+ len1, (long long) largest_diff,
len2, prct,
len3, 100.0,
len4, largest_diff_count);
--
2.50.1 (Apple Git-155)
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re:Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-09 06:12 wang.xiao.peng <[email protected]>
parent: Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: wang.xiao.peng @ 2026-04-09 06:12 UTC (permalink / raw)
To: Chao Li <[email protected]>; [email protected]; +Cc: PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
At 2026-04-08 12:06:07, "Chao Li" <[email protected]> wrote:
>
>
>> On Apr 2, 2026, at 15:28, Chao Li <[email protected]> wrote:
>>
>>
>>
>>> On Apr 2, 2026, at 12:17, Lukas Fittl <[email protected]> wrote:
>>>
>>> Hi Chao,
>>>
>>> On Wed, Apr 1, 2026 at 8:10 PM Chao Li <[email protected]> wrote:
>>>>
>>>> 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 mistake in an error message. The relevant code is like:
>>>> ```
>>>> diff = INSTR_TIME_GET_NANOSEC(diff_time);
>>>>
>>>> fprintf(stderr, _("Time warp: %d ms\n"), diff);
>>>> ```
>>>>
>>>> Here, “diff" is in nanoseconds, but the error message prints ms as 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 “diff"
>>>> 2. Change “ms" to “ns" 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.
>>>>
>>>> “diff" 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:
>>>>
>>>> * 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 value appear negative. In that case, the code could report a “backwards” clock jump when the actual jump was forwards, which would be misleading.
>>>
>>> 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.
>>
>> You are right. Changed to pg_leftmost_one_pos64 in v2.
>>
>>>
>>> Maybe we should error out if the diff is larger than an int32, noting
>>> a positive time drift?
>>
>> 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’s wait for more voices on this.
>>
>>>
>>> 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.
>>>
>>
>> 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.
>>
>> PFA v2 - updated 0002 for pg_leftmost_one_pos64.
>>
>> Best regards,
>> --
>> Chao Li (Evan)
>> HighGo Software Co., Ltd.
>> https://www.highgo.com/
>>
>>
>>
>>
>> <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/
>
>
Hi Chao, Lukas,
Just finished reviewing the v3 patches - looks good to me. The pg_leftmost_one_pos64 fix is spot on, and using INT64_FORMAT for the error message is the right approach.
Nice catch on the unit mismatch and the int32 overflow issue. Both patches are ready to go from my perspective.
Cheers,
Xiaopeng Wang
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-22 07:04 Fujii Masao <[email protected]>
parent: wang.xiao.peng <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Fujii Masao @ 2026-04-22 07:04 UTC (permalink / raw)
To: wang.xiao.peng <[email protected]>; +Cc: Chao Li <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
On Thu, Apr 9, 2026 at 3:13 PM wang.xiao.peng <[email protected]> wrote:
> Just finished reviewing the v3 patches - looks good to me. The pg_leftmost_one_pos64 fix is spot on, and using INT64_FORMAT for the error message is the right approach.
Since pg_leftmost_one_pos64() can return up to 63, should the size of
histogram[] be changed from 32 to 64? If we want to display the full
histogram[] in the output, max_bit in output() would also need to be set to 63.
Alternatively, it may be fine to keep max_bit = 31 and show only
the first 32 histogram entries.
Patch 0001 looks good to me.
Regards,
--
Fujii Masao
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-22 08:57 Chao Li <[email protected]>
parent: Fujii Masao <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Chao Li @ 2026-04-22 08:57 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: wang.xiao.peng <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
> On Apr 22, 2026, at 15:04, Fujii Masao <[email protected]> wrote:
>
> On Thu, Apr 9, 2026 at 3:13 PM wang.xiao.peng <[email protected]> wrote:
>> Just finished reviewing the v3 patches - looks good to me. The pg_leftmost_one_pos64 fix is spot on, and using INT64_FORMAT for the error message is the right approach.
>
> Since pg_leftmost_one_pos64() can return up to 63, should the size of
> histogram[] be changed from 32 to 64? If we want to display the full
> histogram[] in the output, max_bit in output() would also need to be set to 63.
> Alternatively, it may be fine to keep max_bit = 31 and show only
> the first 32 histogram entries.
I revisited this patch and think it makes sense to extend histogram[] to 64 entries.
In practice, the higher buckets will almost always remain zero, and output() already omits trailing histogram entries with zero counts, so this change is unlikely to affect the actual runtime output in normal cases.
Accordingly, I also adjusted the minimum width of the first column, since the maximum int64 value has 19 digits, and updated the printf format accordingly.
>
> Patch 0001 looks good to me.
Cool.
PFA v4:
* 0001 unchanged from v3.
* 0002 changed size of histogram[] 64.
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
Attachments:
[application/octet-stream] v4-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch (1.3K, 2-v4-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch)
download | inline diff:
From f977c49219a708f7bec0f15d0250dc8554584639 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:21:40 +0800
Subject: [PATCH v4 1/2] pg_test_timing: fix unit in backward-clock warning
pg_test_timing measures timing differences in nanoseconds via
INSTR_TIME_GET_NANOSEC(), but the backward-clock warning incorrectly
reported the value as milliseconds. Fix the message to use "ns" so
that it matches the actual unit of diff.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 2afb0e6a410..944b25df1f2 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -281,7 +281,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d ns\n"), diff);
exit(1);
}
--
2.50.1 (Apple Git-155)
[application/octet-stream] v4-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch (3.6K, 3-v4-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch)
download | inline diff:
From d8f053cba2221b365317d3dbf8642cf28cefac72 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:29:06 +0800
Subject: [PATCH v4 2/2] pg_test_timing: use int64 for largest observed time
delta
pg_test_timing obtains timing deltas with INSTR_TIME_GET_NANOSEC(),
which returns a nanosecond value that should be stored in int64. Adjust
diff and largest_diff to use int64 accordingly.
Also fix the corresponding printf format specifiers so these values are
printed correctly.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 28 ++++++++++++++-----------
1 file changed, 16 insertions(+), 12 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 944b25df1f2..530347a9aa5 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -18,14 +18,14 @@ static unsigned int test_duration = 3;
static double max_rprct = 99.99;
/* record duration in powers of 2 nanoseconds */
-static long long int histogram[32];
+static long long int histogram[64];
/* record counts of first 10K durations directly */
#define NUM_DIRECT 10000
static long long int direct_histogram[NUM_DIRECT];
/* separately record highest observed duration */
-static int32 largest_diff;
+static int64 largest_diff;
static long long int largest_diff_count;
@@ -262,8 +262,8 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
while (INSTR_TIME_GT(end_time, cur))
{
- int32 diff,
- bits;
+ int64 diff;
+ int32 bits;
instr_time diff_time;
prev = cur;
@@ -281,13 +281,17 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ns\n"), diff);
+ fprintf(stderr, _("Time warp: " INT64_FORMAT " ns\n"), diff);
exit(1);
}
/* What is the highest bit in the time diff? */
if (diff > 0)
- bits = pg_leftmost_one_pos32(diff) + 1;
+ {
+ bits = pg_leftmost_one_pos64(diff) + 1;
+ /* histogram should be define large enough */
+ Assert(bits < lengthof(histogram));
+ }
else
bits = 0;
@@ -324,7 +328,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
static void
output(uint64 loop_count)
{
- int max_bit = 31;
+ int max_bit = lengthof(histogram) - 1;
const char *header1 = _("<= ns");
const char *header1b = _("ns");
const char *header2 = /* xgettext:no-c-format */ _("% of total");
@@ -342,7 +346,7 @@ output(uint64 loop_count)
max_bit--;
/* set minimum column widths */
- len1 = Max(8, len1);
+ len1 = Max(19, len1);
len2 = Max(10, len2);
len3 = Max(10, len3);
len4 = Max(10, len4);
@@ -360,8 +364,8 @@ output(uint64 loop_count)
double prct = (double) histogram[i] * 100 / loop_count;
rprct += prct;
- printf("%*ld %*.4f %*.4f %*lld\n",
- len1, (1L << i) - 1,
+ printf("%*llu %*.4f %*.4f %*lld\n",
+ len1, (1ULL << i) - 1,
len2, prct,
len3, rprct,
len4, histogram[i]);
@@ -409,8 +413,8 @@ output(uint64 loop_count)
double prct = (double) largest_diff_count * 100 / loop_count;
printf("...\n");
- printf("%*d %*.4f %*.4f %*lld\n",
- len1, largest_diff,
+ printf("%*lld %*.4f %*.4f %*lld\n",
+ len1, (long long) largest_diff,
len2, prct,
len3, 100.0,
len4, largest_diff_count);
--
2.50.1 (Apple Git-155)
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-22 16:11 Fujii Masao <[email protected]>
parent: Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Fujii Masao @ 2026-04-22 16:11 UTC (permalink / raw)
To: Chao Li <[email protected]>; +Cc: wang.xiao.peng <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
On Wed, Apr 22, 2026 at 5:58 PM Chao Li <[email protected]> wrote:
> PFA v4:
>
> * 0001 unchanged from v3.
> * 0002 changed size of histogram[] 64.
Thanks for updating the patch!
Since patch 0001 is a bug fix, it should be backpatched to the supported stable
branches. However, in v19 the unit should be changed like s/ms/ns, while in v18
and earlier s/ms/us, since those older branches report the diff in microseconds.
Right?
Patch 0002 looks more like an improvement than a bug fix, so we should probably
wait for the next CommitFest before committing it. Thoughts?
Regards,
--
Fujii Masao
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-23 02:02 Chao Li <[email protected]>
parent: Fujii Masao <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Chao Li @ 2026-04-23 02:02 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: wang.xiao.peng <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
> On Apr 23, 2026, at 00:11, Fujii Masao <[email protected]> wrote:
>
> On Wed, Apr 22, 2026 at 5:58 PM Chao Li <[email protected]> wrote:
>> PFA v4:
>>
>> * 0001 unchanged from v3.
>> * 0002 changed size of histogram[] 64.
>
> Thanks for updating the patch!
>
> Since patch 0001 is a bug fix, it should be backpatched to the supported stable
> branches. However, in v19 the unit should be changed like s/ms/ns, while in v18
> and earlier s/ms/us, since those older branches report the diff in microseconds.
> Right?
I just checked old branches. Looks like 0001 can be back-patched down to v10. Yes, pre-19, all branches use microsecond, so the back-patch should change “ms” to “us”.
I have helped create back-patch diff files as attached:
* nocfbot.v10-v13.pg_test_timing-backpatch.diff for v10-v13
* nocfbot.v14-v15.pg_test_timing-backpatch.diff for v14-v15
* nocfbot.v16-v18.pg_test_timing-backpatch.diff for v16-v18
For v16 to v18, we can make a tiny improvement by replacing “1e9” with a constant macro NS_PER_S. This change has been included in the diff.
I have built and tested on all branches.
>
> Patch 0002 looks more like an improvement than a bug fix, so we should probably
> wait for the next CommitFest before committing it. Thoughts?
>
I see 0002 a bit differently. In v19, the unit changed from microseconds to nanoseconds, which introduced a potential overflow: nanoseconds require int64, but the local variable remained int32. So I think this is actually a v19-only bug.
PFA v5: 0001 replaced “1e9” with NS_PER_S; 0002 unchanged.
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
Attachments:
[application/octet-stream] nocfbot.v10-v13.pg_test_timing-backpatch.diff (488B, 2-nocfbot.v10-v13.pg_test_timing-backpatch.diff)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index e14802372bd..79ef32353dc 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -138,7 +138,7 @@ test_timing(int32 duration)
if (diff < 0)
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d us\n"), diff);
exit(1);
}
[application/octet-stream] nocfbot.v14-v15.pg_test_timing-backpatch.diff (495B, 3-nocfbot.v14-v15.pg_test_timing-backpatch.diff)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index c29d6f87629..0ccf55761ce 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -149,7 +149,7 @@ test_timing(unsigned int duration)
if (diff < 0)
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d us\n"), diff);
exit(1);
}
[application/octet-stream] nocfbot.v16-v18.pg_test_timing-backpatch.diff (806B, 4-nocfbot.v16-v18.pg_test_timing-backpatch.diff)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index ce7aad4b25a..3c7672f592d 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -149,7 +149,7 @@ test_timing(unsigned int duration)
if (diff < 0)
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d us\n"), diff);
exit(1);
}
@@ -173,7 +173,7 @@ test_timing(unsigned int duration)
INSTR_TIME_SUBTRACT(end_time, start_time);
printf(_("Per loop time including overhead: %0.2f ns\n"),
- INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
+ INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S / loop_count);
return loop_count;
}
[application/octet-stream] v5-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch (1.7K, 5-v5-0001-pg_test_timing-fix-unit-in-backward-clock-warning.patch)
download | inline diff:
From ee388e247cc7d2473b12ca370b06cc9bbf0037fd Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:21:40 +0800
Subject: [PATCH v5 1/2] pg_test_timing: fix unit in backward-clock warning
pg_test_timing measures timing differences in nanoseconds via
INSTR_TIME_GET_NANOSEC(), but the backward-clock warning incorrectly
reported the value as milliseconds. Fix the message to use "ns" so
that it matches the actual unit of diff.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 2afb0e6a410..5eb20e091b1 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -281,7 +281,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ms\n"), diff);
+ fprintf(stderr, _("Time warp: %d ns\n"), diff);
exit(1);
}
@@ -316,7 +316,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
INSTR_TIME_SUBTRACT(end_time, start_time);
printf(_("Average loop time including overhead: %0.2f ns\n"),
- INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
+ INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S / loop_count);
return loop_count;
}
--
2.50.1 (Apple Git-155)
[application/octet-stream] v5-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch (3.6K, 6-v5-0002-pg_test_timing-use-int64-for-largest-observed-tim.patch)
download | inline diff:
From 3eea80de37049bd453cf5724951c18505d557a99 Mon Sep 17 00:00:00 2001
From: "Chao Li (Evan)" <[email protected]>
Date: Thu, 2 Apr 2026 10:29:06 +0800
Subject: [PATCH v5 2/2] pg_test_timing: use int64 for largest observed time
delta
pg_test_timing obtains timing deltas with INSTR_TIME_GET_NANOSEC(),
which returns a nanosecond value that should be stored in int64. Adjust
diff and largest_diff to use int64 accordingly.
Also fix the corresponding printf format specifiers so these values are
printed correctly.
Author: Chao Li <[email protected]>
Reviewed-by: Lukas Fittl <[email protected]>
Reviewed-by: Fujii Masao <[email protected]>
Discussion: https://postgr.es/m/[email protected]
---
src/bin/pg_test_timing/pg_test_timing.c | 28 ++++++++++++++-----------
1 file changed, 16 insertions(+), 12 deletions(-)
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 5eb20e091b1..340b529e972 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -18,14 +18,14 @@ static unsigned int test_duration = 3;
static double max_rprct = 99.99;
/* record duration in powers of 2 nanoseconds */
-static long long int histogram[32];
+static long long int histogram[64];
/* record counts of first 10K durations directly */
#define NUM_DIRECT 10000
static long long int direct_histogram[NUM_DIRECT];
/* separately record highest observed duration */
-static int32 largest_diff;
+static int64 largest_diff;
static long long int largest_diff_count;
@@ -262,8 +262,8 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
while (INSTR_TIME_GT(end_time, cur))
{
- int32 diff,
- bits;
+ int64 diff;
+ int32 bits;
instr_time diff_time;
prev = cur;
@@ -281,13 +281,17 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
if (unlikely(diff < 0))
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
- fprintf(stderr, _("Time warp: %d ns\n"), diff);
+ fprintf(stderr, _("Time warp: " INT64_FORMAT " ns\n"), diff);
exit(1);
}
/* What is the highest bit in the time diff? */
if (diff > 0)
- bits = pg_leftmost_one_pos32(diff) + 1;
+ {
+ bits = pg_leftmost_one_pos64(diff) + 1;
+ /* histogram should be define large enough */
+ Assert(bits < lengthof(histogram));
+ }
else
bits = 0;
@@ -324,7 +328,7 @@ test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timin
static void
output(uint64 loop_count)
{
- int max_bit = 31;
+ int max_bit = lengthof(histogram) - 1;
const char *header1 = _("<= ns");
const char *header1b = _("ns");
const char *header2 = /* xgettext:no-c-format */ _("% of total");
@@ -342,7 +346,7 @@ output(uint64 loop_count)
max_bit--;
/* set minimum column widths */
- len1 = Max(8, len1);
+ len1 = Max(19, len1);
len2 = Max(10, len2);
len3 = Max(10, len3);
len4 = Max(10, len4);
@@ -360,8 +364,8 @@ output(uint64 loop_count)
double prct = (double) histogram[i] * 100 / loop_count;
rprct += prct;
- printf("%*ld %*.4f %*.4f %*lld\n",
- len1, (1L << i) - 1,
+ printf("%*llu %*.4f %*.4f %*lld\n",
+ len1, (1ULL << i) - 1,
len2, prct,
len3, rprct,
len4, histogram[i]);
@@ -409,8 +413,8 @@ output(uint64 loop_count)
double prct = (double) largest_diff_count * 100 / loop_count;
printf("...\n");
- printf("%*d %*.4f %*.4f %*lld\n",
- len1, largest_diff,
+ printf("%*lld %*.4f %*.4f %*lld\n",
+ len1, (long long) largest_diff,
len2, prct,
len3, 100.0,
len4, largest_diff_count);
--
2.50.1 (Apple Git-155)
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-24 03:15 Fujii Masao <[email protected]>
parent: Chao Li <[email protected]>
0 siblings, 1 reply; 11+ messages in thread
From: Fujii Masao @ 2026-04-24 03:15 UTC (permalink / raw)
To: Chao Li <[email protected]>; +Cc: wang.xiao.peng <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
On Thu, Apr 23, 2026 at 11:03 AM Chao Li <[email protected]> wrote:
> I just checked old branches. Looks like 0001 can be back-patched down to v10. Yes, pre-19, all branches use microsecond, so the back-patch should change “ms” to “us”.
Thanks! So I've pushed this unit change to master and backpatched it to
all supported branches.
> For v16 to v18, we can make a tiny improvement by replacing “1e9” with a constant macro NS_PER_S. This change has been included in the diff.
This change looks good to me. However, we should generally keep changes to
old stable branches to the minimum required, so I applied this change only
to master with 0002 patch.
> I see 0002 a bit differently. In v19, the unit changed from microseconds to nanoseconds, which introduced a potential overflow: nanoseconds require int64, but the local variable remained int32. So I think this is actually a v19-only bug.
OK, I've pushed 0002 patch. Thanks!
Regards,
--
Fujii Masao
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: pg_test_timing: fix unit typo and widen diff type
@ 2026-04-24 03:30 Chao Li <[email protected]>
parent: Fujii Masao <[email protected]>
0 siblings, 0 replies; 11+ messages in thread
From: Chao Li @ 2026-04-24 03:30 UTC (permalink / raw)
To: Fujii Masao <[email protected]>; +Cc: wang.xiao.peng <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; Tom Lane <[email protected]>; Hannu Krosing <[email protected]>
> On Apr 24, 2026, at 11:15, Fujii Masao <[email protected]> wrote:
>
> On Thu, Apr 23, 2026 at 11:03 AM Chao Li <[email protected]> wrote:
>> I just checked old branches. Looks like 0001 can be back-patched down to v10. Yes, pre-19, all branches use microsecond, so the back-patch should change “ms” to “us”.
>
> Thanks! So I've pushed this unit change to master and backpatched it to
> all supported branches.
>
>
>> For v16 to v18, we can make a tiny improvement by replacing “1e9” with a constant macro NS_PER_S. This change has been included in the diff.
>
> This change looks good to me. However, we should generally keep changes to
> old stable branches to the minimum required, so I applied this change only
> to master with 0002 patch.
>
>
>> I see 0002 a bit differently. In v19, the unit changed from microseconds to nanoseconds, which introduced a potential overflow: nanoseconds require int64, but the local variable remained int32. So I think this is actually a v19-only bug.
>
> OK, I've pushed 0002 patch. Thanks!
>
> Regards,
>
> --
> Fujii Masao
Hi Fujii-san, thank you very much for pushing.
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
^ permalink raw reply [nested|flat] 11+ messages in thread
end of thread, other threads:[~2026-04-24 03:30 UTC | newest]
Thread overview: 11+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2026-04-02 03:09 pg_test_timing: fix unit typo and widen diff type Chao Li <[email protected]>
2026-04-02 04:17 ` Lukas Fittl <[email protected]>
2026-04-02 07:28 ` Chao Li <[email protected]>
2026-04-08 04:06 ` Chao Li <[email protected]>
2026-04-09 06:12 ` wang.xiao.peng <[email protected]>
2026-04-22 07:04 ` Fujii Masao <[email protected]>
2026-04-22 08:57 ` Chao Li <[email protected]>
2026-04-22 16:11 ` Fujii Masao <[email protected]>
2026-04-23 02:02 ` Chao Li <[email protected]>
2026-04-24 03:15 ` Fujii Masao <[email protected]>
2026-04-24 03:30 ` Chao Li <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox