Hi, using roundcube 0.4beta I see very slow performance when double clicking on an email before it finally displays the email (45 secs) - this is in a large inbox of some 33,000 messages (with threading enabled).
The inbox itself displays quickly (1-2 secs), emails displayed in the preview window display instantly, it's simply double clicking an email to open it which is extremely slow (regardless of whether the preview window is displayed).
The issue appears to be threading related - if I disable threading on the inbox then there is no delay on double clicking, only if I ask for the inbox to be threaded is there a delay opening an email
This seems to be confirmed by the log files from the mail server (Dovecot) which shows the imap requests on opening the message as follows:
cp01 CAPABILITY sel1 SELECT "INBOX" FH12 UID FETCH 52231 (UID RFC822.SIZE FLAGS INTERNALDATE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (DATE FROM TO SUBJECT REPLY-TO IN-REPLY-TO CC BCC CONTENT-TRANSFER-ENCODING CONTENT-TYPE MESSAGE-ID REFERE NCES DISPOSITION-NOTIFICATION-TO X-PRIORITY X-DRAFT-INFO)]) thrd1 THREAD REFS US-ASCII ALL s SORT (ARRIVAL) US-ASCII ALL fuid FETCH 33027 (UID) fuid FETCH 32991 (UID) fuid FETCH 33006 (UID) fuid FETCH 6738 (UID) lsb LSUB "" "*" ftch0 UID FETCH 52231 (BODY.PEEK[1]) I LOGOUT
And in particular the corresponding "thrd1" response is a huge list of all the threads in the inbox. Top shows that there is a ton of load due to the php task. However, although I haven't yet looked at the code, I really don't see why we need a list of all the message threads when opening just an individual message?
Does anyone have a suggestion as to a possible fix?
Thanks
Ed W _______________________________________________ List info: http://lists.roundcube.net/users/
W dniu 2010-07-19 17:44, Ed W pisze:
The issue appears to be threading related - if I disable threading on the inbox then there is no delay on double clicking, only if I ask for the inbox to be threaded is there a delay opening an email
This seems to be confirmed by the log files from the mail server (Dovecot) which shows the imap requests on opening the message as follows:
thrd1 THREAD REFS US-ASCII ALL s SORT (ARRIVAL) US-ASCII ALL fuid FETCH 33027 (UID) fuid FETCH 32991 (UID) fuid FETCH 33006 (UID) fuid FETCH 6738 (UID)
We need this info to build page navigation (the arrows with links to first/previous/next/last message) and we need to call THREAD here, because we want to have the same messages order like in messages list. What IMAP server (and version) are you using? Which command (THREAD or SORT) takes longer? If SORT, you could try to change sorting to Date or None.
Possible solution would be to update navigation links in separate request after the page with a message is loaded.
Hi
On 25/07/2010 08:58, A.L.E.C wrote:
W dniu 2010-07-19 17:44, Ed W pisze:
The issue appears to be threading related - if I disable threading on the inbox then there is no delay on double clicking, only if I ask for the inbox to be threaded is there a delay opening an email
This seems to be confirmed by the log files from the mail server (Dovecot) which shows the imap requests on opening the message as follows:
thrd1 THREAD REFS US-ASCII ALL s SORT (ARRIVAL) US-ASCII ALL fuid FETCH 33027 (UID) fuid FETCH 32991 (UID) fuid FETCH 33006 (UID) fuid FETCH 6738 (UID)
We need this info to build page navigation (the arrows with links to first/previous/next/last message) and we need to call THREAD here, because we want to have the same messages order like in messages list. What IMAP server (and version) are you using? Which command (THREAD or SORT) takes longer? If SORT, you could try to change sorting to Date or None.
Possible solution would be to update navigation links in separate request after the page with a message is loaded.
Thanks for responding. The server is Dovecot (1.2.12)
What I think I didn't state clearly is that the IMAP stuff runs instantly and with no load on the server. However, then Roundcube code locks up for 45 secs with 100% CPU allocated to PHP before the page displays in the browser.
(For reference I have mysql, dovecot and php running on different (virtual) servers so it's quite easy to see where the load is. Further I use fastcgi with nginx so my php process is external and observable)
The log file showing the results of the imap commands above total 406KB, so some quick maths shows that we are getting back around the 33,000 results (that I mentioned matches the number of messages in my inbox) I haven't yet dug into the code, but it would seem very likely that something in the roundcube is trying to parse all of those results and choking?
I guess the question could be better rephrased as whether there is a more efficient way to retrieve (or at least parse) this information? Just glancing at the html produced it's not really clear why we would need all the data anyway? The navigation links don't appear to need this info? (Could you point to the code path perhaps so I can look closer?) The HTML *appears* to do a server side call to find the next/prev messages (so it seems like we retrieve this info only to print "message X of Y"?)
Grateful for any insights? To be clear I think this should be
reproducible for anyone else with a few thousand messages in a mailbox?
I don't think it's the imap server which is limiting performance, but
the PHP side?
Thanks
Ed W
List info: http://lists.roundcube.net/users/
On 26.07.2010 10:34, Ed W wrote:
I guess the question could be better rephrased as whether there is a more efficient way to retrieve (or at least parse) this information? Just glancing at the html produced it's not really clear why we would need all the data anyway? The navigation links don't appear to need this info? (Could you point to the code path perhaps so I can look closer?) The HTML *appears* to do a server side call to find the next/prev messages (so it seems like we retrieve this info only to print "message X of Y"?)
No. You didn't tell which command is slow, SORT or THREAD? As you'll see in the log, the same commands are executed for mailbox listing action. The question is why they are slow in 'show' action. You've got timestamps in debug log, where's the delay?
See steps/mail/show.inc, lines 111-121
Grateful for any insights? To be clear I think this should be reproducible for anyone else with a few thousand messages in a mailbox? I don't think it's the imap server which is limiting performance, but the PHP side?
I have no problems with 10.000 messages in a folder. Dovecot 1.1.
Hi
No. You didn't tell which command is slow, SORT or THREAD? As you'll see in the log, the same commands are executed for mailbox listing action. The question is why they are slow in 'show' action. You've got timestamps in debug log, where's the delay?
See steps/mail/show.inc, lines 111-121
It's possible we are talking cross purposes? The IMAP command returns instantly, no delay. It's something in the PHP code which is slow and chewing CPU. The debug log I was looking at was the Dovecot logs, however, I just noticed in a response to someone else it was mentioned that there might be a roundcube side log? I will try and enable this and also check the lines you mentioned and try to narrow down the slowness - thanks
I have no problems with 10.000 messages in a folder. Dovecot 1.1.
Hmm, interesting, I have another folder with 10K ish messages and this one has more like a 5-10 sec delay opening each message (when threading enabled - and only then). Seems like the slowdown is near linear, but on a faster machine than mine the delay might not be that noticable?
Note the delay ONLY occurs when threading enabled on the main message view
Cheers
Ed W
List info: http://lists.roundcube.net/users/
On 26.07.2010 15:27, Ed W wrote:
It's possible we are talking cross purposes? The IMAP command returns instantly, no delay. It's something in the PHP code which is slow and chewing CPU. The debug log I was looking at was the Dovecot logs, however, I just noticed in a response to someone else it was mentioned that there might be a roundcube side log? I will try and enable this and also check the lines you mentioned and try to narrow down the slowness - thanks
Enable imap_debug option and check logs/imap file.
Note the delay ONLY occurs when threading enabled on the main message view
So, slow is THREAD or its result parsing.
On 26/07/2010 14:50, A.L.E.C wrote:
Note the delay ONLY occurs when threading enabled on the main message view
So, slow is THREAD or its result parsing.
Yes, confirmed in the IMAP logs.
So my reproducible behaviour is to take vanilla RC beta, connect to a dovecot instance with an inbox containing 33K messages, click the icon top left corner of the message list and choose "Thread" from the view options, very short pause while the list redraws, then finally double click on some small message
The imap logs from that point show the imap server very quickly (sub 1 second) return what appears to be the thread info for every message, then a sorted list of the same (sort states completed in 0.102 seconds)
There is then a 45 sec (ish) delay before the connection resumes and grabs the message itself and the browser suddenly wakes up and displays the message. During that period the PHP process is wedged at 100% cpu.
Then I go back into the message list, disable threading and this time
double click on the same message. Now the message displays instantly.
Comparing the imap_log I see what appears the exact same set of commands
except for the lack of the threads list.
It would therefore seem extremely likely that it's the parsing of the imap THREAD results which is causing the delay and high CPU?
Interesting that you don't see this? Does your 10K message folder contain any threaded messages? Do you have threading enabled in your message list view?
Thanks for any thoughts
Ed W _______________________________________________ List info: http://lists.roundcube.net/users/
On 27.07.2010 14:48, Ed W wrote:
So, slow is THREAD or its result parsing.
Yes, confirmed in the IMAP logs.
Yes what? The command or parsing?
So my reproducible behaviour is to take vanilla RC beta, connect to a
Better would be to use svn-trunk
dovecot instance with an inbox containing 33K messages, click the icon top left corner of the message list and choose "Thread" from the view options, very short pause while the list redraws, then finally double click on some small message
The imap logs from that point show the imap server very quickly (sub 1 second) return what appears to be the thread info for every message, then a sorted list of the same (sort states completed in 0.102 seconds) There is then a 45 sec (ish) delay before the connection resumes and
45 sec delay after SORT response? Please attach Roundcube's imap_debug log (with timestamps).
grabs the message itself and the browser suddenly wakes up and displays the message. During that period the PHP process is wedged at 100% cpu.
Then I go back into the message list, disable threading and this time double click on the same message. Now the message displays instantly. Comparing the imap_log I see what appears the exact same set of commands except for the lack of the threads list.
It would therefore seem extremely likely that it's the parsing of the imap THREAD results which is causing the delay and high CPU?
I cannot imagine a 45 sec delay just for PHP code. Please, attach complete THREAD command response.
Interesting that you don't see this? Does your 10K message folder contain any threaded messages? Do you have threading enabled in your message list view?
Yes, I have. Still I have no idea what it could be. Maybe it's something with parallel connections handling in dovecot? Check login_* options in dovecot.conf. When you open a message there are two requests, one for 'show' action and one for 'getunread'.
On 27/07/2010 14:09, A.L.E.C wrote:
On 27.07.2010 14:48, Ed W wrote:
So, slow is THREAD or its result parsing.
Yes, confirmed in the IMAP logs.
Yes what? The command or parsing?
Just to be overtly clear: it's the PHP command parsing where all the time is spent. I see zero delay, zero load, zero signs of problems with the IMAP server or MYSQL server. The IMAP server currently runs a small ISP, yet is actually under very low load.
If it's not inappropriate I will send the detailed IMAP logs to you offlist since they are quite large and likely uninteresting to most readers?
Thanks
Ed W _______________________________________________ List info: http://lists.roundcube.net/users/
On 27.07.2010 15:16, Ed W wrote:
If it's not inappropriate I will send the detailed IMAP logs to you offlist since they are quite large and likely uninteresting to most readers?
ok
On 27.07.2010 15:09, A.L.E.C wrote:
dovecot.conf. When you open a message there are two requests, one for 'show' action and one for 'getunread'.
Forget, this is not true. getunread is called on page load, so after 'show'.
On 27.07.2010 15:16, Ed W wrote:
If it's not inappropriate I will send the detailed IMAP logs to you offlist since they are quite large and likely uninteresting to most readers?
Thanks to the sent log I've fixed the issue. Get me to know about the results.
http://trac.roundcube.net/changeset/3832
On 28/07/2010 09:53, A.L.E.C wrote:
On 27.07.2010 15:16, Ed W wrote:
If it's not inappropriate I will send the detailed IMAP logs to you offlist since they are quite large and likely uninteresting to most readers?
Thanks to the sent log I've fixed the issue. Get me to know about the results.
Oopps, missed this email from you.
Many thanks for looking into this. Will evaluate ASAP
Thanks!
Ed W _______________________________________________ List info: http://lists.roundcube.net/users/
On 28/07/2010 09:53, A.L.E.C wrote:
On 27.07.2010 15:16, Ed W wrote:
If it's not inappropriate I will send the detailed IMAP logs to you offlist since they are quite large and likely uninteresting to most readers?
Thanks to the sent log I've fixed the issue. Get me to know about the results.
With this change it's *substantially* faster at around 3.1 secs to load the message view window, which compares similarly with around 3.8 secs to load the inbox list.
That said, if I turn off threading then these times drop to circa 1 second or so, so threading is still taking a massive amount of CPU?
Just looking at the massive amount of data coming back from the imap server I can't help wondering if we couldn't request less data?
Thanks for looking at this
Ed W _______________________________________________ List info: http://lists.roundcube.net/users/
Ed W wrote:
That said, if I turn off threading then these times drop to circa 1 second or so, so threading is still taking a massive amount of CPU?
and memory
Just looking at the massive amount of data coming back from the imap server I can't help wondering if we couldn't request less data?
I don't think so. You could try to change sorting to Date or None. In this case SORT command will be skipped.
In the whole THREAD response parsing operation most time-consuming part is the rcube_imap_generic::parseThread() function, but I didn't found a way to make it faster.
On 28/07/2010 19:30, A.L.E.C wrote:
In the whole THREAD response parsing operation most time-consuming part is the rcube_imap_generic::parseThread() function, but I didn't found a way to make it faster.
I haven't investigated the imap thread options, but is it possible to return only a subset of the data?
Cheers
Ed W
List info: http://lists.roundcube.net/users/
-
A.L.E.C -
Ed W