Open Bug 479450 Opened 15 years ago Updated 2 years ago

folder with many mails (tens/hundreds of thousands), FETCH cmd is resent every minute. don't fetch flags again after idle response

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Version:
1.8 Branch
Platform:
x86
All
Type:
defect

Tracking

(Not tracked)

People

(Reporter: rcolmegna, Unassigned)

Details

(Keywords: perf, Whiteboard: [has protocol log])

Attachments

(1 file)

Imap log - taken with TB3.0b2
3.37 KB, application/octet-stream
Details 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; it; rv:1.9.0.6) Gecko/2009011913 Firefox/3.0.6
Build Identifier: 2.0.0.19

I have a big stress-test IMAP/mailbox with 200,000 msgs.

TB 2.0.0.19 send a "42 UID fetch 481530:* (FLAGS)" cmd when I enter the mailbox.

The server start to sending data (confirmed by network sniffing) at about
30KByte/sec.
Due to the high msgs nr the data transfer request more than a minutes.

BUT exactly after 60sec after the first cmd TB send another cmd:
"43 UID fetch 481530:* (FLAGS)".  Due to IMAP-srv cmd pipelining the
server honor the new cmd and send the data (after terminating cmd 42).

This produce an infinite send/reply loop.

Reproducible: Always

Actual Results:  
Infinite request/reply.

Expected Results:  
That TB DON'T resend a cmd if data are arriving from server.

Isn't impossible that a similar behavior could appear with busy server or with low bandwidth connection.
Component: General → Networking: IMAP
Product: Thunderbird → MailNews Core
QA Contact: general → networking.imap
Version: unspecified → 1.8 Branch
Roberto could you follow the instructions at https://wiki.mozilla.org/MailNews:Logging and attach the logs here please ?
Roberto, does the server start sending back data immediately? Or is there a long delay before it starts sending data back?

What do you have your check for new mail interval set to for this server? 1 minute? 10 minutes?

An imap protocol log might help:

https://wiki.mozilla.org/MailNews:Logging
> User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; (snip)
> BUT exactly after 60sec after the first cmd TB send another cmd:

