0

Postgres 13.5

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:

  • e.documentmetadata and workflow have one row each per document
  • e.entity has ~1000 rows per document (100M rows total)
  • workflow_steps has ~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:

Explain exerpt

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.

5
  • Not sure how we can help here with so little information about the actual slow query. Is the CTE not performing to your expectations? That's all we can really help with based on what you've provided. Is there no way you can extract the text explain plan from wherever that screenshot came from?
    – dwhitemv
    Nov 10 at 6:54
  • And just to be clear, are you asking about how the row estimates are derived, or are you seeking help fixing your slow query?
    – dwhitemv
    Nov 10 at 7:03
  • Your description and your execution plan don't match at all. Wen need to see the complete execution plan to know what you are talking about. Nov 10 at 7:09
  • @LaurenzAlbe - I was trying to avoid that because it seems too complicated to ask people to look at. I have edited my Q to include the full plan + query (obfuscated by me rather than depesz to try and retain some sanity for readers)
    – Ryley
    Nov 10 at 19:31
  • Thanks. I don't understand how there can be an index-only scan with a filter, but the following should improve performance: VACUUM fentityc. Nov 11 at 4:34

2 Answers 2

1

I'm adding another answer as it addresses a different aspect.

Based on your full plan, more 2/3 of the time is going to one node:

Index Only Scan using fentityc_pkey on fentityc fec 

And I expect that almost all of that time is going to the IO reflected in Heap Fetches: 1,052,233. (If you had gathered the plan using EXPLAIN (ANALYZE, BUFFERS) and with track_io_timing turned on, then we would know that for sure without needing to speculate). If you don't have any open transactions and you VACUUM the table "fentityc", it should greatly improve this. It won't fix the estimates, but it should make the current plan run much faster. If this does make things better, then you might need to ponder making the autovacuuming of this table more aggressive.

This will not fix the estimation problem of course, but is more likely to be a practical solution. Making the planning process better is good. But even if we can do it, it wouldn't see release to production for at least 10 months and getting it done even that fast is unlikely.

Also, even just the planning time here is egregiously slow. Is it that slow on re-executing the query on the same connection? It could be that now the stats target is so large that it slows down planning, and so increasing it that much was counter-productive.

1
  • Thank you - that does seem to have led me to a partial solution - vacuuming this table and then a couple more takes the query from hours to seconds. I'm still frustrated that the query builds and throws away millions of rows (and 100s of billions if I expand the date range to 1 month) but the query finishes in minutes
    – Ryley
    Nov 14 at 19:15
1

There is no such thing as a row estimate for a nested loop join. All join mechanisms which produce the same result (the same "relation") will have the same row estimate, as the row estimate is produced from the top down, before the mechanism for the join is chosen.

If you want to improve these estimates, you could try to increase the default_statistics_target and re-analyzing all the tables. I think it is the overlap of the MCV lists between the tables which principally leads to this estimate. This might work, but then again might not. It could be that the maximum setting you can pick for default_statistics_target is still not enough. What I would generally do is temporarily set default_statistics_target to the max (10,000) and analyze all the involved tables. If that works, you can then search for the best setting of default_statistics_target, or consider chaning it on a table by table basis rather than globally. But if it doesn't work, you can forget about it and quickly move on to something else.

This is probably not the best place to tackle your problem. A 6-fold misestimate might cause it to select a bad plan, but shouldn't single-handedly cause it to pick a completely horrible plan. It might "push it over the edge", but only if it were already standing on that edge due to other problems.

1
  • Thanks for trying to help... I was hoping this was the problem area of my larger query, but it seems it is not. I've edited my question to include a link to the full query (somewhat obfuscated). If you have any tips on that I would greatly appreciate it. I did max out the stats as you suggested before doing this.
    – Ryley
    Nov 10 at 20:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.