explain analyze reports 20x more time than actual - Mailing list pgsql-performance

From Craig A. James
Subject explain analyze reports 20x more time than actual
Date
Msg-id 44A4AE1A.4070308@modgraph-usa.com
Whole thread Raw
In response to Re: function not called if part of aggregate  (Tom Lane <tgl@sss.pgh.pa.us>)
Responses Re: explain analyze reports 20x more time than actual  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-performance
I have a query that needs to run faster, with the obvious solution being to add an index.  But to confirm this, I ran
explainanalyze.  When I run the actual query, it consistently takes 6-7 seconds by the wall clock.  My application with
a"verbose" mode enabled reports 6.6 seconds consistently.  However, when I run EXPLAIN ANALYZE, it takes 120 seconds!
Thisis 20x longer, and it leads me to distrust the plan that it claims to be executing.  How can the actual run time be
somuch faster than that claimed by EXPLAIN ANALYZE?  How can I find out the actual plan it's using? 

Thanks,
Craig


Details:
  Postgres 8.0.3
    shared_buffers = 20000
    work_mem = 500000
    effective_cache_size = 430000
  Dell w/ Xeon
    Linux kernel 2.6.9-1.667smp
    4 GB memory

=> explain analyze select SAMPLE.SAMPLE_ID, SAMPLE.VERSION_ID,SAMPLE.SUPPLIER_ID,SAMPLE.CATALOGUE_ID,SAMPLE.PREP_ID
fromHITLIST_ROWS_281430 join SAMPLE on (HITLIST_ROWS_281430.OBJECTID = SAMPLE.SAMPLE_ID) where  SAMPLE.VERSION_ID in
(7513672,7513650,7513634,7513620,7513592,7513590,7513582,7513576,7513562,7513560)order by
HITLIST_ROWS_281430.SortOrder;

                                          QUERY PLAN
                                                                                               

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=234964.38..234964.52 rows=58 width=24) (actual time=120510.842..120510.889 rows=10 loops=1)
   Sort Key: hitlist_rows_281430.sortorder
   ->  Hash Join  (cost=353.68..234962.68 rows=58 width=24) (actual time=81433.194..120510.753 rows=10 loops=1)
         Hash Cond: ("outer".objectid = "inner".sample_id)
         ->  Seq Scan on hitlist_rows_281430  (cost=0.00..177121.61 rows=11497361 width=8) (actual
time=0.008..64434.110rows=11497361 loops=1) 
         ->  Hash  (cost=353.48..353.48 rows=82 width=20) (actual time=0.293..0.293 rows=0 loops=1)
               ->  Index Scan using i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id,
i_sample_version_id,i_sample_version_id, i_sample_version_id, i_sample_version_id, i_sample_version_id,
i_sample_version_idon sample  (cost=0.00..353.48 rows=82 width=20) (actual time=0.042..0.201 rows=12 loops=1) 
                     Index Cond: ((version_id = 7513672) OR (version_id = 7513650) OR (version_id = 7513634) OR
(version_id= 7513620) OR (version_id = 7513592) OR (version_id = 7513590) OR (version_id = 7513582) OR (version_id =
7513576)OR (version_id = 7513562) OR (version_id = 7513560)) 
 Total runtime: 120511.485 ms
(9 rows)

pgsql-performance by date:

Previous
From: Ron Mayer
Date:
Subject: Re: Some performance numbers, with thoughts
Next
From: "Craig A. James"
Date:
Subject: Sort order in sub-select