Closed Bug 358595 Opened 18 years ago Closed 15 years ago

incoming mail processing (junk filters?) take very long, with high cpu usage

Categories

(Thunderbird :: General, defect)

Product:
Thunderbird
Component:
General
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: amichai2, Unassigned)

Details

(Keywords: perf, Whiteboard: closeme 2009-04-30 helps: shorter update interval, cached connections >1) 

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1) Gecko/20061010 Firefox/2.0
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1) Gecko/20061010 Firefox/2.0

I have TB set up to fetch mail from several accounts on different servers. I have a couple message filters setup to put some mailing lists in special folders, and the standard junk filter running. My Junk folder is quite big (~35K messages) - which I keep both in case of a misdetection and since I'm investigating spam statistics for a side project.

When I check for new mail (all accounts), and there is a fair amount of mails (say over 150, mostly spam), TB takes a very long time to process them (minutes), all the while using up full CPU. During this period, the new messages are shown in the inbox, and the relevant ones already have the Junk mail icon next to them, but it seems the ones marked as junk are processed very slowly - every few seconds a single message is removed from the inbox and moved to the junk folder. So all together it takes minutes for over 100 messages.

Note that this does NOT happen when few new messages are retrieved - if there are 10 messages for example, they are all marked as junk and moved to the junk folder in one quick sweep, and NOT taking a few seconds each.

I *think* this has to do with the multiple accounts processing concurrently - the first account starts its normal processing, but then then the next accounts add additional messages at the same time, and it seems like this concurrency is what's causing the problem - fetching/adding/filtering/moving multiple messages from multiple accounts at the same time. if so, it may be better to do it in stages - first fetch messages from all accounts, then process all of them in one batch for adding/filtering/moving etc.

This happens consistently every time I leave TB closed for a while (messages build up) and then fetch them all, so I can do further tests if it helps.


Reproducible: Always

Steps to Reproduce:
1. setup multiple accounts, at least two of which have over 100 new messages waiting (many spam)
2. dunno if it's related - but maybe have a large Junk folder (~35K spams)
3. select all accounts to be checked automatically at startup.
4. startup TB.

Actual Results:  
it takes a whole lot of time (minutes) to process the new messages, moving them one by one to the junk folder, taking a few seconds each.

Expected Results:  
all new messages from all accounts should be processed in one quick swoop as it does when there are fewer new messages.
Unfortunately, this still happens in version 2 beta 1 (20061206) - takes MINUTES to process a couple hundred new mails (mostly spam), taking up full CPU the whole time, as reported above.

I am pretty sure now that this is indeed a synchronization/locking issue of some sort among the several accounts fetching and processing the mail: when I open TB without it fetching all new messages, and click on 'Get Mail' for each account separately, waiting for it to finish processing before moving on to the next, the same quantities of new messages are processed instantaneously. However, if instead I run 'Get All New Messages', i.e. from all the accounts together, then this serious bug happens. This is completely consistent in my experience and reproducible every time I open TB.

I hope this will be fixed before TB 2 final is released, since having to click on each of 7 accounts separately to download new messages is not quite acceptable, and neither is waiting over 5 minutes while my computer's CPU is all taken up...
I'm seeing this too on Linux and for me TB takes minutes just to process 10-20 mails making this bug really painful.
Flags: blocking-thunderbird2?
I did some additional research by running tcpdump and iptraf when I selected to check for new mail today and the reason why things are so slow might have to do with the fact that TB donwload massive amounts of data from the IMAP server for no apparent reason. Today I got about 100 new mails some are spam and most are regular mailinglist postings. Iptraf showed that TB has downloaded over 30MB of data from the server and I have no idea why it would do that. This takes several minutes on my connection and during that time it becomes virtually impossible to read mail. Once the donwload has stopped things return to normal and TB becomes responsive again.

The severity of this bug should be set to major as it makes TB nearly impossible to use.

I just checked through the mail and then checked for new mail. I got 6 new messages and TB decided to download 6 MB of data again.
To check if a message is junk, we download the message and tokenize the text of it.

