From: Tom Lane <tgl@sss.pgh.pa.us>
To: Hannu Krosing <hannuk@google.com>
cc: Peter Eisentraut <peter@eisentraut.org>,
        "Andrey M. Borodin" <x4mmm@yandex-team.ru>,
        pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: What is a typical precision of gettimeofday()?
In-reply-to: <647660.1719003075@sss.pgh.pa.us>
References: <be0339cc-1ae1-4892-9445-8e6d8995a44d@eisentraut.org> <47AEACEE-E5CC-40E4-8611-01F3A465AF16@yandex-team.ru> <9e7b21e7-4c63-4299-87f4-780a0699a7d8@eisentraut.org> <130996.1718814994@sss.pgh.pa.us> <CAMT0RQSdKQra6QC4b+eAynpqZ0SYdHDfGBBE7hty33OD9jx7Jg@mail.gmail.com> <647660.1719003075@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Fri, 21 Jun 2024 16:51:15 -0400"
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <3109567.1719939295.0@sss.pgh.pa.us>
Date: Tue, 02 Jul 2024 12:55:53 -0400
Message-ID: <3110108.1719939353@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/3110108.1719939353%40sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <3109567.1719939295.1@sss.pgh.pa.us>

I wrote:
> Hannu Krosing <hannuk@google.com> writes:
>> This is my current patch which also adds running % and optionally uses
>> faster way to count leading zeros, though I did not  see a change from
>> that.

> I've not read the patch yet, but I did create a CF entry [1]
> to get some CI cycles on this.  The cfbot complains [2] about
> [ a couple of things ]

Here's a cleaned-up code patch addressing the cfbot complaints
and making the output logic a bit neater.

I think this is committable code-wise, but the documentation needs
work, if not indeed a complete rewrite.  The examples are now
horribly out of date, and it seems that the "Clock Hardware and Timing
Accuracy" section is quite obsolete as well, since it suggests that
the best available accuracy is ~100ns.

TBH I'm inclined to rip most of the OS-specific and hardware-specific
information out of there, as it's not something we're likely to
maintain well even if we got it right for current reality.

			regards, tom lane


------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="v2-pg_test_timing-nanoseconds.patch";
	charset="us-ascii"
Content-ID: <3109567.1719939295.2@sss.pgh.pa.us>
Content-Description: v2-pg_test_timing-nanoseconds.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_tim=
ing/pg_test_timing.c
index ce7aad4b25..a6a271aef1 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -9,19 +9,24 @@
 #include <limits.h>
 =

 #include "getopt_long.h"
+#include "port/pg_bitutils.h"
 #include "portability/instr_time.h"
 =

 static const char *progname;
 =

 static unsigned int test_duration =3D 3;
 =

+/* record duration in powers of 2 nanoseconds */
+static long long int histogram[32];
+
+/* record counts of first 128 durations directly */
+#define NUM_DIRECT 128
+static long long int direct_histogram[NUM_DIRECT];
+
 static void handle_args(int argc, char *argv[]);
 static uint64 test_timing(unsigned int duration);
 static void output(uint64 loop_count);
 =

-/* record duration in powers of 2 microseconds */
-static long long int histogram[32];
-
 int
 main(int argc, char *argv[])
 {
@@ -111,7 +116,6 @@ handle_args(int argc, char *argv[])
 		exit(1);
 	}
 =

