v22-0004-pg_test_timing-Also-test-RDTSC-RDTSCP-timing-and.patch

From e72f0f2b42ba9a740395f7d9d5e8039cde4dfafe Mon Sep 17 00:00:00 2001
From: Lukas Fittl <lukas@fittl.com>
Date: Thu, 12 Feb 2026 01:12:19 -0800
Subject: [PATCH v22 4/5] pg_test_timing: Also test RDTSC/RDTSCP timing and
 report time source and TSC frequency
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Author: Lukas Fittl <lukas@fittl.com>
Author: David Geier <geidav.pg@gmail.com>
Reviewed-by: Andres Freund <andres@anarazel.de>
Reviewed-by: David Geier <geidav.pg@gmail.com>
Reviewed-by: Zsolt Parragi <zsolt.parragi@percona.com>
Reviewed-by: Álvaro Herrera <alvherre@kurilemu.de> (in an earlier version)
Discussion: https://www.postgresql.org/message-id/flat/20200612232810.f46nbqkdhbutzqdg%40alap3.anarazel.de
---
 doc/src/sgml/config.sgml                |   5 +
 doc/src/sgml/ref/pgtesttiming.sgml      | 150 +++++++++++++++++++-----
 src/bin/pg_test_timing/pg_test_timing.c | 105 +++++++++++++++--
 src/include/portability/instr_time.h    |   7 ++
 4 files changed, 229 insertions(+), 38 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index e7228c2d55f..13e95afa97c 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -2595,6 +2595,11 @@ include_dir 'conf.d'
         advised on systems that utilize an emulated <acronym>TSC</acronym>, as it
         is likely slower than the system clock source.
        </para>
+       <para>
+        To help decide which clock source to use you can run the
+        <xref linkend="pgtesttiming"/> utility to check <acronym>TSC</acronym>
+        availability, and perform timing measurements.
+       </para>
       </listitem>
      </varlistentry>
      </variablelist>
diff --git a/doc/src/sgml/ref/pgtesttiming.sgml b/doc/src/sgml/ref/pgtesttiming.sgml
index afe6a12be4b..342f4425c65 100644
--- a/doc/src/sgml/ref/pgtesttiming.sgml
+++ b/doc/src/sgml/ref/pgtesttiming.sgml
@@ -32,9 +32,10 @@ PostgreSQL documentation
  <para>
   <application>pg_test_timing</application> is a tool to measure the
   timing overhead on your system and confirm that the system time never
-  moves backwards.  It simply reads the system clock over and over again
+  moves backwards.  It reads supported clock sources over and over again
   as fast as it can for a specified length of time, and then prints
-  statistics about the observed differences in successive clock readings.
+  statistics about the observed differences in successive clock readings,
+  as well as which clock source will be used.
  </para>
  <para>
   Smaller (but not zero) differences are better, since they imply both
@@ -45,7 +46,10 @@ PostgreSQL documentation
  <para>
   This tool is also helpful to determine if
   the <varname>track_io_timing</varname> configuration parameter is likely
-  to produce useful results.
+  to produce useful results, and whether the
+  <acronym>TSC</acronym> clock source (see
+  <xref linkend="guc-timing-clock-source"/>) is available and if it will be
+  used by default.
  </para>
  </refsect1>
 
@@ -151,47 +155,134 @@ PostgreSQL documentation
    However, the largest observed difference is always shown.
   </para>
   <para>
