Horton

Re: Reduce timing overhead of EXPLAIN ANALYZE using rdtsc?

Ibrar Ahmed <ibrar.ahmad@gmail.com>

View thread
From: Ibrar Ahmed <ibrar.ahmad@gmail.com>
To: Maciek Sakrejda <m.sakrejda@gmail.com>
Cc: Andres Freund <andres@anarazel.de>, Lukas Fittl <lukas@fittl.com>, pgsql-hackers <pgsql-hackers@postgresql.org>
Date: 2022-09-06T06:32:18Z
Lists: pgsql-hackers

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

  1. pg_test_timing: Also test RDTSC[P] timing, report time source, TSC frequency

  2. Allow retrieving x86 TSC frequency/flags from CPUID

  3. instrumentation: Standardize ticks to nanosecond conversion method

  4. instrumentation: Use Time-Stamp Counter on x86-64 to lower overhead

  5. Zero initialize uses of instr_time about to trigger compiler warnings

  6. instr_time: Represent time as an int64 on all platforms

  7. Add 250c8ee07ed to git-blame-ignore-revs

On Fri, Jul 15, 2022 at 11:22 PM Maciek Sakrejda <m.sakrejda@gmail.com>
wrote:

> I ran that original test case with and without the patch. Here are the
> numbers I'm seeing:
>
> master (best of three):
>
> postgres=# SELECT count(*) FROM lotsarows;
> Time: 582.423 ms
>
> postgres=# EXPLAIN (ANALYZE, TIMING OFF) SELECT count(*) FROM lotsarows;
> Time: 616.102 ms
>
> postgres=# EXPLAIN (ANALYZE, TIMING ON) SELECT count(*) FROM lotsarows;
> Time: 1068.700 ms (00:01.069)
>
> patched (best of three):
>
> postgres=# SELECT count(*) FROM lotsarows;
> Time: 550.822 ms
>
> postgres=# EXPLAIN (ANALYZE, TIMING OFF) SELECT count(*) FROM lotsarows;
> Time: 612.572 ms
>
> postgres=# EXPLAIN (ANALYZE, TIMING ON) SELECT count(*) FROM lotsarows;
> Time: 690.875 ms
>
> On Fri, Jul 1, 2022 at 10:26 AM Andres Freund <andres@anarazel.de> wrote:
> > On 2022-07-01 01:23:01 -0700, Lukas Fittl wrote:
> >...
> > > 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
> >
> > Could you explain a bit more what you're seeing? I just tested your
> patches
> > and didn't see that here.
>
> I did not see this either, but I did see that the execution time
> reported by \timing is (for this test case) consistently 0.5-1ms
> *lower* than the Execution Time reported by EXPLAIN. I did not see
> that on master. Is that expected?
>
> Thanks,
> Maciek
>
>
> The patch requires a rebase; please rebase the patch with the latest code.

Hunk #5 succeeded at 147 with fuzz 2 (offset -3 lines).
Hunk #6 FAILED at 170.
Hunk #7 succeeded at 165 (offset -69 lines).
2 out of 7 hunks FAILED -- saving rejects to file
src/include/portability/instr_time.h.rej
patching file src/tools/msvc/Mkvcbuild.pm



-- 
Ibrar Ahmed