On 7/15/09, eric@xxxxxxxxxxxxxxx <eric@xxxxxxxxxxxxxxx> wrote:
> 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).
Do you mean that if the user immediately logs out (clicks the sign out
link) and logs in again, the delay does not happen? What plugins are
active? Please run src/configtest.php and also please try a tarball
of 1.4.19 from our site.
> 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?
--
Paul Lesniewski
SquirrelMail Team
Please support Open Source Software by donating to SquirrelMail!
http://squirrelmail.org/donations.php
------------------------------------------------------------------------------
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
