Postgres Pro
Downloads
Home   >   mailing lists

Thread: EXPLAIN ANALYZE does not return accurate execution times

EXPLAIN ANALYZE does not return accurate execution times

From
Mark Mizzi
Date:
As an example, let's take the following simple table:

CREATE TABLE unary(a VARCHAR);
-- simple way to make table large
ALTER TABLE unary
    ALTER COLUMN a SET STORAGE EXTERNAL;

-- insert one million large rows
INSERT INTO unary
SELECT repeat('a', 8000)
FROM generate_series(0, 100000);

-- update planner statistics on the unary table.
ANALYZE unary;

When I run

EXPLAIN ANALYZE SELECT * FROM unary;

I get the following result:

 Seq Scan on unary  (cost=0.00..1637.01 rows=100001 width=18) (actual
time=0.009..6.667 rows=100001 loops=1)
 Planning Time: 0.105 ms
 Execution Time: 8.565 ms

On the other hand, the following command

time sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null

returns after 17s with:

sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null  0.01s user
0.01s system 0% cpu 16.912 total

I am running Postgres 14 (installed via apt) on Ubuntu 22.04. All settings
are default.
The machine is a Dell Vostro 7500.

All commands are being run locally, so I don't think this is a network
bandwidth issue. What's going on?

Re: EXPLAIN ANALYZE does not return accurate execution times

From
Julien Rouhaud
Date:
Hi,

On Thu, Oct 27, 2022 at 03:28:14PM +0200, Mark Mizzi wrote:
>
> EXPLAIN ANALYZE SELECT * FROM unary;
>
> I get the following result:
>
>  Seq Scan on unary  (cost=0.00..1637.01 rows=100001 width=18) (actual
> time=0.009..6.667 rows=100001 loops=1)
>  Planning Time: 0.105 ms
>  Execution Time: 8.565 ms
>
> [...]
>
> sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null  0.01s user
> 0.01s system 0% cpu 16.912 total
>
> I am running Postgres 14 (installed via apt) on Ubuntu 22.04. All settings
> are default.
> The machine is a Dell Vostro 7500.
>
> All commands are being run locally, so I don't think this is a network
> bandwidth issue. What's going on?

EXPLAIN ANALYZE doesn't output the tuples, so it hides that part of the query
processing.  It's usually not a problem, at least if you want to identify non
optimal queries, but here you probably have the perfect scenario to notice the
difference.

You could try to use something like "SELECT COUNT(*) FROM unary", the timings
should be closer and the query would still scan all the lines.

Re: EXPLAIN ANALYZE does not return accurate execution times

From
Tom Lane
Date:
Mark Mizzi <mizzimark2001@gmail.com> writes:
> When I run

> EXPLAIN ANALYZE SELECT * FROM unary;

> I get the following result:

>  Seq Scan on unary  (cost=0.00..1637.01 rows=100001 width=18) (actual
> time=0.009..6.667 rows=100001 loops=1)
>  Planning Time: 0.105 ms
>  Execution Time: 8.565 ms

> On the other hand, the following command

> time sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null

> returns after 17s with:
> sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null  0.01s user
> 0.01s system 0% cpu 16.912 total

The main thing actual execution does that EXPLAIN does not is
format the data and send it off to the client.  There are a
number of possible bottlenecks involved there -- TOAST fetching,
data formatting, network traffic, or client processing.  Watching
this example in "top", I see psql consuming near 100% CPU, meaning
that the problem is with psql's code to make a nicely-aligned
ASCII table out of the result.  This isn't too surprising: that
code was never meant to operate on resultsets that are too large
for human consumption.  You could use a different formatting rule,
or switch to COPY.

As an example, using

psql -c '\pset format unaligned' -c "SELECT * FROM unary" -o /dev/null

this example drops from ~16s to ~1.7s on my machine.

            regards, tom lane

Re: EXPLAIN ANALYZE does not return accurate execution times

From
Mark Mizzi
Date:
Hi, thanks for your reply.
So to confirm, EXPLAIN ANALYZE does not detoast rows? The original goal of these queries was to see the effect of fetching from toast tables on query performance.

On Thu, 27 Oct 2022 at 15:43, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Mark Mizzi <mizzimark2001@gmail.com> writes:
> When I run

> EXPLAIN ANALYZE SELECT * FROM unary;

> I get the following result:

>  Seq Scan on unary  (cost=0.00..1637.01 rows=100001 width=18) (actual
> time=0.009..6.667 rows=100001 loops=1)
>  Planning Time: 0.105 ms
>  Execution Time: 8.565 ms

> On the other hand, the following command

> time sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null

> returns after 17s with:
> sudo -u postgres psql -c "SELECT * FROM unary" -o /dev/null  0.01s user
> 0.01s system 0% cpu 16.912 total

The main thing actual execution does that EXPLAIN does not is
format the data and send it off to the client.  There are a
number of possible bottlenecks involved there -- TOAST fetching,
data formatting, network traffic, or client processing.  Watching
this example in "top", I see psql consuming near 100% CPU, meaning
that the problem is with psql's code to make a nicely-aligned
ASCII table out of the result.  This isn't too surprising: that
code was never meant to operate on resultsets that are too large
for human consumption.  You could use a different formatting rule,
or switch to COPY.

As an example, using

psql -c '\pset format unaligned' -c "SELECT * FROM unary" -o /dev/null

this example drops from ~16s to ~1.7s on my machine.

                        regards, tom lane

Re: EXPLAIN ANALYZE does not return accurate execution times

From
Tom Lane
Date:
Mark Mizzi <mizzimark2001@gmail.com> writes:
> So to confirm, EXPLAIN ANALYZE does not detoast rows?

Not values that would have been transmitted to the client, no.

            regards, tom lane