From 7ab1d696483f4bd6a74a4e657708609af7b49c07 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 23 Feb 2025 20:44:10 -0800 Subject: [PATCH v10 3/3] Use time stamp counter to measure time on Linux/x86 We switch to using the time stamp counter (TSC) instead of clock_gettime() to reduce overhead of EXPLAIN (ANALYZE, TIME ON). Tests showed that runtime is reduced by around 10% for queries moving lots of rows through the plan. For now this is only enabled on Linux/x86, in case the system clocksource is reported as TSC. Relying on the Linux kernel simplifies the logic to detect if the present TSC is usable (frequency invariant, synchronized between sockets, etc.). In all other cases we fallback to clock_gettime(). Note, that we intentionally use RDTSC in the fast paths, rather than RDTSCP. RDTSCP waits for outstanding instructions to retire on out-of-order CPUs. This adds noticably for little benefit in the typical InstrStartNode() / InstrStopNode() use case. The macro to be used in such cases is called INSTR_TIME_SET_CURRENT_FAST(). The original macro INSTR_TIME_SET_CURRENT() uses RDTSCP and is supposed to be used when precision is more important than performance. Author: David Geier Author: Andres Freund Author: Lukas Fittl Reviewed-by: Discussion: https://www.postgresql.org/message-id/flat/20200612232810.f46nbqkdhbutzqdg%40alap3.anarazel.de --- src/backend/access/heap/vacuumlazy.c | 3 +- src/backend/executor/instrument.c | 12 +- src/backend/utils/init/postinit.c | 3 + src/bin/pg_test_timing/pg_test_timing.c | 7 +- src/bin/pgbench/pgbench.c | 3 + src/bin/psql/startup.c | 4 + src/common/Makefile | 1 + src/common/instr_time.c | 170 ++++++++++++++++++++++++ src/common/meson.build | 1 + src/include/portability/instr_time.h | 139 ++++++++++++++++--- 10 files changed, 314 insertions(+), 29 deletions(-) create mode 100644 src/common/instr_time.c diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 1af18a78a2b..158868729ab 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -3353,8 +3353,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected) INSTR_TIME_SET_CURRENT(currenttime); elapsed = currenttime; INSTR_TIME_SUBTRACT(elapsed, starttime); - if ((INSTR_TIME_GET_MICROSEC(elapsed) / 1000) - >= VACUUM_TRUNCATE_LOCK_CHECK_INTERVAL) + if (INSTR_TIME_GET_MILLISEC(elapsed) >= VACUUM_TRUNCATE_LOCK_CHECK_INTERVAL) { if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock)) { diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 56e635f4700..01f67c5d972 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -67,9 +67,13 @@ InstrInit(Instrumentation *instr, int instrument_options) void InstrStartNode(Instrumentation *instr) { - if (instr->need_timer && - !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime)) - elog(ERROR, "InstrStartNode called twice in a row"); + if (instr->need_timer) + { + if (!INSTR_TIME_IS_ZERO(instr->starttime)) + elog(ERROR, "InstrStartNode called twice in a row"); + else + INSTR_TIME_SET_CURRENT_FAST(instr->starttime); + } /* save buffer usage totals at node entry, if needed */ if (instr->need_bufusage) @@ -95,7 +99,7 @@ InstrStopNode(Instrumentation *instr, double nTuples) if (INSTR_TIME_IS_ZERO(instr->starttime)) elog(ERROR, "InstrStopNode called without start"); - INSTR_TIME_SET_CURRENT(endtime); + INSTR_TIME_SET_CURRENT_FAST(endtime); INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime); INSTR_TIME_SET_ZERO(instr->starttime); diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c index 01bb6a410cb..f1111f917d1 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -785,6 +785,9 @@ InitPostgres(const char *in_dbname, Oid dboid, /* Initialize portal manager */ EnablePortalManager(); + /* initialize high-precision interval timing */ + INSTR_TIME_INITIALIZE(); + /* Initialize status reporting */ pgstat_beinit(); diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c index 29b0db6d619..62a15465f7c 100644 --- a/src/bin/pg_test_timing/pg_test_timing.c +++ b/src/bin/pg_test_timing/pg_test_timing.c @@ -128,7 +128,8 @@ test_timing(unsigned int duration) end_time; instr_time cur; - INSTR_TIME_SET_CURRENT(start_time); + INSTR_TIME_INITIALIZE(); + INSTR_TIME_SET_CURRENT_FAST(start_time); /* * To reduce loop overhead, check loop condition in instr_time domain. @@ -147,7 +148,7 @@ test_timing(unsigned int duration) int32 bits = 0; prev = cur; - INSTR_TIME_SET_CURRENT(cur); + INSTR_TIME_SET_CURRENT_FAST(cur); temp = cur; INSTR_TIME_SUBTRACT(temp, prev); diff = INSTR_TIME_GET_NANOSEC(temp); @@ -179,7 +180,7 @@ test_timing(unsigned int duration) loop_count++; } - INSTR_TIME_SET_CURRENT(end_time); + INSTR_TIME_SET_CURRENT_FAST(end_time); INSTR_TIME_SUBTRACT(end_time, start_time); diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index fdc957fa34d..88dc3b04725 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -7268,6 +7268,9 @@ main(int argc, char **argv) initRandomState(&state[i].cs_func_rs); } + /* initialize high-precision interval timing */ + INSTR_TIME_INITIALIZE(); + /* opening connection... */ con = doConnect(); if (con == NULL) diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c index 703f3f582c1..96bb72c1263 100644 --- a/src/bin/psql/startup.c +++ b/src/bin/psql/startup.c @@ -24,6 +24,7 @@ #include "help.h" #include "input.h" #include "mainloop.h" +#include "portability/instr_time.h" #include "settings.h" /* @@ -322,6 +323,9 @@ main(int argc, char *argv[]) PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL); + /* initialize high-precision interval timing */ + INSTR_TIME_INITIALIZE(); + SyncVariables(); if (options.list_dbs) diff --git a/src/common/Makefile b/src/common/Makefile index 1e2b91c83c4..194e45e7ae8 100644 --- a/src/common/Makefile +++ b/src/common/Makefile @@ -59,6 +59,7 @@ OBJS_COMMON = \ file_perm.o \ file_utils.o \ hashfn.o \ + instr_time.o \ ip.o \ jsonapi.o \ keywords.o \ diff --git a/src/common/instr_time.c b/src/common/instr_time.c new file mode 100644 index 00000000000..9b18e6e3588 --- /dev/null +++ b/src/common/instr_time.c @@ -0,0 +1,170 @@ +/*------------------------------------------------------------------------- + * + * instr_time.c + * Non-inline parts of the portable high-precision interval timing + * implementation + * + * Portions Copyright (c) 2022, PostgreSQL Global Development Group + * + * + * IDENTIFICATION + * src/backend/port/instr_time.c + * + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "portability/instr_time.h" + +#ifndef WIN32 +/* + * Stores what the number of cycles needs to be multiplied with to end up + * with nanoseconds using integer math. See comment in pg_initialize_rdtsc() + * for more details. + * + * By default assume we are using clock_gettime() as a fallback which uses + * nanoseconds as ticks. Hence, we set the multiplier to the precision scalar + * so that the division in INSTR_TIME_GET_NANOSEC() won't change the nanoseconds. + * + * When using the RDTSC instruction directly this is filled in during initialization + * based on the relevant CPUID fields. + */ +int64 ticks_per_ns_scaled = TICKS_TO_NS_PRECISION; +int64 ticks_per_sec = NS_PER_S; +int64 max_ticks_no_overflow = PG_INT64_MAX / TICKS_TO_NS_PRECISION; + +#if defined(__x86_64__) && defined(__linux__) +/* + * Indicates if RDTSC can be used (Linux/x86 only, when OS uses TSC clocksource) + */ +bool has_rdtsc = false; + +/* + * Indicates if RDTSCP can be used. True if RDTSC can be used and RDTSCP is available. + */ +bool has_rdtscp = false; + +#define CPUID_HYPERVISOR_VMWARE(words) (words[1] == 0x61774d56 && words[2] == 0x4d566572 && words[3] == 0x65726177) /* VMwareVMware */ +#define CPUID_HYPERVISOR_KVM(words) (words[1] == 0x4b4d564b && words[2] == 0x564b4d56 && words[3] == 0x0000004d) /* KVMKVMKVM */ + +static bool +get_tsc_frequency_khz(uint32 *tsc_freq) +{ + uint32 r[4]; + + if (__get_cpuid(0x15, &r[0] /* denominator */ , &r[1] /* numerator */ , &r[2] /* hz */ , &r[3]) && r[2] > 0) + { + if (r[0] == 0 || r[1] == 0) + return false; + + *tsc_freq = r[2] / 1000 * r[1] / r[0]; + return true; + } + + /* Some CPUs only report frequency in 16H */ + if (__get_cpuid(0x16, &r[0] /* base_mhz */ , &r[1], &r[2], &r[3])) + { + *tsc_freq = r[0] * 1000; + return true; + } + + /* + * Check if we have a KVM or VMware Hypervisor passing down TSC frequency + * to us in a guest VM + * + * Note that accessing the 0x40000000 leaf for Hypervisor info requires + * use of __cpuidex to set ECX to 0. + * + * TODO: We need to check whether our compiler is new enough + * (https://gcc.gnu.org/bugzilla/show_bug.cgi?id=95973) + */ + __cpuidex((int32 *) r, 0x40000000, 0); + if (r[0] >= 0x40000010 && (CPUID_HYPERVISOR_VMWARE(r) || CPUID_HYPERVISOR_KVM(r))) + { + __cpuidex((int32 *) r, 0x40000010, 0); + if (r[0] > 0) + { + *tsc_freq = r[0]; + return true; + } + } + + return false; +} + +static bool +is_rdtscp_available() +{ + uint32 r[4]; + + return __get_cpuid(0x80000001, &r[0], &r[1], &r[2], &r[3]) > 0 && (r[3] & (1 << 27)) != 0; +} + +/* + * Decide whether we use the RDTSC instruction at runtime, for Linux/x86, + * instead of incurring the overhead of a full clock_gettime() call. + * + * This can't be reliably determined at compile time, since the + * availability of an "invariant" TSC (that is not affected by CPU + * frequency changes) is dependent on the CPU architecture. Additionally, + * there are cases where TSC availability is impacted by virtualization, + * where a simple cpuid feature check would not be enough. + * + * Since Linux already does a significant amount of work to determine + * whether TSC is a viable clock source, decide based on that. + */ +void +pg_initialize_rdtsc(void) +{ + FILE *fp = fopen("/sys/devices/system/clocksource/clocksource0/current_clocksource", "r"); + + if (fp) + { + char buf[128]; + + if (fgets(buf, sizeof(buf), fp) != NULL && strcmp(buf, "tsc\n") == 0) + { + /* + * Compute baseline CPU peformance, determines speed at which + * RDTSC advances. + */ + uint32 tsc_freq; + + if (get_tsc_frequency_khz(&tsc_freq)) + { + /* + * Ticks to nanoseconds conversion requires floating point + * math because because: + * + * sec = ticks / frequency_hz ns = ticks / frequency_hz * + * 1,000,000,000 ns = ticks * (1,000,000,000 / frequency_hz) + * ns = ticks * (1,000,000 / frequency_khz) <-- now in + * kilohertz + * + * Here, 'ns' is usually a floating number. For example for a + * 2.5 GHz CPU the scaling factor becomes 1,000,000 / + * 2,500,000 = 1.2. + * + * To be able to use integer math we work around the lack of + * precision. We first scale the integer up and after the + * multiplication by the number of ticks in + * INSTR_TIME_GET_NANOSEC() we divide again by the same value. + * We picked the scaler such that it provides enough precision + * and is a power-of-two which allows for shifting instead of + * doing an integer division. + */ + ticks_per_ns_scaled = INT64CONST(1000000) * TICKS_TO_NS_PRECISION / tsc_freq; + ticks_per_sec = tsc_freq * 1000; /* KHz->Hz */ + max_ticks_no_overflow = PG_INT64_MAX / ticks_per_ns_scaled; + + has_rdtsc = true; + has_rdtscp = is_rdtscp_available(); + } + } + + fclose(fp); + } +} +#endif /* defined(__x86_64__) && defined(__linux__) */ + +#endif /* WIN32 */ diff --git a/src/common/meson.build b/src/common/meson.build index 1540ba67cca..62b90b3e609 100644 --- a/src/common/meson.build +++ b/src/common/meson.build @@ -13,6 +13,7 @@ common_sources = files( 'file_perm.c', 'file_utils.c', 'hashfn.c', + 'instr_time.c', 'ip.c', 'jsonapi.c', 'keywords.c', diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h index 6ad411c6866..fd8ca122001 100644 --- a/src/include/portability/instr_time.h +++ b/src/include/portability/instr_time.h @@ -4,9 +4,11 @@ * portable high-precision interval timing * * This file provides an abstraction layer to hide portability issues in - * interval timing. On Unix we use clock_gettime(), and on Windows we use - * QueryPerformanceCounter(). These macros also give some breathing room to - * use other high-precision-timing APIs. + * interval timing. On Linux/x86 we use the rdtsc instruction when a TSC + * clocksource is also used on the host OS. Otherwise, and on other + * Unix-like systems we use clock_gettime() and on Windows we use + * QueryPerformanceCounter(). These macros also give some breathing + * room to use other high-precision-timing APIs. * * The basic data type is instr_time, which all callers should treat as an * opaque typedef. instr_time can store either an absolute time (of @@ -19,10 +21,11 @@ * * INSTR_TIME_SET_ZERO(t) set t to zero (memset is acceptable too) * - * INSTR_TIME_SET_CURRENT(t) set t to current time + * INSTR_TIME_SET_CURRENT_FAST(t) set t to current time without waiting + * for instructions in out-of-order window * - * INSTR_TIME_SET_CURRENT_LAZY(t) set t to current time if t is zero, - * evaluates to whether t changed + * INSTR_TIME_SET_CURRENT(t) set t to current time while waiting for + * instructions in OOO to retire * * INSTR_TIME_SET_SECONDS(t, s) set t to s seconds * @@ -84,7 +87,15 @@ typedef struct instr_time #ifndef WIN32 +/* + * Make sure this is a power-of-two, so that the compiler can turn the + * multiplications and divisions into shifts. + */ +#define TICKS_TO_NS_PRECISION (1<<14) +extern int64 ticks_per_ns_scaled; +extern int64 ticks_per_sec; +extern int64 max_ticks_no_overflow; /* Use clock_gettime() */ @@ -110,35 +121,124 @@ typedef struct instr_time #define PG_INSTR_CLOCK CLOCK_REALTIME #endif -/* helper for INSTR_TIME_SET_CURRENT */ +#if defined(__x86_64__) && defined(__linux__) +#include +#include + +extern bool has_rdtsc; +extern bool has_rdtscp; + +extern void pg_initialize_rdtsc(void); +#endif + static inline instr_time -pg_clock_gettime_ns(void) +pg_clock_gettime() { instr_time now; struct timespec tmp; clock_gettime(PG_INSTR_CLOCK, &tmp); now.ticks = tmp.tv_sec * NS_PER_S + tmp.tv_nsec; - return now; } +static inline instr_time +pg_get_ticks_fast(void) +{ +#if defined(__x86_64__) && defined(__linux__) + if (has_rdtsc) + { + instr_time now; + + now.ticks = __rdtsc(); + return now; + } +#endif + + return pg_clock_gettime(); +} + +static inline instr_time +pg_get_ticks(void) +{ +#if defined(__x86_64__) && defined(__linux__) + if (has_rdtscp) + { + instr_time now; + uint32 unused; + + now.ticks = __rdtscp(&unused); + return now; + } +#endif + + return pg_clock_gettime(); +} + +static inline int64_t +pg_ticks_to_ns(instr_time t) +{ + /* + * Would multiplication overflow? If so perform computation in two parts. + * Check overflow without actually overflowing via: a * b > max <=> a > + * max / b + */ + int64 ns = 0; + + if (unlikely(t.ticks > max_ticks_no_overflow)) + { + /* + * Compute how often the maximum number of ticks fits completely into + * the number of elapsed ticks and convert that number into + * nanoseconds. Then multiply by the count to arrive at the final + * value. In a 2nd step we adjust the number of elapsed ticks and + * convert the remaining ticks. + */ + int64 count = t.ticks / max_ticks_no_overflow; + int64 max_ns = max_ticks_no_overflow * ticks_per_ns_scaled / TICKS_TO_NS_PRECISION; + + ns = max_ns * count; + + /* + * Subtract the ticks that we now already accounted for, so that they + * don't get counted twice. + */ + t.ticks -= count * max_ticks_no_overflow; + Assert(t.ticks >= 0); + } + + ns += t.ticks * ticks_per_ns_scaled / TICKS_TO_NS_PRECISION; + return ns; +} + +static inline void +pg_initialize_get_ticks() +{ +#if defined(__x86_64__) && defined(__linux__) + pg_initialize_rdtsc(); +#endif +} + +#define INSTR_TIME_INITIALIZE() \ + pg_initialize_get_ticks() + +#define INSTR_TIME_SET_CURRENT_FAST(t) \ + ((t) = pg_get_ticks_fast()) + #define INSTR_TIME_SET_CURRENT(t) \ - ((t) = pg_clock_gettime_ns()) + ((t) = pg_get_ticks()) #define INSTR_TIME_SET_SECONDS(t, s) \ - ((t).ticks = NS_PER_S * (s)) + ((t).ticks = (s) * ticks_per_sec) #define INSTR_TIME_GET_NANOSEC(t) \ - ((int64) (t).ticks) - + pg_ticks_to_ns(t) #else /* WIN32 */ /* Use QueryPerformanceCounter() */ -/* helper for INSTR_TIME_SET_CURRENT */ static inline instr_time pg_query_performance_counter(void) { @@ -160,6 +260,11 @@ GetTimerFrequency(void) return (double) f.QuadPart; } +#define INSTR_TIME_INITIALIZE() + +#define INSTR_TIME_SET_CURRENT_FAST(t) \ + ((t) = pg_query_performance_counter()) + #define INSTR_TIME_SET_CURRENT(t) \ ((t) = pg_query_performance_counter()) @@ -180,13 +285,8 @@ GetTimerFrequency(void) #define INSTR_TIME_IS_LT(x, y) ((x).ticks < (y).ticks) - #define INSTR_TIME_SET_ZERO(t) ((t).ticks = 0) -#define INSTR_TIME_SET_CURRENT_LAZY(t) \ - (INSTR_TIME_IS_ZERO(t) ? INSTR_TIME_SET_CURRENT(t), true : false) - - #define INSTR_TIME_ADD(x,y) \ ((x).ticks += (y).ticks) @@ -196,7 +296,6 @@ GetTimerFrequency(void) #define INSTR_TIME_ACCUM_DIFF(x,y,z) \ ((x).ticks += (y).ticks - (z).ticks) - #define INSTR_TIME_GET_DOUBLE(t) \ ((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S) -- 2.47.1