pg_test_timing: Show additional TSC clock source debug info

doc/src/sgml/ref/pgtesttiming.sgml

@@ -283,8 +283,10 @@ Observed timing durations up to 99.9900%:
 ...
 61594291       0.0000   100.0000          1
 
+TSC frequency source: x86, cpuid 0x15
 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>

src/bin/pg_test_timing/pg_test_timing.c

@@ -7,6 +7,7 @@
 #include "postgres_fe.h"
 
 #include <limits.h>
+#include <math.h>
 
 #include "getopt_long.h"
 #include "port/pg_bitutils.h"
@@ -184,7 +185,7 @@ static void
 test_tsc_timing(void)
 {
 	uint64		loop_count;
-	uint32		calibrated_freq;
+	const TscClockSourceInfo *info;
 
 	printf("\n");
 	loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, false);
@@ -197,23 +198,53 @@ test_tsc_timing(void)
 		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);
+	/*
+	 * Report TSC information regardless of whether it was usable, makes
+	 * debugging a lot easier.
+	 */
+	info = pg_timing_tsc_clock_source_info();
+	if (info->frequency_source[0] != '\0')
+		printf(_("TSC frequency source: %s\n"), info->frequency_source);
+	printf(_("TSC frequency in use: %d kHz\n"), info->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"));
+	if (info->calibrated_frequency_khz > 0)
+	{
+		printf(_("TSC frequency from calibration: %d kHz\n"), info->calibrated_frequency_khz);
+
+		if (info->frequency_khz > 0)
+		{
+			double		diff_pct;
+
+			diff_pct = fabs((double) info->calibrated_frequency_khz - info->frequency_khz) /
+				info->frequency_khz * 100.0;
+
+			if (diff_pct > 10.0)
+			{
+				printf(_("WARNING: Calibrated TSC frequency differs by %.1f%% from the TSC frequency in use\n"),
+					   diff_pct);
+				printf(_("HINT: Consider setting timing_clock_source to 'system'. Report bugs to <%s>.\n"), PACKAGE_BUGREPORT);
+			}
+		}
+	}
+	else
+		printf(_("TSC calibration did not converge\n"));
 
+	/*
+	 * Report whether TSC was usable and, if so, whether it will be used
+	 * automatically.
+	 */
+	if (loop_count > 0)
+	{
 		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"));
+			printf(_("\nTSC 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"));
+			printf(_("\nTSC 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"));
+		printf(_("\nTSC clock source is not usable. Likely unable to determine TSC frequency. Are you running in an unsupported virtualized environment?\n"));
 }
 #endif
 

src/common/instr_time.c

@@ -70,6 +70,8 @@ static void set_ticks_per_ns(void);
 static void set_ticks_per_ns_system(void);
 
 #if PG_INSTR_TSC_CLOCK
+static TscClockSourceInfo tsc_info = {.calibrated_frequency_khz = -1};
+
 static bool tsc_use_by_default(void);
 static void set_ticks_per_ns_for_tsc(void);
 #endif
@@ -166,6 +168,7 @@ set_ticks_per_ns_system(void)
 #if PG_INSTR_TSC_CLOCK
 
 static void tsc_detect_frequency(void);
+static uint32 pg_tsc_calibrate_frequency(void);
 
 /*
  * Initialize the TSC clock source by determining its usability and frequency.
@@ -202,21 +205,50 @@ static void
 tsc_detect_frequency(void)
 {
 	timing_tsc_frequency_khz = 0;
+	tsc_info.frequency_khz = 0;
+	tsc_info.frequency_source[0] = '\0';
+
+	strlcat(tsc_info.frequency_source, "x86",
+			sizeof(tsc_info.frequency_source));
 
 	/* We require RDTSCP support and an invariant TSC, bail if not available */
-	if (!x86_feature_available(PG_RDTSCP) || !x86_feature_available(PG_TSC_INVARIANT))
+	if (!x86_feature_available(PG_RDTSCP))
+	{
+		strlcat(tsc_info.frequency_source, ", no rdtscp",
+				sizeof(tsc_info.frequency_source));
 		return;
+	}
+
+	if (!x86_feature_available(PG_TSC_INVARIANT))
+	{
+		strlcat(tsc_info.frequency_source, ", not invariant",
+				sizeof(tsc_info.frequency_source));
+		return;
+	}
 
 	/* Determine speed at which the TSC advances */
-	timing_tsc_frequency_khz = x86_tsc_frequency_khz();
+	timing_tsc_frequency_khz = x86_tsc_frequency_khz(tsc_info.frequency_source,
+													 sizeof(tsc_info.frequency_source));
 	if (timing_tsc_frequency_khz > 0)
+	{
+		tsc_info.frequency_khz = timing_tsc_frequency_khz;
 		return;
+	}
 
 	/*
 	 * CPUID did not give us the TSC frequency. We can instead measure the
 	 * frequency by comparing ticks against walltime in a calibration loop.
 	 */
-	timing_tsc_frequency_khz = pg_tsc_calibrate_frequency();
+	if (tsc_info.calibrated_frequency_khz < 0)
+		tsc_info.calibrated_frequency_khz = pg_tsc_calibrate_frequency();
+
+	timing_tsc_frequency_khz = tsc_info.calibrated_frequency_khz;
+	if (timing_tsc_frequency_khz > 0)
+	{
+		strlcat(tsc_info.frequency_source, ", calibration",
+				sizeof(tsc_info.frequency_source));
+		tsc_info.frequency_khz = timing_tsc_frequency_khz;
+	}
 }
 
 /*
@@ -282,7 +314,7 @@ tsc_use_by_default(void)
 #define TSC_CALIBRATION_ITERATIONS	1000000
 #define TSC_CALIBRATION_SKIPS		100
 #define TSC_CALIBRATION_STABLE_CYCLES	10
-uint32
+static uint32
 pg_tsc_calibrate_frequency(void)
 {
 	instr_time	initial_wall;
@@ -369,4 +401,24 @@ pg_tsc_calibrate_frequency(void)
 	return (uint32) freq_khz;
 }
 
+/*
+ * Returns TSC clock source information for diagnostic purposes.
+ *
+ * On first call, runs the TSC calibration loop (if not already done during
+ * frequency detection) which may take up to TSC_CALIBRATION_MAX_NS.
+ * Subsequent calls return cached results.
+ *
+ * Note: This won't return the right info in EXEC_BACKEND builds if this were
+ * used in the backend (which it currently is not), as tsc_info is not copied
+ * using read_backend_variables - only the TSC frequency is.
+ */
+const TscClockSourceInfo *
+pg_timing_tsc_clock_source_info(void)
+{
+	if (tsc_info.calibrated_frequency_khz < 0)
+		tsc_info.calibrated_frequency_khz = pg_tsc_calibrate_frequency();
+
+	return &tsc_info;
+}
+
 #endif							/* PG_INSTR_TSC_CLOCK */

