Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?

On 2023-01-20 22:50:37 -0600, Justin Pryzby wrote:
> 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(at)anarazel(dot)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 ?

Oops. I was intending to drop the last paragraph.

Looking at the docs again I noticed that I needed to rephrase the 'acpi_pm'
section further, as I'd left the "a small multiple of what's measured directly
by this utility" language in there.

Do the changes otherwise make sense?

The "small multiple" stuff was just due to a) comparing "raw statement" with
explain analyze b) not accounting for two timestamps being taken per row.

I think it makes sense to remove the "jiffies" section - the output shown is
way outdated. And I don't think the jiffies time counter is one something
still sees in the wild, outside of bringing up a new cpu architecture or such.

Greetings,

Andres Freund