[imp] Imp search timeout
Simon Wilson
simon at simonandkate.net
Sun Feb 2 10:11:02 UTC 2020
>>>> I have a newly installed setup with Horde 5.2.21, working really
>>>> well, on CentOS8 with PHP7.4 from Remi. So much faster than the
>>>> old VM (CentOS6 with PHP5.6)!
>>>>
>>>> Anyway, only one issue so far - doing Imp Advanced Searches with
>>>> a broad search (e.g. Entire Message, all mailboxes, 4 letter
>>>> string) I am getting timeouts (backend is off-server to a local
>>>> Cyrus IMAP server). A narrower search works fine, so something is
>>>> timing out. These searches would work OK on the old server.
>>>
>>> Would they be hitting the same cyrus server, and also not running
>>> on the same host?
>>>
>>>> Horde logs:
>>>> 2020-01-22T18:57:10+10:00 WARN: HORDE [imp] [search] Error when
>>>> communicating with the mail server. [pid 4722 on line 730 of
>>>> "/var/www/horde/imp/lib/Imap.php"]
>>>>
>>>> I notice that in backends.php there is a timeout option
>>>> available, but the documentation indicates that this only applies
>>>> to the SMTP option. True enough, having a guess and setting
>>>> $servers['imap']['timeout'] = 120; doesn't help...
>>>
>>> This would be the correct setting for the timeout, assuming 'imap'
>>> is the correct server stanza for your configuration. FWIW, the
>>> description is listed in the header of the backends.php file, but
>>> it's the very last option, I missed it the first time I looked too
>>> ;)
>>>
>>> Are you sure the issue was a timeout on the IMAP server?
>>>
>>>> Can anyone point me at where or if I can set a longer IMAP
>>>> timeout? Or if there is something else I am missing - a PHP-FPM
>>>> timeout accessing IMAP? Php.ini max_execution_time = 30?
>>>
>>> A possibility, sure. How long did the searches take on your old system?
>>>
>>>> Or is this just something I need to improve on the Cyrus box - squatter?
>>
>> If your question is whether to use squatter, then definitely: yes!
>>
>>>> Any ideas would be helpful.
>>>
>>> Anything of interest on the cyrus server logs? You can also
>>> activate imap debug logging in backends.php to log the IMAP
>>> conversation so we can see if there is anything weird going on
>>> there.
>>>
>>>> Thanks
>>>> Simon
>>>>
>
> Thanks Mike and Jan.
>
> Yes, running squatter already on the IMAP server - every day in full
> and every 3 hours incrementally... not sure there is much more I can
> do there.
>
> I'll fire the old VM up again and do some side by side comparisons,
> with IMAP debugging enabled.
>
> Simon.
> ___________
OK, the old VM also has issues with short (i.e. 3 or 4 character)
entire message / entire mailbox searches, but timeouts seem to take
longer (90 to 120 seconds) which means sometimes the results return,
particularly if repeated. On the new VM Imp advanced search timeouts
are exactly at 60 seconds if result is not yet returned. While running
a search the IMAP VM (single VCPU) was going 100% CPU... but addition
of a VCPU shows that Cyrus is still seems to only use 1 core, and
searches remain same times, so I assume it is only single-threaded and
that is not going to help. I suspect that this is a combination of old
Cyrus (this is on CentOS 7) with its non-authoritative squatter
indexing ("may" contain, not "does" contain, so each match in the
index needs to be checked to confirm) a too-slow IMAP VM and 4GB of
emails ion the indexes.
I know we are getting out of the realm of Horde / Imp support...
Squatter is running daily in full and 3 hrly incrementally. IMP IMAP
debug below, salient lines with mailboxes removed. Nothing in Cyrus
log except the TLS login as the query starts.
Simon.
------------------------------
>> Sun, 02 Feb 2020 19:41:12 +1000
>> Connection to: imap://emp07.simonandkate.lan/
>> Server connection took 0.001 seconds.
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS
LOGINDISABLED] emp07 Cyrus IMAP v2.4.17-Fedora-RPM-2.4.17-15.el7
server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
>> Command 1 took 0.0024 seconds.
>> Successfully completed TLS negotiation.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA
MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN
MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ
SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE
LIST-EXTENDED WITHIN QRESYNC SCAN XLIST URLAUTH URLAUTH=BINARY
X-NETSCAPE AUTH=PLAIN AUTH=LOGIN SASL-IR COMPRESS=DEFLATE IDLE
S: 2 OK Completed
>> Command 2 took 0.0018 seconds.
C: 3 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: simon)]
S: 3 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA
MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN
MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ
SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE
LIST-EXTENDED WITHIN QRESYNC SCAN XLIST URLAUTH URLAUTH=BINARY
X-NETSCAPE LOGINDISABLED COMPRESS=DEFLATE IDLE] Success (tls
protection) SESSIONID=<emp07-22442-1580636472-1>
>> Command 3 took 0.0179 seconds.
>> CACHE: Using the IMP_Imap_Cache_Wrapper storage driver.
C: 4 ENABLE QRESYNC
C: 5 NAMESPACE
S: * ENABLED CONDSTORE QRESYNC
S: 4 OK Completed
>> Command 4 took 0.0006 seconds.
S: * NAMESPACE (("INBOX/" "/")) (("user/" "/")) (("" "/"))
S: 5 OK Completed
>> Command 5 took 0.0011 seconds.
C: 6 LIST () "" (INBOX INBOX/* user/* *) RETURN (SUBSCRIBED)
S: * LIST (\Subscribed \HasChildren) "/" INBOX (CHILDINFO (SUBSCRIBED))
S: * LIST (\Subscribed \HasNoChildren) "/" INBOX/Drafts
S: * LIST (\Subscribed \HasChildren) "/" "INBOX/Saved Emails"
(CHILDINFO (SUBSCRIBED))
{snip 203 lines of mailbox listing}
S: 6 OK Completed (0.020 secs 984 calls)
>> Command 6 took 0.0225 seconds.
C: 7 LIST () "" (INBOX INBOX/* user/* *) RETURN (SUBSCRIBED)
S: * LIST (\Subscribed \HasChildren) "/" INBOX (CHILDINFO (SUBSCRIBED))
S: * LIST (\Subscribed \HasNoChildren) "/" INBOX/Drafts
S: * LIST (\Subscribed \HasChildren) "/" "INBOX/Saved Emails"
(CHILDINFO (SUBSCRIBED))
{snip 203 lines of mailbox listing}
S: 7 OK Completed (0.020 secs 984 calls)
>> Command 7 took 0.0215 seconds.
C: 8 STATUS INBOX/Sent (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX/Sent (MESSAGES 11658 UIDNEXT 11806 HIGHESTMODSEQ 1944)
S: 8 OK Completed
>> Command 8 took 0.0007 seconds.
C: 9 STATUS INBOX (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 75 UIDNEXT 236855 HIGHESTMODSEQ 320422)
S: 9 OK Completed
>> Command 9 took 0.0006 seconds.
>> Slow Command: 45.026 seconds
C: 10 STATUS INBOX (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 75 UIDNEXT 236855 HIGHESTMODSEQ 320422)
S: 10 OK Completed
>> Command 10 took 0.0109 seconds.
C: 11 STATUS INBOX/Sent (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX/Sent (MESSAGES 11658 UIDNEXT 11806 HIGHESTMODSEQ 1944)
S: 11 OK Completed
>> Command 11 took 0.0105 seconds.
>> Slow Command: 45.018 seconds
C: 10 STATUS INBOX/Sent (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX/Sent (MESSAGES 11658 UIDNEXT 11806 HIGHESTMODSEQ 1944)
S: 10 OK Completed
>> Command 10 took 0.0008 seconds.
C: 11 STATUS INBOX (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 75 UIDNEXT 236855 HIGHESTMODSEQ 320422)
S: 11 OK Completed
>> Command 11 took 0.0005 seconds.
>> Slow Command: 45.017 seconds
C: 12 STATUS INBOX (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 76 UIDNEXT 236856 HIGHESTMODSEQ 320423)
S: 12 OK Completed
>> Command 12 took 0.0007 seconds.
C: 13 STATUS INBOX/Sent (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX/Sent (MESSAGES 11658 UIDNEXT 11806 HIGHESTMODSEQ 1944)
S: 13 OK Completed
>> Command 13 took 0.0005 seconds.
C: 14 LOGOUT
S: * BYE LOGOUT received
S: 14 OK Completed
>> Command 14 took 0.0005 seconds.
>> Slow Command: 45.018 seconds
C: 12 STATUS INBOX/Sent (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX/Sent (MESSAGES 11658 UIDNEXT 11806 HIGHESTMODSEQ 1944)
S: 12 OK Completed
>> Command 12 took 0.0007 seconds.
C: 13 STATUS INBOX (MESSAGES UIDNEXT HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 76 UIDNEXT 236856 HIGHESTMODSEQ 320423)
S: 13 OK Completed
>> Command 13 took 0.0012 seconds.
C: 14 LOGOUT
S: * BYE LOGOUT received
S: 14 OK Completed
>> Command 14 took 0.0011 seconds.
--
Simon Wilson
M: 0400 12 11 16
More information about the imp
mailing list