I have a query where the plan it comes up with creates (via nested loops) huge numbers of rows, spends hours processing them, and then promptly discards them (Rows Removed by Filter: big number). One part of the query is this (in a CTE):
EXPLAIN ANALYZE SELECT e.id FROM e.entity e JOIN e.documentmetadata dm ON (dm.document_id = e.document_id) JOIN workflow_steps wfs10 ON (wfs10.hl7_events_id = dm.source_document_id and wfs10.step=10) JOIN workflow w ON (w.id=wfs10.workflow_id) JOIN workflow_steps wfs ON (wfs.workflow_id = w.id and wfs.step=5) where wfs.step_ts between to_timestamp('20220923 00:00:00', 'YYYYMMDD HH24:MI:SS') and to_timestamp('20220930 00:00:00', 'YYYYMMDD HH24:MI:SS')
Output (link to pretty output on depesz):
Nested Loop (cost=171.95..55119.00 rows=55423 width=4) (actual time=1.875..237.227 rows=270596 loops=1) -> Nested Loop (cost=171.51..25255.15 rows=687 width=4) (actual time=1.859..79.601 rows=3195 loops=1) -> Nested Loop (cost=171.08..23989.45 rows=2505 width=8) (actual time=1.834..68.871 rows=3195 loops=1) -> Nested Loop (cost=170.66..21754.41 rows=4131 width=16) (actual time=1.614..54.872 rows=3254 loops=1) -> Bitmap Heap Scan on workflow_steps wfs (cost=170.23..9455.11 rows=4131 width=8) (actual time=1.574..15.174 rows=3254 loops=1) Recheck Cond: ((step = 5) AND (step_ts >= to_timestamp('20220923 00:00:00'::text, 'YYYYMMDD HH24:MI:SS'::text)) AND (step_ts <= to_timestamp('20220930 00:00:00'::text, 'YYYYMD) Heap Blocks: exact=535 -> Bitmap Index Scan on workflow_steps_step_step_ts_idx (cost=0.00..169.20 rows=4131 width=0) (actual time=1.499..1.500 rows=3261 loops=1) Index Cond: ((step = 5) AND (step_ts >= to_timestamp('20220923 00:00:00'::text, 'YYYYMMDD HH24:MI:SS'::text)) AND (step_ts <= to_timestamp('20220930 00:00:00'::text, 'YY) -> Index Only Scan using workflow_pkey on workflow w (cost=0.43..2.98 rows=1 width=8) (actual time=0.011..0.011 rows=1 loops=3254) Index Cond: (id = wfs.workflow_id) Heap Fetches: 3248 -> Index Scan using workflow_steps_step_10_workflow_id_idx on workflow_steps wfs10 (cost=0.42..0.53 rows=1 width=16) (actual time=0.003..0.004 rows=1 loops=3254) Index Cond: (workflow_id = w.id) -> Index Scan using e_documentmetadata_source_document_id_idx on documentmetadata dm (cost=0.43..0.50 rows=1 width=12) (actual time=0.003..0.003 rows=1 loops=3195) Index Cond: (source_document_id = wfs10.hl7_events_id) -> Index Scan using e_entity_document_id_idx on entity e (cost=0.44..28.46 rows=1501 width=8) (actual time=0.012..0.039 rows=85 loops=3195) Index Cond: (document_id = dm.document_id) Planning Time: 1.702 ms Execution Time: 250.440 ms (20 rows)
Info about these tables:
workflowhave one row each per document
e.entityhas ~1000 rows per document (100M rows total)
workflow_stepshas ~10 rows per document
The link between the two schemas is not 100% though,
workflow_steps has one step that may have an
hl7_events_id that links to
e.documentmetadata.source_document_id. I'm not sure if that's where this is breaking down. When I read the plan, it seems like it's mostly overestimating but then right at the end (2nd/3rd row down) it suddenly gets off by 6x.
As I said before, the motivation is that my real query has stuff like this in it. I'm hoping that by understanding this part, I can tackle the larger problem:
Here's a version of the full plan and query (with some obfuscation introduced by me, sorry): https://explain.depesz.com/s/PCmW
In this version, ran on production servers, some indexes are not installed (that are referenced in my simpler query), but I did analyze all the tables at full stats.