Date: Fri, 20 Jan 2023 22:50:37 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Andres Freund <andres@anarazel.de>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Robert Haas <robertmhaas@gmail.com>,
	David Geier <geidav.pg@gmail.com>, vignesh C <vignesh21@gmail.com>,
	Lukas Fittl <lukas@fittl.com>,
	Michael Paquier <michael@paquier.xyz>,
	Ibrar Ahmed <ibrar.ahmad@gmail.com>,
	Maciek Sakrejda <m.sakrejda@gmail.com>,
	pgsql-hackers@postgresql.org
Subject: Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?
Message-ID: <20230121045037.GN13860@telsasoft.com>
References: 
 <CAP53PkwtWtY-hkSwV7E6g_n657RnFcK0asSp0foSk5Qz_CCJXQ@mail.gmail.com>
 <cc72a411-aa07-834c-85c0-489a5924f8bc@gmail.com>
 <CALDaNm080KHmRHo8OPcAEj+vNzXejwHgmddji5hkAdCwNsuqKA@mail.gmail.com>
 <b201ac3c-1bff-2414-be8e-fc287f78be1a@gmail.com>
 <20230113195547.k4nlrmawpijqwlsa@awork3.anarazel.de>
 <CA+TgmoYOvh=k-H9m21Lh-SWbn7TNurm3JoOVxW+kOO=Gn1_8Xw@mail.gmail.com>
 <20230117164758.gx4uuzhk5grw7zea@awork3.anarazel.de>
 <3044621.1673976417@sss.pgh.pa.us>
 <20230117185053.owqxw4ebp5ny6zhd@awork3.anarazel.de>
 <20230121004032.rzyaxmirbvt7gkd5@awork3.anarazel.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20230121004032.rzyaxmirbvt7gkd5@awork3.anarazel.de>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20230121045037.GN13860%40telsasoft.com>
Precedence: bulk

On Fri, Jan 20, 2023 at 04:40:32PM -0800, Andres Freund wrote:
> From 5a458d4584961dedd3f80a07d8faea66e57c5d94 Mon Sep 17 00:00:00 2001
> From: Andres Freund <andres@anarazel.de>
> Date: Mon, 16 Jan 2023 11:19:11 -0800
> Subject: [PATCH v8 4/5] wip: report nanoseconds in pg_test_timing

>    <para>
> -   The i7-860 system measured runs the count query in 9.8 ms while
> -   the <command>EXPLAIN ANALYZE</command> 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
> +   <literal>TIMING OFF</literal> query, and 6.965 ms for the
> +   <literal>TIMING ON</literal>, each processing 100,000 rows.
> +
> +   That 2.849 ms difference means the timing overhead per row is 28 ns.  As
> +   <literal>TIMING ON</literal> measures timestamps twice per row returned by
> +   an executor node, the overhead is very close to what pg_test_timing
> +   estimated it would be.
> +
> +   more than what pg_test_timing estimated it would be.  Even that relatively
> +   small amount of overhead is making the fully timed count statement take
> +   about 60% longer.  On more substantial queries, the timing overhead would
> +   be less problematic.

I guess you intend to merge these two paragraphs ?