Hi,
I re-based again on master and applied the following changes:
I removed the fallback for obtaining the TSC frequency from /proc/cpu as
suggested by Andres. Worst-case we fall back to clock_gettime().
I added code to obtain the TSC frequency via CPUID when under a
hypervisor. I had to use __cpuid() directly instead of __get_cpuid(),
because __get_cpuid() returns an error if the leaf is > 0x80000000
(probably the implementation pre-dates the hypervisor timing leafs).
Unfortunately, while testing my implementation under VMWare, I found
that RDTSC runs awfully slow there (like 30x slower). [1] indicates that
we cannot generally rely on RDTSC being actually fast on VMs. However,
the same applies to clock_gettime(). It runs as slow as RDTSC on my
VMWare setup. Hence, using RDTSC is not at disadvantage. I'm not
entirely sure if there aren't cases where e.g. clock_gettime() is
actually faster than RDTSC and it would be advantageous to use
clock_gettime(). We could add a GUC so that the user can decide which
clock source to use. Any thoughts?
I also somewhat improved the accuracy of the cycles to milli- and
microseconds conversion functions by having two more multipliers with
higher precision. For microseconds we could also keep the computation
integer-only. I'm wondering what to best do for seconds and
milliseconds. I'm currently leaning towards just keeping it as is,
because the durations measured and converted are usually long enough
that precision shouldn't be a problem.
In vacuum_lazy.c we do if ((INSTR_TIME_GET_MICROSEC(elapsed) / 1000). I
changed that to use INSTR_TIME_GET_MILLISECS() instead. Additionally, I
initialized a few variables of type instr_time which otherwise resulted
in warnings due to use of potentially uninitialized variables.
I also couldn't reproduce the reported timing discrepancy. For me the
runtime reported by \timing is just slightly higher than the time
reported by EXPLAIN ANALYZE, which is expected.
Beyond that:
What about renaming INSTR_TIME_GET_DOUBLE() to INSTR_TIME_GET_SECS() so
that it's consistent with the _MILLISEC() and _MICROSEC() variants?
The INSTR_TIME_GET_MICROSEC() returns a uint64 while the other variants
return double. This seems error prone. What about renaming the function
or also have the function return a double and cast where necessary at
the call site?
If no one objects I would also re-register this patch in the commit fest.
[1]
https://vmware.com/content/dam/digitalmarketing/vmware/en/pdf/techpaper/Timekeeping-In-VirtualMachines.pdf
(page 11 "Virtual TSC")
--
David Geier
(ServiceNow)
From 321d00ae5dd1bcffc8fbdb39879b7f5c78e3930f Mon Sep 17 00:00:00 2001
From: David Geier <geidav...@gmail.com>
Date: Thu, 17 Nov 2022 10:22:01 +0100
Subject: [PATCH 1/3] Change instr_time to just store nanoseconds, that's
cheaper.
---
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.h
index 22bcf3d288..4bd555113b 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -80,63 +80,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 /* WIN32 */
--
2.34.1
From 28b3b35a51841642ae1d47b5740c3b1526a0c574 Mon Sep 17 00:00:00 2001
From: David Geier <geidav...@gmail.com>
Date: Thu, 17 Nov 2022 13:03:59 +0100
Subject: [PATCH 2/3] 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 | 120 ++++++++++++++++++++++++
src/include/portability/instr_time.h | 52 ++++++++--
src/tools/msvc/Mkvcbuild.pm | 2 +-
8 files changed, 175 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.c
index a990c833c5..c684725af3 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -804,6 +804,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 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.c
index 3182a73ad7..0858678534 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -7076,6 +7076,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 f5b9e268f2..14f368b658 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 898701fae1..fca4b546c8 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..5f85350d1b
--- /dev/null
+++ b/src/common/instr_time.c
@@ -0,0 +1,120 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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"
+
+/*
+ * 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 RDTSC instruction directly this is filled in during
+ * initialization based on the relevant cpuid fields.
+ */
+double cycles_to_sec = 1.0 / NS_PER_S;
+double cycles_to_ms = 1.0 / MS_PER_S;
+double cycles_to_us = 1.0 / US_PER_S;
+
+#if defined(__x86_64__) && defined(__linux__)
+/*
+ * Determines whether rdtsc is used (Linux/x86 only, when OS uses tsc clocksource)
+ */
+bool use_rdtsc = false;
+
+static bool under_hypervisor(void)
+{
+ uint32 r0, r1, r2, r3;
+ int result = __get_cpuid(0x1, &r0, &r1, &r2, &r3);
+ return result > 0 && ((r2 >> 31) & 1) == 1;
+}
+
+static bool get_hypervisor_tsc_frequency_khz(uint32 *tsc_freq)
+{
+ uint32 r0, r1, r2;
+
+ if (!under_hypervisor())
+ return false;
+
+ /*
+ * Use __cpuid() because __get_cpuid() bails out for leafs > 0x80000000.
+ * Likely, it's not accounting for recently introduced VM leafs.
+ * Unlike leaf 0x16, the hypervisor timing leafs return the frequency already in KHz.
+ */
+ __cpuid(0x40000010, *tsc_freq, r0, r1, r2);
+ return *tsc_freq > 0;
+}
+
+static bool get_host_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 get_tsc_frequency_khz(uint32 *tsc_freq)
+{
+ if (get_hypervisor_tsc_frequency_khz(tsc_freq))
+ return true;
+ if (get_host_tsc_frequency_khz(tsc_freq))
+ return true;
+
+ return false;
+}
+
+/*
+ * 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");
+
+ 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))
+ {
+ cycles_to_sec = 1.0 / (tsc_freq * 1000);
+ cycles_to_ms = 1.0 / tsc_freq;
+ cycles_to_us = 1000.0 / tsc_freq;
+ use_rdtsc = true;
+ }
+ }
+
+ fclose(fp);
+ }
+}
+#endif /* defined(__x86_64__) && defined(__linux__) */
diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h
index 4bd555113b..6442732f3e 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
@@ -56,10 +58,15 @@
#ifndef WIN32
-/* 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
@@ -80,7 +87,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)
@@ -92,17 +101,38 @@ 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;
+extern double cycles_to_ms;
+extern double cycles_to_us;
+
+#if defined(__x86_64__) && defined(__linux__)
+extern bool use_rdtsc;
+
+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 { \
@@ -120,13 +150,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_ms)
#define INSTR_TIME_GET_MICROSEC(t) \
- ((double) (t) / NS_PER_US)
+ ((uint64) (t) * cycles_to_us)
#else /* WIN32 */
@@ -138,6 +168,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.pm
index 7b855d51f0..c3b5b780f5 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
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
From 4360cbf2f9ef11b169a16180ee9aaaf03f3d59fc Mon Sep 17 00:00:00 2001
From: David Geier <geidav...@gmail.com>
Date: Mon, 2 Jan 2023 13:32:58 +0100
Subject: [PATCH 3/3] Refactor some instr_time related code
---
src/backend/access/heap/vacuumlazy.c | 3 +--
src/backend/access/transam/xlog.c | 4 ++--
src/backend/storage/buffer/bufmgr.c | 4 ++--
src/bin/psql/common.c | 8 ++++----
4 files changed, 9 insertions(+), 10 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 9923994b50..49be7c767d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -2992,8 +2992,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/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 91473b00d9..1a3ce8d239 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2177,7 +2177,7 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible)
Size nbytes;
Size nleft;
int written;
- instr_time start;
+ instr_time start = 0;
/* OK to write the page(s) */
from = XLogCtl->pages + startidx * (Size) XLOG_BLCKSZ;
@@ -8129,7 +8129,7 @@ void
issue_xlog_fsync(int fd, XLogSegNo segno, TimeLineID tli)
{
char *msg = NULL;
- instr_time start;
+ instr_time start = 0;
Assert(tli != 0);
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 73d30bf619..d3365b6a36 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -2824,8 +2824,8 @@ FlushBuffer(BufferDesc *buf, SMgrRelation reln)
{
XLogRecPtr recptr;
ErrorContextCallback errcallback;
- instr_time io_start,
- io_time;
+ instr_time io_start = 0;
+ instr_time io_time = 0;
Block bufBlock;
char *bufToWrite;
uint32 buf_state;
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index b989d792aa..901bb84916 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1269,8 +1269,8 @@ DescribeQuery(const char *query, double *elapsed_msec)
bool timing = pset.timing;
PGresult *result;
bool OK;
- instr_time before,
- after;
+ instr_time before = 0;
+ instr_time after = 0;
*elapsed_msec = 0;
@@ -1689,8 +1689,8 @@ ExecQueryUsingCursor(const char *query, double *elapsed_msec)
int ntuples;
int fetch_count;
char fetch_cmd[64];
- instr_time before,
- after;
+ instr_time before = 0;
+ instr_time after = 0;
int flush_error;
*elapsed_msec = 0;
--
2.34.1
