If you want a faster Kolab, read this.

Brady, Mike mike.brady at devnull.net.nz
Wed Sep 9 03:13:05 CEST 2015 

 

On 2015-09-09 11:56, Paul Bronson wrote: 

> Hi guys, 
> 
> For those of you who are not CC'ed on my bug (https://issues.kolab.org/show_bug.cgi?id=5219 [1]) here's what I've came up with regarding this plugin slow down: 
> 
> Okay, so I tried putting the preview pane down.. Opening an actual message I got the following for a SINGLE message: 
> 
> Sep 8 19:38:58 es1 imap[25729]: starttls: TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication 
> Sep 8 19:38:58 es1 imap[25729]: login: localhost [::1] jdoe at domain.info PLAIN+TLS User logged in SESSIONID=<es1.domain.com-25729-1441755538-1-17808047228044173595> 
> Sep 8 19:38:59 es1 imap[25729]: USAGE jdoe at domain.info user: 0.017997 sys: 0.017997 
> Sep 8 19:39:00 es1 imap[25714]: starttls: TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication 
> Sep 8 19:39:00 es1 imap[25760]: starttls: TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication 
> Sep 8 19:39:00 es1 imap[25714]: login: localhost [::1] jdoe at domain.info PLAIN+TLS User logged in SESSIONID=<es1.domain.com-25714-1441755540-1-1643183847780605755> 
> Sep 8 19:39:00 es1 imap[25714]: USAGE jdoe at domain.info user: 0.003999 sys: 0.003000 
> Sep 8 19:39:00 es1 imap[25760]: login: localhost [::1] jdoe at domain.info PLAIN+TLS User logged in SESSIONID=<es1.domain.com-25760-1441755540-1-3316720433793663553> 
> Sep 8 19:39:00 es1 imap[25760]: USAGE jdoe at domain.info user: 0.008998 sys: 0.005000 
> 
> Back to original problem of just going through messages Now, just turning on SQL debug, here's all the queries running just simply selecting a message to be shown in the preview pane: 
> 
> [08-Sep-2015 19:46:15,000000 -0400]: <840cvre1> [1] SELECT `vars`, `ip`, `changed`, now() AS ts FROM `session` WHERE `sess_id` = '840cvre1hecdhc9qnkgkfk73t0'; 
> [08-Sep-2015 19:46:15,000000 -0400]: <840cvre1> [2] SELECT * FROM `users` WHERE `user_id` = '4'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [3] SELECT `folder_id`, `synclock`, `ctag`, `changed`, `objectcount` FROM `kolab_folders` WHERE `resource` = 'imap://tperson%40domain.info@localhost/Configuration'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [4] SELECT COUNT(*) AS `numrows` FROM `kolab_cache_configuration` WHERE `folder_id` = '46'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [5] SELECT * FROM `kolab_cache_configuration` WHERE `folder_id` = '46' AND `type` = 'relation' AND `tags` LIKE '% category:tag %' LIMIT 100; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [6] SELECT `flags`, `data` FROM `cache_messages` WHERE `user_id` = '4' AND `mailbox` = 'INBOX' AND `uid` = '1'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [7] SELECT * FROM `kolab_cache_configuration` WHERE `folder_id` = '46' AND `type` = 'relation' AND `tags` LIKE '% category:generic %' AND `words` LIKE '% <0d41a56b9d73f705c587eda81c950ae4 at domain.com> %' LIMIT 100; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [8] SELECT `folder_id`, `synclock`, `ctag`, `changed`, `objectcount` FROM `kolab_folders` WHERE `resource` = 'imap://tperson%40domain.info@localhost/Contacts'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [9] SELECT COUNT(*) AS `numrows` FROM `kolab_cache_contact` WHERE `folder_id` = '47'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [10] SELECT COUNT(*) AS `numrows` FROM `kolab_cache_contact` WHERE `folder_id` = '47' AND `words` LIKE '% jdoe at domain.com %'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [11] SELECT * FROM `kolab_cache_contact` WHERE `folder_id` = '47' AND `words` LIKE '% jdoe at domain.com %'; 
> [08-Sep-2015 19:46:16,000000 -0400]: <840cvre1> [12] SELECT * FROM `kolab_cache_configuration` WHERE `folder_id` = '46' AND `type` = 'relation' AND `tags` LIKE '% category:tag %' LIMIT 100; 
> [08-Sep-2015 19:46:17,000000 -0400]: <840cvre1> [13] SELECT `vars`, `ip`, `changed`, now() AS ts FROM `session` WHERE `sess_id` = '840cvre1hecdhc9qnkgkfk73t0'; 
> [08-Sep-2015 19:46:19,000000 -0400]: <840cvre1> [1] SELECT `vars`, `ip`, `changed`, now() AS ts FROM `session` WHERE `sess_id` = '840cvre1hecdhc9qnkgkfk73t0'; 
> [08-Sep-2015 19:46:19,000000 -0400]: <840cvre1> [2] SELECT * FROM `users` WHERE `user_id` = '4'; 
> [08-Sep-2015 19:46:19,000000 -0400]: <840cvre1> [3] SELECT `data`, `valid` FROM `cache_index` WHERE `user_id` = '4' AND `mailbox` = 'INBOX'; 
> [08-Sep-2015 19:46:21,000000 -0400]: <840cvre1> [4] SELECT `vars`, `ip`, `changed`, now() AS ts FROM `session` WHERE `sess_id` = '840cvre1hecdhc9qnkgkfk73t0'; 
> 
> There's a lot of cache tables it looks like... But why is IMAP being queried so heavily? And yes, there is stuff in these tables. 
> 
> On Tue, Sep 8, 2015 at 5:51 PM, <signaldeveloper at gmail.com> wrote:
> 
>> Hi Christian,
>> 
>> I basically installed memcache and just changed 'DB' to 'memcache' in the kolab config. This seemed to give me a small boost but I think I'll feel the better boost when I start piling on users.
>> 
>> I for some reason couldn't get memcache to work with "session_storage" though, it just gives me a white screen. Let me know if you need more in depth directions!
>> 
>> If anyone has varnish setup please let me know if love to know how to get that working with roundcube!
>> 
>> - Paul
>> 
>>> On Sep 8, 2015, at 12:09 PM, Christian Hügel <christian.huegel at stonebyte.de> wrote:
>>> 
>>> OK, i got you right now :) You mentioned a performance boost using
>>> memcached. Can you point me a documentation enabling this?
>>> Thanks
>>> 
>>>> Am 08.09.2015 um 17:54 schrieb signaldeveloper at gmail.com:
>>>> Christian,
>>>> 
>>>> Obviously. This is meant more as a bug test case not as a fix.
>>>> 
>>>> 
>>>> 
>>>>> On Sep 8, 2015, at 11:46 AM, Christian Hügel <christian.huegel at stonebyte.de> wrote:
>>>>> 
>>>>> I also have a major performance problem although with kolab 3.2 but I do
>>>>> not see the point in deactivating those plugins; it would´ t be a kolab
>>>>> server anymore instead just an ordinary imap server. So this workaround
>>>>> is a "no go"
>>>>> 
>>>>> Cheers,
>>>>> 
>>>>> Christian
>>>>> 
>>>>>> Am 07.09.2015 um 20:55 schrieb Paul Bronson:
>>>>>> Hi guys, (happy labor day!)
>>>>>> 
>>>>>> As you've probably seen me asking a thousand questions about slowness
>>>>>> for my brand new kolab 3.4, here's what my few weeks of research has
>>>>>> come up with... And hopefully this will work for all of you as well, or
>>>>>> something you can try and replicate on your end:
>>>>>> 
>>>>>> A few kolab plugins are initiating an imap connection every time the
>>>>>> user simply tries to read a message. Those plugins are:
>>>>>> 
>>>>>> kolab_addressbook
>>>>>> kolab_notes
>>>>>> kolab_tags
>>>>>> tasklist
>>>>>> 
>>>>>> If you disable ALL (not one) of these plugins, watch how magically fast
>>>>>> clicking on a message is. You will also notice logs in your
>>>>>> var/log/maillog such as this disappear:
>>>>>> 
>>>>>> 
>>>>>> Sep 7 13:59:55 es1 imap[18657]: USAGE tperson at domain.info
>>>>>> <mailto:tperson at domain.info>user: 0.004000 sys: 0.007999
>>>>>> 
>>>>>> Sep 7 14:00:55 es1 imap[18657]: login: localhost [::1] tperson at domain.info <mailto:tperson at domain.info> PLAIN User logged in SESSIONID=<es1.domain.com-18657-1441648854-1-17261199637593060143>
>>>>>> 
>>>>>> These above log entries will however happen when you go to different
>>>>>> folders, but simply just single clicking a message to see it on the
>>>>>> preview pane will no longer log the entry.
>>>>>> 
>>>>>> 
>>>>>> I have also seen a HUGE improvement from memcache as well. (now that
>>>>>> instead of opening a new connection, it can now actually check against
>>>>>> memcache for a cache'd version) I also went to vast lands to try to make
>>>>>> cyrus faster thinking that was the problem, but I think this was the key!
>>>>>> 
>>>>>> 
>>>>>> I've logged a bug for this:
>>>>>> 
>>>>>> https://issues.kolab.org/show_bug.cgi?id=5219 [1]
>>>>>> 
>>>>>> 
>>>>>> Hopefully this will be an easy fix for the team!
>>>>>> 
>>>>>> 
>>>>>> 
>> I do not see that level of login activity. 
>> 
>> If I select an email that I have not previously selected within the cache TTL then I see two logins. If I select an email within the cache TTL then I see one login. 
>> 
>> Doing a data capture of the latter situation I get: 
>> 
>> [root at kolab04 etc]# tshark -i lo port 143
>> 59.229818 ::1 -> ::1 TCP 94 57268 > imap [SYN] Seq=0 Win=65476 Len=0 MSS=65476 SACK_PERM=1 TSval=1846400895 TSecr=0 WS=128
>> 59.229856 ::1 -> ::1 TCP 94 imap > 57268 [SYN, ACK] Seq=0 Ack=1 Win=65464 Len=0 MSS=65476 SACK_PERM=1 TSval=1846400895 TSecr=1846400895 WS=128
>> 59.229878 ::1 -> ::1 TCP 86 57268 > imap [ACK] Seq=1 Ack=1 Win=65536 Len=0 TSval=1846400895 TSecr=1846400895
>> 59.230788 ::1 -> ::1 IMAP 259 Response: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS AUTH=LOGIN AUTH=PLAIN SASL-IR] kolab04.devnull.net.nz Cyrus IMAP git2.5+0-Kolab-2.5-108.1.el6.kolab_3.4 server ready
>> 59.230820 ::1 -> ::1 TCP 86 57268 > imap [ACK] Seq=1 Ack=174 Win=66560 Len=0 TSval=1846400896 TSecr=1846400896
>> 59.231018 ::1 -> ::1 IMAP 165 Request: A0001 AUTHENTICATE PLAIN AG1pa2UuYnJhZHlAZGV2bnVsbC5uZXQubnoASnVtYm8tLTc0NyE=
>> 59.231034 ::1 -> ::1 TCP 86 imap > 57268 [ACK] Seq=174 Ack=80 Win=65536 Len=0 TSval=1846400896 TSecr=1846400896
>> 59.256049 ::1 -> ::1 IMAP 760 Response: A0001 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE URLAUTH URLAUTH=BINARY X-NETSCAPE LOGINDISABLED COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE] Success (no protection) SESSIONID=<kolab04.devnull.net.nz-7682-1441704301-1-10394088694658571917>
>> 59.257515 ::1 -> ::1 IMAP 114 Request: A0002 SELECT Configuration
>> 59.258149 ::1 -> ::1 IMAP 406 Response: * 0 EXISTS
>> 59.297563 ::1 -> ::1 TCP 86 57268 > imap [ACK] Seq=108 Ack=1168 Win=69248 Len=0 TSval=1846400963 TSecr=1846400923
>> 59.448120 ::1 -> ::1 IMAP 100 Request: A0003 LOGOUT
>> 59.448412 ::1 -> ::1 IMAP 129 Response: * BYE LOGOUT received
>> 59.448438 ::1 -> ::1 TCP 86 57268 > imap [ACK] Seq=122 Ack=1211 Win=69248 Len=0 TSval=1846401114 TSecr=1846401113
>> 59.448501 ::1 -> ::1 TCP 86 imap > 57268 [FIN, ACK] Seq=1211 Ack=122 Win=65536 Len=0 TSval=1846401114 TSecr=1846401114
>> 59.448556 ::1 -> ::1 TCP 86 57268 > imap [FIN, ACK] Seq=122 Ack=1212 Win=69248 Len=0 TSval=1846401114 TSecr=1846401114
>> 59.448568 ::1 -> ::1 TCP 86 imap > 57268 [ACK] Seq=1212 Ack=123 Win=65536 Len=0 TSval=1846401114 TSecr=1846401114
>> 
>> I see the "SELECT Configuration" for every email selected. I think that the Configuration folder is where tags are kept? So I am assuming that this is a check for tags for every selection? Should this be cached?
>> 
>> Even with the level of logins you are seeing, which I agree with you doesn't seem right, I would not expect to see the level of poor performance that you have indicated. In a previous thread I think that you said 5 seconds for an email? I think that you may well have other non cache issues as well.
>> 
>> Have you also looked at taking measures to speed up the IMAP connections. Two that have made a difference for me are adding "$config['imap_auth_type'] = 'PLAIN';" to /etc/roundcube/config.inc.php and not running TLS for localhost IMAP connections.
>> 
>> Regards
>> 
>> Mike

 

Links:
------
[1] https://issues.kolab.org/show_bug.cgi?id=5219
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kolab.org/pipermail/users/attachments/20150909/8fe82539/attachment-0001.html>

More information about the users mailing list