Closed Bug 572397 Opened 14 years ago Closed 13 years ago

100% CPU usage sending large mails with SMTP account

Categories

(MailNews Core :: Networking: SMTP, defect)

Product:
MailNews Core
Component:
Networking: SMTP
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 538283

People

(Reporter: ea4eoz, Unassigned)

Details

(Keywords: perf, Whiteboard: dupme)

Attachments

(2 files)

Performace Counter log for CPU usage, Process=System/thunderbird
2.78 KB, text/plain
Details
Performace Counter log for Coounter object=Process, % Processor Time only, for all instances of process, with network.tcp.sendbuffer=4096
21.53 KB, text/plain
Details 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; es-ES; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; es-ES; rv:1.9.1.9) Gecko/20100317 Thunderbird/3.0.4

Each time a large mail is sent (a mail that needs several seconds/minutes to be sent through your connection) Thunderbird eats 100% CPU and the whole system gets unresponsive: VLC stops playing, Firefox gets stalled, Openofice gets unusable... All the computer gets almost frozen until the message is sent.

Reproducible: Always

Steps to Reproduce:
1. Compose a large mail, for example attach a MP3 file or something big so the final message size is larger than 3 or 4 Mb. Better effect with 10-20Mb message.

2. Send the message using a SMPT account through a slow uplink (here 320 kbps).

Actual Results:  
The message spent several seconds or even minutes to be send (This is ok because of the slow connection). While sending observe Thunderbird's CPU usage and responsiveness of the whole system.

Expected Results:  
Low or almost no CPU usage, as seen with other programs uploading large amounts of data using the same connection.

This bug(?) is a real problem. If you need to send large emails with attachaments you can't use your computer normally until all messages are sent.

Computer is AMD Athlon 64, 2Gb RAM, Windows XP SP3 (32 bits). ADSL connection with 320 kbps uplink.
Component: General → Networking: SMTP
Keywords: perf
Product: Thunderbird → MailNews Core
QA Contact: general → networking.smtp
Whiteboard: dupme
Just upgraded to version 3.0.5 ( Mozilla/5.0 (Windows; U; Windows NT 5.1; es-ES; rv:1.9.1.10) Gecko/20100512 Thunderbird/3.0.5 ). The problem is still present.
Just upgraded to version 3.1.1 ( Mozilla/5.0 (Windows; U; Windows NT 5.1; es-ES; rv:1.9.2.7) Gecko/20100713 Thunderbird/3.1.1 ). The problem is still there.
(Q1) Problem with Gmail's SMTP server? Does your problem occur with any SMTP server you can use? 

(Q2) When did your problem start to occur?
(after upgrade of Tb, add-on install, modem change, OS update, ISP change, ...) 

(Q3) Can you check with network.tcp.sendbuffer=65536, 32768, 16384, ..., 4096 followed by restart of Tb?
Get SMTP log while sending, and check log I wrote in bug 538283 comment #62 to see mail data size and to estimate transmission time.
> https://wiki.mozilla.org/MailNews:Logging
> SET NSPR_LOG_MODULES=timestamp,smtp:5
Lets see:

(Q1) Problem with Gmail's SMTP server? Does your problem occur with any SMTP
server you can use?

(A1) Yes, the problem occurs with all smtp server I use: GMail, Yahoo and various local ISP servers plus one server I administrate running Postfix.

(Q2) When did your problem start to occur? (after upgrade of Tb, add-on install, modem change, OS update, ISP change, ...) 

(A2) I could not answer you exactly because It take long time I realized the problem was TB sending large mails. Sorry.

(Q3) Can you check with network.tcp.sendbuffer=65536, 32768, 16384, ..., 4096
followed by restart of Tb?

(A3) After reading your comment I tried to compare sending message using SSL o just plain SMTP. No difference at all. The CPU was 100% between Thunderbird.exe and the process System (If Thunderbird eats 60% CPU, System eats 40%, in TB eats 80% CPU, System eats 20% and so on)

I tried also different buffer sizes sending a 8600KB message as suggested.