src/include/port/pg_cpu.h

@@ -56,7 +56,7 @@ x86_feature_available(X86FeatureId feature)
 	return X86Features[feature];
 }
 
-extern uint32 x86_tsc_frequency_khz(void);
+extern uint32 x86_tsc_frequency_khz(char *source, size_t source_len);
 
 #endif							/* defined(USE_SSE2) || defined(__i386__) */
 

src/include/portability/instr_time.h

@@ -161,14 +161,24 @@ extern PGDLLIMPORT bool timing_tsc_enabled;
  */
 extern PGDLLIMPORT int32 timing_tsc_frequency_khz;
 
+
 #if PG_INSTR_TSC_CLOCK
 
 extern void pg_initialize_timing_tsc(void);
 
-extern uint32 pg_tsc_calibrate_frequency(void);
+typedef struct TscClockSourceInfo
+{
+	int32		frequency_khz;	/* from CPUID or calibration */
+	int32		calibrated_frequency_khz;	/* from calibration */
+	char		frequency_source[128];	/* describes how frequency was
+										 * determined */
+} TscClockSourceInfo;
+
+extern const TscClockSourceInfo *pg_timing_tsc_clock_source_info(void);
 
 #endif							/* PG_INSTR_TSC_CLOCK */
 
+
 /*
  * Returns the current timing clock source effectively in use, resolving
  * TIMING_CLOCK_SOURCE_AUTO to either TIMING_CLOCK_SOURCE_SYSTEM or

src/port/pg_cpu_x86.c

@@ -13,7 +13,11 @@
  *-------------------------------------------------------------------------
  */
 
-#include "c.h"
+#ifndef FRONTEND
+#include "postgres.h"
+#else
+#include "postgres_fe.h"
+#endif
 
 #if defined(USE_SSE2) || defined(__i386__)
 
@@ -161,7 +165,7 @@ static uint32 x86_hypervisor_tsc_frequency_khz(void);
  * 0 indicates the frequency information was not accessible via CPUID.
  */
 uint32
-x86_tsc_frequency_khz(void)
+x86_tsc_frequency_khz(char *source, size_t source_len)
 {
 	unsigned int reg[4] = {0};
 
@@ -174,7 +178,17 @@ x86_tsc_frequency_khz(void)
 	 * to be wildly incorrect when virtualized.
 	 */
 	if (x86_feature_available(PG_HYPERVISOR))
-		return x86_hypervisor_tsc_frequency_khz();
+	{
+		uint32		freq = x86_hypervisor_tsc_frequency_khz();
+
+		if (source)
+		{
+			strlcat(source, ", hypervisor", source_len);
+			if (freq > 0)
+				strlcat(source, ", cpuid 0x40000010", source_len);
+		}
+		return freq;
+	}
 
 	/*
 	 * On modern Intel CPUs, the TSC is implemented by invariant timekeeping
@@ -207,6 +221,9 @@ x86_tsc_frequency_khz(void)
 		if (reg[EAX] == 0 || reg[EBX] == 0)
 			return 0;
 
+		if (source)
+			strlcat(source, ", cpuid 0x15", source_len);
+
 		return reg[ECX] / 1000 * reg[EBX] / reg[EAX];
 	}
 
@@ -217,7 +234,12 @@ x86_tsc_frequency_khz(void)
 	 */
 	pg_cpuid(0x16, reg);
 	if (reg[EAX] > 0)
+	{
+		if (source)
+			strlcat(source, ", cpuid 0x16", source_len);
+
 		return reg[EAX] * 1000;
+	}
 
 	return 0;
 }

src/tools/pgindent/typedefs.list

@@ -3090,6 +3090,7 @@ TParserStateActionItem
 TQueueDestReceiver
 TRGM
 TSAnyCacheEntry
+TscClockSourceInfo
 TSConfigCacheEntry
 TSConfigInfo
 TSDictInfo