| From: | Achilleas Mantzios <achill(at)matrix(dot)gatewaynet(dot)com> | 
|---|---|
| To: | pgsql-admin(at)postgresql(dot)org | 
| Subject: | Postgresql 9.0.2 explain analyze very slow (10x), compared to actual query time | 
| Date: | 2011-01-11 15:53:22 | 
| Message-ID: | 201101111753.22602.achill@matrix.gatewaynet.com | 
| Views: | Whole Thread | Raw Message | Download mbox | Resend email | 
| Thread: | |
| Lists: | pgsql-admin | 
Hello,
I have noticed that in 9.0.2 EXPLAIN ANALYZE takes considerably longer time to return than the actual query. I never noticed this in 8.3.
Example:
In 9.0.2 i get
dynacom=# EXPLAIN ANALYZE SELECT count(ms.id) from marinerstates ms,mariner m where ms.endtime IS NOT NULL AND ms.marinerid=m.id;
                                                            QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=4716.48..4716.49 rows=1 width=4) (actual time=413.378..413.379 rows=1 loops=1)
   ->  Hash Join  (cost=788.77..4582.04 rows=53775 width=4) (actual time=54.029..330.286 rows=53845 loops=1)
         Hash Cond: (ms.marinerid = m.id)
         ->  Seq Scan on marinerstates ms  (cost=0.00..2583.33 rows=53775 width=8) (actual time=0.005..99.092 rows=53845 loops=1)
               Filter: (endtime IS NOT NULL)
         ->  Hash  (cost=583.90..583.90 rows=16390 width=4) (actual time=54.011..54.011 rows=16390 loops=1)
               Buckets: 2048  Batches: 1  Memory Usage: 577kB
               ->  Seq Scan on mariner m  (cost=0.00..583.90 rows=16390 width=4) (actual time=0.004..27.587 rows=16390 loops=1)
 Total runtime: 413.495 ms
dynacom=# \timing
Timing is on.
dynacom=# SELECT count(ms.id) from marinerstates ms,mariner m where ms.endtime IS NOT NULL AND ms.marinerid=m.id;
 count
-------
 53845
(1 row)
Time: 39,038 ms
So the actual time (39 ms) differs considerably from the EXPLAIN ANALYZE Total runtime (413 ms) (10 times bigger)
In 8.3 i get
postgres(at)dynacom=# EXPLAIN ANALYZE SELECT count(ms.id) from marinerstates ms,mariner m where ms.endtime IS NOT NULL AND ms.marinerid=m.id;
                                                            QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=5094.13..5094.14 rows=1 width=4) (actual time=84.180..84.180 rows=1 loops=1)
   ->  Hash Join  (cost=869.15..4954.27 rows=55942 width=4) (actual time=11.284..72.630 rows=54168 loops=1)
         Hash Cond: (ms.marinerid = m.id)
         ->  Seq Scan on marinerstates ms  (cost=0.00..2756.50 rows=55942 width=8) (actual time=0.013..25.696 rows=54168 loops=1)
               Filter: (endtime IS NOT NULL)
         ->  Hash  (cost=642.40..642.40 rows=18140 width=4) (actual time=11.256..11.256 rows=16442 loops=1)
               ->  Seq Scan on mariner m  (cost=0.00..642.40 rows=18140 width=4) (actual time=0.007..5.762 rows=16442 loops=1)
 Total runtime: 84.346 ms
(8 rows)
postgres(at)dynacom=# SELECT count(ms.id) from marinerstates ms,mariner m where ms.endtime IS NOT NULL AND ms.marinerid=m.id;
 count
-------
 54168
(1 row)
Time: 42.224 ms
In 8.3 the Total runtime is only double the value of the actual time.
Is there anything that can shed some light on this?
-- 
Achilleas Mantzios
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Tom Lane | 2011-01-11 16:19:11 | Re: Postgresql 9.0.2 explain analyze very slow (10x), compared to actual query time | 
| Previous Message | somnathzankar | 2011-01-11 05:55:51 | problem about postgresql installation and user login |