Обсуждение: Explain Analyze returns faster than psql or JDBC calls.

Hi there

We are runing Postgres 8.3.7 on a
We have a problem with Explain Analyze that we haven't seen before.

  we run an Explain Analyze on a query.

 Nested Loop  (cost=1256.32..2097.31 rows=198 width=1120) (actual time=12.958..20.846 rows=494 loops=1)
   ->  HashAggregate  (cost=1256.32..1256.92 rows=198 width=4) (actual time=12.936..13.720 rows=494 loops=1)
         ->  Limit  (cost=1255.53..1255.63 rows=198 width=20) (actual time=9.841..11.901 rows=500 loops=1)
               ->  Sort  (cost=1255.53..1255.63 rows=198 width=20) (actual time=9.838..10.588 rows=500 loops=1)
                     Sort Key: ((abs((ri_metadata.latitude - 44.0247062::double precision)) + abs((ri_metadata.longitude - (-88.5426136)::double precision))))
                     Sort Method:  quicksort  Memory: 52kB
                     ->  Bitmap Heap Scan on ri_metadata  (cost=385.54..1254.02 rows=198 width=20) (actual time=4.638..8.558 rows=595 loops=1)
                           Recheck Cond: ((latitude > 43.6687062::double precision) AND (latitude < 44.3807062::double precision) AND (longitude > (-88.8986136)::double precision) AND (longitude < (-88.1866136)::double precision))
                           Filter: (category_id = ANY ('{3,274,4,1,2,275,7,278,8,277,5,280,6,279,11,9,10,15,285,16,14,19,18,17,24,23,21,266,25,32,31,30,29,40,34,48,41,44,313,54,53,55,50,52,62,61,63,302,58,57,59,71,341,69,67,338,68,337,65,66,339,79,352,77,78,74,85,83,324,81,334,335,336,372,376,373,374,363,122,368,127,128,356,355,360,359,118,358,357,140,139,138,137,143,142,141,132,130,129,135,134,191,185,186,187,188,183,202,200,193,219}'::integer[]))
                           ->  Bitmap Index Scan on ri_metadata_latitude_longitude_category_id_idx  (cost=0.00..385.53 rows=462 width=0) (actual time=4.533..4.533 rows=1316 loops=1)
                                 Index Cond: ((latitude > 43.6687062::double precision) AND (latitude < 44.3807062::double precision) AND (longitude > (-88.8986136)::double precision) AND (longitude < (-88.1866136)::double precision))
   ->  Index Scan using ri_result_result_id_idx on ri_result  (cost=0.00..4.24 rows=1 width=1120) (actual time=0.006..0.008 rows=1 loops=494)
         Index Cond: (ri_result.result_id = ri_metadata.result_id)
 Total runtime: 21.658 ms
(14 rows)

It takes only *21* ms. Then we run the same query on psql (on localhost) with timing on

 select * from ri_result where result_id in
 (select result_id from ri_metadata
 WHERE category_id IN (3,274,4,1,2,275,7,278,8,277,5,280,6,279,11,9,10,15,285,16,14,19,18,17,24,23,21,266,25,32,31,30,29,40,34,48,41,44,313,54,53
 ,55,50,52,62,61,63,302,58,57,59,71,341,69,67,338,68,337,65,66,339,79,352,77,78,74,85,83,324,81,334,335,336,372,376,373,374,363,122,368,127,
 128,356,355,360,359,118,358,357,140,139,138,137,143,142,141,132,130,129,135,134,191,185,186,187,188,183,202,200,193,219) AND  latitude >43.668706199999995 AND latitude <44.3807062 AND longitude>-88.89861359999999 AND longitude<-88.1866136
   order by  abs(latitude  - 44.0247062)+abs(longitude - -88.5426136) limit 500)
;
Time: 2611.491 ms

The longer runtime from psql console is corroborated when we do same  queries via JDBC
How can  explain-analyze return significantly much faster than other means? (I understand that some data is returned from the query to either client end on psql or to a resultset in jdbc as opposed to a small  chunk of data in the form of a plan but still..,)
By the way, I run the explain analyze first and then run the query  to avoid any caching.

Our system : Ubuntu Ubuntu 8.04.3 64 bit,  8GB RAM ,2 GHz single core, running a vm on an esx server. the database is read-only.



ri_metadata has 1473864 rows, 200MB,
                                             Table "public.ri_metadata"
     Column     |            Type             |                              Modifiers
----------------+-----------------------------+----------------------------------------------------------------------
 ri_metadata_id | integer                     | not null default nextval('ri_metadata_ri_metadata_id_seq'::regclass)
 result_id      | integer                     | not null
 start_time     | timestamp without time zone | not null
 end_time       | timestamp without time zone | not null
 category_id    | integer                     | not null
 category_name  | text                        | not null
 location_id    | integer                     |
 longitude      | double precision            |
 latitude       | double precision            |
 city           | text                        |
 state          | text                        |
 zip            | text                        |
 street_address | text                        |
Indexes:
    "ri_metadata_pkey" PRIMARY KEY, btree (ri_metadata_id)
    "ri_metadata_category_id_idx" btree (category_id)
    "ri_metadata_category_id_state" btree (category_id, state)
    "ri_metadata_end_time_idx" btree (end_time)
    "ri_metadata_latitude_idx" btree (latitude)
    "ri_metadata_latitude_longitude_category_id_idx" btree (latitude, longitude, category_id)
    "ri_metadata_location_id_idx" btree (location_id)
    "ri_metadata_longitude_idx" btree (longitude)
    "ri_metadata_result_id_idx" btree (result_id)
    "ri_metadata_start_time_idx" btree (start_time)
    "ri_metadata_state_idx" btree (state)


ri_result has 1323061 rows, 3.3GB total size

                                      Table "public.ri_result"
    Column    |       Type       |                            Modifiers
--------------+------------------+------------------------------------------------------------------
 ri_result_id | integer          | not null default nextval('ri_result_ri_result_id_seq'::regclass)
 result_id    | integer          | not null
 facets       | bytea            | not null
 props        | bytea            | not null
 random       | double precision |
Indexes:
    "ri_result_pkey" PRIMARY KEY, btree (ri_result_id)
    "ri_result_random_idx" btree (random)
    "ri_result_result_id_idx" btree (result_id)

G B <g.b.coder@gmail.com> writes:
> How can  explain-analyze return significantly much faster than other means?

If the returned data is large or takes a lot of work to convert to text,
this could happen, since EXPLAIN ANALYZE doesn't bother to format the
tuples for display.  How big are those bytea columns, on average?

            regards, tom lane

You should also keep in mind that JDBC uses prepared statements, so you have to explain analyze accordingly.

Dave