I would suggest adding filters to mark messages that you know aren't junk (e.g., your mailinglist postings) as non-junk - that will prevent us from downloading the message bodies to analzye them for junk status.
(In reply to comment #5)
> To check if a message is junk, we download the message and tokenize the text of
> it.
> 
> I would suggest adding filters to mark messages that you know aren't junk
> (e.g., your mailinglist postings) as non-junk - that will prevent us from
> downloading the message bodies to analzye them for junk status.

I'm already filtering all mailinglist messages to move them to subfolders and they don't seem to get checked as far as I can tell. The only folder that seems to get checked for spam is the inbox.

But even if that was the problem it still wouldn't explain what TB is downloading. The 6 messages I got in comment #4 add up to max. 50kb so why is TB downloading 6 MB of data? The slowness of both the marking of junk mail and general browsing of mails seems to be directly related to that download because once the traffic dies down TB becomes quite snappy. What I see is that when I select a message TB tries to download it from the server (status says "Loading Mesage...") but this gets choked by the other big download. This doesn't happen under TB 1.5 either so there is definitely a problem with TB 2.0 .

Is your junk folder an imap folder as well? It's easy to see what TB's doing with the imap server:

http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap

This might generate a rather large log, but you could zip it up and send it to me, if you want.

Are you sending junk mail from 7 different imap accounts to a single junk folder on one of the imap accounts? Or do you have one junk folder per imap account?
I don't know if these are separate issues or the same, but for what it's worth, I don't have any imap accounts, only pop3 - I guess I somehow forgot to mention it in the original bug report. But as I did mention, the problem seems to be occurring after the junk tagging has already taken place - I see a large number of messages in the inbox with the little junk icon next to them - up to this point there's no problem, but then they are moved one by one ever so slowly to the junk folder while crunching the CPU endlessly (well for many minutes at least, on bad days).
(In reply to comment #7)
> Is your junk folder an imap folder as well? It's easy to see what TB's doing
> with the imap server:
> 
> http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap
> 
> This might generate a rather large log, but you could zip it up and send it to
> me, if you want.
> 
> Are you sending junk mail from 7 different imap accounts to a single junk
> folder on one of the imap accounts? Or do you have one junk folder per imap
> account?

It's a very trivial setup I have one imap account with a junk folder, that's it. I just created a log (130mb, 2.1mb bzip2ed) that I will send your way in a minute. I took a peek in there and even though TB shows 37 new messages it seems it FETCHes a lot more than these from the folder...and multiple times. I also disabled the automatic checking of mail on startup and set the maximum number of connections to cache for this server to 1 to make the debugging a bit easier.

Here's the gist of what I e-mail Dennis privately - perhaps it will help others who are seeing similar problems.

Setting the max number of cached connections to 1 exacerbates the problem greatly, in your situation. In your situation, I'd set it back to the default, 5, or even higher, to the number of folders that frequently get mailing list messages moved to them by filters, plus 1.

and/or

Go into tools | options | general, pick the Customize... button and uncheck the show message preview text box.


Here's what's happening:

You receive a lot of mailing list messages and filter them each to their own folder. These folders are quite large. If you're showing preview text, whenever a new message is filtered to an other folder, internally we select that folder, and download the beginning of the message text so we can show it in the new mail alert and folder new mail tooltip.  When we select an imap folder, we have to sync up the flags between the imap server mailbox and our local store. If you have large folders, this syncing will generate a large response from the server. (unfortunately, IMAP has no way of telling us a folder hasn't changed - we're pretty much required by the IMAP RFC to sync all the flags each time, because some other client might have changed the flags).

By setting the max number of cached connections to 1, you've ensured that each time we try to update a folder, we'll have to do a full sync. If we have a cached connection to a folder, we just get the new headers and there is relatively little traffic. What's happening to you is that once we've finished syncing all the target folders, which can take some time, we go back to the inbox, resync it, and in the meantime, new messages have arrived that are filtered to other folders; we sync those folders, and go back to the inbox, etc, and repeat until new mail stops arriving.

By setting the cached connections to a large enough number, we won't have to completely resync folders all the time. And by turning off the message preview text, we won't try to sync folders that have new messages moved into them by filters, until you select the folder.

(I'm assuming you don't have the other folders configured to be automatically checked for new mail - that also forces us to update them).

You could also keep your folders a bit smaller by archiving older messages.
Status: UNCONFIRMED → NEW
Ever confirmed: true
amichai2, Dennis, 
Have you changed anything and if so how are you getting on now?
What happens/happened if you uncheck preview?

in customize I have only address checked off.
Keywords: perf
Well for one thing my old box died and I got a brand new machine... :)

Regarding the problem though yes things are a lot better now. I think the problem was caused by a combination of two factors:
1) The fact that "show message preview text" was enabled
2) What David wrote above:
"When we select an imap folder, we have to sync up the flags between the imap server mailbox and our local store. If you have large folders, this syncing will generate a large response from the server."

