Hi,
I'm using PostgreSQL 14.3 and I'm getting strange behavior in a complex
query generated by the Entity Framework.
The inner (complex) query has a quick execution time:
# SELECT "Extent1"."id", CAST ("Extent1"."date" AS timestamp) AS "C3"
FROM "dbo"."ng_content" AS "Extent1"
INNER JOIN "dbo"."ng_path_content" AS "Extent2" ON "Extent1"."id" =
"Extent2"."id_content"
WHERE "Extent1"."date_from" <= CAST (LOCALTIMESTAMP AS timestamp)
AND "Extent1"."date_to" >= CAST (LOCALTIMESTAMP AS
timestamp)
AND 2 = "Extent1"."id_status"
AND EXISTS (
SELECT 1 AS "C1"
FROM (
SELECT "Extent3"."TagId" FROM
"dbo"."ngx_tag_content" AS "Extent3"
WHERE "Extent1"."id" = "Extent3"."ContentId"
) AS "Project1"
WHERE EXISTS (
SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS
"SingleRowTable1"
WHERE "Project1"."TagId" = 337139)
)
AND ("Extent2"."id_path" IN (27495,27554,27555) AND
NOT EXISTS (SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS "SingleRowTable2"
WHERE TRUE = FALSE)
);
id | C3
----------+---------------------
13505155 | 2021-03-27 12:01:00
13505187 | 2021-03-27 12:03:00
13505295 | 2021-03-27 12:06:00
13505348 | 2021-03-27 12:09:00
13505552 | 2021-03-27 12:11:00
(5 rows)
*Time: 481.826 ms*
If I run the same query as a nested select I get similar results (Q1):
*SELECT "Project5".idFROM (*
SELECT "Extent1"."id", CAST ("Extent1"."date" AS timestamp) AS "C3"
FROM "dbo"."ng_content" AS "Extent1"
INNER JOIN "dbo"."ng_path_content" AS "Extent2" ON "Extent1"."id" =
"Extent2"."id_content"
WHERE "Extent1"."date_from" <= CAST (LOCALTIMESTAMP AS timestamp)
AND "Extent1"."date_to" >= CAST (LOCALTIMESTAMP AS
timestamp)
AND 2 = "Extent1"."id_status"
AND EXISTS (
SELECT 1 AS "C1"
FROM (
SELECT "Extent3"."TagId" FROM
"dbo"."ngx_tag_content" AS "Extent3"
WHERE "Extent1"."id" = "Extent3"."ContentId"
) AS "Project1"
WHERE EXISTS (
SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS
"SingleRowTable1"
WHERE "Project1"."TagId" = 337139)
)
AND ("Extent2"."id_path" IN (27495,27554,27555) AND
NOT EXISTS (SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS "SingleRowTable2"
WHERE TRUE = FALSE)
)
*) AS "Project5";*
id
----------
13505155
13505187
13505295
13505348
13505552
(5 rows)
*Time: 486.174 ms*
But if I add an ORDER BY and a LIMIT something goes very wrong (Q2):
# SELECT "Project5".id
FROM (
SELECT "Extent1"."id", CAST ("Extent1"."date" AS timestamp) AS "C3"
FROM "dbo"."ng_content" AS "Extent1"
INNER JOIN "dbo"."ng_path_content" AS "Extent2" ON "Extent1"."id" =
"Extent2"."id_content"
WHERE "Extent1"."date_from" <= CAST (LOCALTIMESTAMP AS timestamp)
AND "Extent1"."date_to" >= CAST (LOCALTIMESTAMP AS
timestamp)
AND 2 = "Extent1"."id_status"
AND EXISTS (
SELECT 1 AS "C1"
FROM (
SELECT "Extent3"."TagId" FROM
"dbo"."ngx_tag_content" AS "Extent3"
WHERE "Extent1"."id" = "Extent3"."ContentId"
) AS "Project1"
WHERE EXISTS (
SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS
"SingleRowTable1"
WHERE "Project1"."TagId" = 337139)
)
AND ("Extent2"."id_path" IN (27495,27554,27555) AND
NOT EXISTS (SELECT 1 AS "C1" FROM (SELECT 1 AS "C") AS "SingleRowTable2"
WHERE TRUE = FALSE)
)
) AS "Project5" *ORDER BY "Project5"."C3" DESC LIMIT 6*;
id
----------
13505552
13505348
13505295
13505187
13505155
(5 rows)
*Time: 389375.374 ms (06:29.375)*
An EXPLAIN (ANALYZE, BUFFERS) for Q1 returns this:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Result (cost=661.07..826757.96 rows=27943 width=4) (actual
time=446.767..492.874 rows=5 loops=1)
One-Time Filter: (NOT $1)
Buffers: shared hit=344618 read=17702 written=349
InitPlan 2 (returns $1)
-> Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.003..0.003
rows=0 loops=1)
One-Time Filter: false
-> Nested Loop (cost=661.07..826757.96 rows=27943 width=4) (actual
time=267.061..313.166 rows=5 loops=1)
Buffers: shared hit=344618 read=17702 written=349
-> Bitmap Heap Scan on ng_path_content "Extent2"
(cost=660.63..30053.47 rows=58752 width=4) (actual time=2.455..28.005
rows=51330 loops=1)
Recheck Cond: (id_path = ANY
('{27495,27554,27555}'::integer[]))
Heap Blocks: exact=2914
Buffers: shared hit=5 read=2963 written=35
-> Bitmap Index Scan on ng_path_content_id_path_idx
(cost=0.00..645.94 rows=58752 width=0) (actual time=2.020..2.021
rows=51332 loops=1)
Index Cond: (id_path = ANY
('{27495,27554,27555}'::integer[]))
Buffers: shared hit=5 read=47
-> Index Scan using pk_ng_content on ng_content "Extent1"
(cost=0.43..13.55 rows=1 width=4) (actual time=0.005..0.005 rows=0
loops=51330)
Index Cond: (id = "Extent2".id_content)
Filter: ((2 = id_status) AND (date_from <= LOCALTIMESTAMP)
AND (date_to >= LOCALTIMESTAMP) AND (SubPlan 1))
Rows Removed by Filter: 1
Buffers: shared hit=344613 read=14739 written=314
SubPlan 1
-> Index Only Scan using ix_ngx_tag_content on
ngx_tag_content "Extent3" (cost=0.43..8.46 rows=1 width=0) (actual
time=0.001..0.001 rows=0 loops=51327)
Index Cond: (("TagId" = 337139) AND ("ContentId" =
"Extent1".id))
Heap Fetches: 5
Buffers: shared hit=153982 read=4
Planning:
Buffers: shared hit=464 read=87 written=51
Planning Time: 5.374 ms
JIT:
Functions: 18
Options: Inlining true, Optimization true, Expressions true, Deforming
true
Timing: Generation 1.678 ms, Inlining 81.653 ms, Optimization 63.837 ms,
Emission 33.967 ms, Total 181.135 ms
Execution Time: 534.009 ms
(33 rows)
An EXPLAIN (ANALYZE, BUFFERS) for Q2 returns this:
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.88..8979.75 rows=6 width=12) (actual
time=11037.149..183849.138 rows=5 loops=1)
Buffers: shared hit=15414548 read=564485 written=504
InitPlan 2 (returns $1)
-> Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.000..0.001
rows=0 loops=1)
One-Time Filter: false
-> Result (cost=0.86..41816103.19 rows=27943 width=12) (actual
time=11037.146..183849.127 rows=5 loops=1)
One-Time Filter: (NOT $1)
Buffers: shared hit=15414548 read=564485 written=504
-> Nested Loop (cost=0.86..41816103.19 rows=27943 width=12)
(actual time=11037.143..183849.116 rows=5 loops=1)
Buffers: shared hit=15414548 read=564485 written=504
-> Index Scan Backward using ix_ng_content_date on
ng_content "Extent1" (cost=0.43..40616715.85 rows=2231839 width=12)
(actual time=11027.808..183839.289 rows=5 loops=1)
Filter: ((2 = id_status) AND (date_from <=
LOCALTIMESTAMP) AND (date_to >= LOCALTIMESTAMP) AND (SubPlan 1))
Rows Removed by Filter: 4685618
Buffers: shared hit=15414533 read=564480 written=504
SubPlan 1
-> Index Only Scan using ix_ngx_tag_content on
ngx_tag_content "Extent3" (cost=0.43..8.46 rows=1 width=0) (actual
time=0.003..0.003 rows=0 loops=4484963)
Index Cond: (("TagId" = 337139) AND
("ContentId" = "Extent1".id))
Heap Fetches: 5
Buffers: shared hit=13454890 read=4
-> Index Scan using ng_path_content_id_content_idx on
ng_path_content "Extent2" (cost=0.43..0.53 rows=1 width=4) (actual
time=1.956..1.958 rows=1 loops=5)
Index Cond: (id_content = "Extent1".id)
Filter: (id_path = ANY
('{27495,27554,27555}'::integer[]))
Buffers: shared hit=15 read=5
Planning:
Buffers: shared hit=474 read=76
Planning Time: 113.080 ms
Execution Time: 183849.283 ms
Can someone help me understand what's going on?
--
Paulo Silva <paulo...@gmail.com>
