Some of my users are experiencing an odd delay during login. The reason I
say odd is because the server is idle during the delay. I've reviewed much
of the documentation about performance, and most of it seems to relate to
reducing bandwidth or CPU load. Since there is no network traffic and the
CPU is idle during the delay, none of those measures have helped.
System details:
It's an Ubuntu 8.04 LTS server running:
- SquirrelMail 1.4.13 (ubuntu's package squirrelmail 2:1.4.13-2)
- Apache 2 (apache2 2.2.8-1ubuntu0.9)
- PHP 5 (php 5 5.2.4-2ubuntu5.6)
- Dovecot (dovecot-imapd 1:1.0.10-1ubuntu5.1)
To find the exact location of the delay, and to determine if it's a
bandwidth problem or a dovecot problem, I did a tcpdump of the
conversation between SquirrelMail and dovecot. It seems that SquirrelMail
does just fine logging in, getting the server info, fetching the message
headers (all in less than a second), and then it pauses for one or more
minutes before sending the 'EXPUNGE' command. So I guess my next question
is: what does SquirrelMail normally do at that point? Is it waiting on
some kind of timeout? Also note that the delay does not happen on
subsequent logins, only on initial login (unless some time has passed).
Here is a condensed version of the capture:
06:54:40.358253-06:54:40.358280: TCP Handshake: SYN;SYN+ACK;ACK
06:54:40.359249 Server: * OK Dovecot ready.
06:54:40.359438 Client: A001 LOGIN (credentials)
06:54:40.363099 Server: A001 OK Logged in.
06:54:40.363213 Client: A002 CAPABILITY
06:54:40.363266 Server: * CAPABILITY IMAP4rev1 SASL-IR SORT
THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE
LOGIN-REFERRALS
A002 OK Capability completed.
06:54:40.363439 Client: A003 NAMESPACE
06:54:40.363486 Server: * NAMESPACE (("" ".")) NIL NIL
A003 OK Namespace completed.
06:54:40.363756 Client: A004 LOGOUT
06:54:40.363788 Server: * BYE Logging out
06:54:40.364428 Server: A004 OK Logout completed.
06:54:40.364428-06:54:40.367562: TCP Teardown: FIN;ACK;FIN;ACK
06:54:40.423405-06:54:40.423431: TCP Handshake: SYN;SYN+ACK;ACK
06:54:40.423573 Server: * OK Dovecot ready.
06:54:40.423719 Client: A001 LOGIN (credentials)
06:54:40.426977 Server: A001 OK Logged in.
06:54:40.427095 Client: A002 STATUS "INBOX" (MESSAGES UNSEEN RECENT)
06:54:40.483043 Server: * STATUS "INBOX" (MESSAGES 186 RECENT 0 UNSEEN 26)
A002 OK Status completed.
06:54:40.483244 Client: A003 SELECT "INBOX"
06:54:40.483380 Server: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted
\Seen \Draft \*)] Flags permitted.
* 186 EXISTS
* 0 RECENT
* OK [UNSEEN 31] First unseen.
* OK [UIDVALIDITY 1229579150] UIDs valid
* OK [UIDNEXT 631] Predicted next UID
A003 OK [READ-WRITE] Select completed.
06:54:40.483572 Client: A004 EXPUNGE
06:54:40.483678 Server: A004 OK Expunge completed.
06:54:40.485400 Client: A005 SELECT "INBOX"
06:54:40.485519 Server: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted
\Seen \Draft \*)] Flags permitted.
* 186 EXISTS
* 0 RECENT
* OK [UNSEEN 31] First unseen.
* OK [UNSEEN 31] First unseen.
* OK [UIDVALIDITY 1229579150] UIDs valid
* OK [UIDNEXT 631] Predicted next UID
A005 OK [READ-WRITE] Select completed.
06:54:40.485695 Client: A006 EXPUNGE
06:54:40.485762 Server: A006 OK Expunge completed.
06:54:40.485837 Client: A007 UID FETCH 1:* (FLAGS BODY.PEEK[HEADER.FIELDS
(RECEIVED)])
06:54:40.488559 Server: * 1 FETCH (FLAGS (\Seen) UID 1 BODY[HEADER.FIELDS
(RECEIVED)] {748}
(etc. - headers for 186 messages in two packets)
A007 OK Fetch completed.
06:54:40.537902 Client: (Final TCP ACK sent from client acknowledging
receipt of the message headers.)
(This is the unexplained delay: 1:22 minutes elapse with no network
activity and server CPU is idle. Another user has a 2:08 minutes delay. On
subsequent logins there is no delay unless the user hasn't logged in for
some time.)
06:56:02.767988 Client: A008 EXPUNGE
06:56:02.768220 Server: A008 OK Expunge completed.
06:56:02.769604 Client: A009 SELECT "INBOX"
06:56:02.769823 Server: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted
\Seen \Draft \*)] Flags permitted.
* 186 EXISTS
* 0 RECENT
* OK [UNSEEN 31] First unseen.
* OK [UIDVALIDITY 1229579150] UIDs valid
* OK [UIDNEXT 631] Predicted next UID
A009 OK [READ-WRITE] Select completed.
06:56:02.770488 Client: A010 EXPUNGE
06:56:02.770584 Server: A010 OK Expunge completed.
etc...
Any ideas?
Thanks,
-Eric
------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize
details at: http://p.sf.net/sfu/Challenge
-----
squirrelmail-users mailing list
Posting guidelines: http://squirrelmail.org/postingguidelines
List address: squirrelmail-users@xxxxxxxxxxxxxxxxxxxxx
List archives: http://news.gmane.org/gmane.mail.squirrelmail.user
List info (subscribe/unsubscribe/change options): https://lists.sourceforge.net/lists/listinfo/squirrelmail-users
