BUG #14889: explain analyze is taking much more time than actual execution

On 6 November 2017 at 19:50, <mahmoud.alorfaly@gmail.com> wrote:

Running a simple count(*) is finishing in 250ms While Explain Analyze is
reaching 4 seconds to complete !

How about with: EXPLAIN (ANALYZE, TIMING OFF) ?

--
David Rowley http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

With EXPLAIN (ANALYZE, TIMING OFF), it is back to normal execution speed.

Regards
Mahmoud

On Mon, Nov 6, 2017 at 10:59 AM, David Rowley <david.rowley@2ndquadrant.com>
wrote:

On 6 November 2017 at 21:04, mahmoud alorfaly
<mahmoud.alorfaly@gmail.com> wrote:

With EXPLAIN (ANALYZE, TIMING OFF), it is back to normal execution speed.

Then it's just the TIMING overhead that's causing the slowdown. This
will vary depending on how long gettimeofday() takes on your system.

This is known to be an overhead which is one of the reasons the TIMING
OFF option exists.

--
David Rowley http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

David Rowley <david.rowley@2ndquadrant.com> writes:

On 6 November 2017 at 21:04, mahmoud alorfaly
<mahmoud.alorfaly@gmail.com> wrote:

With EXPLAIN (ANALYZE, TIMING OFF), it is back to normal execution speed.

Then it's just the TIMING overhead that's causing the slowdown. This
will vary depending on how long gettimeofday() takes on your system.
This is known to be an overhead which is one of the reasons the TIMING
OFF option exists.

The size of the overhead in this case implies that gettimeofday() is doing
a kernel call, which I wouldn't really have expected on any modern Linux
kernel. What hardware is this on? Is there virtualization involved?

For context, on RHEL6 on run-of-the-mill server iron, I get overheads more
like this:

regression=# explain analyze select i from generate_series(1,10000000) i;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------
Function Scan on generate_series i (cost=0.00..10.00 rows=1000 width=4) (actual time=1711.319..3083.864 rows=10000000 loops=1)
Planning time: 0.078 ms
Execution time: 3636.962 ms
(3 rows)

regression=# explain (analyze, timing off) select i from generate_series(1,10000000) i;
QUERY PLAN
---------------------------------------------------------------------------------------------------------
Function Scan on generate_series i (cost=0.00..10.00 rows=1000 width=4) (actual rows=10000000 loops=1)
Planning time: 0.077 ms
Execution time: 2870.410 ms
(3 rows)

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Mon, Nov 6, 2017 at 12:04 AM, mahmoud alorfaly <
mahmoud.alorfaly@gmail.com> wrote:

With EXPLAIN (ANALYZE, TIMING OFF), it is back to normal execution speed.

What do you get out of the command line tool "pg_test_timing"?

Is the server otherwise idle while you run your query, or is it busy with
other stuff?

Cheers,

Jeff

On Tue, Nov 7, 2017 at 3:43 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

The size of the overhead in this case implies that gettimeofday() is doing
a kernel call, which I wouldn't really have expected on any modern Linux
kernel. What hardware is this on? Is there virtualization involved?

A virtual server with no vDSO, I'll bet. Like this:

https://stackoverflow.com/questions/42622427/gettimeofday-not-using-vdso

--
Thomas Munro
http://www.enterprisedb.com

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs