EXPLAIN ANALYZE does not return accurate execution times
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?
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 totalI 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.
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
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:
Show quoted text
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 msOn 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 totalThe 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