NSPR log doesn't have timestamp capability yet. See Bug 402793 Comment #6 for adding timestamp to NSPR log on MS Win.
You could also try changing "mailnews.tcptimeout" in the config editor to 120 seconds, restart, and see if that fixes the problem, or if the interval becomes 2 minutes. If so, then we're timing out, and that's only supposed to happen if the server does not respond to our request before the timeout.
(In reply to comment #2)
> Roberto, does the server start sending back data immediately? Or is there a
> long delay before it starts sending data back?

Server start immediately to reply to the 1st cmd.
Due to the diagnostic difficulties (IMAP srv log and TB) I opened the IMAP test server on the internet.

Please connect TB to:
srv: 151.38.135.18 
port: 143
user: stressTest
account: stessTest

this account have some folder with thousands of email.  Please use this account for checking the describe behavior.

Please note that the PC isn't powered on all the days ...
Here is the end of the log file :
2364[5a40640]: 27c9000:151.38.135.18:NA:ProcessCurrentURL:imap://stressTest@151.38.135.18:143/select%3E%5EINBOX:  = currentUrl
2364[5a40640]: 27c9000:151.38.135.18:NA:CreateNewLineFromSocket: * OK IMAP4rev1 RCServer
2364[5a40640]: 27c9000:151.38.135.18:NA:SendData: 1 capability
2364[5a40640]: 27c9000:151.38.135.18:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4 IMAP4rev1 IDLE
2364[5a40640]: 27c9000:151.38.135.18:NA:CreateNewLineFromSocket: 1 OK CAPABILITY completed
2364[5a40640]: 27c9000:151.38.135.18:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
2364[5a40640]: 27c9000:151.38.135.18:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2364[5a40640]: 27c9000:151.38.135.18:NA:TellThreadToDie: close socket connection
2364[5a40640]: 27c9000:151.38.135.18:NA:CreateNewLineFromSocket: (null)
2364[5a40640]: 27c9000:151.38.135.18:NA:SendData: clearing IMAP_CONNECTION_IS_OPEN
2364[5a40640]: 27c9000:151.38.135.18:NA:TellThreadToDie: close socket connection
2364[5a40640]: 27c9000:151.38.135.18:NA:SendData: clearing IMAP_CONNECTION_IS_OPEN
2364[5a40640]: 27c9000:151.38.135.18:NA:TellThreadToDie: close socket connection
2364[5a40640]: 27c9000:151.38.135.18:NA:SendData: clearing IMAP_CONNECTION_IS_OPEN
2364[5a40640]: 27c9000:151.38.135.18:NA:TellThreadToDie: close socket connection
2364[5a40640]: 27c9000:151.38.135.18:NA:ProcessCurrentURL: aborting queued urls
(In reply to comment #7)
> Created an attachment (id=364068) [details]
> Imap log - taken with TB3.0b2

Ignore - password was incorrect - used the one stated in comment #6 - which misses one character.
Sorry:

srv: 151.38.135.18 
port: 143
user: stressTest
account: stressTest
Logs are a bit big, but my imap.log file does not show what is described in comment #0 when accessing the server with Thunderbird 3.0b2. Commands are passed one after the other.
When I wrote the comment #0 I used a folder with more msgs (200,000).  I retry will with this size (which require more than 1 minutes to be downloaded).
Updating as soon as possible.
Checked.  I have replicated the initial problem conditions.  
But I have committed an error in comment #0.  

The problem appears in the case of an "INBOX" mailbox which receives a continuous flux of 2 mails per second.  The scenario span on a lot of minutes.

Also if TB can fetch the new mails in some seconds, it continue to fetch mail, using this schema: "IDLE->[new msg]->NOOP->UID FETCH->[<loop again>]".
This is due to the others mails arrived.

Substantially also if TB is configured a "download mail every minutes", 
in this case, it fetch at the maximum possible speed.

You can see below the IMAP srv cmd trace (all cmds arrives on the
same connection tagged as "20"):
--------------------------------------------------------------------
2009-03-01 11:53:10,897 DEBUG 20 acceptCmdFromNetwork() [391 IDLE]
2009-03-01 11:53:12,050 DEBUG 20 acceptCmdFromNetwork() [392 noop]
2009-03-01 11:53:12,771 DEBUG 20 acceptCmdFromNetwork() [393 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:13,492 DEBUG 20 acceptCmdFromNetwork() [394 UID fetch 630363:630403 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:14,015 DEBUG 20 acceptCmdFromNetwork() [395 IDLE]
2009-03-01 11:53:15,164 DEBUG 20 acceptCmdFromNetwork() [396 noop]
2009-03-01 11:53:15,889 DEBUG 20 acceptCmdFromNetwork() [397 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:16,904 DEBUG 20 acceptCmdFromNetwork() [398 UID fetch 630405:630445 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:17,574 DEBUG 20 acceptCmdFromNetwork() [399 IDLE]
2009-03-01 11:53:18,785 DEBUG 20 acceptCmdFromNetwork() [400 noop]
2009-03-01 11:53:19,625 DEBUG 20 acceptCmdFromNetwork() [401 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:20,346 DEBUG 20 acceptCmdFromNetwork() [402 UID fetch 630447:630491 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:20,924 DEBUG 20 acceptCmdFromNetwork() [403 IDLE]
2009-03-01 11:53:22,046 DEBUG 20 acceptCmdFromNetwork() [404 noop]
2009-03-01 11:53:22,984 DEBUG 20 acceptCmdFromNetwork() [405 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:24,575 DEBUG 20 acceptCmdFromNetwork() [406 UID fetch 630493:630527 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:25,120 DEBUG 20 acceptCmdFromNetwork() [407 IDLE]
2009-03-01 11:53:26,700 DEBUG 20 acceptCmdFromNetwork() [408 noop]
2009-03-01 11:53:27,866 DEBUG 20 acceptCmdFromNetwork() [409 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:28,819 DEBUG 20 acceptCmdFromNetwork() [410 UID fetch 630529:630557 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:29,229 DEBUG 20 acceptCmdFromNetwork() [411 IDLE]
2009-03-01 11:53:30,288 DEBUG 20 acceptCmdFromNetwork() [412 noop]
2009-03-01 11:53:31,030 DEBUG 20 acceptCmdFromNetwork() [413 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:31,841 DEBUG 20 acceptCmdFromNetwork() [414 UID fetch 630559:630599 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:32,355 DEBUG 20 acceptCmdFromNetwork() [415 IDLE]
2009-03-01 11:53:33,417 DEBUG 20 acceptCmdFromNetwork() [416 noop]
2009-03-01 11:53:34,153 DEBUG 20 acceptCmdFromNetwork() [417 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:34,963 DEBUG 20 acceptCmdFromNetwork() [418 UID fetch 630601:630643 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:35,500 DEBUG 20 acceptCmdFromNetwork() [419 IDLE]
2009-03-01 11:53:36,539 DEBUG 20 acceptCmdFromNetwork() [420 noop]
2009-03-01 11:53:37,281 DEBUG 20 acceptCmdFromNetwork() [421 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:38,005 DEBUG 20 acceptCmdFromNetwork() [422 UID fetch 630645:630689 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:38,560 DEBUG 20 acceptCmdFromNetwork() [423 IDLE]
2009-03-01 11:53:39,703 DEBUG 20 acceptCmdFromNetwork() [424 noop]
2009-03-01 11:53:40,427 DEBUG 20 acceptCmdFromNetwork() [425 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:41,237 DEBUG 20 acceptCmdFromNetwork() [426 UID fetch 630691:630719 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:41,783 DEBUG 20 acceptCmdFromNetwork() [427 IDLE]
2009-03-01 11:53:42,910 DEBUG 20 acceptCmdFromNetwork() [428 noop]
2009-03-01 11:53:43,775 DEBUG 20 acceptCmdFromNetwork() [429 UID fetch 1:* (FLAGS)]
2009-03-01 11:53:44,479 DEBUG 20 acceptCmdFromNetwork() [430 UID fetch 630721:630753 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])]
2009-03-01 11:53:45,065 DEBUG 20 acceptCmdFromNetwork() [431 IDLE]
yes, we shouldn't have to fetch the flags again after the idle response. Taking and confirming.
Assignee: nobody → bienvenu
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Keywords: perf
Summary: An a folder with a lot of mails FETCH cmd is resend every minute → folder with a lot of mails FETCH cmd is resent every minute. don't fetch flags again after idle response
Assignee: mozilla → nobody
Status: ASSIGNED → NEW
Whiteboard: [has protocol log]
Is this only with specific imap feature/server?
Flags: needinfo?
OS: Windows XP → All
Summary: folder with a lot of mails FETCH cmd is resent every minute. don't fetch flags again after idle response → folder with many mails (tens/hundreds of thousands), FETCH cmd is resent every minute. don't fetch flags again after idle response
Is http://forums.mozillazine.org/viewtopic.php?p=13742465#p13742465 perhaps an example of this?  
 (courier IMAP server and super-large Inbox, 200k messages)
Further down in the thread robo45h mentions disabling IDLE improved performance.
Removing myslef on all the bugs I'm cced on. Please NI me if you need something on MailNews Core bugs from me.

The now disabled CONDSTORE imap feature may have a positive effect on this. I.e., reduces number of FLAGS fetches needed for a folder with many messages.

Severity: major → normal
Flags: needinfo?

(In reply to gene smith from comment #17)

The now disabled CONDSTORE imap feature may have a positive effect on this. I.e., reduces number of FLAGS fetches needed for a folder with many messages.

Shoot - I guess gmail should be removed from the summary bug Bug 912216 ? Temporarily disable CONDSTORE support for many "GMail IMAP + Thunderbird/SeaMonkey" users

Flags: needinfo?(gds)

Yes, I remember there was really nothing just gmail specific about the CONDSTORE issues.

Flags: needinfo?(gds)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: