1

My query execution time explodes when I add an ORDER BY, I can't seem to get the reasoning behind it. I feel it should be simple to order on an indexed field.

So two queries look like this:

This one takes 30-50 seconds:

EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS, FORMAT JSON)
SELECT * FROM "content_entry"
INNER JOIN "marketplace_review" ON ("content_entry"."id" = "marketplace_review"."entry_ptr_id")
INNER JOIN "marketplace_product" ON ("marketplace_review"."product_id" = "marketplace_product"."id")
WHERE ("content_entry"."type" = 3 AND "marketplace_product"."brand_id" = 750)
ORDER BY "content_entry"."timestamp" DESC
LIMIT 3

This one takes less than one second

EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS, FORMAT JSON)
SELECT * FROM "content_entry"
INNER JOIN "marketplace_review" ON ("content_entry"."id" = "marketplace_review"."entry_ptr_id")
INNER JOIN "marketplace_product" ON ("marketplace_review"."product_id" = "marketplace_product"."id")
WHERE ("content_entry"."type" = 3 AND "marketplace_product"."brand_id" = 750)
LIMIT 3

The output of the one with order by:

[
  {
    "Plan": {
      "Node Type": "Limit",
      "Parallel Aware": false,
      "Startup Cost": 1.43,
      "Total Cost": 98242.01,
      "Plan Rows": 3,
      "Plan Width": 385,
      "Actual Startup Time": 2668.251,
      "Actual Total Time": 45068.099,
      "Actual Rows": 3,
      "Actual Loops": 1,
      "Output": [""],
      "Shared Hit Blocks": 60929421,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 0,
      "Shared Written Blocks": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Temp Read Blocks": 0,
      "Temp Written Blocks": 0,
      "Plans": [
        {
          "Node Type": "Nested Loop",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "Join Type": "Inner",
          "Startup Cost": 1.43,
          "Total Cost": 29046467.49,
          "Plan Rows": 887,
          "Plan Width": 385,
          "Actual Startup Time": 2668.250,
          "Actual Total Time": 45068.095,
          "Actual Rows": 3,
          "Actual Loops": 1,
          "Output": [""],
          "Shared Hit Blocks": 60929421,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 0,
          "Shared Written Blocks": 0,
          "Local Hit Blocks": 0,
          "Local Read Blocks": 0,
          "Local Dirtied Blocks": 0,
          "Local Written Blocks": 0,
          "Temp Read Blocks": 0,
          "Temp Written Blocks": 0,
          "Plans": [
            {
              "Node Type": "Nested Loop",
              "Parent Relationship": "Outer",
              "Parallel Aware": false,
              "Join Type": "Inner",
              "Startup Cost": 1.00,
              "Total Cost": 18561128.82,
              "Plan Rows": 17657640,
              "Plan Width": 389,
              "Actual Startup Time": 0.036,
              "Actual Total Time": 23010.813,
              "Actual Rows": 5636983,
              "Actual Loops": 1,
              "Output": [""],
              "Shared Hit Blocks": 29168382,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 0,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0,
              "Plans": [
                {
                  "Node Type": "Index Scan",
                  "Parent Relationship": "Outer",
                  "Parallel Aware": false,
                  "Scan Direction": "Backward",
                  "Index Name": "content_entry_d7e6d55b",
                  "Relation Name": "content_entry",
                  "Schema": "public",
                  "Alias": "content_entry",
                  "Startup Cost": 0.56,
                  "Total Cost": 5903549.69,
                  "Plan Rows": 24176239,
                  "Plan Width": 385,
                  "Actual Startup Time": 0.031,
                  "Actual Total Time": 5038.896,
                  "Actual Rows": 5636983,
                  "Actual Loops": 1,
                  "Output": [""],
                  "Filter": "(content_entry.type = 3)",
                  "Rows Removed by Filter": 1872638,
                  "Shared Hit Blocks": 6559529,
                  "Shared Read Blocks": 0,
                  "Shared Dirtied Blocks": 0,
                  "Shared Written Blocks": 0,
                  "Local Hit Blocks": 0,
                  "Local Read Blocks": 0,
                  "Local Dirtied Blocks": 0,
                  "Local Written Blocks": 0,
                  "Temp Read Blocks": 0,
                  "Temp Written Blocks": 0
                },
                {
                  "Node Type": "Index Scan",
                  "Parent Relationship": "Inner",
                  "Parallel Aware": false,
                  "Scan Direction": "Forward",
                  "Index Name": "marketplace_review_pkey",
                  "Relation Name": "marketplace_review",
                  "Schema": "public",
                  "Alias": "marketplace_review",
                  "Startup Cost": 0.44,
                  "Total Cost": 0.51,
                  "Plan Rows": 1,
                  "Plan Width": 8,
                  "Actual Startup Time": 0.002,
                  "Actual Total Time": 0.002,
                  "Actual Rows": 1,
                  "Actual Loops": 5636983,
                  "Output": [""],
                  "Index Cond": "(marketplace_review.entry_ptr_id = content_entry.id)",
                  "Rows Removed by Index Recheck": 0,
                  "Shared Hit Blocks": 22608853,
                  "Shared Read Blocks": 0,
                  "Shared Dirtied Blocks": 0,
                  "Shared Written Blocks": 0,
                  "Local Hit Blocks": 0,
                  "Local Read Blocks": 0,
                  "Local Dirtied Blocks": 0,
                  "Local Written Blocks": 0,
                  "Temp Read Blocks": 0,
                  "Temp Written Blocks": 0
                }
              ]
            },
            {
              "Node Type": "Index Scan",
              "Parent Relationship": "Inner",
              "Parallel Aware": false,
              "Scan Direction": "Forward",
              "Index Name": "marketplace_product_pkey",
              "Relation Name": "marketplace_product",
              "Schema": "public",
              "Alias": "marketplace_product",
              "Startup Cost": 0.43,
              "Total Cost": 0.58,
              "Plan Rows": 1,
              "Plan Width": 4,
              "Actual Startup Time": 0.003,
              "Actual Total Time": 0.003,
              "Actual Rows": 0,
              "Actual Loops": 5636983,
              "Output": ["marketplace_product.id"],
              "Index Cond": "(marketplace_product.id = marketplace_review.product_id)",
              "Rows Removed by Index Recheck": 0,
              "Filter": "(marketplace_product.brand_id = 750)",
              "Rows Removed by Filter": 1,
              "Shared Hit Blocks": 31761039,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 0,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0
            }
          ]
        }
      ]
    },
    "Planning Time": 1.493,
    "Triggers": [
    ],
    "Execution Time": 45068.146
  }
]