-   The example results below show that 99.99% of timing loops took between
-   8 and 31 nanoseconds, with the worst case somewhere between 32768 and
-   65535 nanoseconds.  In the second block, we can see that typical loop
-   time is 16 nanoseconds, and the readings appear to have full nanosecond
-   precision.
+   On platforms that support the <acronym>TSC</acronym> clock source,
+   additional output sections are shown for the <command>RDTSCP</command>
+   instruction (used for general timing needs, such as
+   <varname>track_io_timing</varname>) and the <command>RDTSC</command>
+   instruction (used for <command>EXPLAIN ANALYZE</command>).  At the end
+   of the output, the <acronym>TSC</acronym> frequency, which may either be
+   sourced from CPU information directly, or the alternate calibration
+   mechanism are shown, as well as whether the <acronym>TSC</acronym> clock
+   source will be used by default.
+  </para>
+
+  <para>
+   The example results below show system clock timing where 99.99% of loops
+   took between 16 and 63 nanoseconds, followed by <acronym>TSC</acronym>
+   clock source results.  The <command>RDTSCP</command> instruction shows
+   most loops completing in 20&ndash;30 nanoseconds, while the
+   <command>RDTSC</command> instruction is the fastest at
+   9&ndash;30 nanoseconds.  In this example the <acronym>TSC</acronym>
+   clock source will be used by default, but can be disabled by setting
+   <varname>timing_clock_source</varname> to <literal>system</literal>.
   </para>
 
   <para>
 <screen><![CDATA[
+System clock source: clock_gettime (CLOCK_MONOTONIC)
 Testing timing overhead for 3 seconds.
-Average loop time including overhead: 16.40 ns
+Average loop time including overhead: 44.67 ns
+Histogram of timing durations:
+   <= ns   % of total  running %      count
+       0       0.0000     0.0000          0
+       1       0.0000     0.0000          0
+       3       0.0000     0.0000          0
+       7       0.0000     0.0000          0
+      15       0.0000     0.0000          0
+      31      24.0606    24.0606    5385707
+      63      75.8342    99.8948   16974658
+     127       0.0900    99.9848      20143
+     255       0.0069    99.9917       1542
+     511       0.0014    99.9932        322
+    1023       0.0003    99.9935         68
+    2047       0.0001    99.9936         23
+    4095       0.0036    99.9972        813
+    8191       0.0018    99.9990        402
+   16383       0.0005    99.9995        120
+   32767       0.0001    99.9997         32
+   65535       0.0001    99.9998         24
+
+Observed timing durations up to 99.9900%:
+      ns   % of total  running %      count
+      29       3.6921     3.6921     826442
+      30      16.6755    20.3676    3732628
+      31       3.6930    24.0606     826637
+      40      75.7761    99.8368   16961658
+      41       0.0019    99.8387        431
+...
+     190       0.0003    99.9901         65
+...
+29657159       0.0000   100.0000          1
+
+Clock source: RDTSCP
+Average loop time including overhead: 37.32 ns
+Histogram of timing durations:
+   <= ns   % of total  running %      count
+       0       0.0000     0.0000          0
+       1       0.0000     0.0000          0
+       3       0.0000     0.0000          0
+       7       0.0000     0.0000          0
+      15       0.0000     0.0000          0
+      31      99.9499    99.9499   26782299
+      63       0.0381    99.9880      10220
+     127       0.0008    99.9889        224
+     255       0.0052    99.9941       1403
+     511       0.0013    99.9954        340
+    1023       0.0001    99.9954         17
+    2047       0.0000    99.9955          7
+    4095       0.0021    99.9976        569
+    8191       0.0013    99.9989        357
+   16383       0.0005    99.9994        128
+   32767       0.0003    99.9996         70
+   65535       0.0001    99.9997         19
+
+Observed timing durations up to 99.9900%:
+      ns   % of total  running %      count
+      20      16.9064    16.9064    4530201
+      29      41.5214    58.4279   11125972
+      30      41.5220    99.9499   11126126
+      40       0.0089    99.9587       2374
+...
+     130       0.0007    99.9902        181
+...
+18501572       0.0000   100.0000          1
+
+Fast clock source: RDTSC
+Average loop time including overhead: 27.12 ns
 Histogram of timing durations:
    <= ns   % of total  running %      count
        0       0.0000     0.0000          0
        1       0.0000     0.0000          0
        3       0.0000     0.0000          0
        7       0.0000     0.0000          0
-      15       4.5452     4.5452    8313178
-      31      95.4527    99.9979  174581501
-      63       0.0001    99.9981        253
-     127       0.0001    99.9982        165
-     255       0.0000    99.9982         35
-     511       0.0000    99.9982          1
-    1023       0.0013    99.9994       2300
-    2047       0.0004    99.9998        690
-    4095       0.0000    99.9998          9
-    8191       0.0000    99.9998          8
-   16383       0.0002   100.0000        337
-   32767       0.0000   100.0000          2
-   65535       0.0000   100.0000          1
+      15       1.2247     1.2247     456231
+      31      98.7566    99.9813   36789785
+      63       0.0109    99.9921       4049
+     127       0.0029    99.9951       1087
+     255       0.0008    99.9959        305
+     511       0.0007    99.9966        279
+    1023       0.0000    99.9966          7
+    2047       0.0001    99.9967         22
+    4095       0.0018    99.9985        673
+    8191       0.0010    99.9995        383
+   16383       0.0003    99.9998         94
+   32767       0.0001    99.9999         38
+   65535       0.0000    99.9999          9
 
 Observed timing durations up to 99.9900%:
       ns   % of total  running %      count
-      15       4.5452     4.5452    8313178
-      16      58.3785    62.9237  106773354
-      17      33.6840    96.6078   61607584
-      18       3.1151    99.7229    5697480
-      19       0.2638    99.9867     482570
-      20       0.0093    99.9960      17054
+       9       0.6316     0.6316     235290
+      10       0.5931     1.2247     220941
+      20      91.4328    92.6574   34061442
+      29       3.6427    96.3001    1357007
+      30       3.6811    99.9813    1371336
+      40       0.0089    99.9902       3325
 ...
-   38051       0.0000   100.0000          1
+61594291       0.0000   100.0000          1
+
+TSC frequency in use: 2449228 kHz
+TSC frequency from calibration: 2448603 kHz
+TSC clock source will be used by default, unless timing_clock_source is set to 'system'.
 ]]></screen>
   </para>
 
