Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pJ6U3-0002bf-DS for pgsql-hackers@arkaria.postgresql.org; Sat, 21 Jan 2023 05:32:07 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1pJ6U2-0000n4-8Z for pgsql-hackers@arkaria.postgresql.org; Sat, 21 Jan 2023 05:32:06 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pJ6U1-0000mu-SK for pgsql-hackers@lists.postgresql.org; Sat, 21 Jan 2023 05:32:05 +0000 Received: from wout1-smtp.messagingengine.com ([64.147.123.24]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1pJ6Ty-00052p-KA for pgsql-hackers@postgresql.org; Sat, 21 Jan 2023 05:32:05 +0000 Received: from compute2.internal (compute2.nyi.internal [10.202.2.46]) by mailout.west.internal (Postfix) with ESMTP id B77C232005BC; Sat, 21 Jan 2023 00:31:59 -0500 (EST) Received: from mailfrontend1 ([10.202.2.162]) by compute2.internal (MEProxy); Sat, 21 Jan 2023 00:32:00 -0500 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=anarazel.de; h= cc:cc:content-type:date:date:from:from:in-reply-to:in-reply-to :message-id:mime-version:references:reply-to:sender:subject :subject:to:to; s=fm3; t=1674279119; x=1674365519; bh=nkTjB8fO4K D36rwZyPJaRa8pIDigzmJUPzSfGcZ7nw4=; b=eyLDGsHMOrn3rKdt1p9THwHm6V C4HGr09dzwNaH0/uKV+6prpSnw4jTjHn85Spm1KkZpwo2lToLE0eMFdpp3UxjiAU jx+Jxk371EUeF9daoCQhL+3+a8Gzabhv+z3QxGfDPQESb7b787qgmOiWB+YJ5q8U 1gEq0AAimn/8gaMoZ8JeYOLS10gY9i3HTDQJqLefS1DVzHWx/KBOKsHXViUtbHJ5 3HTEllZOIr1+zSuWPLBTuIs6Vu2UIfAVpD+Hnbwk+XWIC57uEzGAArArGQFL4KYX eC5x9ke/b/cw2FdKx2hypCZf1Jla0uxD1/UGotWUK7ERyWA1gU8r2xNpP1hg== DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d= messagingengine.com; h=cc:cc:content-type:date:date:feedback-id :feedback-id:from:from:in-reply-to:in-reply-to:message-id :mime-version:references:reply-to:sender:subject:subject:to:to :x-me-proxy:x-me-proxy:x-me-sender:x-me-sender:x-sasl-enc; s= fm3; t=1674279119; x=1674365519; bh=nkTjB8fO4KD36rwZyPJaRa8pIDig zmJUPzSfGcZ7nw4=; b=nQ+ZVZK995wHnNmp8fYrWivC0xAH/2IycVI1kznY1rda rgXTF479e5jLPqpTrv4I6liM53x+tRGRAZx3LxIN3AlMYe3sGErrW4plTWbFOVHO swwqw7Zz+D7CSKPihMCOg32NOcvUdYI8jO8HnF+x4Jhy3QeHrtHkE/4b82WmMK+2 q3irGM31Z4f8hbw7XkJjaZ517tbCopSZmkLQ7xGICwXm7j9FimSlSTMV+SF1Wb9I B6n4i9S0IX1/p3RdH/P4UDWLmpj71wCTPxa9lEsyllvlEOWo8FcM0jQXFfdsf7+m lAsU0lnrW71tHOEKJHQf/LDQX7zxhJxPrk2U8gKLKA== X-ME-Sender: X-ME-Received: X-ME-Proxy-Cause: gggruggvucftvghtrhhoucdtuddrgedvhedruddufedgkeehucetufdoteggodetrfdotf fvucfrrhhofhhilhgvmecuhfgrshhtofgrihhlpdfqfgfvpdfurfetoffkrfgpnffqhgen uceurghilhhouhhtmecufedttdenucesvcftvggtihhpihgvnhhtshculddquddttddmne cujfgurhepfffhvfevuffkfhggtggujgesmhdtreertddtvdenucfhrhhomheptehnughr vghsucfhrhgvuhhnugcuoegrnhgurhgvshesrghnrghrrgiivghlrdguvgeqnecuggftrf grthhtvghrnhepkeeiueegvedugeeutdeifeffiedvgfeugeekhfeftdevfeekffelgfeg vefhudejnecuvehluhhsthgvrhfuihiivgeptdenucfrrghrrghmpehmrghilhhfrhhomh eprghnughrvghssegrnhgrrhgriigvlhdruggv X-ME-Proxy: Feedback-ID: id4a34324:Fastmail Received: by mail.messagingengine.com (Postfix) with ESMTPA; Sat, 21 Jan 2023 00:31:58 -0500 (EST) Date: Fri, 20 Jan 2023 21:31:57 -0800 From: Andres Freund To: David Geier Cc: Tom Lane , Robert Haas , David Geier , vignesh C , Lukas Fittl , Michael Paquier , Ibrar Ahmed , Maciek Sakrejda , pgsql-hackers@postgresql.org Subject: Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc? Message-ID: <20230121053157.hsdemsvq7oqydfl6@awork3.anarazel.de> References: <20230113195547.k4nlrmawpijqwlsa@awork3.anarazel.de> <20230117164758.gx4uuzhk5grw7zea@awork3.anarazel.de> <3044621.1673976417@sss.pgh.pa.us> <20230117185053.owqxw4ebp5ny6zhd@awork3.anarazel.de> <51876d9a-6812-24b6-57ab-a555e85afb6b@gmail.com> <20230121041613.xhjfzk7iobhpqm3u@awork3.anarazel.de> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="2e47imhqa2hvpvyc" Content-Disposition: inline In-Reply-To: <20230121041613.xhjfzk7iobhpqm3u@awork3.anarazel.de> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --2e47imhqa2hvpvyc Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Hi, On 2023-01-20 20:16:13 -0800, Andres Freund wrote: > On 2023-01-18 14:05:35 +0100, David Geier wrote: > > @Andres: will you take care of these changes and provide me with an updated > > patch set so I can rebase the RDTSC changes? > > Otherwise, I can also apply Tom suggestions to your patch set and send out > > the complete patch set. > > I'm planning to push most of my changes soon, had hoped to get to it a bit > sooner, but ... I pushed the int64-ification commits. > If you have time to look at the pg_test_timing part, it'd be > appreciated. That's a it larger, and nobody looked at it yet. So I'm a bit > hesitant to push it. I haven't yet pushed the pg_test_timing (nor it's small prerequisite) patch. Thanks to Justin I've polished the pg_test_timing docs some. I've attached those two patches. Feel free to include them in your series if you want, then the CF entry (and thus cfbot) makes sense again... Greetings, Andres Freund --2e47imhqa2hvpvyc Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v9-0001-instr_time-Add-INSTR_TIME_SET_SECONDS-INSTR_TIME_.patch" From 2546f3000455a7086ea930986b294fd79024ea59 Mon Sep 17 00:00:00 2001 From: Andres Freund Date: Fri, 20 Jan 2023 15:31:54 -0800 Subject: [PATCH v9 1/2] instr_time: Add INSTR_TIME_SET_SECONDS(), INSTR_TIME_IS_LT() INSTR_TIME_SET_SECONDS() is useful to calculate the end of a time-bound loop without having to convert into time units (which is costly). INSTR_TIME_IS_LT() can be used to check the loop condition. Author: Reviewed-by: Discussion: https://postgr.es/m/ Backpatch: --- src/include/portability/instr_time.h | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h index cc85138e21f..aab80effb00 100644 --- a/src/include/portability/instr_time.h +++ b/src/include/portability/instr_time.h @@ -15,6 +15,8 @@ * * INSTR_TIME_IS_ZERO(t) is t equal to zero? * + * INSTR_TIME_IS_LT(x, y) x < y + * * INSTR_TIME_SET_ZERO(t) set t to zero (memset is acceptable too) * * INSTR_TIME_SET_CURRENT(t) set t to current time @@ -22,6 +24,8 @@ * INSTR_TIME_SET_CURRENT_LAZY(t) set t to current time if t is zero, * evaluates to whether t changed * + * INSTR_TIME_SET_SECONDS(t, s) set t to s seconds + * * INSTR_TIME_ADD(x, y) x += y * * INSTR_TIME_SUBTRACT(x, y) x -= y @@ -122,6 +126,9 @@ pg_clock_gettime_ns(void) #define INSTR_TIME_SET_CURRENT(t) \ ((t) = pg_clock_gettime_ns()) +#define INSTR_TIME_SET_SECONDS(t, s) \ + ((t).ticks = NS_PER_S * (s)) + #define INSTR_TIME_GET_NANOSEC(t) \ ((int64) (t).ticks) @@ -156,6 +163,9 @@ GetTimerFrequency(void) #define INSTR_TIME_SET_CURRENT(t) \ ((t) = pg_query_performance_counter()) +#define INSTR_TIME_SET_SECONDS(t, s) \ + ((t).ticks = s * GetTimerFrequency()) + #define INSTR_TIME_GET_NANOSEC(t) \ ((int64) ((t).ticks * ((double) NS_PER_S / GetTimerFrequency()))) @@ -168,6 +178,8 @@ GetTimerFrequency(void) #define INSTR_TIME_IS_ZERO(t) ((t).ticks == 0) +#define INSTR_TIME_IS_LT(x, y) ((x).ticks < (y).ticks) + #define INSTR_TIME_SET_ZERO(t) ((t).ticks = 0) -- 2.38.0 --2e47imhqa2hvpvyc Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="v9-0002-wip-report-nanoseconds-in-pg_test_timing.patch" From a3149e3430c9594ca2ceb3039c954e729bd7c46e Mon Sep 17 00:00:00 2001 From: Andres Freund Date: Mon, 16 Jan 2023 11:19:11 -0800 Subject: [PATCH v9 2/2] wip: report nanoseconds in pg_test_timing This commit also updates pg_test_timing's documentation: - compare EXPLAIN (ANALYZE, TIMING ON/OFF) instead of comparing performance of of statement with/without EXPLAIN ANALYZE - explain the 2x overhead (due to two timestamp acquisitions per row) - remove old section about old versions of linux - I couldn't update the numbers, and it's old enough nobody would care --- src/bin/pg_test_timing/pg_test_timing.c | 74 +++++++++------ doc/src/sgml/ref/pgtesttiming.sgml | 117 ++++++++++-------------- 2 files changed, 95 insertions(+), 96 deletions(-) diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c index c29d6f87629..e20718669a5 100644 --- a/src/bin/pg_test_timing/pg_test_timing.c +++ b/src/bin/pg_test_timing/pg_test_timing.c @@ -19,8 +19,8 @@ static void handle_args(int argc, char *argv[]); static uint64 test_timing(unsigned int duration); static void output(uint64 loop_count); -/* record duration in powers of 2 microseconds */ -long long int histogram[32]; +/* record duration in powers of 2 nanoseconds */ +uint64 histogram[64]; int main(int argc, char *argv[]) @@ -121,35 +121,48 @@ handle_args(int argc, char *argv[]) static uint64 test_timing(unsigned int duration) { - uint64 total_time; - int64 time_elapsed = 0; uint64 loop_count = 0; - uint64 prev, - cur; + instr_time until_time, + total_time; instr_time start_time, - end_time, - temp; - - total_time = duration > 0 ? duration * INT64CONST(1000000) : 0; + end_time; + instr_time cur; INSTR_TIME_SET_CURRENT(start_time); - cur = INSTR_TIME_GET_MICROSEC(start_time); - while (time_elapsed < total_time) + /* + * To reduce loop overhead, check loop condition in instr_time domain. + */ + INSTR_TIME_SET_SECONDS(total_time, duration); + until_time = start_time; + INSTR_TIME_ADD(until_time, total_time); + + cur = start_time; + + while (INSTR_TIME_IS_LT(cur, until_time)) { - int32 diff, - bits = 0; + instr_time temp; + instr_time prev; + int64 diff; + int32 bits = 0; prev = cur; - INSTR_TIME_SET_CURRENT(temp); - cur = INSTR_TIME_GET_MICROSEC(temp); - diff = cur - prev; + INSTR_TIME_SET_CURRENT(cur); + temp = cur; + INSTR_TIME_SUBTRACT(temp, prev); + diff = INSTR_TIME_GET_NANOSEC(temp); /* Did time go backwards? */ - if (diff < 0) + if (unlikely(diff <= 0)) { + /* can't do anything with that measurement */ + if (diff == 0) + { + loop_count++; + continue; + } fprintf(stderr, _("Detected clock going backwards in time.\n")); - fprintf(stderr, _("Time warp: %d ms\n"), diff); + fprintf(stderr, _("Time warp: %lld ns\n"), (long long) diff); exit(1); } @@ -164,8 +177,6 @@ test_timing(unsigned int duration) histogram[bits]++; loop_count++; - INSTR_TIME_SUBTRACT(temp, start_time); - time_elapsed = INSTR_TIME_GET_MICROSEC(temp); } INSTR_TIME_SET_CURRENT(end_time); @@ -173,7 +184,7 @@ test_timing(unsigned int duration) INSTR_TIME_SUBTRACT(end_time, start_time); printf(_("Per loop time including overhead: %0.2f ns\n"), - INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count); + (INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S) / loop_count); return loop_count; } @@ -181,9 +192,10 @@ test_timing(unsigned int duration) static void output(uint64 loop_count) { - int64 max_bit = 31, + int64 low_bit = 0, + max_bit = 63, i; - char *header1 = _("< us"); + char *header1 = _("< ns"); char *header2 = /* xgettext:no-c-format */ _("% of total"); char *header3 = _("count"); int len1 = strlen(header1); @@ -194,15 +206,19 @@ output(uint64 loop_count) while (max_bit > 0 && histogram[max_bit] == 0) max_bit--; + /* find lowest bit value */ + while (low_bit < max_bit && histogram[low_bit] == 0) + low_bit++; + printf(_("Histogram of timing durations:\n")); printf("%*s %*s %*s\n", - Max(6, len1), header1, + Max(9, len1), header1, Max(10, len2), header2, Max(10, len3), header3); - for (i = 0; i <= max_bit; i++) - printf("%*ld %*.5f %*lld\n", - Max(6, len1), 1l << i, + for (i = low_bit; i <= max_bit; i++) + printf("%*ld %*.5f %*llu\n", + Max(9, len1), 1l << i, Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count, - Max(10, len3), histogram[i]); + Max(10, len3), (long long unsigned) histogram[i]); } diff --git a/doc/src/sgml/ref/pgtesttiming.sgml b/doc/src/sgml/ref/pgtesttiming.sgml index a5eb3aa25e0..7e0266cf58b 100644 --- a/doc/src/sgml/ref/pgtesttiming.sgml +++ b/doc/src/sgml/ref/pgtesttiming.sgml @@ -93,28 +93,34 @@ PostgreSQL documentation Good results will show most (>90%) individual timing calls take less than - one microsecond. Average per loop overhead will be even lower, below 100 - nanoseconds. This example from an Intel i7-860 system using a TSC clock - source shows excellent performance: + one microsecond (1000 nanoseconds). Average per loop overhead will be even + lower, below 100 nanoseconds. This example from an Intel i9-9880H system + using a TSC clock source shows excellent performance: - Note that different units are used for the per loop time than the - histogram. The loop can have resolution within a few nanoseconds (ns), - while the individual timing calls can only resolve down to one microsecond - (us). + Note that the accuracy of the histogram entries may be lower than the + per loop time. @@ -125,24 +131,25 @@ Histogram of timing durations: When the query executor is running a statement using EXPLAIN ANALYZE, individual operations are timed as well as showing a summary. The overhead of your system can be checked by - counting rows with the psql program: + disabling the per-row timing, using the TIMING OFF + option: -CREATE TABLE t AS SELECT * FROM generate_series(1,100000); -\timing -SELECT COUNT(*) FROM t; -EXPLAIN ANALYZE SELECT COUNT(*) FROM t; +CREATE TABLE t AS SELECT * FROM generate_series(1, 100000); +EXPLAIN (ANALYZE, TIMING OFF) SELECT COUNT(*) FROM t; +EXPLAIN (ANALYZE, TIMING ON) SELECT COUNT(*) FROM t; - The i7-860 system measured runs the count query in 9.8 ms while - the EXPLAIN ANALYZE version takes 16.6 ms, each - processing just over 100,000 rows. That 6.8 ms difference means the timing - overhead per row is 68 ns, about twice what pg_test_timing estimated it - would be. Even that relatively small amount of overhead is making the fully - timed count statement take almost 70% longer. On more substantial queries, - the timing overhead would be less problematic. + The i9-9880H system measured shows an execution time of 4.116 ms for the + TIMING OFF query, and 6.965 ms for the + TIMING ON, each processing 100,000 rows. + + That 2.849 ms difference means the timing overhead per row is 28 ns. As + TIMING ON measures timestamps twice per row returned by + an executor node, the overhead is very close to what pg_test_timing + estimated it would be. @@ -157,28 +164,31 @@ EXPLAIN ANALYZE SELECT COUNT(*) FROM t; /sys/devices/system/clocksource/clocksource0/current_clocksource # pg_test_timing -Per loop time including overhead: 722.92 ns +Testing timing overhead for 3 seconds. +Per loop time including overhead: 708.58 ns Histogram of timing durations: - < us % of total count - 1 27.84870 1155682 - 2 72.05956 2990371 - 4 0.07810 3241 - 8 0.01357 563 - 16 0.00007 3 + < ns % of total count + 1024 99.79796 4225270 + 2048 0.15560 6588 + 4096 0.00035 15 + 8192 0.01738 736 + 16384 0.01679 711 + 32768 0.01190 504 ]]> In this configuration, the sample EXPLAIN ANALYZE above - takes 115.9 ms. That's 1061 ns of timing overhead, again a small multiple - of what's measured directly by this utility. That much timing overhead - means the actual query itself is only taking a tiny fraction of the - accounted for time, most of it is being consumed in overhead instead. In - this configuration, any EXPLAIN ANALYZE totals involving - many timed operations would be inflated significantly by timing overhead. + shows an execution time of 148.7 ms. That's 1392 ns of per-row timing + overhead. Taking the two timestamps per row into account, that's again + close to what pg_test_timing estimated. That much timing overhead means + the actual query itself is only taking a tiny fraction of the accounted for + time, most of it is being consumed in overhead instead. In this + configuration, any EXPLAIN ANALYZE totals involving many + timed operations would be inflated significantly by timing overhead. @@ -196,33 +206,6 @@ kern.timecounter.hardware: ACPI-fast -> TSC - - Other systems may only allow setting the time source on boot. On older - Linux systems the "clock" kernel setting is the only way to make this sort - of change. And even on some more recent ones, the only option you'll see - for a clock source is "jiffies". Jiffies are the older Linux software clock - implementation, which can have good resolution when it's backed by fast - enough timing hardware, as in this example: - - - -- 2.38.0 --2e47imhqa2hvpvyc--