Thread: Abnormal long SELECT query under postgresql 9.0.4
Hi everyone,
We've just moved our website database from pg 8.4 to pg 9.0 and we found
out a very long query (that wasn't that long under 8.4).
And I actually can't explain why it's taking so much timeŠ
Here it is :
EXPLAIN ANALYZE SELECT "articles_article"."id",
"articles_article"."name", "articles_article"."post_date" FROM
"articles_article" WHERE ("articles_article"."permis" = true AND
"articles_article"."status" = 2 AND "articles_article"."flux_id" = 3107
AND NOT ("articles_article"."id" = 784923 )) ORDER BY
"articles_article"."post_date" DESC LIMIT 4;
QUERY PLAN
---------------------------------------------------------------------------
---------------------------------------------------------------------------
-------------------
Limit (cost=0.00..7737.95 rows=4 width=53) (actual
time=440296.783..448149.439 rows=4 loops=1)
-> Index Scan Backward using index_articles_post on articles_article
(cost=0.00..7233050.00 rows=3739 width=53) (actual
time=440296.783..448149.437 rows=4 loops=1)
Filter: (permis AND (id <> 784923) AND (status = 2) AND (flux_id
= 3107))
Total runtime: 448149.477 ms
(4 rows)
Then, if I remove the ORDER BY clause, this is much much better :
EXPLAIN ANALYZE SELECT "articles_article"."id",
"articles_article"."name", "articles_article"."post_date" FROM
"articles_article" WHERE ("articles_article"."permis" = true AND
"articles_article"."status" = 2 AND "articles_article"."flux_id" = 3107
AND NOT ("articles_article"."id" = 784923 )) LIMIT 4;
QUERY PLAN
---------------------------------------------------------------------------
---------------------------------------------------------------------------
---
Limit (cost=0.00..8.25 rows=4 width=53) (actual time=1.472..74.679
rows=4 loops=1)
-> Index Scan using articles_article_flux_id on articles_article
(cost=0.00..7710.04 rows=3739 width=53) (actual time=1.468..74.672 rows=4
loops=1)
Index Cond: (flux_id = 3107)
Filter: (permis AND (id <> 784923) AND (status = 2))
Total runtime: 74.779 ms
(5 rows)
Same query under 8.4 :
EXPLAIN ANALYZE SELECT "articles_article"."id", "articles_article"."name",
"articles_article"."post_date" FROM "articles_article" WHERE
("articles_article"."permis" = true AND "articles_article"."status" = 2
AND "articles_article"."flux_id" = 3107 AND NOT ("articles_article"."id" =
784923 )) ORDER BY "articles_article"."post_date" DESC LIMIT 4;
QUERY PLAN
---------------------------------------------------------------------------
---------------------------------------------------------------------------
---------- Limit (cost=693.11..693.12 rows=4 width=53) (actual
time=12.617..12.619 rows=4 loops=1) -> Sort (cost=693.11..693.94
rows=330 width=53) (actual time=12.615..12.616 rows=4 loops=1)
Sort Key: post_date Sort Method: top-N heapsort Memory: 25kB
-> Index Scan using articles_article_flux_id on articles_article
(cost=0.00..688.16 rows=330 width=53) (actual time=0.034..12.255 rows=1072
loops=1)
Index Cond: (flux_id = 3107)
Filter: (permis AND (id <> 784923) AND (status = 2))
Total runtime: 12.672 ms
(8 rows)
Would anyone know where this might come from? 448 secondes for a basic
SELECT sounds amazing oO
Thanks,
Gaëtan
Gaëtan Allart <gaetan@nexylan.com> Wednesday 08 of June 2011 14:59:05
> Hi everyone,
>
> We've just moved our website database from pg 8.4 to pg 9.0 and we found
> out a very long query (that wasn't that long under 8.4).
> And I actually can't explain why it's taking so much timeŠ
>
>
>
> Here it is :
>
> EXPLAIN ANALYZE SELECT "articles_article"."id",
> "articles_article"."name", "articles_article"."post_date" FROM
> "articles_article" WHERE ("articles_article"."permis" = true AND
> "articles_article"."status" = 2 AND "articles_article"."flux_id" = 3107
> AND NOT ("articles_article"."id" = 784923 )) ORDER BY
> "articles_article"."post_date" DESC LIMIT 4;
>
> QUERY PLAN
>
> ---------------------------------------------------------------------------
> ---------------------------------------------------------------------------
> -------------------
> Limit (cost=0.00..7737.95 rows=4 width=53) (actual
> time=440296.783..448149.439 rows=4 loops=1)
> -> Index Scan Backward using index_articles_post on articles_article
> (cost=0.00..7233050.00 rows=3739 width=53) (actual
> time=440296.783..448149.437 rows=4 loops=1)
> Filter: (permis AND (id <> 784923) AND (status = 2) AND (flux_id
> = 3107))
> Total runtime: 448149.477 ms
> (4 rows)
>
>
>
>
>
>
> Then, if I remove the ORDER BY clause, this is much much better :
>
> EXPLAIN ANALYZE SELECT "articles_article"."id",
> "articles_article"."name", "articles_article"."post_date" FROM
> "articles_article" WHERE ("articles_article"."permis" = true AND
> "articles_article"."status" = 2 AND "articles_article"."flux_id" = 3107
> AND NOT ("articles_article"."id" = 784923 )) LIMIT 4;
> QUERY PLAN
>
> ---------------------------------------------------------------------------
> ---------------------------------------------------------------------------
> ---
> Limit (cost=0.00..8.25 rows=4 width=53) (actual time=1.472..74.679
> rows=4 loops=1)
> -> Index Scan using articles_article_flux_id on articles_article
> (cost=0.00..7710.04 rows=3739 width=53) (actual time=1.468..74.672 rows=4
> loops=1)
> Index Cond: (flux_id = 3107)
> Filter: (permis AND (id <> 784923) AND (status = 2))
> Total runtime: 74.779 ms
> (5 rows)
>
>
>
>
> Same query under 8.4 :
>
> EXPLAIN ANALYZE SELECT "articles_article"."id", "articles_article"."name",
> "articles_article"."post_date" FROM "articles_article" WHERE
> ("articles_article"."permis" = true AND "articles_article"."status" = 2
> AND "articles_article"."flux_id" = 3107 AND NOT ("articles_article"."id" =
> 784923 )) ORDER BY "articles_article"."post_date" DESC LIMIT 4;
> QUERY PLAN
>
> ---------------------------------------------------------------------------
> ---------------------------------------------------------------------------
> ---------- Limit (cost=693.11..693.12 rows=4 width=53) (actual
> time=12.617..12.619 rows=4 loops=1) -> Sort (cost=693.11..693.94
> rows=330 width=53) (actual time=12.615..12.616 rows=4 loops=1)
> Sort Key: post_date Sort Method: top-N heapsort Memory: 25kB
> -> Index Scan using articles_article_flux_id on articles_article
> (cost=0.00..688.16 rows=330 width=53) (actual time=0.034..12.255 rows=1072
> loops=1)
> Index Cond: (flux_id = 3107)
> Filter: (permis AND (id <> 784923) AND (status = 2))
> Total runtime: 12.672 ms
> (8 rows)
>
>
>
>
>
>
> Would anyone know where this might come from? 448 secondes for a basic
> SELECT sounds amazing oO
>
> Thanks,
>
> Gaëtan
Did You ran analyze or vacuum after migration?
Best regards,
Radek