Re: EXPLAIN ANALYZE does not return accurate execution times
Mark Mizzi writes: > So to confirm, EXPLAIN ANALYZE does not detoast rows? Not values that would have been transmitted to the client, no. regards, tom lane
Re: EXPLAIN ANALYZE does not return accurate execution times
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 >
Re: EXPLAIN ANALYZE does not return accurate execution times
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
Re: EXPLAIN ANALYZE does not return accurate execution times
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=11 width=18) (actual > time=0.009..6.667 rows=11 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.
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, 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?