Mailing List Archive

Although I don't have an answer, I can confirm the slow query happens on
3.2.1, though for me at least unrepeatable, subsequent runs of the query
are returned sub second.

The query planner shows nothing unusual, also table stats for each of
the query tables shows few table scans. Fortunately it hasn't affected
me enough to investigate further.

I haven't tried header_cache_readonly which may help.

Currently running PostgreSQL 9.2, previously saw more on MySQL 5.1
though no stats to compare fairly.

Regards,
Alan

On 24/11/2014 10:51, Daniel Schütze wrote:
>
> I’ve noticed in my slow query log there is a particular type of query
> which is regularly showing up and I was wondering what was triggering it.
>
> The most recent example is this (but it’s being going on since I
> turned the slow query log on in July:
>
> SELECT m.message_idnr, n.headername, v.headervalue, CASE WHEN
> n.headername='from' THEN 0 WHEN n.headername='to' THEN 1 WHEN
> n.headername='cc' THEN 2 WHEN n.headername='bcc' THEN 3 WHEN
> n.headername='subject' THEN 4 WHEN n.headername='date' THEN 5 WHEN
> n.headername='message-id' THEN 6 WHEN n.headername='priority' THEN 7
> WHEN n.headername='x-priority' THEN 8 WHEN n.headername='references'
> THEN 9 WHEN n.headername='newsgroups' THEN 10 WHEN
> n.headername='in-reply-to' THEN 11 WHEN n.headername='content-type'
> THEN 12 WHEN n.headername='reply-to' THEN 13 END AS seq FROM
> dbmail_header h LEFT JOIN dbmail_messages m ON
> h.physmessage_id=m.physmessage_id LEFT JOIN dbmail_headername n ON
> h.headername_id=n.id LEFT JOIN dbmail_headervalue v ON
> h.headervalue_id=v.id WHERE m.mailbox_idnr = 170 AND m.message_idnr
> BETWEEN 5477613 AND 5479501 AND n.headername IN
> ('from','to','cc','bcc','subject','date','message-id','priority','x-priority','references','newsgroups','in-reply-to','content-type','reply-to')
> ORDER BY message_idnr, seq;
>
> Which slow reports as taking some 33 seconds
>
> # Time: 141124 10:32:05
>
> # User@Host: dbmail[dbmail] @ localhost []
>
> # Query_time: 33.363653 Lock_time: 0.000014 Rows_sent: 0
> Rows_examined: 20214893
>
> I’m still using dbmail 3.1.15 so apologies if this is obsolete by the
> current 3.2.1 release; but I’m wondering if this query/speed is normal
> or a sign something is a miss.
>
>
> Regards
>
>
> Daniel Schütze
>
> ------------------------
>
> CWA International
>
> Balmoral House
>
> 9 John Street
>
> London
> WC1N 2ES
>
> (t) + 44 (0)20 7242 8444
>
> (e) dms@cwa.uk.com
>
> (w) http://www.cwa.uk.com/
>
>
>
> _______________________________________________
> DBmail mailing list
> DBmail@dbmail.org
> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail

--
Persistent Objects Ltd
128 Lilleshall Road
Morden SM4 6DR

The Home of Lasting Solutions

Mobile: 079 3030 5004
Tel: 020 8544 5292
Web: p-o.co.uk
Skype: alan-hicks-london
Personal blog https://plus.google.com/+AlanHicksLondon
Company blog https://plus.google.com/+PoCoUkLondon/posts
LinkedIn https://uk.linkedin.com/in/alanhickslondon/
GitHub https://github.com/alan-hicks

On 24/11/2014 15:50, Alan Hicks wrote:
> Although I don't have an answer, I can confirm the slow query happens
> on 3.2.1, though for me at least unrepeatable, subsequent runs of the
> query are returned sub second.
>
> The query planner shows nothing unusual, also table stats for each of
> the query tables shows few table scans. Fortunately it hasn't
> affected me enough to investigate further.
>
> I haven't tried header_cache_readonly which may help.
>
> Currently running PostgreSQL 9.2, previously saw more on MySQL 5.1
> though no stats to compare fairly.
>
> Regards,
> Alan

This explanation may help to clarify why it might be useful to use
header_cache_readonly.

If delivery of a new message adds to the headername table and due to any
of complexity, size or server load takes longer to commit, the index may
be locked on the headername table until the transaction is complete.

Both MySQL and PostgreSQL offer excellent Multiversion Concurrency
Control (MVCC), nevertheless the query plan shows these are evaluated as
Hash indexes whose locks are held for the duration of the nested loop.
Lock contention on the index may be the cause of the slow query.

Using header_cache_readonly would not add any new records to the
headername table and so should not need any locks.

It might be useful to get feedback to see if anyone using
header_cache_readonly still sees those slow queries.

SELECT m.message_idnr, n.headername, ... AS seq
FROM dbmail_header h
LEFT JOIN dbmail_messages m ON h.physmessage_id=m.physmessage_id
LEFT JOIN dbmail_headername n ON h.headername_id=n.id
LEFT JOIN dbmail_headervalue v ON h.headervalue_id=v.id
WHERE m.mailbox_idnr = 170
AND m.message_idnr BETWEEN 5477613 AND 5479501
AND n.headername IN ('from','to',...)
ORDER BY message_idnr, seq

Sort (cost=6387.09..6387.62 rows=212 width=163)
Sort Key: m.message_idnr, (CASE WHEN ((n.headername)::text =
'from'::text) THEN 0 WHEN ((n.headername)::text = 'to'::text) THEN 1
WHEN ((n.headername)::text = 'cc'::text) THEN 2 WHEN
((n.headername)::text = 'bcc'::text) THEN 3 WHEN ((n.headername)::text
(...)
-> Nested Loop Left Join (cost=115.79..6378.90 rows=212 width=163)
-> Hash Join (cost=115.79..4857.12 rows=212 width=32)
Hash Cond: (h.headername_id = n.id)
-> Nested Loop (cost=54.82..4734.68 rows=15828 width=24)
-> Bitmap Heap Scan on dbmail_messages m
(cost=54.82..1520.85 rows=500 width=16)
Recheck Cond: (mailbox_idnr = 1851)
Filter: ((message_idnr >= 2779446) AND
(message_idnr <= 2834893))
-> Bitmap Index Scan on dbmail_messages_7
(cost=0.00..54.69 rows=1923 width=0)
Index Cond: (mailbox_idnr = 1851)
-> Index Only Scan using dbmail_header_pkey on
dbmail_header h (cost=0.00..6.04 rows=39 width=24)
Index Cond: (physmessage_id = m.physmessage_id)
-> Hash (cost=60.75..60.75 rows=18 width=24)
-> Seq Scan on dbmail_headername n
(cost=0.00..60.75 rows=18 width=24)
Filter: ((headername)::text = ANY
('{from,to,cc,bcc,subject,date,message-id,priority,x-priority,references,newsgroups,in-reply-to,content-type,reply-to,x-spam-flag,sender,reply-to,x-cron-env}'::text[]))
-> Index Scan using dbmail_headervalue_pkey on
dbmail_headervalue v (cost=0.00..7.12 rows=1 width=147)
Index Cond: (h.headervalue_id = id)

Further reading on Locking and Indexes
http://dev.mysql.com/doc/refman/5.6/en/innodb-locks-set.html
http://www.postgresql.org/docs/9.2/interactive/locking-indexes.html

Regards,
Alan

>
> On 24/11/2014 10:51, Daniel Schütze wrote:
>>
>> I’ve noticed in my slow query log there is a particular type of query
>> which is regularly showing up and I was wondering what was triggering it.
>>
>> The most recent example is this (but it’s being going on since I
>> turned the slow query log on in July:
>>
>> SELECT m.message_idnr, n.headername, v.headervalue, CASE WHEN
>> n.headername='from' THEN 0 WHEN n.headername='to' THEN 1 WHEN
>> n.headername='cc' THEN 2 WHEN n.headername='bcc' THEN 3 WHEN
>> n.headername='subject' THEN 4 WHEN n.headername='date' THEN 5 WHEN
>> n.headername='message-id' THEN 6 WHEN n.headername='priority' THEN 7
>> WHEN n.headername='x-priority' THEN 8 WHEN n.headername='references'
>> THEN 9 WHEN n.headername='newsgroups' THEN 10 WHEN
>> n.headername='in-reply-to' THEN 11 WHEN n.headername='content-type'
>> THEN 12 WHEN n.headername='reply-to' THEN 13 END AS seq FROM
>> dbmail_header h LEFT JOIN dbmail_messages m ON
>> h.physmessage_id=m.physmessage_id LEFT JOIN dbmail_headername n ON
>> h.headername_id=n.id LEFT JOIN dbmail_headervalue v ON
>> h.headervalue_id=v.id WHERE m.mailbox_idnr = 170 AND m.message_idnr
>> BETWEEN 5477613 AND 5479501 AND n.headername IN
>> ('from','to','cc','bcc','subject','date','message-id','priority','x-priority','references','newsgroups','in-reply-to','content-type','reply-to')
>> ORDER BY message_idnr, seq;
>>
>> Which slow reports as taking some 33 seconds
>>
>> # Time: 141124 10:32:05
>>
>> # User@Host: dbmail[dbmail] @ localhost []
>>
>> # Query_time: 33.363653 Lock_time: 0.000014 Rows_sent: 0
>> Rows_examined: 20214893
>>
>> I’m still using dbmail 3.1.15 so apologies if this is obsolete by the
>> current 3.2.1 release; but I’m wondering if this query/speed is
>> normal or a sign something is a miss.
>>
>>
>> Regards
>>
>>
>> Daniel Schütze
>>
>> ------------------------
>>
>> CWA International
>>
>> Balmoral House
>>
>> 9 John Street
>>
>> London
>> WC1N 2ES
>>
>> (t) + 44 (0)20 7242 8444
>>
>> (e) dms@cwa.uk.com
>>
>> (w) http://www.cwa.uk.com/
>>
>>
>>
>> _______________________________________________
>> DBmail mailing list
>> DBmail@dbmail.org
>> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
>
> --
> Persistent Objects Ltd
> 128 Lilleshall Road
> Morden SM4 6DR
>
> The Home of Lasting Solutions
>
> Mobile: 079 3030 5004
> Tel: 020 8544 5292
> Web: p-o.co.uk
> Skype: alan-hicks-london
> Personal bloghttps://plus.google.com/+AlanHicksLondon
> Company bloghttps://plus.google.com/+PoCoUkLondon/posts
> LinkedInhttps://uk.linkedin.com/in/alanhickslondon/
> GitHubhttps://github.com/alan-hicks
>
>
> _______________________________________________
> DBmail mailing list
> DBmail@dbmail.org
> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail

--
Persistent Objects Ltd
128 Lilleshall Road
Morden SM4 6DR

The Home of Lasting Solutions

Mobile: 079 3030 5004
Tel: 020 8544 5292
Web: p-o.co.uk
Skype: alan-hicks-london
Personal blog https://plus.google.com/+AlanHicksLondon
Company blog https://plus.google.com/+PoCoUkLondon/posts
LinkedIn https://uk.linkedin.com/in/alanhickslondon/
GitHub https://github.com/alan-hicks

Finally able to reproduce this one. There is a use case where the
message_idnr between scans a sufficiently large portion of the
dbmail_messages table, for example an inbox that is rarely cleared. As
there is always a table scan, if that table is not in memory, then there
is a lot of disc access.

In this use case the query first showed up as > 30 seconds, then
subsequent query runs about 5-6 seconds showing that the table was
available in memory (I previously had sub second response times). After
a reindex this runs for > 60 seconds then subsequent queries about 11-12
seconds. This is indicative of data joining multiple tables spread
widely across a physical disk incurring additional disk head seek time
made worse by the reindex putting the data further away on the physical
disk.

Tablespaces may be an answer as they allow related tables to be
physically close. For this query the four related tables dbmail_header,
dbmail_messages, dbmail_headername and dbmail_headervalue would be good
candidates, though perhaps a better solution might be for two
tablespaces with one for the large data tables example dbmail_authlog,
dbmail_envelope, dbmail_mimeparts and all the rest on another.

Alas I don't have spare kit on hand to be able to offer to evaluate.

http://www.postgresql.org/docs/9.3/static/manage-ag-tablespaces.html
http://dev.mysql.com/doc/refman/5.6/en/innodb-tablespace.html

Regards,
Alan

On 28/11/2014 13:53, Alan Hicks wrote:
>
> On 24/11/2014 15:50, Alan Hicks wrote:
>> Although I don't have an answer, I can confirm the slow query happens
>> on 3.2.1, though for me at least unrepeatable, subsequent runs of the
>> query are returned sub second.
>>
>> The query planner shows nothing unusual, also table stats for each of
>> the query tables shows few table scans. Fortunately it hasn't
>> affected me enough to investigate further.
>>
>> I haven't tried header_cache_readonly which may help.
>>
>> Currently running PostgreSQL 9.2, previously saw more on MySQL 5.1
>> though no stats to compare fairly.
>>
>> Regards,
>> Alan
>
> This explanation may help to clarify why it might be useful to use
> header_cache_readonly.
>
> If delivery of a new message adds to the headername table and due to
> any of complexity, size or server load takes longer to commit, the
> index may be locked on the headername table until the transaction is
> complete.
>
> Both MySQL and PostgreSQL offer excellent Multiversion Concurrency
> Control (MVCC), nevertheless the query plan shows these are evaluated
> as Hash indexes whose locks are held for the duration of the nested
> loop. Lock contention on the index may be the cause of the slow query.
>
> Using header_cache_readonly would not add any new records to the
> headername table and so should not need any locks.
>
> It might be useful to get feedback to see if anyone using
> header_cache_readonly still sees those slow queries.
>
> SELECT m.message_idnr, n.headername, ... AS seq
> FROM dbmail_header h
> LEFT JOIN dbmail_messages m ON h.physmessage_id=m.physmessage_id
> LEFT JOIN dbmail_headername n ON h.headername_id=n.id
> LEFT JOIN dbmail_headervalue v ON h.headervalue_id=v.id
> WHERE m.mailbox_idnr = 170
> AND m.message_idnr BETWEEN 5477613 AND 5479501
> AND n.headername IN ('from','to',...)
> ORDER BY message_idnr, seq
>
> Sort (cost=6387.09..6387.62 rows=212 width=163)
> Sort Key: m.message_idnr, (CASE WHEN ((n.headername)::text =
> 'from'::text) THEN 0 WHEN ((n.headername)::text = 'to'::text) THEN 1
> WHEN ((n.headername)::text = 'cc'::text) THEN 2 WHEN
> ((n.headername)::text = 'bcc'::text) THEN 3 WHEN
> ((n.headername)::text (...)
> -> Nested Loop Left Join (cost=115.79..6378.90 rows=212 width=163)
> -> Hash Join (cost=115.79..4857.12 rows=212 width=32)
> Hash Cond: (h.headername_id = n.id)
> -> Nested Loop (cost=54.82..4734.68 rows=15828 width=24)
> -> Bitmap Heap Scan on dbmail_messages m
> (cost=54.82..1520.85 rows=500 width=16)
> Recheck Cond: (mailbox_idnr = 1851)
> Filter: ((message_idnr >= 2779446) AND
> (message_idnr <= 2834893))
> -> Bitmap Index Scan on dbmail_messages_7
> (cost=0.00..54.69 rows=1923 width=0)
> Index Cond: (mailbox_idnr = 1851)
> -> Index Only Scan using dbmail_header_pkey on
> dbmail_header h (cost=0.00..6.04 rows=39 width=24)
> Index Cond: (physmessage_id = m.physmessage_id)
> -> Hash (cost=60.75..60.75 rows=18 width=24)
> -> Seq Scan on dbmail_headername n
> (cost=0.00..60.75 rows=18 width=24)
> Filter: ((headername)::text = ANY
> ('{from,to,cc,bcc,subject,date,message-id,priority,x-priority,references,newsgroups,in-reply-to,content-type,reply-to,x-spam-flag,sender,reply-to,x-cron-env}'::text[]))
> -> Index Scan using dbmail_headervalue_pkey on
> dbmail_headervalue v (cost=0.00..7.12 rows=1 width=147)
> Index Cond: (h.headervalue_id = id)
>
> Further reading on Locking and Indexes
> http://dev.mysql.com/doc/refman/5.6/en/innodb-locks-set.html
> http://www.postgresql.org/docs/9.2/interactive/locking-indexes.html
>
> Regards,
> Alan
>
>>
>> On 24/11/2014 10:51, Daniel Schütze wrote:
>>>
>>> I’ve noticed in my slow query log there is a particular type of
>>> query which is regularly showing up and I was wondering what was
>>> triggering it.
>>>
>>> The most recent example is this (but it’s being going on since I
>>> turned the slow query log on in July:
>>>
>>> SELECT m.message_idnr, n.headername, v.headervalue, CASE WHEN
>>> n.headername='from' THEN 0 WHEN n.headername='to' THEN 1 WHEN
>>> n.headername='cc' THEN 2 WHEN n.headername='bcc' THEN 3 WHEN
>>> n.headername='subject' THEN 4 WHEN n.headername='date' THEN 5 WHEN
>>> n.headername='message-id' THEN 6 WHEN n.headername='priority' THEN 7
>>> WHEN n.headername='x-priority' THEN 8 WHEN n.headername='references'
>>> THEN 9 WHEN n.headername='newsgroups' THEN 10 WHEN
>>> n.headername='in-reply-to' THEN 11 WHEN n.headername='content-type'
>>> THEN 12 WHEN n.headername='reply-to' THEN 13 END AS seq FROM
>>> dbmail_header h LEFT JOIN dbmail_messages m ON
>>> h.physmessage_id=m.physmessage_id LEFT JOIN dbmail_headername n ON
>>> h.headername_id=n.id LEFT JOIN dbmail_headervalue v ON
>>> h.headervalue_id=v.id WHERE m.mailbox_idnr = 170 AND m.message_idnr
>>> BETWEEN 5477613 AND 5479501 AND n.headername IN
>>> ('from','to','cc','bcc','subject','date','message-id','priority','x-priority','references','newsgroups','in-reply-to','content-type','reply-to')
>>> ORDER BY message_idnr, seq;
>>>
>>> Which slow reports as taking some 33 seconds
>>>
>>> # Time: 141124 10:32:05
>>>
>>> # User@Host: dbmail[dbmail] @ localhost []
>>>
>>> # Query_time: 33.363653 Lock_time: 0.000014 Rows_sent: 0
>>> Rows_examined: 20214893
>>>
>>> I’m still using dbmail 3.1.15 so apologies if this is obsolete by
>>> the current 3.2.1 release; but I’m wondering if this query/speed is
>>> normal or a sign something is a miss.
>>>
>>>
>>> Regards
>>>
>>>
>>> Daniel Schütze
>>>
>>> ------------------------
>>>
>>> CWA International
>>>
>>> Balmoral House
>>>
>>> 9 John Street
>>>
>>> London
>>> WC1N 2ES
>>>
>>> (t) + 44 (0)20 7242 8444
>>>
>>> (e) dms@cwa.uk.com
>>>
>>> (w) http://www.cwa.uk.com/
>>>
>>>
>>>
>>> _______________________________________________
>>> DBmail mailing list
>>> DBmail@dbmail.org
>>> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
>>
>> --
>> Persistent Objects Ltd
>> 128 Lilleshall Road
>> Morden SM4 6DR
>>
>> The Home of Lasting Solutions
>>
>> Mobile: 079 3030 5004
>> Tel: 020 8544 5292
>> Web: p-o.co.uk
>> Skype: alan-hicks-london
>> Personal bloghttps://plus.google.com/+AlanHicksLondon
>> Company bloghttps://plus.google.com/+PoCoUkLondon/posts
>> LinkedInhttps://uk.linkedin.com/in/alanhickslondon/
>> GitHubhttps://github.com/alan-hicks
>>
>>
>> _______________________________________________
>> DBmail mailing list
>> DBmail@dbmail.org
>> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail
>
> --
> Persistent Objects Ltd
> 128 Lilleshall Road
> Morden SM4 6DR
>
> The Home of Lasting Solutions
>
> Mobile: 079 3030 5004
> Tel: 020 8544 5292
> Web: p-o.co.uk
> Skype: alan-hicks-london
> Personal bloghttps://plus.google.com/+AlanHicksLondon
> Company bloghttps://plus.google.com/+PoCoUkLondon/posts
> LinkedInhttps://uk.linkedin.com/in/alanhickslondon/
> GitHubhttps://github.com/alan-hicks
>
>
> _______________________________________________
> DBmail mailing list
> DBmail@dbmail.org
> http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail

--
Persistent Objects Ltd
128 Lilleshall Road
Morden SM4 6DR

The Home of Lasting Solutions

Mobile: 079 3030 5004
Tel: 020 8544 5292
Web: p-o.co.uk
Skype: alan-hicks-london
Personal blog https://plus.google.com/+AlanHicksLondon
Company blog https://plus.google.com/+PoCoUkLondon/posts
LinkedIn https://uk.linkedin.com/in/alanhickslondon/
GitHub https://github.com/alan-hicks