4

I am trying to debug a slow query on a PostgreSQL 9.1.13 database, and I am a bit at loss. The exact query generated by the ORM framework is:

SELECT "core_product"."sales_price", "core_product"."recommended_price", "core_productgroup"."name", "core_product"."number", "core_product"."name", "core_product"."description", "core_product"."cost_price", "core_product"."bar_code", "core_product"."accessible"
FROM "core_product" INNER JOIN "core_productgroup" ON ( "core_product"."product_group_id" = "core_productgroup"."id" )
WHERE "core_productgroup"."company_id" = 1056
ORDER BY "core_product"."id" ASC
LIMIT 200;

This query takes 28 seconds to return 200 rows, which is too slow for our use case.

In a first attempt to understand where the performance bottleneck might be. I tried first removing the LIMIT 200 expecting it to be even slower. However without LIMIT 200 the query takes just 2 seconds to return approximately 293000 rows.

How can it be faster to return all 293000 matching rows rather than only the first 200?

I have tried using EXPLAIN to see how the query plans for the two queries differ. It turns out these two almost identical queries have quite different query plans. With LIMIT:

                                                   QUERY PLAN                                                   
----------------------------------------------------------------------------------------------------------------
 Limit  (cost=10.69..52229.70 rows=200 width=76)
   ->  Nested Loop  (cost=10.69..17054740.55 rows=65320 width=76)
         Join Filter: (core_product.product_group_id = core_productgroup.id)
         ->  Index Scan using core_product_pkey on core_product  (cost=0.00..3124799.28 rows=2957497 width=71)
         ->  Materialize  (cost=10.69..131.18 rows=314 width=13)
               ->  Bitmap Heap Scan on core_productgroup  (cost=10.69..129.61 rows=314 width=13)
                     Recheck Cond: (company_id = 1056)
                     ->  Bitmap Index Scan on core_productgroup_company_id  (cost=0.00..10.61 rows=314 width=0)
                           Index Cond: (company_id = 1056)

Without LIMIT:

                                                   QUERY PLAN                                                   
----------------------------------------------------------------------------------------------------------------
 Sort  (cost=110561.36..110724.66 rows=65320 width=76)
   Sort Key: core_product.id
   ->  Hash Join  (cost=133.54..102432.32 rows=65320 width=76)
         Hash Cond: (core_product.product_group_id = core_productgroup.id)
         ->  Seq Scan on core_product  (cost=0.00..90554.97 rows=2957497 width=71)
         ->  Hash  (cost=129.61..129.61 rows=314 width=13)
               ->  Bitmap Heap Scan on core_productgroup  (cost=10.69..129.61 rows=314 width=13)
                     Recheck Cond: (company_id = 1056)
                     ->  Bitmap Index Scan on core_productgroup_company_id  (cost=0.00..10.61 rows=314 width=0)
                           Index Cond: (company_id = 1056)

Is there some way I can influence the query plan chosen by PostgreSQL to avoid the very inefficient query plan it is currently using when LIMIT is being used?

Verbose query plan with LIMIT:

                                                                                                                                                                                                                            QUERY PLAN                                                                                                                                                                                                                            
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=10.69..52229.70 rows=200 width=76) (actual time=41669.575..41681.069 rows=200 loops=1)
   Output: core_product.sales_price, core_product.recommended_price, core_productgroup.name, core_product.number, core_product.name, core_product.description, core_product.cost_price, core_product.bar_code, core_product.accessible, core_product.id
   ->  Nested Loop  (cost=10.69..17054740.55 rows=65320 width=76) (actual time=41669.573..41681.040 rows=200 loops=1)
         Output: core_product.sales_price, core_product.recommended_price, core_productgroup.name, core_product.number, core_product.name, core_product.description, core_product.cost_price, core_product.bar_code, core_product.accessible, core_product.id
         Join Filter: (core_product.product_group_id = core_productgroup.id)
         ->  Index Scan using core_product_pkey on public.core_product  (cost=0.00..3124799.28 rows=2957497 width=71) (actual time=0.033..803.265 rows=773270 loops=1)
               Output: core_product.id, core_product.product_group_id, core_product.name, core_product.sales_price, core_product.cost_price, core_product.recommended_price, core_product.accessible, core_product.volume, core_product.in_stock, core_product.on_order, core_product.ordered, core_product.available, core_product.bar_code, core_product.description, core_product.logical_timestamp, core_product.number, core_product.unit, core_product.uuid
         ->  Materialize  (cost=10.69..131.18 rows=314 width=13) (actual time=0.000..0.018 rows=300 loops=773270)
               Output: core_productgroup.name, core_productgroup.id
               ->  Bitmap Heap Scan on public.core_productgroup  (cost=10.69..129.61 rows=314 width=13) (actual time=0.073..0.140 rows=300 loops=1)
                     Output: core_productgroup.name, core_productgroup.id
                     Recheck Cond: (core_productgroup.company_id = 1056)
                     ->  Bitmap Index Scan on core_productgroup_company_id  (cost=0.00..10.61 rows=314 width=0) (actual time=0.060..0.060 rows=300 loops=1)
                           Index Cond: (core_productgroup.company_id = 1056)
 Total runtime: 41681.125 ms
(15 rows)