@@ -203,6 +294,7 @@ Observed timing durations up to 99.9900%:
 
   <simplelist type="inline">
    <member><xref linkend="sql-explain"/></member>
+   <member><xref linkend="guc-timing-clock-source"/></member>
    <member><ulink url="https://wiki.postgresql.org/wiki/Pg_test_timing">Wiki
    discussion about timing</ulink></member>
   </simplelist>
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index 513ae88cafc..84388b74ace 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -30,14 +30,16 @@ static long long int largest_diff_count;
 
 
 static void handle_args(int argc, char *argv[]);
-static uint64 test_timing(unsigned int duration);
+static void test_system_timing(void);
+#if PG_INSTR_TSC_CLOCK
+static void test_tsc_timing(void);
+#endif
+static uint64 test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing);
 static void output(uint64 loop_count);
 
 int
 main(int argc, char *argv[])
 {
-	uint64		loop_count;
-
 	set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
 	progname = get_progname(argv[0]);
 
@@ -46,9 +48,11 @@ main(int argc, char *argv[])
 	/* initialize timing infrastructure (required for INSTR_* calls) */
 	pg_initialize_timing();
 
-	loop_count = test_timing(test_duration);
+	test_system_timing();
 
-	output(loop_count);
+#if PG_INSTR_TSC_CLOCK
+	test_tsc_timing();
+#endif
 
 	return 0;
 }
@@ -146,20 +150,99 @@ handle_args(int argc, char *argv[])
 		exit(1);
 	}
 
-	printf(ngettext("Testing timing overhead for %u second.\n",
-					"Testing timing overhead for %u seconds.\n",
+	printf(ngettext("Testing timing overhead for %u second.\n\n",
+					"Testing timing overhead for %u seconds.\n\n",
 					test_duration),
 		   test_duration);
 }
 
+/*
+ * This tests default (non-fast) timing code. A clock source for that is
+ * always available. Hence, we can unconditionally output the result.
+ */
+static void
+test_system_timing(void)
+{
+	uint64		loop_count;
+
+	loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_SYSTEM, false);
+	output(loop_count);
+}
+
+/*
+ * If on a supported architecture, test the TSC clock source. This clock
+ * source is not always available. In that case we print an informational
+ * message indicating as such.
+ *
+ * We first emit "slow" timings (RDTSCP on x86), which are used for higher
+ * precision measurements when the TSC clock source is enabled. We emit
+ * "fast" timings second (RDTSC on x86), which is used for faster timing
+ * measurements with lower precision.
+ */
+#if PG_INSTR_TSC_CLOCK
+static void
+test_tsc_timing(void)
+{
+	uint64		loop_count;
+	uint32		calibrated_freq;
+
+	printf("\n");
+	loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, false);
+	if (loop_count > 0)
+	{
+		output(loop_count);
+		printf("\n");
+
+		/* Now, emit fast timing measurements */
+		loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, true);
+		output(loop_count);
+		printf("\n");
+
+		printf(_("TSC frequency in use: %u kHz\n"), timing_tsc_frequency_khz);
+
+		calibrated_freq = pg_tsc_calibrate_frequency();
+		if (calibrated_freq > 0)
+			printf(_("TSC frequency from calibration: %u kHz\n"), calibrated_freq);
+		else
+			printf(_("TSC calibration did not converge\n"));
+
+		pg_set_timing_clock_source(TIMING_CLOCK_SOURCE_AUTO);
+		if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
+			printf(_("TSC clock source will be used by default, unless timing_clock_source is set to 'system'.\n"));
+		else
+			printf(_("TSC clock source will not be used by default, unless timing_clock_source is set to 'tsc'.\n"));
+	}
+	else
+		printf(_("TSC clock source is not usable. Likely unable to determine TSC frequency. are you running in an unsupported virtualized environment?\n"));
+}
+#endif
+
 static uint64