And output of the one without order by:

[
  {
    "Plan": {
      "Node Type": "Limit",
      "Parallel Aware": false,
      "Startup Cost": 24.64,
      "Total Cost": 1780.29,
      "Plan Rows": 3,
      "Plan Width": 1412,
      "Actual Startup Time": 0.039,
      "Actual Total Time": 0.060,
      "Actual Rows": 3,
      "Actual Loops": 1,
      "Output": [""],
      "Shared Hit Blocks": 25,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 0,
      "Shared Written Blocks": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Temp Read Blocks": 0,
      "Temp Written Blocks": 0,
      "Plans": [
        {
          "Node Type": "Nested Loop",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "Join Type": "Inner",
          "Startup Cost": 24.64,
          "Total Cost": 527304.93,
          "Plan Rows": 901,
          "Plan Width": 1412,
          "Actual Startup Time": 0.038,
          "Actual Total Time": 0.059,
          "Actual Rows": 3,
          "Actual Loops": 1,
          "Output": [""],
          "Shared Hit Blocks": 25,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 0,
          "Shared Written Blocks": 0,
          "Local Hit Blocks": 0,
          "Local Read Blocks": 0,
          "Local Dirtied Blocks": 0,
          "Local Written Blocks": 0,
          "Temp Read Blocks": 0,
          "Temp Written Blocks": 0,
          "Plans": [
            {
              "Node Type": "Nested Loop",
              "Parent Relationship": "Outer",
              "Parallel Aware": false,
              "Join Type": "Inner",
              "Startup Cost": 24.08,
              "Total Cost": 526285.64,
              "Plan Rows": 1249,
              "Plan Width": 1027,
              "Actual Startup Time": 0.028,
              "Actual Total Time": 0.033,
              "Actual Rows": 3,
              "Actual Loops": 1,
              "Output": [""],
              "Shared Hit Blocks": 10,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 0,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0,
              "Plans": [
                {
                  "Node Type": "Index Scan",
                  "Parent Relationship": "Outer",
                  "Parallel Aware": false,
                  "Scan Direction": "Forward",
                  "Index Name": "marketplace_product_521b20f5",
                  "Relation Name": "marketplace_product",
                  "Schema": "public",
                  "Alias": "marketplace_product",
                  "Startup Cost": 0.43,
                  "Total Cost": 761.18,
                  "Plan Rows": 189,
                  "Plan Width": 986,
                  "Actual Startup Time": 0.010,
                  "Actual Total Time": 0.010,
                  "Actual Rows": 1,
                  "Actual Loops": 1,
                  "Output": [""],
                  "Index Cond": "(marketplace_product.brand_id = 750)",
                  "Rows Removed by Index Recheck": 0,
                  "Shared Hit Blocks": 4,
                  "Shared Read Blocks": 0,
                  "Shared Dirtied Blocks": 0,
                  "Shared Written Blocks": 0,
                  "Local Hit Blocks": 0,
                  "Local Read Blocks": 0,
                  "Local Dirtied Blocks": 0,
                  "Local Written Blocks": 0,
                  "Temp Read Blocks": 0,
                  "Temp Written Blocks": 0
                },
                {
                  "Node Type": "Bitmap Heap Scan",
                  "Parent Relationship": "Inner",
                  "Parallel Aware": false,
                  "Relation Name": "marketplace_review",
                  "Schema": "public",
                  "Alias": "marketplace_review",
                  "Startup Cost": 23.65,
                  "Total Cost": 2771.16,
                  "Plan Rows": 939,
                  "Plan Width": 41,
                  "Actual Startup Time": 0.013,
                  "Actual Total Time": 0.017,
                  "Actual Rows": 3,
                  "Actual Loops": 1,
                  "Output": [""],
                  "Recheck Cond": "(marketplace_review.product_id = marketplace_product.id)",
                  "Rows Removed by Index Recheck": 0,
                  "Exact Heap Blocks": 3,
                  "Lossy Heap Blocks": 0,
                  "Shared Hit Blocks": 6,
                  "Shared Read Blocks": 0,
                  "Shared Dirtied Blocks": 0,
                  "Shared Written Blocks": 0,
                  "Local Hit Blocks": 0,
                  "Local Read Blocks": 0,
                  "Local Dirtied Blocks": 0,
                  "Local Written Blocks": 0,
                  "Temp Read Blocks": 0,
                  "Temp Written Blocks": 0,
                  "Plans": [
                    {
                      "Node Type": "Bitmap Index Scan",
                      "Parent Relationship": "Outer",
                      "Parallel Aware": false,
                      "Index Name": "marketplace_review_product_id_4e8c6bab491b1730_idx",
                      "Startup Cost": 0.00,
                      "Total Cost": 23.42,
                      "Plan Rows": 939,
                      "Plan Width": 0,
                      "Actual Startup Time": 0.009,
                      "Actual Total Time": 0.009,
                      "Actual Rows": 13,
                      "Actual Loops": 1,
                      "Index Cond": "(marketplace_review.product_id = marketplace_product.id)",
                      "Shared Hit Blocks": 3,
                      "Shared Read Blocks": 0,
                      "Shared Dirtied Blocks": 0,
                      "Shared Written Blocks": 0,
                      "Local Hit Blocks": 0,
                      "Local Read Blocks": 0,
                      "Local Dirtied Blocks": 0,
                      "Local Written Blocks": 0,
                      "Temp Read Blocks": 0,
                      "Temp Written Blocks": 0
                    }
                  ]
                }
              ]
            },
            {
              "Node Type": "Index Scan",
              "Parent Relationship": "Inner",
              "Parallel Aware": false,
              "Scan Direction": "Forward",
              "Index Name": "content_entry_pkey",
              "Relation Name": "content_entry",
              "Schema": "public",
              "Alias": "content_entry",
              "Startup Cost": 0.56,
              "Total Cost": 0.81,
              "Plan Rows": 1,
              "Plan Width": 385,
              "Actual Startup Time": 0.006,
              "Actual Total Time": 0.006,
              "Actual Rows": 1,
              "Actual Loops": 3,
              "Output": [""],
              "Index Cond": "(content_entry.id = marketplace_review.entry_ptr_id)",
              "Rows Removed by Index Recheck": 0,
              "Filter": "(content_entry.type = 3)",
              "Rows Removed by Filter": 0,
              "Shared Hit Blocks": 15,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 0,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0
            }
          ]
        }
      ]
    },
    "Planning Time": 0.771,
    "Triggers": [
    ],
    "Execution Time": 0.182
  }
]

