Re: EXPLAIN ANALYZE does not return accurate execution times

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