Open Bug 389132 Opened 17 years ago Updated 2 years ago

100% CPU for long time when forwarding multiple messages as attachment, if many garbages of nsmail-N.tmp remain in \Temp or /tmp directory

Categories

(MailNews Core :: Composition, defect)

Product:
MailNews Core
Component:
Composition
Platform:
x86
All
Type:
defect

Tracking

(Not tracked)

People

(Reporter: mlathoud, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: perf, Whiteboard: see comment 15-19) 

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.1.5) Gecko/20070713 Firefox/2.0.0.5
Build Identifier: version 2.0.0.5 (20070716)

I select a varying amount of new messages in a spam folder to report them, from 10  to several hundreds, using forward as attachment. On Windows, CPU goes to max and the amount of new messages in the folder slowly decreases (i.e 1/sec). The very same operation on the same account from TB on Linux doesn't exhibit the same behaviour.

Reproducible: Always

Steps to Reproduce:
1. select a lot of new messages in an IMAP folder
2. forward as attachment
3 [review]. send
Actual Results:  
it takes a very long time for the message to be actually sent (i.e ~1s/attached message even if its size is 1k), and CPU is maxed (actually only one core out of 2 on my system)

Expected Results:  
Messages attached as fast as the connection/IMAP permits or a reduced CPU usage; as it is, CPU is the bottleneck, and this bug only occurs on Windows.
(In reply to comment #0)
> Windows NT 5.1;
>(snip) 
> I select a varying amount of new messages in a spam folder to report them, from
> 10 to several hundreds, using forward as attachment.
> On Windows, CPU goes to max and the amount of new messages in the folder slowly decreases (i.e 1/sec).
> The very same operation on the same account from TB on Linux doesn't exhibit
> the same behaviour.

Does problem occur even just after restart of Thunderbird?
Isn't it simply a severe swapping when you tried to forward?
If swapping seems to be involved, will "config.trim_on_minimize=true and minimize of Thunderbird just before forward" alter phenomenon on MS Win?
Put following line in user.js, and restart Thunderbird.
> user_pref("config.trim_on_minimize", true);
Watch CPU/Memory Usage(real momory)/Virtual Memory Size of thunderbird.exe in Task Manager/Process tab while operation.

If server communication related issue seems to be involved, get IMAP protocol log first, and check whether something wrong(such as time out/retry) is involved or not.
  http://kb.mozillazine.org/Session_logging_for_mail/news
  http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap
  http://www.mozilla.org/projects/netlib/http/http-debugging.html
"SET NSPR_LOG_MODULES=imap:5" is sufficient for first analysis, I think.
Will slowness or high CPU usage observed on MS Win in next test?
1. Compose a mail using From: for POP3 account
   (If no POP3 account, create dummy POP3 account of no Global Inbox)
2. Attach mails in IMAP folder to the composing mail
3. "Send Later"
   3.1 mail data to be attached are fetched from IMAP server
   3.2 mail data stream is generated
   3.2 composed mail is saved in Unsent folder of "Local Folders"
   (No SMTP send, no copying of sent mail to Sent folder at IMAP server)
Wada, I did the test you suggested, and result is the same. I am the sysadmin of the IMAP server and there is no issue there nor on the network. What I should mention too is that the progress scrolling bar isn't smooth, it seems to be stalling (for a few 10th of a sec) after each message to be attached is fetched. I tried to enable logging but nothing got written to it, maybe loglevel isn't sufficient?
(In reply to comment #3)
> What I should mention too is that the progress scrolling bar isn't smooth,
> it seems to be stalling (for a few 10th of a sec)
> after each message to be attached is fetched.

Does "after each message to be attached is fetched" mean that fetch of mails from IMAP server itself is normal(fast enough) but attaching(composing mail data) is very slow and consumes high CPU?

What will happen when fetch only? (how long will it take?)
1. Copy   10 mails in folder at IMAP server to a local mail folder
2. Copy  100 mails in folder at IMAP server to a local mail folder
3. Copy 1000 mails in folder at IMAP server to a local mail folder
Watch CPU/Memory Usage(real memory)/Virtual Memory Size of thunderbird.exe in
Task Manager/Process Tab while testing.

> I tried to enable logging but nothing got written to it
Did you specify environment variables correctly?
Try next. Still no log?
 1. Use "SET NSPR_LOG_MODULES=all:5" instead of "SET NSPR_LOG_MODULES=imap:5"
 2. Start Thunderbird, then terminate Thunderbird.
Yes, fetch of mails from IMAP is normal (10 msg/s).
Copying 10 msg from IMAP to local is nearly instant, 100msg takes ~10s, I haven't a thousand messages waiting so far. CPU never increased more than a couple %, nor memory.
About logging I forgot to replace protocol with imap in a sample I grabbed.. now I have ~1.3MB of log, but there's no timestamp inthere.
(In reply to comment #5)
> Yes, fetch of mails from IMAP is normal (10 msg/s).
> Copying 10 msg from IMAP to local is nearly instant, 100msg takes ~10s

It may be slowness and high CPU while file writing of composing mail.
Do you use anti-virus software?
If yes, will "excluding of Tb's mail directory from scan target" alter phenomenon?

Another possibilty: Similar phenomenon to Bug 383718.
Bug 383718 is problem when mail display caused by phishing detection.
If similar phishing detection is executed while mail composing, and if many URL's are involved in attached mails, similar problem may occur.  

> but there's no timestamp in there.

NSPR logging doesn't have timestamp capabilty yet. (See Bug 86396)
But combination of DebugView & NSPR log is available when MS Windows.
See Bug 86396 Comment #7 for use of DebugView.

Wada, as previously stated even 1k messages with no url produce this behaviour. Aren't you able to reproduce it? I disabled my AV (which is fast anyway), same result. CPU is being used by TB itself. Is there a way to use DebugView against the composing mail/attaching messages thread?
(In reply to comment #7)
> Aren't you able to reproduce it?

I didn't try to re-create problem because I was under impression that IMAP related problem and I have no IMAP account. But it now seems that problem will be reproduced with attachments of many mails in local mail folder. I'll try to test using my backup of 20,000 junk mails.

> Is there a way to use DebugView against the composing mail/attaching messages thread?

Usual NSPR logging doesn't have trace facility of detailed activity.
I think followings are helpful in first analysis of problem.
1. Performance Log(counter log of Process for thunderbird.exe).
   This makes Tb's behavior(memory size increase, CPU usage etc.) clear.
2. Activity log of Tb by such as Process Explorer, Process Monitor.
   http://www.microsoft.com/technet/sysinternals/utilitiesindex.mspx
3. XPCOM leak logging tools.
   http://www.mozilla.org/performance/leak-tutorial.html
   Huge increase of virtual memory size indicates resource leak in many cases.
   Note: Perl seems to be required to generate report.
         "Get log on Win, run script on Linux" may be required.
Tested with Tb 2.0.0.5(MS Win-XP SP2 on Core2 Duo), using mails in local mail folder.

1. Restart Tb, Select  50 mails, "Forward as Attachments", Send Later
2. Restart Tb, Select 100 mails, "Forward as Attachments", Send Later
3. Restart Tb, Select 150 mails, "Forward as Attachments", Send Later
4. Restart Tb, Select 200 mails, "Forward as Attachments", Send Later

In any case, CPU utilization of Thunderbird.exe was around 50%.
(around 100% if single CPU, I think).
But maximum "Virtual Memory Size" was 30MB even when case 4.
Execution time looks to be proportional to number of attached mails(linear).

(Reference)
5. Restart Tb, Select 200 mails, Copy to other local mail folder
CPU utilization of Thunderbird.exe was around 50%.
Execution time is far less than attaching of 200 mails, but virtual memory after copy was 40MB.

High CPU utilizaion is simply an evidence of efficient processing and file I/O, I believe.

Questions to mlathoud@b2b2c.ca(bug opener):
(Q1) Is huge virtual memory size increase observed? 
(Q2) While CPU 100% by composing, won't Thunderbird respond to any operation?
     (for eaxmple, viewing a mail in other mail folder is impossible)

Q1: no
Q2: it responds, but very sluggish (i.e a couple seconds minimum for each operation).
It was found that a part of "CPU 100%" was caused by unproductive work, by "Process Monitor" log. (17MB when CSV, so I didn't attach log to this bug)

Test case: Select 100 mails in a local mail folder, and "Forward as Attachments"
(Note: Temp directory is cleared before start of test)

(1) Creation of nsmail-1.tmp.
> "6281","10:23:25.8594023","thunderbird.exe","304","IRP_MJ_CREATE",
>        "C:\Doc...\Temp\nsmail-1.tmp","SUCCESS", ...

(2) For each N (N=2 to 99)
> "IRP_MJ_CREATE", "C:\Doc...\Temp\nsmail.tmp","NAME COLLISION", ...
> "NAME COLILSION" for nsmail-1.tmp to nsmail-(N-2).tmp 
> "IRP_MJ_CREATE", "C:\Doc...\Temp\nsmail-(N-1).tmp","NAME COLLISION",
> "IRP_MJ_CREATE", "C:\Doc...\Temp\nsmail-N.tmp","SUCCESS",

(3) Creation of nsmail-100.tmp.
> "43463","10:23:35.4551425","thunderbird.exe","304","IRP_MJ_CREATE",
>         "C:\Doc...\Temp\nsmail.tmp","NAME COLLISION", ...
> ("NAME COLILSION" for nsmail-1.tmp to nsmail-99.tmp) 
> "44105","10:23:35.6054315","thunderbird.exe","304","IRP_MJ_CREATE",
>  "C:\Doc...\Temp\nsmail-99.tmp","NAME COLLISION",
> "44111","10:23:35.6069685","thunderbird.exe","304","IRP_MJ_CREATE",
>          "C:\Doc...\Temp\nsmail-100.tmp","SUCCESS",
(After this, "reading of mail data from local mail folder file" starts)

Above took 10 sec with CPU 50% on Core2 Duo/T5500@1.66GHz, even though objective is simply to create nsmail.tmp and nsmail-1.tmp to nsmail-100.tmp.
And, if garbages of nsmail-X.tmp remain in Temp directory, it'll take longer. 

Confirming.

To mlathoud@b2b2c.ca:
Please remove IMAP from bug summary, because IMAP has no relation to problem.
Status: UNCONFIRMED → NEW
Ever confirmed: true
Correction.
In each step of above (1)/(2)/(3), logs of reading from local mail folder and log of writeng nsmail-X.tmp exist. So (1)/(2)/(3) was copy phase to nsmail-X.tmp.

(4) End of composing of mail
> "75503","10:23:43.1138039","thunderbird.exe","304","IRP_MJ_CLOSE",
>         "C:\DOC...\Temp\nsmail.eml","SUCCESS",""
(5) Last log after writing to Unsent folder, deletion of tmp files etc.
> "105325","10:25:54.0028663","thunderbird.exe","304","FASTIO_WRITE",
>          "C:\Doc...\panacea.dat","SUCCESS","Offset: 23,946, Length: 79"

Test result summary:
 (1/2/3) Copy phase   : 10 sec to copy of 100 mails
 (3 - 4) Compose phase: 10 sec to read 100 mails and write to nsmail.eml
 (4 - 5) Move phase   : 10 sec to read nsmail.eml and write to Unsent folder
                        and for cleanup process such as deletion of temp files

Although inefficient logic in determination of temp file name is involved, I think that 10 sec for each phase is understandable and reasonable. So I believe "CPU 100%" is an evidence of efficient processing and file I/O, and "CPU 100%" itself is not a problem nor a bug.

I think problem is following when "CPU 100%" by other heavy process such as mail composition.
   it responds, but very sluggish
   (i.e a couple seconds minimum for each operation)
I think improvement/change in task priority setting or improvement of task scheduling mechanism/algorithm is required.
Correction of log of (5). Sorry for repeated spam.
Log which seems to be end of forwarding (after close of compose window) was next.
(5) Log for end of process
> "80475","10:23:52.9615658","thunderbird.exe","304","IRP_MJ_CLOSE",
>          "C:\...\chrome\en-US.jar","SUCCESS",""

Wada, remember that whatever the issue is, it doesn't happen on linux (barely a few sec to attach hundreds of messages -network not being an issue there- on a Celeron).
Summary: 100% CPU when forwarding multiple messages as attachment from IMAP → 100% CPU when forwarding multiple messages as attachment
(In reply to comment #14)
> it doesn't happen on linux (barely a few sec to attach hundreds of messages -network not being an issue there- on a Celeron).

A culprit is possibly garbages in Temp directory of MS Win.

Before test of  Comment #11 to #13, I had garbages of more than 1000 nsmail-X.tmp because I killed Tb during test of "Forward as Attachments" for many many mails. So I cleared Temp directory before getting process Monitor log in order to get clean data.
After test of Comment #11 to #13, I couldn't observe very long execution time in "Forward as Attachments" for 100 mails.
So I executed "Forward as Attachments" for 6000 mails and killed Thunderbird again when nsmail-2000.tmp was generated.
After that, I could observe slowness in "Forward as Attachments" for 100 mails again, and after clear Temp directory again, I couldn't observe severe slowness in "Forward as Attachments" for 100 mails again.
In order to avoid slowdown when many garbages of nsmail-X.tmp, I think use of system function for temporary file (GetTempFileName when MS Win) is better to be considered in temporary file creation.
 - http://msdn2.microsoft.com/en-us/library/aa364991.aspx
When Linux, mkstemp() looks to be the function to create unique temporary file.
  http://www.penguin-soft.com/penguin/man/3/mkstemp.html
Nice catch! I had 3500 nsmail temporary files, after removal the symptoms disappear (no more high cpu nor slugginess). Cleaning up at startup would be nice though, that plus using the right syscall to create them in the first place. Thanks anyway, my bug is gone without any fix :)
Putting shortcut of next bacth in "Startup" of "All Users" is the easiest way to cleanup \Temp on MS Windows.
DEL-TEMP.BAT
  DEL %temp%\*.* /S /Q
Severity: normal → minor
Summary: 100% CPU when forwarding multiple messages as attachment → 100% CPU for long time when forwarding multiple messages as attachment, if many garbages of nsmail-N.tmp remain in \Temp directory
Component: Message Compose Window → MailNews: Composition
Product: Thunderbird → Core
QA Contact: message-compose → composition
Version: unspecified → Trunk
Changing to OS=All, based on similar report on Linux(then probably on Mac OS X too)
OS: Windows XP → All
Summary: 100% CPU for long time when forwarding multiple messages as attachment, if many garbages of nsmail-N.tmp remain in \Temp directory → 100% CPU for long time when forwarding multiple messages as attachment, if many garbages of nsmail-N.tmp remain in \Temp or /tmp directory
possible relation bug 423761
Product: Core → MailNews Core
Depends on: 356808
Severity: minor → normal
Keywords: perf
Whiteboard: see comment 15-19
Why do those files even exist (after TB close)? I filed bug 235432 for them long ago.
I believe that the landed fix for Bug 671440 will help to avoid the problem of this bug to some extent.
Depends on: 671440
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.