Just ordering without joins is again under 1 second, which is normal because ordered field is indexed, so I don't get why joins corrupt the ordering that much.

Erwin Brandstetter
  • 605,456
  • 145
  • 1,078
  • 1,228
EralpB
  • 1,621
  • 4
  • 23
  • 36
  • What exactly is the question? Do you want to optimize the slow query ? Or do you want to understand why adding ORDER BY causes such a dramatic change? – krokodilko Apr 03 '18 at 18:53
  • How many rows are in the query result if you leave off the limit? – Joe Love Apr 03 '18 at 19:40
  • Is there an index on `content_entry.timestamp` though? Do you actually expect to get 5636983 rows on the join without any limit? From my sketchy understanding of `EXPLAIN` output, I'd say without the ORDER BY it's just calculating and returning you the first three results, whereas with the ORDER it is calculating the results of the two JOIN for the full table, then ordering, then returning 3 of those. If so, then restructure it - for example, if one or both of the other tables have little matching data, put them in a subquery and join on that rather than the table. – 404 Apr 03 '18 at 21:02
  • 1
    Most of the essential information for \[postgresql-performance\] questions is missing. Consider [instructions in the tag wiki](https://stackoverflow.com/tags/postgresql-performance/info). – Erwin Brandstetter Apr 03 '18 at 22:07
  • 2
    For humans the output of `explain (analyze, bufferst)` (**no** json) is typically easier to read –  Apr 04 '18 at 11:02

1 Answers1

3

Your query with reduced noise:

SELECT *
FROM   content_entry       ce
JOIN   marketplace_review  mr ON mr.entry_ptr_id = ce.id
JOIN   marketplace_product mp ON mp.id = mr.product_id
WHERE  ce.type = 3
AND    mp.brand_id = 750
ORDER  BY ce.timestamp DESC  -- adding this makes it slow
LIMIT  3

A query with LIMIT 3 and no ORDER BY is free to return any three rows that qualify. That's your first, fast query.

Once you add ORDER BY, Postgres has to consider all qualifying rows, sort them and identify the "first" 3 according to your ORDER BY expressions. If substantially more rows qualify that just the three in LIMIT 3 this is consequently substantially more expensive. The query might have to visit millions of rows instead of just a hand full. That's your second, slow query.

It may seem counter-intuitive that the first query gets faster the more rows qualify, while the second gets slower. Makes sense, though, if you think about it.

You can improve performance of the second query dramatically, if you have an index that fits your ORDER BY criteria exactly and does not include too many non-qualifying rows - and Postgres also does not expect too many non-qualifying rows based on current statistics and cost settings.

Estimating the combined selectivity of 4 predicates (2x WHERE, 2x JOIN) isn't easy. Increasing the statistics target for crucial columns might help.

The (missing) output of EXPLAIN (ANALYZE, BUFFERS) in combination with available resources and actual resource settings should provide clues where estimates stray from actual counts, where cost or resource settings might be inappropriate and where different indexes could help.

A shot in the dark:

If you don't have that already, a multicolumn index on content_entry(type, timestamp DESC) would be instrumental for both queries. Or if you always query for type = 3 (and that's not the type of most rows anyway), a partial index would be even more potent: 

CREATE INDEX foo ON content_entry (timestamp DESC) WHERE entry = 3;

Related:

Be sure the column content_entry.timestamp is defined NOT NULL, or consider ORDER BY ce.timestamp DESC NULL LAST. Related:

And do you really need to return all columns from 3 tables (SELECT *)?

Erwin Brandstetter
  • 605,456
  • 145
  • 1,078
  • 1,228
  • Regarding your second paragraph, can't it select the first top N rows (say 1000) from the content_entry and join them and check if it finds 3 satisfying rows. And if not failback to do more (1000-2000, maybe with quadratic fallback) or ALL. How would I instruct db to do this? By manually doing multiple queries? I mean if I have 2 HUGE tables, I wouldn't want to join that all and then check. We are sure *if* we inspect top 1000 of content_entry *AND* find 3 matches (which should happen, it's not very rare), no need to check other content_entry rows. – EralpB Apr 04 '18 at 11:30
  • content_entry is a huge table and what I'm trying to find is probably at the top of the table, so no need to join the whole table. (if that's what the database doing), I think I should research subqueries. – EralpB Apr 04 '18 at 11:36
  • @EralpB: Please improve the information in your question as requested in the comments above first. – Erwin Brandstetter Apr 05 '18 at 12:22