Is it possible that when TB syncs the flags it actually also downloads the preview text for all these messages? That would explain the massive use of bandwidth and why it went away when I unchecked that option.

Nothing new in my case. Still pop3 and no imap, still happens after tagging all messages with the junk icon (which is probably far after all communications are over), still takes a whole lot of time to move them to the junk folder when there are a lot of new messages to process. I just try to keep TB running all the time, so whenever I want to check my mail it's already there (via standard 10-minute polls) rather than having to get them in a large batch. If TB was closed, I open it, walk away for a few minutes or read some interesting article on the web, and then come back to TB when it's done. I haven't tried turning off the preview text, though given the possible imap sync explanations above, I don't see how that's relevant to my pop3 already-fetched-and-marked-as-junk setting...
To David Bienvenu and Dennis J. :
As amichai2@amichais.net(the bug opener) says in comment #8 and comment #13, original problem is POP3 case, and IMAP case(Dennis's case) involves many many different issues from bug opener's case. And one of issues when IMAP is similar one  to Bug 384360. 
I recommend Dennis to open separate bug for IMAP case.           
To amichai2@amichais.net(the bug opener):
Watch behavior/phenomenon when manual "Mark As Junk"(and moved to Junk) first.
1. Create a folder, and copy 100 junk mails from Junk to the new folder
2. Enable "When I mark messages as junk/Move them to the account's Junk folder"
3. Enable Performance Counter logging
   Counter object=Process, Counter=all, Instance=thunderbird.exe
4. Start Task Manager, open Process tab
   See at least CPU, "Memory Usage", "Virtual Memory Size" columns.
