Re: 8.1 -- very slow query time because of "BETWEEN" (dbmail) - Mailing list pgsql-novice

Ahhh.  I knew troubleshooting this would lead to cool new discoveries and troubleshooting tools.  I apologize if Yahoo jacks the formatting up:

EXPLAIN ANALYZE
SELECT message_idnr,headername,headervalue
    FROM dbmail_headervalue v JOIN dbmail_messages m ON v.physmessage_id=m.physmessage_id
    JOIN dbmail_headername n ON v.headername_id=n.id
    WHERE m.mailbox_idnr = 417 AND message_idnr BETWEEN 253775 AND 253775 AND lower(headername)
    IN ('from','to','cc','subject','date','message-id','priority','x-priority','references','newsgroups','in-reply-to','content-type');


"Hash Join  (cost=166.74..46797.70 rows=1310 width=258) (actual time=4060.356..4142.813 rows=6 loops=1)"
"  Hash Cond: ("outer".headername_id = "inner".id)"
"  ->  Hash Join  (cost=22.27..46528.32 rows=22360 width=48) (actual time=4006.255..4088.688 rows=17 loops=1)"
"        Hash Cond: ("outer".physmessage_id = "inner".physmessage_id)"
"        ->  Seq Scan on dbmail_headervalue v  (cost=0.00..38828.97 rows=1490697 width=48) (actual time=0.085..2628.264 rows=1474315 loops=1)"
"        ->  Hash  (cost=22.26..22.26 rows=3 width=16) (actual time=0.198..0.198 rows=1 loops=1)"
"              ->  Bitmap Heap Scan on dbmail_messages m  (cost=10.54..22.26 rows=3 width=16) (actual time=0.170..0.172 rows=1 loops=1)"
"                    Recheck Cond: ((message_idnr >= 253775) AND (message_idnr <= 253775) AND (mailbox_idnr = 417))"
"                    ->  Bitmap Index Scan on dbmail_messages_bwn  (cost=0.00..10.54 rows=3 width=0) (actual time=0.103..0.103 rows=1 loops=1)"
"                          Index Cond: ((message_idnr >= 253775) AND (message_idnr <= 253775) AND (mailbox_idnr = 417))"
"  ->  Hash  (cost=144.20..144.20 rows=109 width=226) (actual time=53.976..53.976 rows=30 loops=1)"
"        ->  Seq Scan on dbmail_headername n  (cost=0.00..144.20 rows=109 width=226) (actual time=0.223..53.864 rows=30 loops=1)"
"              Filter: ((lower((headername)::text) = 'from'::text) OR (lower((headername)::text) = 'to'::text) OR (lower((headername)::text) = 'cc'::text) OR (lower((headername)::text) = 'subject'::text) OR (lower((headername)::text) = 'date'::text) OR (lower((headername)::text) = 'message-id'::text) OR (lower((headername)::text) = 'priority'::text) OR (lower((headername)::text) = 'x-priority'::text) OR (lower((headername)::text) = 'references'::text) OR (lower((headername)::text) = 'newsgroups'::text) OR (lower((headername)::text) = 'in-reply-to'::text) OR (lower((headername)::text) = 'content-type'::text))"
"Total runtime: 4143.164 ms"


EXPLAIN ANALYZE
SELECT message_idnr,headername,headervalue
    FROM dbmail_headervalue v JOIN dbmail_messages m ON v.physmessage_id=m.physmessage_id
    JOIN dbmail_headername n ON v.headername_id=n.id
    WHERE m.mailbox_idnr = 417 AND message_idnr = 253775 AND lower(headername)
    IN ('from','to','cc','subject','date','message-id','priority','x-priority','references','newsgroups','in-reply-to','content-type');


"Hash Join  (cost=228.56..16195.32 rows=437 width=258) (actual time=68.418..68.512 rows=6 loops=1)"
"  Hash Cond: ("outer".headername_id = "inner".id)"
"  ->  Nested Loop  (cost=84.09..16009.20 rows=7454 width=48) (actual time=13.905..13.973 rows=17 loops=1)"
"        ->  Index Scan using dbmail_messages_bwn on dbmail_messages m  (cost=0.00..6.02 rows=1 width=16) (actual time=0.235..0.248 rows=1 loops=1)"
"              Index Cond: ((message_idnr = 253775) AND (mailbox_idnr = 417))"
"        ->  Bitmap Heap Scan on dbmail_headervalue v  (cost=84.09..15910.01 rows=7454 width=48) (actual time=13.653..13.678 rows=17 loops=1)"
"              Recheck Cond: (v.physmessage_id = "outer".physmessage_id)"
"              ->  Bitmap Index Scan on dbmail_headervalue_1  (cost=0.00..84.09 rows=7454 width=0) (actual time=13.589..13.589 rows=17 loops=1)"
"                    Index Cond: (v.physmessage_id = "outer".physmessage_id)"
"  ->  Hash  (cost=144.20..144.20 rows=109 width=226) (actual time=54.464..54.464 rows=30 loops=1)"
"        ->  Seq Scan on dbmail_headername n  (cost=0.00..144.20 rows=109 width=226) (actual time=0.127..54.381 rows=30 loops=1)"
"              Filter: ((lower((headername)::text) = 'from'::text) OR (lower((headername)::text) = 'to'::text) OR (lower((headername)::text) = 'cc'::text) OR (lower((headername)::text) = 'subject'::text) OR (lower((headername)::text) = 'date'::text) OR (lower((headername)::text) = 'message-id'::text) OR (lower((headername)::text) = 'priority'::text) OR (lower((headername)::text) = 'x-priority'::text) OR (lower((headername)::text) = 'references'::text) OR (lower((headername)::text) = 'newsgroups'::text) OR (lower((headername)::text) = 'in-reply-to'::text) OR (lower((headername)::text) = 'content-type'::text))"
"Total runtime: 68.796 ms"





Tom Lane <tgl@sss.pgh.pa.us> wrote:

Brian Neu writes:
> The strange part is that if you change the "BETWEEN" to just an "= 253775" . . . the query takes around 70ms.

Please show EXPLAIN ANALYZE output for both cases. I suppose it's
changing plans but it's not clear why.

> Is my answer to just upgrade to 8.2 ? Is this a known problem in 8.1 ?

8.1.which?

regards, tom lane