Add TSC debug info to pg_test_timing

src/bin/pg_test_timing/pg_test_timing.c

@@ -184,7 +184,7 @@ static void
 test_tsc_timing(void)
 {
 	uint64		loop_count;
-	uint32		calibrated_freq;
+	TscClockSourceInfo info;
 
 	printf("\n");
 	loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, false);
@@ -198,11 +198,13 @@ test_tsc_timing(void)
 		output(loop_count);
 		printf("\n");
 
-		printf(_("TSC frequency in use: %u kHz\n"), timing_tsc_frequency_khz);
+		info = pg_timing_tsc_clock_source_info();
+		printf(_("TSC frequency in use: %d kHz\n"), info.frequency_khz);
+		if (info.frequency_source)
+			printf(_("TSC frequency source: %s\n"), info.frequency_source);
 
-		calibrated_freq = pg_tsc_calibrate_frequency();
-		if (calibrated_freq > 0)
-			printf(_("TSC frequency from calibration: %u kHz\n"), calibrated_freq);
+		if (info.calibrated_frequency_khz > 0)
+			printf(_("TSC frequency from calibration: %d kHz\n"), info.calibrated_frequency_khz);
 		else
 			printf(_("TSC calibration did not converge\n"));
 

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 const char *timing_tsc_frequency_source = NULL;
+
 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,13 +205,14 @@ static void
 tsc_detect_frequency(void)
 {
 	timing_tsc_frequency_khz = 0;
+	timing_tsc_frequency_source = NULL;
 
 	/* We require RDTSCP support and an invariant TSC, bail if not available */
 	if (!x86_feature_available(PG_RDTSCP) || !x86_feature_available(PG_TSC_INVARIANT))
 		return;
 
 	/* Determine speed at which the TSC advances */
-	timing_tsc_frequency_khz = x86_tsc_frequency_khz();
+	timing_tsc_frequency_khz = x86_tsc_frequency_khz(&timing_tsc_frequency_source);
 	if (timing_tsc_frequency_khz > 0)
 		return;
 
@@ -217,6 +221,8 @@ tsc_detect_frequency(void)
 	 * frequency by comparing ticks against walltime in a calibration loop.
 	 */
 	timing_tsc_frequency_khz = pg_tsc_calibrate_frequency();
+	if (timing_tsc_frequency_khz > 0)
+		timing_tsc_frequency_source = "x86, calibration";
 }
 
 /*
@@ -282,7 +288,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 +375,22 @@ pg_tsc_calibrate_frequency(void)
 	return (uint32) freq_khz;
 }
 
+/*
+ * Returns TSC clock source information for diagnostic purposes.
+ *
+ * Note: This always runs the TSC calibration loop which may take up to
+ * TSC_CALIBRATION_MAX_NS.
+ */
+TscClockSourceInfo
+pg_timing_tsc_clock_source_info(void)
+{
+	TscClockSourceInfo info;
+
+	info.frequency_khz = timing_tsc_frequency_khz;
+	info.frequency_source = timing_tsc_frequency_source;
+	info.calibrated_frequency_khz = pg_tsc_calibrate_frequency();
+
+	return 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(const char **source);
 
 #endif							/* defined(USE_SSE2) || defined(__i386__) */
 

src/include/portability/instr_time.h

@@ -165,7 +165,15 @@ extern PGDLLIMPORT int32 timing_tsc_frequency_khz;
 
 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 loop, 0 if did
+											 * not converge */
+	const char *frequency_source;	/* describes how frequency was determined */
+} TscClockSourceInfo;
+
+extern TscClockSourceInfo pg_timing_tsc_clock_source_info(void);
 
 #endif							/* PG_INSTR_TSC_CLOCK */
 

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__)
 
@@ -152,7 +156,7 @@ set_x86_features(void)
 
 /* TSC (Time-stamp Counter) handling code */
 