-test_timing(unsigned int duration)
+test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing)
 {
 	uint64		loop_count = 0;
 	instr_time	start_time,
 				end_time,
 				prev,
 				cur;
+	char	   *time_source = NULL;
+
+	if (!pg_set_timing_clock_source(source))
+		return 0;
+
+	time_source = PG_INSTR_SYSTEM_CLOCK_NAME;
+
+#if PG_INSTR_TSC_CLOCK
+	if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
+		time_source = fast_timing ? PG_INSTR_TSC_CLOCK_NAME_FAST : PG_INSTR_TSC_CLOCK_NAME;
+#endif
+
+	if (fast_timing)
+		printf(_("Fast clock source: %s\n"), time_source);
+	else if (source == TIMING_CLOCK_SOURCE_SYSTEM)
+		printf(_("System clock source: %s\n"), time_source);
+	else
+		printf(_("Clock source: %s\n"), time_source);
 
 	/*
 	 * Pre-zero the statistics data structures.  They're already zero by
@@ -184,7 +267,11 @@ test_timing(unsigned int duration)
 		instr_time	diff_time;
 
 		prev = cur;
-		INSTR_TIME_SET_CURRENT(cur);
+
+		if (fast_timing)
+			INSTR_TIME_SET_CURRENT_FAST(cur);
+		else
+			INSTR_TIME_SET_CURRENT(cur);
 
 		diff_time = cur;
 		INSTR_TIME_SUBTRACT(diff_time, prev);
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index ba69c92b888..bd81bb68b4c 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -207,10 +207,13 @@ pg_current_timing_clock_source(void)
  */
 #if defined(__darwin__) && defined(CLOCK_MONOTONIC_RAW)
 #define PG_INSTR_SYSTEM_CLOCK	CLOCK_MONOTONIC_RAW
+#define PG_INSTR_SYSTEM_CLOCK_NAME	"clock_gettime (CLOCK_MONOTONIC_RAW)"
 #elif defined(CLOCK_MONOTONIC)
 #define PG_INSTR_SYSTEM_CLOCK	CLOCK_MONOTONIC
+#define PG_INSTR_SYSTEM_CLOCK_NAME	"clock_gettime (CLOCK_MONOTONIC)"
 #else
 #define PG_INSTR_SYSTEM_CLOCK	CLOCK_REALTIME
+#define PG_INSTR_SYSTEM_CLOCK_NAME	"clock_gettime (CLOCK_REALTIME)"
 #endif
 
 static inline instr_time
@@ -231,6 +234,7 @@ pg_get_ticks_system(void)
 
 /* On Windows, use QueryPerformanceCounter() for system clock source */
 
+#define PG_INSTR_SYSTEM_CLOCK_NAME	"QueryPerformanceCounter"
 static inline instr_time
 pg_get_ticks_system(void)
 {
@@ -329,6 +333,9 @@ pg_ns_to_ticks(int64 ns)
 
 #if PG_INSTR_TSC_CLOCK
 
+#define PG_INSTR_TSC_CLOCK_NAME_FAST  "RDTSC"
+#define PG_INSTR_TSC_CLOCK_NAME "RDTSCP"
+
 #ifdef _MSC_VER
 #include <intrin.h>
 #endif							/* defined(_MSC_VER) */
-- 
2.47.1