Hey Everyone,
I seem to be getting an inaccurate cost from explain. Here are two examples for one query with two different query plans:
exchange_prod=# set enable_nestloop = on;
SET
exchange_prod=#
exchange_prod=# explain analyze SELECT COUNT(DISTINCT "exchange_uploads"."id") FROM "exchange_uploads" INNER JOIN "upload_destinations" ON "upload_destinations"."id" = "exchange_uploads"."upload_destination_id" LEFT OUTER JOIN "uploads" ON "uploads"."id" = "exchange_uploads"."upload_id" LEFT OUTER JOIN "import_errors" ON "import_errors"."exchange_upload_id" = "exchange_uploads"."id" LEFT OUTER JOIN "exchanges" ON "exchanges"."id" = "upload_destinations"."exchange_id" WHERE (("exchange_uploads"."created_at" >= '2012-07-27 21:21:57.363944' AND "upload_destinations"."office_id" = 6));
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=190169.54..190169.55 rows=1 width=4) (actual time=199806.806..199806.807 rows=1 loops=1)
-> Nested Loop Left Join (cost=0.00..190162.49 rows=2817 width=4) (actual time=163.293..199753.548 rows=43904 loops=1)
-> Nested Loop (cost=0.00..151986.53 rows=2817 width=4) (actual time=163.275..186869.844 rows=43904 loops=1)
-> Index Scan using upload_destinations_office_id_idx on upload_destinations (cost=0.00..29.95 rows=4 width=8) (actual time=0.060..0.093 rows=6 loops=1)
Index Cond: (office_id = 6)
-> Index Scan using index_exchange_uploads_on_upload_destination_id on exchange_uploads (cost=0.00..37978.21 rows=875 width=12) (actual time=27.197..31140.375 rows=7317 loops=6)
Index Cond: (upload_destination_id = upload_destinations.id)
Filter: (created_at >= '2012-07-27 21:21:57.363944'::timestamp without time zone)
-> Index Scan using index_import_errors_on_exchange_upload_id on import_errors (cost=0.00..8.49 rows=405 width=4) (actual time=0.291..0.291 rows=0 loops=43904)
Index Cond: (exchange_upload_id = exchange_uploads.id)
Total runtime: 199806.951 ms
(11 rows)
exchange_prod=#
exchange_prod=# set enable_nestloop = off;
SET
exchange_prod=#
exchange_prod=# explain analyze SELECT COUNT(DISTINCT "exchange_uploads"."id") FROM "exchange_uploads" INNER JOIN "upload_destinations" ON "upload_destinations"."id" = "exchange_uploads"."upload_destination_id" LEFT OUTER JOIN "uploads" ON "uploads"."id" = "exchange_uploads"."upload_id" LEFT OUTER JOIN "import_errors" ON "import_errors"."exchange_upload_id" = "exchange_uploads"."id" LEFT OUTER JOIN "exchanges" ON "exchanges"."id" = "upload_destinations"."exchange_id" WHERE (("exchange_uploads"."created_at" >= '2012-07-27 21:21:57.363944' AND "upload_destinations"."office_id" = 6));
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=2535992.33..2535992.34 rows=1 width=4) (actual time=133447.507..133447.507 rows=1 loops=1)
-> Hash Right Join (cost=1816553.69..2535985.56 rows=2708 width=4) (actual time=133405.326..133417.078 rows=43906 loops=1)
Hash Cond: (import_errors.exchange_upload_id = exchange_uploads.id)
-> Seq Scan on import_errors (cost=0.00..710802.71 rows=2300471 width=4) (actual time=0.006..19199.569 rows=2321888 loops=1)
-> Hash (cost=1816519.84..1816519.84 rows=2708 width=4) (actual time=112938.606..112938.606 rows=43906 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1544kB
-> Hash Join (cost=28.25..1816519.84 rows=2708 width=4) (actual time=42.957..112892.689 rows=43906 loops=1)
Hash Cond: (exchange_uploads.upload_destination_id = upload_destinations.id)
-> Index Scan using index_upload_destinations_on_created_at on exchange_uploads (cost=0.00..1804094.96 rows=3298545 width=12) (actual time=17.686..111649.272 rows=3303488 loops=1)
Index Cond: (created_at >= '2012-07-27 21:21:57.363944'::timestamp without time zone)
-> Hash (cost=28.20..28.20 rows=4 width=8) (actual time=0.043..0.043 rows=6 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Bitmap Heap Scan on upload_destinations (cost=6.28..28.20 rows=4 width=8) (actual time=0.026..0.036 rows=6 loops=1)
Recheck Cond: (office_id = 6)
-> Bitmap Index Scan on upload_destinations_office_id_idx (cost=0.00..6.28 rows=4 width=0) (actual time=0.020..0.020 rows=6 loops=1)
Index Cond: (office_id = 6)
Total runtime: 133447.790 ms
(17 rows)
The first query shows a cost of 190,169.55 and runs in 199,806.951 ms. When I disable nested loop, I get a cost of 2,535,992.34 which runs in only 133,447.790 ms. We have run queries on our database with a cost of 200K cost before and they ran less then a few seconds, which makes me wonder if the first query plan is inaccurate. The other issue is understanding why a query plan with a much higher cost is taking less time to run.
I do not think these queries are cached differently, as we have gotten the same results ran a couple of times at across a few days. We also analyzed the tables that we are querying before trying the explain analyze again, and were met with the same statistics. Any help on how Postgres comes up with a query plan like this, and why there is a difference would be very helpful.
Thanks!
--
Robert Sosinski
