EXPLAIN ANALYZE does not return accurate execution times

[Mark Mizzi]

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, 10);

-- 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=11 width=18) (actual
time=0.009..6.667 rows=11 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

[Mark Mizzi]

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  wrote:

> Mark Mizzi  writes:
> > When I run
>
> > EXPLAIN ANALYZE SELECT * FROM unary;
>
> > I get the following result:
>
> >  Seq Scan on unary  (cost=0.00..1637.01 rows=11 width=18) (actual
> > time=0.009..6.667 rows=11 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
>