From 1e0f93a8973449bf8b5e6e01dbcbf10e7b065b26 Mon Sep 17 00:00:00 2001 From: David Geier Date: Mon, 23 Jan 2023 18:13:55 +0100 Subject: [PATCH v9 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/commands/explain.c | 2 +- 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 | 130 ++++++++++++++++++++++ src/common/meson.build | 1 + src/include/portability/instr_time.h | 137 ++++++++++++++++++++---- src/tools/msvc/Mkvcbuild.pm | 2 +- 12 files changed, 273 insertions(+), 32 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 8f14cf85f3..212093568b 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -3002,8 +3002,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/commands/explain.c b/src/backend/commands/explain.c index e57bda7b62..9eca5901f0 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -526,7 +526,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, double totaltime = 0; int eflags; int instrument_option = 0; - + Assert(plannedstmt->commandType != CMD_UTILITY); if (es->analyze && es->timing) diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index ee78a5749d..1ce3d62cff 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 2f07ca7a0e..2eef902483 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -805,6 +805,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 e20718669a..d185c8fe2e 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 508ed218e8..4125bc8cb7 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -7059,6 +7059,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 5a28b6f713..3f95e01320 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 113029bf7b..23a5c68705 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 0000000000..c73956d0df --- /dev/null +++ b/src/common/instr_time.c @@ -0,0 +1,130 @@ +/*------------------------------------------------------------------------- + * + * 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; + +/* + * This fails on hypervisors. On hypervisors a different CPUID leaf could be used + * to obtain the TSC frequency. We don't do that because the TSC on hypervisors + * is usually emulated and the performance of emulated an TSC is usually as bad as + * the performance of the hypervisor's clock_gettime() implementation. + */ +static bool get_tsc_frequency_khz(uint32 *tsc_freq) +{ + uint32 r0, r1, r2; + int result = __get_cpuid(0x16, tsc_freq, &r0, &r1, &r2); + *tsc_freq *= 1000; // Convert from MHz to KHz + return result > 0 && *tsc_freq > 0; +} + +static bool is_rdtscp_available() +{ + uint32 r0, r1, r2, r3; + return __get_cpuid(0x80000001, &r0, &r1, &r2, &r3) > 0 && (r3 & (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 41bd58ebdf..000983c6bf 100644 --- a/src/common/meson.build +++ b/src/common/meson.build @@ -11,6 +11,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 aab80effb0..3f17cd2102 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_LAZY(t) set t to current time if t is zero, - * evaluates to whether t changed + * INSTR_TIME_SET_CURRENT_FAST(t) set t to current time without waiting + * for instructions in out-of-order window + * + * 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,120 @@ 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; + uint32 a; + now.ticks = __rdtscp(&a); + 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 +256,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 +281,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 +292,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) diff --git a/src/tools/msvc/Mkvcbuild.pm b/src/tools/msvc/Mkvcbuild.pm index f1c9ddf4a0..bec74b52ae 100644 --- a/src/tools/msvc/Mkvcbuild.pm +++ b/src/tools/msvc/Mkvcbuild.pm @@ -135,7 +135,7 @@ sub mkvcbuild our @pgcommonallfiles = qw( archive.c base64.c checksum_helper.c compression.c config_info.c controldata_utils.c d2s.c encnames.c exec.c - f2s.c file_perm.c file_utils.c hashfn.c ip.c jsonapi.c + f2s.c file_perm.c file_utils.c hashfn.c ip.c instr_time.o jsonapi.c keywords.c kwlookup.c link-canary.c md5_common.c percentrepl.c pg_get_line.c pg_lzcompress.c pg_prng.c pgfnames.c psprintf.c relpath.c rmtree.c saslprep.c scram-common.c string.c stringinfo.c unicode_norm.c -- 2.34.1