network.tcp.sendbuffer=65536
> 2010-08-10 22:37:46.031000 UTC - 0[192a140]: SMTP Send: MAIL FROM:<ea4eoz@++++.es> SIZE=8810541
> 2010-08-10 22:37:46.203000 UTC - 0[192a140]: SMTP Response: 354 End data with <CR><LF>.<CR><LF>
> 2010-08-10 22:42:10.968000 UTC - 0[192a140]: SMTP Response: 250 2.0.0 Ok: queued as D962D6F6022

network.tcp.sendbuffer=32768
> 2010-08-10 22:47:15.218000 UTC - 0[192a140]: SMTP Send: MAIL FROM:<ea4eoz@++++.es> SIZE=8810543
> 2010-08-10 22:47:15.390000 UTC - 0[192a140]: SMTP Response: 354 End data with <CR><LF>.<CR><LF>
> 2010-08-10 22:51:43.078000 UTC - 0[192a140]: SMTP Response: 250 2.0.0 Ok: queued as 0DF366F6022

network.tcp.sendbuffer=16384
> 2010-08-10 22:53:43.828000 UTC - 0[192a140]: SMTP Send: MAIL FROM:<ea4eoz@++++.es> SIZE=8810545
> 2010-08-10 22:53:44.000000 UTC - 0[192a140]: SMTP Response: 354 End data with <CR><LF>.<CR><LF>
> 2010-08-10 22:58:11.968000 UTC - 0[192a140]: SMTP Response: 250 2.0.0 Ok: queued as A61996F6022


network.tcp.sendbuffer=8192
> 2010-08-10 23:00:04.234000 UTC - 0[192a140]: SMTP Send: MAIL FROM:<ea4eoz@++++.es> SIZE=8810547
> 2010-08-10 23:00:04.406000 UTC - 0[192a140]: SMTP Response: 354 End data with <CR><LF>.<CR><LF>
> 2010-08-10 23:04:32.328000 UTC - 0[192a140]: SMTP Response: 250 2.0.0 Ok: queued as 197626F6022

In all cases CPU usage was 100%.

This bug seems to be very simmilar (if not the same) to the bug 538283 you pointed me.
Question to avoid my misunderstanding.
(Q4) Did you restart Tb after each network.tcp.sendbuffer value change?
Reporter of other similar bug says "CPU hog occurs with SSL only".
(Q5) Can you compare non-SSL case and SSL case?
     Same server(your Postfix server) is ideal, but it's not mandatory.

By the way, SIZE increases 2bytes on each test([CRLF] is probably added each time.) "Edit As New+Send" of previous sent copy is probably a workaround of it.
(Q6) Which type of connection with your ISP?
     Direct TCP/IP connection type? (no dialer)
     Or PPP over Ethernet type? (connection is etablised by dialer)
> http://en.wikipedia.org/wiki/Point-to-Point_Protocol_over_Ethernet
(Q7) Is CPU hog also observerd when uploading of mail data to Gmail's IMAP?
Hello again!

(A4) Yes, Tb was restarted each time sendbuffer was changed, and you are absolutelly right and I am totaly stupid! I changed only the POP3 configuration, not the SMTP configuration. Sorry for wasting your time!

I re-tested all again and I can confirm it: "CPU hog occurs with SSL only".

Sending the 8MByte mail over a plain SMTP connection produces a CPU usage between 0 and 2%. The same mail sent with SSL/TSL produces 100% CPU usage, being this usage the sum of the process Thunderbird.exe and the process "System" (whatever it is).

If Tb uses 85%, System uses 15%. If Tb uses 75%, System uses 25%. If Tb uses 60%, System uses 40%, and so on...

(A5) Yes, see A4 :o)

(A6) PPP over Ethernet (PPPoE)

(A7) Yes, I activated IMAP on Gmail account and the same case: Imap over SSL/TSL is also 100% CPU usage.

Remember the real problem (for me) is not the 100% CPU usage, the real problem is the whole system get unresponsive making very difficult to work with it while sending mails. Maybe a lower thread priority somewhere could solve it *temporaly*. Just an idea.

