upstream/postgresql
1
0
Fork 0
mirror of https://github.com/postgres/postgres.git synced 2026-05-27 12:00:13 -04:00
Code Issues Projects Releases Packages Wiki Activity Actions

pg_test_timing: Show additional TSC clock source debug info

Browse source 
In some cases its necessary to understand whether TSC frequency data was
sourced from CPUID, and which of the registers. Show this debug info at
the end of pg_test_timing, and rework TSC functions to support that.

This would have helped debug the buildfarm report fixed in 7fc36c5db5
and is likely going to aid in any TSC-related issues reported during the
beta period or later.

Additionally, emit a warning if TSC frequency from calibration differs
by more than 10% from the TSC frequency in use, and suggest the use
of timing_clock_source = 'system'.

In passing, add an explicit early return in the output function if the
loop count is zero. This can't happen in practice, but coverity complained
because we unconditionally call output for the fast TSC measurement.

Author: Lukas Fittl <lukas@fittl.com>
Suggested-by: Andres Freund <andres@anarazel.de>
Reviewed-by: Andres Freund <andres@anarazel.de>
Reviewed-by: Haibo Yan <tristan.yim@gmail.com>
Reviewed-by: Tom Lane <tgl@sss.pgh.pa.us> (coverity fix only)
Discussion: https://postgr.es/m/CAP53Pkw3Gzb+KTF5pu_o7tzbfZ7+qm2m6uDWuGtTJjZpV9yNpg@mail.gmail.com
This commit is contained in:
Andres Freund 2026-05-16 11:51:34 -04:00
parent aa1f93a338
commit 5ba34f6dc8
7 changed files with 145 additions and 22 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
doc/src/sgml/ref/pgtesttiming.sgml
View file

@ -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>

61
src/bin/pg_test_timing/pg_test_timing.c
View file

@ -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,51 @@ 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)
{
double diff_pct;
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"));
printf(_("TSC frequency from calibration: %d kHz\n"), info->calibrated_frequency_khz);
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);
exit(1);
}
}
else
printf(_("TSC clock source is not usable. Likely unable to determine TSC frequency. Are you running in an unsupported virtualized environment?\n"));
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(_("\nTSC clock source will be used by default, unless timing_clock_source is set to 'system'.\n"));
else
printf(_("\nTSC clock source will not be used by default, unless timing_clock_source is set to 'tsc'.\n"));
}
else
printf(_("\nTSC clock source is not usable. Likely unable to determine TSC frequency. Are you running in an unsupported virtualized environment?\n"));
}
#endif
@ -341,6 +370,12 @@ output(uint64 loop_count)
double rprct;
bool stopped = false;
if (loop_count == 0)
{
printf(_("WARNING: No timing measurements collected. Report this as a bug to <%s>.\n"), PACKAGE_BUGREPORT);
return;
}
/* find highest bit value */
while (max_bit > 0 && histogram[max_bit] == 0)
max_bit--;

60
src/common/instr_time.c
View file

@ -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, may run the TSC calibration loop (if not already done during
* frequency detection) which can 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.frequency_khz > 0 && tsc_info.calibrated_frequency_khz < 0)
tsc_info.calibrated_frequency_khz = pg_tsc_calibrate_frequency();
return &tsc_info;
}
#endif /* PG_INSTR_TSC_CLOCK */

2
src/include/port/pg_cpu.h
View file

@ -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_size);
#endif /* defined(USE_SSE2) || defined(__i386__) */

10
src/include/portability/instr_time.h
View file

@ -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 */
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 */

31
src/port/pg_cpu_x86.c
View file

@ -13,7 +13,11 @@
*-------------------------------------------------------------------------
*/
#include "c.h"
#ifndef FRONTEND
#include "postgres.h"
#else
#include "postgres_fe.h"
#endif
#if defined(USE_SSE2) || defined(__i386__)
@ -158,9 +162,12 @@ static uint32 x86_hypervisor_tsc_frequency_khz(void);
*
* Needed to interpret the tick value returned by RDTSC/RDTSCP. Return value of
* 0 indicates the frequency information was not accessible via CPUID.
*
* The optional source argument may contain a pre-allocated string of capacity
* source_size that will be concatenated with info on the TSC frequency source.
*/
uint32
x86_tsc_frequency_khz(void)
x86_tsc_frequency_khz(char *source, size_t source_size)
{
unsigned int reg[4] = {0};
@ -173,7 +180,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_size);
if (freq > 0)
strlcat(source, ", cpuid 0x40000010", source_size);
}
return freq;
}
/*
* On modern Intel CPUs, the TSC is implemented by invariant timekeeping
@ -206,6 +223,9 @@ x86_tsc_frequency_khz(void)
if (reg[EAX] == 0 || reg[EBX] == 0)
return 0;
if (source)
strlcat(source, ", cpuid 0x15", source_size);
return reg[ECX] / 1000 * reg[EBX] / reg[EAX];
}
@ -216,7 +236,12 @@ x86_tsc_frequency_khz(void)
*/
pg_cpuid(0x16, reg);
if (reg[EAX] > 0)
{
if (source)
strlcat(source, ", cpuid 0x16", source_size);
return reg[EAX] * 1000;
}
return 0;
}

1
src/tools/pgindent/typedefs.list
View file

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