Thread: 8.1 -- very slow query time because of "BETWEEN" (dbmail)

8.1 -- very slow query time because of "BETWEEN" (dbmail)

From

Brian Neu

Date:

22 June 2007, 01:30:12

Here is the original query which runs over 2500 ms:

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');

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

Running
select * from dbmail_messages
    where (mailbox_idnr = 417)
    AND message_idnr > 253755 AND message_idnr <= 253790

takes 20ms and the same when it says "BETWEEN"

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

Re: 8.1 -- very slow query time because of "BETWEEN" (dbmail)

From

Tom Lane

Date:

22 June 2007, 02:11:07

Brian Neu <proclivity76@yahoo.com> 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

Re: 8.1 -- very slow query time because of "BETWEEN" (dbmail)

From

Brian Neu

Date:

22 June 2007, 03:05:31

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

Re: 8.1 -- very slow query time because of "BETWEEN" (dbmail)

From

Tom Lane

Date:

22 June 2007, 03:33:21

Brian Neu <proclivity76@yahoo.com> writes:
> Ahhh.  I knew troubleshooting this would lead to cool new discoveries and troubleshooting tools.  I apologize if
Yahoojacks the formatting up: 

It's still readable ... seems the core of the problem is here:

> "        ->  Bitmap Heap Scan on dbmail_headervalue v  (cost=84.09..15910.01 rows=7454 width=48) (actual
time=13.653..13.678rows=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.589rows=17 loops=1)" 
> "                    Index Cond: (v.physmessage_id = "outer".physmessage_id)"

In the slow case, the planner estimates it would have to do this scan 3
times not just once, when once is correct.  (This is because range
estimation is a bit fuzzier than equality estimation.  Estimating 3
matching rows instead of 1 is still well within reasonable error
though.)  The problem is that it's estimating 7454 matching
dbmail_headervalue rows per outer row, when the truth is only 17; and
that results in a large overestimate of the cost of doing this scan,
which convinces it that it doesn't want to do it more than once.

So basically the trick here is to get that 7454 number closer to
reality.  Has this table been ANALYZEd lately?  If so, could we
see the pg_stats entry for the physmessage_id column?

            regards, tom lane

Re: 8.1 -- very slow query time because of "BETWEEN" (dbmail)

From

Brian Neu

Date:

22 June 2007, 09:00:35

It's amazing sometimes how overlooking a "-z" can cost you 4 days of troubleshooting when you start looking in all the wrong places.

Tom, you nailed it. While this server gets vacuum'd, it had never been ANALYZE'd. I just plain missed this when setting up maintenance. I hang my head in IT administrator shame.

Thank you much for your help.

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

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

It's still readable ... seems the core of the problem is here:

> " -> 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)"

In the slow case, the planner estimates it would have to do this scan 3
times not just once, when once is correct. (This is because range
estimation is a bit fuzzier than equality estimation. Estimating 3
matching rows instead of 1 is still well within reasonable error
though.) The problem is that it's estimating 7454 matching
dbmail_headervalue rows per outer row, when the truth is only 17; and
that results in a large overestimate of the cost of doing this scan,
which convinces it that it doesn't want to do it more than once.

So basically the trick here is to get that 7454 number closer to
reality. Has this table been ANALYZEd lately? If so, could we
see the pg_stats entry for the physmessage_id column?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend