From: Lukas Fittl <lukas@fittl.com>
To: Andres Freund <andres@anarazel.de>
Cc: pgsql-hackers@postgresql.org
Subject: Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?
Date: Fri, 1 Jul 2022 01:23:01 -0700
Message-ID: <CAP53Pky+4MJfdC-R3HQFPRauy2N+5_7ExpEhCFUo8EU3bCPjEg@mail.gmail.com> (raw)
In-Reply-To: <20200612232810.f46nbqkdhbutzqdg@alap3.anarazel.de>
References: <20200612232810.f46nbqkdhbutzqdg@alap3.anarazel.de>
On Fri, Jun 12, 2020 at 4:28 PM Andres Freund <andres@anarazel.de> wrote:
> The attached patches are really just a prototype. I'm also not really
> planning to work on getting this into a "production ready" patchset
> anytime soon. I developed it primarily because I found it the overhead
> made it too hard to nail down in which part of a query tree performance
> changed. If somebody else wants to continue from here...
>
> I do think it's be a pretty significant improvement if we could reduce
> the timing overhead of EXPLAIN ANALYZE by this much. Even if requires a
> bunch of low-level code.
>
Based on an off-list conversation with Andres, I decided to dust off this
old
patch for using rdtsc directly. The significant EXPLAIN ANALYZE performance
improvements (especially when using rdtsc instead of rdtsc*p*) seem to
warrant
giving this a more thorough look.
See attached an updated patch (adding it to the July commitfest), with a few
changes:
- Keep using clock_gettime() as a fallback if we decide to not use rdtsc
- Fallback to /proc/cpuinfo for clock frequency, if cpuid(0x16) doesn't work
- The decision to use rdtsc (or not) is made at runtime, in the new
INSTR_TIME_INITIALIZE() -- we can't make this decision at compile time
because this is dependent on the specific CPU in use, amongst other things
- In an abundance of caution, for now I've decided to only enable this if we
are on Linux/x86, and the current kernel clocksource is TSC (the kernel
has
quite sophisticated logic around making this decision, see [1])
Note that if we implemented the decision logic ourselves (instead of relying
on the Linux kernel), I'd be most worried about older virtualization
technology. In my understanding getting this right is notably more
complicated
than just checking cpuid, see [2].
Known WIP problems with this patch version:
* There appears to be a timing discrepancy I haven't yet worked out, where
the \timing data reported by psql doesn't match what EXPLAIN ANALYZE is
reporting. With Andres' earlier test case, I'm seeing a consistent ~700ms
higher for \timing than for the EXPLAIN ANALYZE time reported on the
server
side, only when rdtsc measurement is used -- its likely there is a problem
somewhere with how we perform the cycles to time conversion
* Possibly related, the floating point handling for the cycles_to_sec
variable
is problematic in terms of precision (see FIXME, taken over from Andres'
POC)
Open questions from me:
1) Do we need to account for different TSC offsets on different CPUs in SMP
systems? (the Linux kernel certainly has logic to that extent, but [3]
suggests this is no longer a problem on Nehalem and newer chips, i.e.
those
having an invariant TSC)
2) Should we have a setting "--with-tsc" for configure? (instead of always
enabling it when on Linux/x86 with a TSC clocksource)
3) Are there cases where we actually want to use rdtsc*p*? (i.e. wait for
current instructions to finish -- the prior discussion seemed to suggest
we don't want it for node instruction measurements, but possibly we do
want
this in other cases?)
4) Should we support using the "mrs" instruction on ARM? (which is similar
to
rdtsc, see [4])
Thanks,
Lukas
[1] https://github.com/torvalds/linux/blob/master/arch/x86/kernel/tsc.c
[2] http://oliveryang.net/2015/09/pitfalls-of-TSC-usage/
[3] https://stackoverflow.com/a/11060619/1652607
[4] https://cpufun.substack.com/p/fun-with-timers-and-cpuid
--
Lukas Fittl
Attachments:
[application/octet-stream] v2-0002-WIP-Use-cpu-reference-cycles-via-rdtsc-to-measure.patch (11.1K, ../CAP53Pky+4MJfdC-R3HQFPRauy2N+5_7ExpEhCFUo8EU3bCPjEg@mail.gmail.com/3-v2-0002-WIP-Use-cpu-reference-cycles-via-rdtsc-to-measure.patch)
download | inline diff:
From 8bd31560afe60bed38c3f63305d924d3b629206b Mon Sep 17 00:00:00 2001
From: Lukas Fittl <lukas@fittl.com>
Date: Thu, 30 Jun 2022 17:57:37 -0700
Subject: [PATCH v2 2/2] WIP: Use cpu reference cycles, via rdtsc, to measure
time for instrumentation.
For now this is only enabled on Linux/x86 when the system clocksource is
marked tsc as well, as determined at runtime. This way we can rely on the
Linux kernel to make a decision whether tsc is invariant and usable on the
current CPU architecture. In all other cases we continue to use the
clock_gettime() implementation like before.
Note that this intentionally uses rdtsc, not rdtscp, as rdtscp waits for
currently running CPU instructions to have finished, and that adds up to
noticable latency for little benefit in the typical InstrStartNode() /
InstrStopNode() use case.
---
src/backend/utils/init/postinit.c | 3 +
src/bin/pg_test_timing/pg_test_timing.c | 1 +
src/bin/pgbench/pgbench.c | 3 +
src/bin/psql/startup.c | 4 +
src/common/Makefile | 1 +
src/common/instr_time.c | 107 ++++++++++++++++++++++++
src/include/portability/instr_time.h | 53 +++++++++---
src/tools/msvc/Mkvcbuild.pm | 2 +-
8 files changed, 163 insertions(+), 11 deletions(-)
create mode 100644 src/common/instr_time.c
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.cindex 6b9082604f..6ec0ad3271 100644--- a/src/backend/utils/init/postinit.c+++ b/src/backend/utils/init/postinit.c@@ -735,6 +735,9 @@ InitPostgres(const char *in_dbname, Oid dboid, const char *username,
/* 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.cindex c29d6f8762..0d667ff5a7 100644--- a/src/bin/pg_test_timing/pg_test_timing.c+++ b/src/bin/pg_test_timing/pg_test_timing.c@@ -132,6 +132,7 @@ test_timing(unsigned int duration)
total_time = duration > 0 ? duration * INT64CONST(1000000) : 0;
+ INSTR_TIME_INITIALIZE();
INSTR_TIME_SET_CURRENT(start_time);
cur = INSTR_TIME_GET_MICROSEC(start_time);
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.cindex fbb74bdc4c..043e2e433d 100644--- a/src/bin/pgbench/pgbench.c+++ b/src/bin/pgbench/pgbench.c@@ -7093,6 +7093,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.cindex 7c2f555f15..da930043c0 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/Makefileindex e9af7346c9..437a018590 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.cnew file mode 100644index 0000000000..a63ef19f08--- /dev/null+++ b/src/common/instr_time.c@@ -0,0 +1,107 @@+/*-------------------------------------------------------------------------+ *+ * 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"++#ifdef HAVE_CLOCK_GETTIME++/*+ * Stores what the number of cycles needs to be multiplied with to end up with+ * seconds. This indirection exists to support the rtdsc instruction.+ *+ * As a default, assume we are using clock_gettime() as a fallback and treat it+ * as 1 "cycle" per nanosecond (aka 1 GHz).+ *+ * When using the rtdsc instruction directly this is filled in during+ * initialization based on the relevant cpuid fields.+ */+double cycles_to_sec = 1.0 / NS_PER_S;++/*+ * Determines whether rdtsc is used (Linux/x86 only, when OS uses tsc clocksource)+ */+bool use_rdtsc = false;++#if defined(__x86_64__) && defined(__linux__)+/*+ * 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_clock_gettime_initialize_rdtsc(void)+{+ FILE *fp = fopen("/sys/devices/system/clocksource/clocksource0/current_clocksource", "r");+ char buf[128];++ if (fp)+ {+ fgets(buf, sizeof(buf), fp);+ if (strcmp(buf, "tsc\n") == 0)+ {+ use_rdtsc = true;+ }+ fclose(fp);+ }++ /*+ * Compute baseline cpu peformance, determines speed at which rdtsc advances+ */+ if (use_rdtsc)+ {+ uint32 cpuinfo[4] = {0};++ /*+ * FIXME: We should probably not unnecessarily use floating point math+ * here. And it's likely that the numbers are small enough that we are running+ * into floating point inaccuracies already. Probably worthwhile to be a good+ * bit smarter.+ */++ __get_cpuid(0x16, cpuinfo, cpuinfo + 1, cpuinfo + 2, cpuinfo + 3);++ if (cpuinfo[0] != 0) {+ cycles_to_sec = 1 / ((double) cpuinfo[0] * 1000 * 1000);+ } else {+ FILE *fp = fopen("/proc/cpuinfo", "r");+ char buf[128];+ float cpu_mhz;++ if (fp)+ {+ while (fgets(buf, sizeof(buf), fp))+ {+ if (sscanf(buf, "cpu MHz : %f", &cpu_mhz) == 1)+ {+ cycles_to_sec = 1 / ((double) cpu_mhz * 1000 * 1000);+ break;+ }+ }+ }+ fclose(fp);+ }+ }+}+#endif /* defined(__x86_64__) && defined(__linux__) */++#endif /* HAVE_CLOCK_GETTIME */diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.hindex ca260032d1..a23b88d9e6 100644--- a/src/include/portability/instr_time.h+++ b/src/include/portability/instr_time.h@@ -4,10 +4,12 @@
* portable high-precision interval timing
*
* This file provides an abstraction layer to hide portability issues in
- * interval timing. On Unix we use clock_gettime() if available, else- * gettimeofday(). On Windows, gettimeofday() gives a low-precision result- * so we must use QueryPerformanceCounter() instead. 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() if available, else gettimeofday().+ * On Windows, gettimeofday() gives a low-precision result so we must use+ * QueryPerformanceCounter() instead. 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
@@ -59,10 +61,15 @@
#ifdef HAVE_CLOCK_GETTIME
-/* Use clock_gettime() */+/* Uses rdtsc on Linux/x86 if available, otherwise clock_gettime() */
#include <time.h>
+#if defined(__x86_64__) && defined(__linux__)+#include <x86intrin.h>+#include <cpuid.h>+#endif+
/*
* The best clockid to use according to the POSIX spec is CLOCK_MONOTONIC,
* since that will give reliable interval timing even in the face of changes
@@ -83,7 +90,9 @@
#define PG_INSTR_CLOCK CLOCK_REALTIME
#endif
+/* time in cpu reference cycles (when using rdtsc), otherwise nanoseconds */
typedef int64 instr_time;
+
#define NS_PER_S INT64CONST(1000000000)
#define US_PER_S INT64CONST(1000000)
#define MS_PER_S INT64CONST(1000)
@@ -95,17 +104,37 @@ typedef int64 instr_time;
#define INSTR_TIME_SET_ZERO(t) ((t) = 0)
-static inline instr_time pg_clock_gettime_ns(void)+extern double cycles_to_sec;++bool use_rdtsc;++#if defined(__x86_64__) && defined(__linux__)+extern void pg_clock_gettime_initialize_rdtsc(void);+#endif++static inline instr_time pg_clock_gettime_ref_cycles(void)
{
struct timespec tmp;
+#if defined(__x86_64__) && defined(__linux__)+ if (use_rdtsc)+ return __rdtsc();+#endif+
clock_gettime(PG_INSTR_CLOCK, &tmp);
return tmp.tv_sec * NS_PER_S + tmp.tv_nsec;
}
+#if defined(__x86_64__) && defined(__linux__)+#define INSTR_TIME_INITIALIZE() \+ pg_clock_gettime_initialize_rdtsc()+#else+#define INSTR_TIME_INITIALIZE()+#endif+
#define INSTR_TIME_SET_CURRENT(t) \
- (t) = pg_clock_gettime_ns()+ (t) = pg_clock_gettime_ref_cycles()
#define INSTR_TIME_ADD(x,y) \
do { \
@@ -123,13 +152,13 @@ static inline instr_time pg_clock_gettime_ns(void)
} while (0)
#define INSTR_TIME_GET_DOUBLE(t) \
- ((double) (t) / NS_PER_S)+ ((double) (t) * cycles_to_sec)
#define INSTR_TIME_GET_MILLISEC(t) \
- ((double) (t) / NS_PER_MS)+ ((double) (t) * (cycles_to_sec * MS_PER_S))
#define INSTR_TIME_GET_MICROSEC(t) \
- ((double) (t) / NS_PER_US)+ ((uint64) (t) * (cycles_to_sec * US_PER_S))
#else /* !HAVE_CLOCK_GETTIME */
@@ -143,6 +172,8 @@ typedef struct timeval instr_time;
#define INSTR_TIME_SET_ZERO(t) ((t).tv_sec = 0, (t).tv_usec = 0)
+#define INSTR_TIME_INITIALIZE()+
#define INSTR_TIME_SET_CURRENT(t) gettimeofday(&(t), NULL)
#define INSTR_TIME_ADD(x,y) \
@@ -207,6 +238,8 @@ typedef LARGE_INTEGER instr_time;
#define INSTR_TIME_SET_ZERO(t) ((t).QuadPart = 0)
+#define INSTR_TIME_INITIALIZE()+
#define INSTR_TIME_SET_CURRENT(t) QueryPerformanceCounter(&(t))
#define INSTR_TIME_ADD(x,y) \
diff --git a/src/tools/msvc/Mkvcbuild.pm b/src/tools/msvc/Mkvcbuild.pmindex e4feda10fd..a881fcc64e 100644--- a/src/tools/msvc/Mkvcbuild.pm+++ b/src/tools/msvc/Mkvcbuild.pm@@ -126,7 +126,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
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.0
[application/octet-stream] v2-0001-WIP-Change-instr_time-to-just-store-nanoseconds-t.patch (2.9K, ../CAP53Pky+4MJfdC-R3HQFPRauy2N+5_7ExpEhCFUo8EU3bCPjEg@mail.gmail.com/4-v2-0001-WIP-Change-instr_time-to-just-store-nanoseconds-t.patch)
download | inline diff:
From 0c690c76cb4ccfc995eb98340628f10274d89c81 Mon Sep 17 00:00:00 2001
From: Lukas Fittl <lukas@fittl.com>
Date: Thu, 30 Jun 2022 17:55:32 -0700
Subject: [PATCH v2 1/2] WIP: Change instr_time to just store nanoseconds,
that's cheaper.
Author: Andres Freund
Reviewed-By:
Discussion: https://postgr.es/m/
Backpatch:
---
src/include/portability/instr_time.h | 62 ++++++++++++----------------
1 file changed, 26 insertions(+), 36 deletions(-)
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.hindex ca09a1608f..ca260032d1 100644--- a/src/include/portability/instr_time.h+++ b/src/include/portability/instr_time.h@@ -83,63 +83,53 @@
#define PG_INSTR_CLOCK CLOCK_REALTIME
#endif
-typedef struct timespec instr_time;+typedef int64 instr_time;+#define NS_PER_S INT64CONST(1000000000)+#define US_PER_S INT64CONST(1000000)+#define MS_PER_S INT64CONST(1000)-#define INSTR_TIME_IS_ZERO(t) ((t).tv_nsec == 0 && (t).tv_sec == 0)+#define NS_PER_MS INT64CONST(1000000)+#define NS_PER_US INT64CONST(1000)-#define INSTR_TIME_SET_ZERO(t) ((t).tv_sec = 0, (t).tv_nsec = 0)+#define INSTR_TIME_IS_ZERO(t) ((t) == 0)-#define INSTR_TIME_SET_CURRENT(t) ((void) clock_gettime(PG_INSTR_CLOCK, &(t)))+#define INSTR_TIME_SET_ZERO(t) ((t) = 0)++static inline instr_time pg_clock_gettime_ns(void)+{+ struct timespec tmp;++ clock_gettime(PG_INSTR_CLOCK, &tmp);++ return tmp.tv_sec * NS_PER_S + tmp.tv_nsec;+}++#define INSTR_TIME_SET_CURRENT(t) \+ (t) = pg_clock_gettime_ns()
#define INSTR_TIME_ADD(x,y) \
do { \
- (x).tv_sec += (y).tv_sec; \- (x).tv_nsec += (y).tv_nsec; \- /* Normalize */ \- while ((x).tv_nsec >= 1000000000) \- { \- (x).tv_nsec -= 1000000000; \- (x).tv_sec++; \- } \+ (x) += (y); \
} while (0)
#define INSTR_TIME_SUBTRACT(x,y) \
do { \
- (x).tv_sec -= (y).tv_sec; \- (x).tv_nsec -= (y).tv_nsec; \- /* Normalize */ \- while ((x).tv_nsec < 0) \- { \- (x).tv_nsec += 1000000000; \- (x).tv_sec--; \- } \+ (x) -= (y); \
} while (0)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
do { \
- (x).tv_sec += (y).tv_sec - (z).tv_sec; \- (x).tv_nsec += (y).tv_nsec - (z).tv_nsec; \- /* Normalize after each add to avoid overflow/underflow of tv_nsec */ \- while ((x).tv_nsec < 0) \- { \- (x).tv_nsec += 1000000000; \- (x).tv_sec--; \- } \- while ((x).tv_nsec >= 1000000000) \- { \- (x).tv_nsec -= 1000000000; \- (x).tv_sec++; \- } \+ (x) += (y) - (z); \
} while (0)
#define INSTR_TIME_GET_DOUBLE(t) \
- (((double) (t).tv_sec) + ((double) (t).tv_nsec) / 1000000000.0)+ ((double) (t) / NS_PER_S)
#define INSTR_TIME_GET_MILLISEC(t) \
- (((double) (t).tv_sec * 1000.0) + ((double) (t).tv_nsec) / 1000000.0)+ ((double) (t) / NS_PER_MS)
#define INSTR_TIME_GET_MICROSEC(t) \
- (((uint64) (t).tv_sec * (uint64) 1000000) + (uint64) ((t).tv_nsec / 1000))+ ((double) (t) / NS_PER_US)
#else /* !HAVE_CLOCK_GETTIME */
--
2.34.0
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: lukas@fittl.com, andres@anarazel.de
Subject: Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?
In-Reply-To: <CAP53Pky+4MJfdC-R3HQFPRauy2N+5_7ExpEhCFUo8EU3bCPjEg@mail.gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox