Explain Analyze returns faster than psql or JDBC calls.

From: G B <g(dot)b(dot)coder(at)gmail(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: Explain Analyze returns faster than psql or JDBC calls.
Date: 2009-10-08 20:30:37
Message-ID: 655864830910081330m5b11be2bi8fd408685e4b3ee4@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

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)

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Kevin Grittner 2009-10-08 20:37:39 Re: dump time increase by 1h with new kernel
Previous Message Justin T Pryzby 2009-10-08 20:16:03 Re: dump time increase by 1h with new kernel