Greetings!
(In reply to comment #8)
> If Tb uses 85%, System uses 15%. If Tb uses 75%, System uses 25%. If Tb uses
> 60%, System uses 40%, and so on...

(Q8) What process other than Tb does consume CPU power?

> (A6) PPP over Ethernet (PPPoE)

It's big difference from my environment where CPU hog with SSL can't be observed. My VDSL modem is directly connected via TCP/IP over Ethernet(Home LAN with LAN cable). As I wrote bug 577545 comment #15, following log of Read operation is periodically seen in Socket log and is only when SSL connection.
>     nsSocketOutputStream::Read [this=abcdefgh count=4096]
>       calling PR_Read [count=4096]    
>       PR_Read returned [n=-1]
>     nsSocketInputStream::AsyncWait [this=abcdefgh]     
It may interfere "TCP/IP over PPP over Ethernet"(like frequent switch between "Ready to send" status" and "Ready to receive" status).
Are you familiar with data flow of TCP/IP on PPP, PPP, PPPoE, etc.?
(In reply to comment #8)
> If Tb uses 85%, System uses 15%. If Tb uses 75%, System uses 25%. If Tb uses
> 60%, System uses 40%, and so on...

(Q9) Does CPU utilization of Tb depend on network.tcp.sendbuffer value?
(A8) No other one. When sending mails using SSL/TLS only Thunderbird.exe and the process called "System" consume CPU.

(A9) No, it is always 100% whatever value placed in network.tcp.sendbuffer

I think now is pretty clear my bug is exactly the bug number 538283, and the problem appears sending data using SSL/TSL only. So you can close this bug if you want.
(In reply to comment #11)
> (A8) No other one. When sending mails using SSL/TLS only Thunderbird.exe and
> the process called "System" consume CPU.

"System", instead of "System Idle Process"?

> (A9) No, it is always 100% whatever value placed in network.tcp.sendbuffer

You say next.
> If Tb uses 85%, System uses 15%. If Tb uses 75%, System uses 25%. If Tb uses
> 60%, System uses 40%, and so on...
Does it mean next?
  CPU utilization of thunderbird.exe at Task Manager is 100% through out
  data sending to SSL SMTP with any network.tcp.sendbuffer.
  But Tb's CPU utilization decreases to 85%, 75%, 60% sometimes, and the
  System's CPU uitilization is shown as 15% or 25% or 40% respectively.
No, "System" only. At least in XP/SP3 there is a "System" process, from the user SYSTEM always running (XP kernel? I don't know). The "System Idle Process" logically takes 0% CPU usage when sending mail, this is, no spare cpu time.

Any CPU usage meter will show 100% CPU, but if you look at the details, Thunderbird.exe + System is always 100% CPU usage. Yes, strictly speaking Tb does not goes up to 100%, but it is obvious Tb produces also very high cpu usage on the process System while sending SSL/TLS data over SMTP.

When sending large mails, Thunderbird.exe cpu usage goes from 60-65% up to 90 or 95%. The remainder up to 100% is always from the process System.

I'm not a programming expert, I have very little experience but it sounds to me as an active polling loop waiting the data to be SSL'ed. is it possible?

Thank you!
System process is kernel related load. Usually antivirus is loaded kernel-driver which is reside in system process as thread cause load for example, or bad behaving driver will cause spikes on system process. Process Explorer can help reveal which thread in system process actually make cpu load.
(In reply to comment #13)
> Any CPU usage meter will show 100% CPU, but if you look at the details,
> Thunderbird.exe + System is always 100% CPU usage.

Miguel(bug opener), can you check MS Win's "Performance Counter Log"? CPU is consumed by which tasks of which process?
(1) Quick check
> Process, % Processor Time, for "all process", or for "thunderbird.exe + System" + some other processes which consume relatively large CPU% 
(2) % Processor Time of each thread of focused processes.
> Process, % Processor Time, for thunderbird.exe, System, and some other processes which consume relatively large CPU%
> Thread, % Processor Time, for all threads of thunderbird.exe, of System, of the some other processes 
See Performance Counter Log I attached to bug 559676, please.

By the way, as you can see in other similar bugs, "PPPoE" and "Tb's CPU% + System's CPU% = 100%" is reported at first time in your bug by you(As I didn't ask about PPPoE in other bug, no one reported such environment specific data in other bugs, and "CPU 100%" was repeated...). And, as seen in other similar bugs, environment depends on reporter. So, log or trace analysis obtained at different environment is hard, because it's performance related issue(CPU time, utilization, transmission speed, ...).
I'd like to analyze data obtained by you in your environment in this bug, although Ialso  think some bugs of "CPU 100%, SSL, SMTP or IMAP, Tb only" are for same problem.
Miguel, do you agree?
I'm agree, but keep in mind I'm using a translated OS, so sometimes find things here is a pain. I don't remember anything like "Performance Counter Log" in the system, and therefore no idea about using it or configure it. Any help?
(In reply to comment #16)
> I don't remember anything like "Performance Counter Log" in the system, (snip)

It may be called "Performance Monitor". On my Win-XP SP3, Control Panel->Management Tool(?)->Performance->Performance Log->Performance Log and Alert(?)->Counter Log is path to invoke "Performance Counter Log" which I called.
Following is a document found by Google search for 'windows "performance counter" log'. 
> http://www.windowsnetworking.com/articles_tutorials/Windows_2003_Performance_Monitor.html
Ok, I found it. Sorry for the delay. I have been outside home this weekend.

At first sight seems quite complex. Any guide to configurate it to get Tb data?
setting dependency to bug 538283 for ease of tracking and search.
Depends on: 538283
Log is for mail sending to smtp.gmail.com(SSL).
Open .csv file by Excel, 1-2-3 etc., please.
Column name corresponds "Counter" which is set at Performnce/Counter of MS Win. Following column is relevant. 
  (a) Process(_Total)\% Processor Time
  (b) Process(System)\% Processor Time
  (c) Process(thunderbird)\% Processor Time
As 200 is seen at column (a) and my CPU is Core2Duo, column value is usage of single CPU. Column (a) contains usage of System Idle Process.
In my test, Tb uses 20% of a CPU, and "System" uses a few to 8% of a CPU.
Which step is hard for you?
(0) Start Tb
(1) Go to Performance/Counter of MS Win, with administrator privilege
(2) Create new counter log definition
(3) Add counter, Performance Object:Process, choose CPU related ones,
    choose instances of System and thunderbird.exe from list,
    set log file type(csv), set log interval, save
(4) At Thunderbird, compose a mail, Send Later
(5) At Performance/Counter, start the create counter
(6) At Thunderbird, Send Unsent Messages
(7) At Performance/Counter, stop the counter, after end of mail send.
(8) View saved .csv file by Excel, 1-2-3 etc.
Open file by excel, 1-2-3 etc., please. After roughly looking CPU usage of all processs, delete columns except next columns.
  (PDH-CSV 4.0) ()(-540)
  Process(Idle)\% Processor Time
  Process(System)\% Processor Time
  Process(explorer)\% Processor Time
  Process(thunderbird)\% Processor Time
  Process(smlogsvc)\% Processor Time
  Process(_Total)\% Processor Time
  End of column
Mail is sent to smtp.gmail.com(SSL). Sent mail is generated by "Edit As New" of mail used in previous test, so mail size is same as previous test. It took 60 seconds to send, because of network.tcp.sendbuffer=4096(default=131072 was used in previous test).
Just for your info:

Last tuesday I upgraded to a new computer. Now it is using Windows 7/64. No problems at all. CPU usage sending larger mails is almost zero, so the problem seems to be on XP systems.

Thank you for your attention.
I just found this thread. 
I'm having the same 100% CPU usage problem on my system when sending large emails using SSL/TLS.
Thunderbird 3.1.10
Windows XP Pro (sp3)

The problem appeared after switching providers and the new provider requires a ssl/tls connection for POP mail.

Thanks
Rob
not sure what to make of comment 23. I suppose we go with either a dupe of bug 538283, a different bug, or incomplete. opting for dupe.
Status: UNCONFIRMED → RESOLVED
Closed: 13 years ago
Resolution: --- → DUPLICATE
No longer depends on: 538283
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: