Re: Very slow query - why?

On Mon, 02 Feb 2004 09:53:50 -0500, Tom Lane wrote:

> Also note that the planner has gotten successively smarter about outer
> joins in each of the past several releases.  Without knowing which PG
> version this is (and it ain't "PostgreSQL 4.3" as alleged in the OP's
> message...),

Sorry, SHB PostgreSQL 7.3 - my apologies...

> and without seeing EXPLAIN ANALYZE results, it's hard to speculate about
> what's going on.

Here they are. Also, just to explain, I wasn't really asking why the 12
second timing was happening, I was asking why this took several seconds rather
than coming back in a fraction of a second - since there were indexes on
everything, it seemed to me that the rows involved in both tables could be
identified more or less instantly, then combined as required, then
returned. >1 second on a 3 GHz processor is a TON of computing time, and
most operations appear to happen instantly within this particular
database. This machine is actually a dual 3 GHz machine, but I get the
impression that PostgreSQL uses one at a time for a particular job, so
it's not effectively 6 GHz. Still, it's a pretty fast machine. :)

The details:

EXPLAIN ANALYZE
SELECT a.zcustnum,trim(a.zcompany),trim(a.zfirstname),
       trim(a.zlastname),trim(a.zaddr),trim(a.zaddr2),
       trim(a.zcity),trim(a.zstate),trim(a.zzipcode),
       trim(a.zcountry),a.zbigphone,a.zbigaltph,trim(a.zemail),
       a.zanumb,trim(a.zsalu),trim(a.ztitle),a.zoptin,
       b.zodr_date,b.zbadcheck,trim(b.zcomment),trim(b.zcomment2)
       FROM sonaddr AS a LEFT OUTER JOIN momcust AS b
       ON (a.zcustnum = b.zcustnum)
       WHERE a.zcustnum=30538;

 QUERY PLAN
 ----------
 Merge Join  (cost=34952.76..40696.70 rows=260923 width=464) (actual
 time=1492.00..1492.55 rows=6 loops=1)
   Merge Cond: ("outer".zcustnum = "inner".zcustnum) ->  Index Scan using
   acn_index on sonaddr a  (cost=0.00..1965.45 rows=508 width=359) (actual
   time=0.10..0.28 rows=6 loops=1)
         Index Cond: (zcustnum = 30538)
   ->  Sort  (cost=34952.76..35209.39 rows=102650 width=105) (actual
   time=1441.52..1467.60 rows=27367 loops=1)
         Sort Key: b.zcustnum
         ->  Seq Scan on momcust b  (cost=0.00..13858.50 rows=102650
         width=105) (actual time=0.03..521.36 rows=102657 loops=1)
 Total runtime: 1504.42 msec
(8 rows)