-
 	printf(ngettext("Testing timing overhead for %u second.\n",
 					"Testing timing overhead for %u seconds.\n",
 					test_duration),
@@ -130,19 +134,19 @@ test_timing(unsigned int duration)
 				end_time,
 				temp;
 =

-	total_time =3D duration > 0 ? duration * INT64CONST(1000000) : 0;
+	total_time =3D duration > 0 ? duration * INT64CONST(1000000000) : 0;
 =

 	INSTR_TIME_SET_CURRENT(start_time);
-	cur =3D INSTR_TIME_GET_MICROSEC(start_time);
+	cur =3D INSTR_TIME_GET_NANOSEC(start_time);
 =

 	while (time_elapsed < total_time)
 	{
 		int32		diff,
-					bits =3D 0;
+					bits;
 =

 		prev =3D cur;
 		INSTR_TIME_SET_CURRENT(temp);
-		cur =3D INSTR_TIME_GET_MICROSEC(temp);
+		cur =3D INSTR_TIME_GET_NANOSEC(temp);
 		diff =3D cur - prev;
 =

 		/* Did time go backwards? */
@@ -154,18 +158,21 @@ test_timing(unsigned int duration)
 		}
 =

 		/* What is the highest bit in the time diff? */
-		while (diff)
-		{
-			diff >>=3D 1;
-			bits++;
-		}
+		if (diff > 0)
+			bits =3D pg_leftmost_one_pos32(diff) + 1;
+		else
+			bits =3D 0;
 =

 		/* Update appropriate duration bucket */
 		histogram[bits]++;
 =

+		/* Update direct histogram of time diffs */
+		if (diff < NUM_DIRECT)
+			direct_histogram[diff]++;
+
 		loop_count++;
 		INSTR_TIME_SUBTRACT(temp, start_time);
-		time_elapsed =3D INSTR_TIME_GET_MICROSEC(temp);
+		time_elapsed =3D INSTR_TIME_GET_NANOSEC(temp);
 	}
 =

 	INSTR_TIME_SET_CURRENT(end_time);
@@ -181,28 +188,65 @@ test_timing(unsigned int duration)
 static void
 output(uint64 loop_count)
 {
-	int64		max_bit =3D 31,
+	int			max_bit =3D 31,
 				i;
-	char	   *header1 =3D _("< us");
+	char	   *header1 =3D _("<=3D ns");
+	char	   *header1b =3D _("ns");
 	char	   *header2 =3D /* xgettext:no-c-format */ _("% of total");
-	char	   *header3 =3D _("count");
+	char	   *header3 =3D /* xgettext:no-c-format */ _("running %");
+	char	   *header4 =3D _("count");
 	int			len1 =3D strlen(header1);
 	int			len2 =3D strlen(header2);
 	int			len3 =3D strlen(header3);
+	int			len4 =3D strlen(header4);
+	double		rprct;
 =

 	/* find highest bit value */
 	while (max_bit > 0 && histogram[max_bit] =3D=3D 0)
 		max_bit--;
 =

+	/* set minimum column widths */
+	len1 =3D Max(8, len1);
+	len2 =3D Max(10, len2);
+	len3 =3D Max(10, len3);
+	len4 =3D Max(10, len4);
+
 	printf(_("Histogram of timing durations:\n"));
-	printf("%*s   %*s %*s\n",
-		   Max(6, len1), header1,
-		   Max(10, len2), header2,
-		   Max(10, len3), header3);
-
-	for (i =3D 0; i <=3D max_bit; i++)
-		printf("%*ld    %*.5f %*lld\n",
-			   Max(6, len1), 1l << i,
-			   Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
-			   Max(10, len3), histogram[i]);
+	printf("%*s   %*s %*s %*s\n",
+		   len1, header1,
+		   len2, header2,
+		   len3, header3,
+		   len4, header4);
+
+	for (i =3D 0, rprct =3D 0; i <=3D max_bit; i++)
+	{
+		double		prct =3D (double) histogram[i] * 100 / loop_count;
+
+		rprct +=3D prct;
+		printf("%*ld   %*.4f %*.4f %*lld\n",
+			   len1, (1L << i) - 1,
+			   len2, prct,
+			   len3, rprct,
+			   len4, histogram[i]);
+	}
+
+	printf(_("\nTiming durations less than %d ns:\n"), NUM_DIRECT);
+	printf("%*s   %*s %*s %*s\n",
+		   len1, header1b,
+		   len2, header2,
+		   len3, header3,
+		   len4, header4);
+
+	for (i =3D 0, rprct =3D 0; i < NUM_DIRECT; i++)
+	{
+		double		prct =3D (double) direct_histogram[i] * 100 / loop_count;
+
+		rprct +=3D prct;
+		if (direct_histogram[i])
+			printf("%*d   %*.4f %*.4f %*lld\n",
+				   len1, i,
+				   len2, prct,
+				   len3, rprct,
+				   len4, direct_histogram[i]);
+	}
 }

------- =_aaaaaaaaaa0--