5. Select all 100 mails, then "Mark As Junk",
   and watch numbers displayed for thunderbird.exe in Task Manager/Process.
   (Please don't do for too many mails. When I tested this for 6000 small mails)
   (on PC of 128MB in the past, it took more than 40 minutes due to swapping.  )
6. Stop Performance Counter logging, and save log. 
Second check item: To see what files are accessed by Tb.
1. Start Process Monitor
   http://www.microsoft.com/technet/sysinternals/Utilities/processmonitor.mspx
2. Copy 10 junk mails to a folder, select all 10 mails, then "Mark As Junk"
3. Save Process Monitor log
Can you see something wrong such as long file I/O, too many file open/close?
hi WADA,

The 100 emails test runs almost instantaneously, so the performance counters, which from what I can find go down to second resolution only, don't really give too much info...

As for the procmon test, there are many entries reading, writing and "QueryStandardInformationFile" (whatever that is) of both the junk folder's file and the test folder's file. At first it looks like the test folder's file is being opened, read and closed many times, but later on it' opened once, has a lot of reads and finally closed. There are also a bunch of accesses to a file named 'panacea.dat' - dunno what this is, but I remember seeing it a lot a while back when I ran procmon on the live fetch-mail-junk-delay problem (the current test moving between folders was immediate without any special delays).
Mail moving doesn't look have problem.
What about "Run Junk Mail Controls on Folder" case?
 (1) Copy 100 to 1000 junk mails to a folder from Junk folder
 (2) Start Process Monitor
 (3) "Run Junk Mail Controls on Folder"
with "Run Junk Mail Controls on Folder" and about 285 messages, it took a few good seconds for all of them, however this is still far less than a few seconds *per message* that I get when this many messages are fetched from pop3 and tagged as junk. Other than many accesses to the junk and test folders, there's a surprising bunch of accesses from the TB process to the Acrobat Reader executable.... very strange. Also, after running the junk mail controls, about 20 message were left behind and not moved back to the junk folder (even though they remained marked as junk).
(In reply to comment #19)
> Also, after running the junk mail controls, about 20 message were left behind
> and not moved back to the junk folder (even though they remained marked as junk).

This is different and already reported problem. I also experienced remained Junk mails several times, and I fortunately could observe "marked as Junk when download but not moved when compacting folder is in progress" once.
(auto compact by disk space option. probably when auto compact of Junk folder)

Please focus on issue of "a few seconds *per message*".
(Q1) Do you use Global Inbox?
When Global Inbox, and when "Get All New Messages(of all accounts)", moving to Junk folder(of Global Inbox owner, usually "Local Folders") is seriarized. Thus elapsed time of Junk move from account1 to accountN will become large.
(Q2) Do you enable biff options?
New mail alert consumes CPU because animation or playing sound etc. are involved, and is executed for each account. 
What will happen when all biff related options are disabled?
See screen shot in following MozillaZine forum thread for mail.biff.xxx.yyy options.
http://forums.mozillazine.org/viewtopic.php?p=2980289&sid=4fff547b2bb0d4689d63af57733bac27
I do use a common 'Local Folders' for all accounts, and I can see in the status bar that the accounts are processed one at a time (not concurrently), however the problem of "a few seconds *per message*" is definitely within a given account's messages, not a delay between accounts. To clarify, there are 8 accounts configured, 6 of them get less than a single email a week, another around 100 a day (mostly spam), and the last one about 300 a day (mostly spam). So I'm talking about a delay of a few seconds for each of a couple hundred of messages - and this definitely shows also when all emails from the first 'active' account have already been processed (and moved to junk) and only the second 'active' account's emails remain to be processed.
Flags: blocking-thunderbird2?
amichal2, any change when using TB 2.0.0.12?

Wada, where do you think we go from here?
Since the original bug report, I've worked around this by just leaving TB open all the time, and polling for new mail every few minutes, so that there is never a build-up of many new messages at a time.

Following Wayne's ping, I just tried recreating it on TB 2.0.0.14 by shutting TB down for a day and then opening it, which brought up over 200 new messages (mostly spam) - and it seemed to be ok now!

Now the junk processing takes several seconds in total, but at least it's not several seconds per message, so it looks like this bug was indeed fixed (don't know in which version). I'll give it a few more tests in the next few days, just to make sure.
Assignee: mscott → nobody
reporter's issue is sort of WFM.

but before closing, can you try beta 1 to see whether the problem is better, worse, same?
backup your profile first
 http://www.mozillamessaging.com/en-US/thunderbird/early_releases/
Whiteboard: helps: shorter update interval, cached connections >1
Version: unspecified → 1.5
Whiteboard: helps: shorter update interval, cached connections >1 → closeme 2009-04-30 helps: shorter update interval, cached connections >1
RESO INCO due to lack of response to last comment. If you feel this change was made in error, please respond to this bug with your reasons why.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → INCOMPLETE
I am now on a several-years-newer pc and migrated to linux, so there's not much room for comparison any more... but from my comment from a year ago, the problem was apparently fixed sometime along the way. It worked well on the old machine until it retired. Thanks to whomever did that, and to everyone involved :-)
Resolution: INCOMPLETE → WORKSFORME
You need to log in before you can comment on or make changes to this bug.