Verbose query plan without LIMIT:

                                                                                                                                                                                                                            QUERY PLAN                                                                                                                                                                                                                            
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=110561.36..110724.66 rows=65320 width=76) (actual time=1733.710..1831.820 rows=292797 loops=1)
   Output: core_product.sales_price, core_product.recommended_price, core_productgroup.name, core_product.number, core_product.name, core_product.description, core_product.cost_price, core_product.bar_code, core_product.accessible, core_product.id
   Sort Key: core_product.id
   Sort Method: external merge  Disk: 28688kB
   ->  Hash Join  (cost=133.54..102432.32 rows=65320 width=76) (actual time=1.561..1239.564 rows=292797 loops=1)
         Output: core_product.sales_price, core_product.recommended_price, core_productgroup.name, core_product.number, core_product.name, core_product.description, core_product.cost_price, core_product.bar_code, core_product.accessible, core_product.id
         Hash Cond: (core_product.product_group_id = core_productgroup.id)
         ->  Seq Scan on public.core_product  (cost=0.00..90554.97 rows=2957497 width=71) (actual time=0.006..726.778 rows=3051563 loops=1)
               Output: core_product.id, core_product.product_group_id, core_product.name, core_product.sales_price, core_product.cost_price, core_product.recommended_price, core_product.accessible, core_product.volume, core_product.in_stock, core_product.on_order, core_product.ordered, core_product.available, core_product.bar_code, core_product.description, core_product.logical_timestamp, core_product.number, core_product.unit, core_product.uuid
         ->  Hash  (cost=129.61..129.61 rows=314 width=13) (actual time=0.186..0.186 rows=300 loops=1)
               Output: core_productgroup.name, core_productgroup.id
               Buckets: 1024  Batches: 1  Memory Usage: 13kB
               ->  Bitmap Heap Scan on public.core_productgroup  (cost=10.69..129.61 rows=314 width=13) (actual time=0.055..0.111 rows=300 loops=1)
                     Output: core_productgroup.name, core_productgroup.id
                     Recheck Cond: (core_productgroup.company_id = 1056)
                     ->  Bitmap Index Scan on core_productgroup_company_id  (cost=0.00..10.61 rows=314 width=0) (actual time=0.045..0.045 rows=300 loops=1)
                           Index Cond: (core_productgroup.company_id = 1056)
 Total runtime: 1883.235 ms
(18 rows)
  • Post the results of explain (analyze, verbose) instead of the plain analyze – a_horse_with_no_name Feb 23 '16 at 21:18
  • With LIMIT 200 the server has to perform a sort. Otherwise it can just belch out data without doing index lookups. Postgres philosophy is that optimiser hints are evil! – Vérace Feb 23 '16 at 21:58
  • This is a tricky query, we have had similar cases in the past: dba.stackexchange.com/q/124790/3684, dba.stackexchange.com/q/18300/3684, dba.stackexchange.com/q/66294/3684. Please add table and index definition and cardinalities. In particular also: typically how many distinct core_productgroup.id per core_productgroup.company_id? – Erwin Brandstetter Feb 24 '16 at 4:04
  • @a_horse_with_no_name I have updated the question with verbose output. – kasperd Feb 24 '16 at 8:45
  • The plan with limit underestimates the rows returned for the core_product table substantially. I guess that's the reason why Postgres chooses the slow nested loop in that case. I am not sure if this is caused by out of date statistics or because of the limit clause. Running analyze core_product might improve this. You can improve the query with the limit clause by increasing the work_mem for the session e.g. set work_mem = '64MB'. That might improve the statement without the limit as well because it might choose a hash join as well instead of the nested loop. – a_horse_with_no_name Feb 24 '16 at 9:06
5

The planner thinks that it can run through in core_product.id order, and rapidly find 200 matches where company_id=1056, at which point it is done.

But that doesn't work out, because all the things with a small core_product.id are things which don't have company_id=1056. (For example, company_id=1056 is a recently-joined client of yours, so all of their data falls on the upper end of the id sequence. But PostgreSQL doesn't understand that.)

You can probably force the plan you want by using a CTE and writing it like this:

with t as (
   <your query, without the limit, goes here>
)
select * from t limit 200;
  • 1
    This change does in fact speed up the query. I have no idea how to get the ORM to produce the query like that, so I'll keep looking for a better solution. The other answer sounds promising. But thank you for suggesting using a common table expression, at least I learned something new from your answer. – kasperd Feb 24 '16 at 7:54
  • 2
    I had a similar problem, which I solved by simply adding a column to the ORDER BY. If the columns in the ORDER BY do not match the index columns, Postgres will not use that index and instead choose a better one. So in this example, if you sort by id+barcode instead of just id, Postgres will probably choose to use the company_id index instead of the one on the id column. – zooglash Mar 7 '17 at 12:17
  • @zooglash "If the columns in the ORDER BY do not match the index columns, Postgres will not use that index and instead choose a better one." - I bumped into this, do you have any pointers to find more information about it? – Tuukka Mustonen Jul 26 '18 at 12:03
  • @TuukkaMustonen - sorry for the delay. This page details how PostgreSQL sometimes uses indexes for sorting, and it explains the differences in the original question's query plans: postgresql.org/docs/current/indexes-ordering.html – zooglash Nov 6 '18 at 13:45
1

This link says you are not able to directly influence the join.

The query plan uses statistics on the table to choose its plan, so you might see better performance after you use ANALYZE on the tables

  • This sounds useful. I don't feel like running the ANALYZE command in production without first having seen it help. And I haven't seen that particular performance problem outside of production. I'll probably have to setup a testing environment and restore a backup of production there in order to test your suggestions in a way that I am comfortable with. But it sounds promising enough, that is worth some effort on my part to evaluate your suggestion. – kasperd Feb 24 '16 at 7:59

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.