curious cost vs execution time (local test)

From: Wim Bertels <wim(dot)bertels(at)ucll(dot)be>
To: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: curious cost vs execution time (local test)
Date: 2021-03-09 09:56:26
Message-ID: eac2a140af70f0f905fa9b9f7642e445e4cd8452.camel@ucll.be
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hello,

Using the chinook database
https://github.com/lerocha/chinook-database/blob/master/ChinookDatabase/DataSources/Chinook_PostgreSql.sql
locally,
so there should be little side-effects (network, host, cache..)
for the following two equivalent queries,
the cost and execution times are curious.

(tip if you have problems on linux psql for the chinook database
#set client_encoding to 'windows-1251';
)

Can anyone confirm or correct this?

The equivalent queries are

SELECT r1."Title",hs."Name",hs."Milliseconds"
FROM "Album" r1 LEFT JOIN LATERAL
(SELECT *
FROM "Track" b2
natural inner join "Album"
WHERE r1."AlbumId" = b2."AlbumId"
ORDER BY "Milliseconds" desc
FETCH FIRST 2 ROW ONLY) hs
ON true;

vs

SELECT "Title", "Name", "Milliseconds"
FROM "Album" A NATURAL INNER JOIN "Track" T
WHERE 1 >= (SELECT COUNT(*)
FROM "Album" NATURAL INNER JOIN "Track"
WHERE "Album"."Title" = A."Title"
AND "Track"."Milliseconds" < T."Milliseconds");

Running explain (analyze) a few times gives the following curious
result:

With the Lateral join query:

QUERY
PLAN

---------------------------------------------------------------------
---------------------------------------------------------------------
------------------
Nested Loop Left Join (cost=16.37..5701.03 rows=694 width=43) (actual
time=0.043..7.347 rows=612 loops=1)
-> Seq Scan on "Album" r1 (cost=0.00..6.47 rows=347 width=27)
(actual time=0.006..0.022 rows=347 loops=1)
-> Limit (cost=16.37..16.37 rows=2 width=856) (actual
time=0.021..0.021 rows=2 loops=347)
-> Sort (cost=16.37..16.39 rows=10 width=856) (actual
time=0.021..0.021 rows=2 loops=347)
Sort Key: b2."Milliseconds" DESC
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=0.28..16.27 rows=10 width=856)
(actual time=0.009..0.019 rows=10 loops=347)
-> Seq Scan on "Album" (cost=0.00..7.34 rows=1
width=4) (actual time=0.008..0.016 rows=1 loops=347)
Filter: ("AlbumId" = r1."AlbumId")
Rows Removed by Filter: 346
-> Index Scan using "IFK_TrackAlbumId" on "Track"
b2 (cost=0.28..8.83 rows=10 width=24) (actual time=0.001..0.002
rows=10 loops=347)
Index Cond: ("AlbumId" = r1."AlbumId")
Planning Time: 0.094 ms
Execution Time: 7.388 ms

With the correlated subquery (where):
QUE
RY
PLAN

---------------------------------------------------------------------
---------------------------------------------------------------------
---------
Hash Join (cost=10.81..148.79 rows=1168 width=43) (actual
time=0.109..80.502 rows=612 loops=1)
Hash Cond: (t."AlbumId" = a."AlbumId")
Join Filter: (1 >= (SubPlan 1))
Rows Removed by Join Filter: 2891
-> Seq Scan on "Track" t (cost=0.00..80.03 rows=3503 width=24)
(actual time=0.003..0.193 rows=3503 loops=1)
-> Hash (cost=6.47..6.47 rows=347 width=27) (actual
time=0.054..0.055 rows=347 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 29kB
-> Seq Scan on "Album" a (cost=0.00..6.47 rows=347 width=27)
(actual time=0.003..0.025 rows=347 loops=1)
SubPlan 1
-> Aggregate (cost=16.23..16.24 rows=1 width=8) (actual
time=0.022..0.022 rows=1 loops=3503)
-> Nested Loop (cost=0.28..16.22 rows=3 width=0) (actual
time=0.011..0.022 rows=7 loops=3503)
-> Seq Scan on "Album" (cost=0.00..7.34 rows=1
width=4) (actual time=0.008..0.018 rows=1 loops=3503)
Filter: (("Title")::text = (a."Title")::text)
Rows Removed by Filter: 346
-> Index Scan using "IFK_TrackAlbumId" on
"Track" (cost=0.28..8.85 rows=3 width=4) (actual time=0.001..0.003
rows=7 loops=3503)
Index Cond: ("AlbumId" = "Album"."AlbumId")
Filter: ("Milliseconds" < t."Milliseconds")
Rows Removed by Filter: 8
Planning Time: 0.206 ms
Execution Time: 80.561 ms

Summarized:

Lateral: (cost=16.37..5701.03 rows=694 rows=1168) (actual
time=0.043..7.347 )
C Subq: (cost=10.81..148.79 rows=1168 width=43) (actual
time=0.109..80.502)
with the actual amount of rows for this queries being 612,
so the amount of rows for the C Subq is not well estimated.

Nonetheless in this case, the most expensive query here, is the fastest
one.

(PS: Analyze was run on the tables prior to the queries)

--
mvg,
Wim Bertels
--
https://coronalert.be

--
"Not Hercules could have knock'd out his brains, for he had none."
-- Shakespeare

Browse pgsql-general by date

  From Date Subject
Next Message Thomas Munro 2021-03-09 10:07:11 Re: SV: Log files polluted with permission denied error messages after every 10 seconds
Previous Message Wim Bertels 2021-03-09 09:20:05 Re: Import data from one instance another