-static uint32 x86_hypervisor_tsc_frequency_khz(void);
+static uint32 x86_hypervisor_tsc_frequency_khz(const char **hvname);
 
 /*
  * Determine the TSC frequency of the CPU through CPUID, where supported.
@@ -161,13 +165,17 @@ 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(const char **source)
 {
 	unsigned int reg[4] = {0};
+	const char *hvname = NULL;
+
+	if (source)
+		*source = NULL;
 
 	if (x86_feature_available(PG_HYPERVISOR))
 	{
-		uint32		freq = x86_hypervisor_tsc_frequency_khz();
+		uint32		freq = x86_hypervisor_tsc_frequency_khz(&hvname);
 
 		/*
 		 * If the hypervisor specific logic didn't figure out the frequency,
@@ -176,7 +184,12 @@ x86_tsc_frequency_khz(void)
 		 * frequency.
 		 */
 		if (freq > 0)
+		{
+			if (source)
+				*source = psprintf("x86, hypervisor (%s), cpuid 0x40000010",
+								   hvname);
 			return freq;
+		}
 	}
 
 	/*
@@ -210,6 +223,9 @@ x86_tsc_frequency_khz(void)
 		if (reg[EAX] == 0 || reg[EBX] == 0)
 			return 0;
 
+		if (source)
+			*source = hvname ? psprintf("x86, hypervisor (%s), cpuid 0x15", hvname) : "x86, cpuid 0x15";
+
 		return reg[ECX] / 1000 * reg[EBX] / reg[EAX];
 	}
 
@@ -220,7 +236,12 @@ x86_tsc_frequency_khz(void)
 	 */
 	pg_cpuid(0x16, reg);
 	if (reg[EAX] > 0)
+	{
+		if (source)
+			*source = hvname ? psprintf("x86, hypervisor (%s), cpuid 0x16", hvname) : "x86, cpuid 0x16";
+
 		return reg[EAX] * 1000;
+	}
 
 	return 0;
 }
@@ -239,11 +260,13 @@ x86_tsc_frequency_khz(void)
 #define CPUID_HYPERVISOR_VMWARE(r) (r[EBX] == 0x61774d56 && r[ECX] == 0x4d566572 && r[EDX] == 0x65726177)	/* VMwareVMware */
 #define CPUID_HYPERVISOR_KVM(r) (r[EBX] == 0x4b4d564b && r[ECX] == 0x564b4d56 && r[EDX] == 0x0000004d)	/* KVMKVMKVM */
 static uint32
-x86_hypervisor_tsc_frequency_khz(void)
+x86_hypervisor_tsc_frequency_khz(const char **hvname)
 {
 #if defined(HAVE__CPUIDEX)
 	unsigned int reg[4] = {0};
 
+	Assert(hvname != NULL);
+
 	/*
 	 * The hypervisor is determined using the 0x40000000 Hypervisor
 	 * information leaf, which requires use of __cpuidex to set ECX to 0 to
@@ -255,12 +278,23 @@ x86_hypervisor_tsc_frequency_khz(void)
 	 */
 	__cpuidex((int *) reg, 0x40000000, 0);
 
+	/* Always identify the hypervisor */
+	if (CPUID_HYPERVISOR_VMWARE(reg))
+		*hvname = "vmware";
+	else if (CPUID_HYPERVISOR_KVM(reg))
+		*hvname = "kvm";
+	else
+		*hvname = "other";
+
 	if (reg[EAX] >= 0x40000010 && (CPUID_HYPERVISOR_VMWARE(reg) || CPUID_HYPERVISOR_KVM(reg)))
 	{
 		__cpuidex((int *) reg, 0x40000010, 0);
 		if (reg[EAX] > 0)
 			return reg[EAX];
 	}
+#else
+	Assert(hvname != NULL);
+	*hvname = "unknown";
 #endif							/* HAVE__CPUIDEX */
 
 	return 0;

src/tools/pgindent/typedefs.list

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