573432 - TB is slow for POP3 download of large files

Status: RESOLVED INCOMPLETE

(MailNews Core :: Networking: POP, defect)

Description

[quazgar]

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3
Build Identifier: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.1.10) Gecko/20100512 Lightning/1.0b1 Thunderbird/3.0.5

Downloading larger files (with POP3 here) takes a looong time, and seems to send/receive a lot more network traffic than what should be necessary.  I created a small 1MB test file from /dev/urandom, see the attached log for debugging output.  Said 1MB file took around one minute at 500kB/s.

Reproducible: Always

Steps to Reproduce:
1. Send big file to yourself.
2. Check for new email and get the message.

Actual Results:  
Message takes a long time to download.

Expected Results:  
Message should take "normal" time to download.

See the attached log for more info.

Comment 1

[quazgar]

Attachment: Gzipped log for this bug.

Comment 2

[WADA:World Anti-bad-Duping Agency]

Following is a POP3 log took on 2008/5/21. Left side digits is log sequence number added by a tool. So, no log line is omitted. Cocecutive RECV: logs were written by Tb 2 or Tb 1.x.
> 00001062	20.14764404	[3344] 0[3c4788]: RECV: Subject: POP3-Test 	
> 00001063	20.14772034	[3344] 0[3c4788]: RECV: Content-type: text/plain; 	
> 00001064	20.14781189	[3344] 0[3c4788]: RECV:  charset="KOI8-R" 	
> 00001065	20.14788818	[3344] 0[3c4788]: RECV: Content-transfer-encoding: base64 	
> 00001066	20.14796638	[3344] 0[3c4788]: RECV:  	
> 00001067	20.14816475	[3344] 0[3c4788]: RECV: LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t

Your log for one line data of base64 attachment.
See http://kb.mozillazine.org/Session_logging_for_mail/news for POP3 state in log.
> -1603500256[130ab40]: RECV: m1thlZa7HRIXAFGzVu79uM+cztcwgCJJILT9Vxwdnek0zi6Tx6uMKAnAEjd5Af0kq4dFnhni
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 7
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 7
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 7
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 10
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 14
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 9
> -1603500256[130ab40]: POP3: Entering state: 19
> -1603500256[130ab40]: RECV: (null)
> -1603500256[130ab40]: Entering NET_ProcessPop3 29
> -1603500256[130ab40]: POP3: Entering state: 19
>(Log for next data line follos)
> -1603500256[130ab40]: RECV: vw3IuHxcVr6txp5xy5ro7gcx/FFOicB53T3MNUNeOgu7xCV3zkVmoquXF49okPhI2LKRv5AD

Perhaps bug 539389.

Can you check with Tb 3.1 RC? (probably rc2 is available).
Please check using new profile, POP3 account definition with "Leave Messages on Server", without any automatic mail deletion setting.
If you use current profile by both Tb 3.0 and Tb 3.1, as Gloda's schema is changed, re-idexing of all mail data probably occurs upon both changing to Tb 3.1 and changing back to Tb 3.0. 

By the way, do you think log data without timestamp is useful for diagnosis of problem of "it takes long"?
Please add timestamp(new from Tb 3.0) to log by parameter of timestamp,POP3:5.
> https://wiki.mozilla.org/MailNews:Logging

Comment 3

[quazgar]

(In reply to comment #2)
> Can you check with Tb 3.1 RC? (probably rc2 is available).
> Please check using new profile,
> ...
> By the way, do you think log data without timestamp is useful for diagnosis of
> problem of "it takes long"?
> Please add timestamp(new from Tb 3.0) to log by parameter of timestamp,POP3:5.
> > https://wiki.mozilla.org/MailNews:Logging

Hi,
I hope that the next two logs are more useful, made with TB-3.1-rc2 including timestamps, and once with a copy of the old profile, and once with a new and nearly empty profile, without any extensions.

Comment 4

[quazgar]

Attachment: Log with the old profile, TB 3.1rc2, part 1

Comment 5

[quazgar]

Attachment: Log with the old profile, TB 3.1rc2, part 2

Sorry, but the log became rather big.

Comment 6

[WADA:World Anti-bad-Duping Agency]

Does "attaching log again" mean problem still occurs with Tb3.1rc2?
Did you see log data(text file) and compare log data by yourself?

Comment 7

[quazgar]

Yes, the speed has not changed with TB-3.1rc2, as far as I can tell.

Comment 8

[WADA:World Anti-bad-Duping Agency]

Continuous log of RECV: is seen.
However log lines like comment #2 is seen at many many places. It happens even upon first "SEND: TOP 16 20"(retrieve all mail headers and additional 20 lines) after first login.

> 2010-06-21 15:39:20.778750 UTC - -1603500256[150ab20]: Entering NET_ProcessPop3 1362
> 2010-06-21 15:39:20.778818 UTC - -1603500256[150ab20]: POP3: Entering state: 19
> 2010-06-21 15:39:20.778880 UTC - -1603500256[150ab20]: RECV:    attachment..
> (23 lines of RECV: is omitted)
> 2010-06-21 15:39:20.781073 UTC - -1603500256[150ab20]: RECV: 7Vedr5md8x9qQR+2OSRDFPbGPsyQqliZGNh4idtxEkndl71mf2cWDCer1yiKIPA9hv63pqfm
> 2010-06-21 15:39:20.781144 UTC - -1603500256[150ab20]: RECV: (null)

It may be problem like bug 541367 or bug 566548. In your case, receiver = Thunderbird on Mac OS X and sender = POP3 server, and, as you use Mac OS X 10.5, I think TCP Window Scaling is enabled by default.
i.e. Similar to next issue on Vista which is pointed in bug 566548 comment #44.
> (d) http://support.microsoft.com/kb/934430 (expanad "More Information" section)

Do you use SMTP server or IMAP server with SSL enabled? If yes, do you see similar slowness with SMTP sending or IMAP uploading of big mail?

Comment 9

[WADA:World Anti-bad-Duping Agency]

Can you check with TCP Window Scaling disabled? (no need to check with Tb3.1rc.) 
  sudo sysctl -w net.inet.tcp.rfc1323=0
  ( sudo sysctl -w kern.ipc.maxsockbuf=65536 may be required )
> http://www.ecr6.ohio-state.edu/window-scaling.html
> http://www.psc.edu/networking/projects/tcptune/
> http://lima.osu.edu/ots/tb/200711011550 _Mac_OS_X_and_Linux_TCP_Window_Scaling.htm
> http://8help.osu.edu/3562.html

Comment 10

[quazgar]

I send email via SMTP (secured with STARTTLS), and sending is as fast as should be expected, between 0.5 and 2 seconds (with 1MB attachment).  Setting net.inet.tcp.rfc1323 to 0 had no effect.

Comment 11

[WADA:World Anti-bad-Duping Agency]

When did your problem start to occur? After upgrae to Tb 3.0 from Tb 2.0.x?
As log like comment #2 is seen even for first and only fetching of "TOP 16 20" after first login, it may be server side problem.

Comment 12

[WADA:World Anti-bad-Duping Agency]

Can you get socket log too?
> https://developer.mozilla.org/en/HTTP_Logging
> Win sample: SET NSPR_LOG_MODULES=timestamp,pop3:5,nsSocketTransport:5
As log becomes huge, attach log lines for next only, please.
(a) login, LIST/UIDL and responses, "TOP nn 20" if exist, and QUIT.
(b) Downloading of several data lines(several log line sets like comment #2).

Note:
"RECV: (null)" is perhaps "End of data in receive buffer". So, continuous Entering NET_ProcessPop3 N, POP3: Entering state: 17(TOP response, or 19, RETR response), RECV: (null) for 2msec to 5msec means that only one data line arrives per 2-5 msec.
> 2010-06-21 15:39:15.523675 UTC - -1603500256[150ab20]: Entering NET_ProcessPop3 1
> 2010-06-21 15:39:15.523696 UTC - -1603500256[150ab20]: POP3: Entering state: 17
> 2010-06-21 15:39:15.523742 UTC - -1603500256[150ab20]: RECV: Content-Type: application/octet-stream; x-mac-type="0"; x-mac-creator="0";
> 2010-06-21 15:39:15.523820 UTC - -1603500256[150ab20]: RECV: (null)
> 2010-06-21 15:39:15.523891 UTC - -1603500256[150ab20]: Entering NET_ProcessPop3 1
> 2010-06-21 15:39:15.523947 UTC - -1603500256[150ab20]: POP3: Entering state: 17
> 2010-06-21 15:39:15.523958 UTC - -1603500256[150ab20]: RECV: (null)

Comment 13

[quazgar]

I tested for this bug again, now with TB 3.1.1, still on OS X 10.5, still the same behavior (~ 2 minutes for downloading a mail with 1MB attachment).  Apple's Mail.app took "only" ~20 seconds for the same email, which still is slower than the upload (which might be attributed to the mail server) but a lot faster than TB.

During the latest test, the download was canceled in-between somehow, maybe you can find something in the logs.

I'll attach the relevant log file sections, I produced them with "grep -B 20 -A 200 LOGIN" etc., please tell me if you need more info from it.  A first glance at the logs shows that there have probably been two logins, maybe the first was the regular login to check for new mail and the second one from fully downloading the relevant mail with its 1MB attachment.

Comment 14

[quazgar]

Attachment: Parts of the logfile around the requested keywords.

The KEYWORD log excerpts.

Comment 15

[quazgar]

Attachment: Parts of the logfile around the first lines of the attachment

grep -B 100 -A 5000 ZYUsLM0zil8xsm/DKjY2oCZJP pop3_3.1.1_currentProfile.log > pop3_3.1.1_currentProfile.attachment_lines.log

The attachment starts like this:

ZYUsLM0zil8xsm/DKjY2oCZJPSb56HrjmSLNwyVRK60EcCE/QZlfF/wA05OCqaDg670pBOYb
Z/Eaj9nVbKRpjnzQSw9M1BkUF8rKSaxmLz71NTDOm2sIKQVjhyz4u9gnsQfLQpWTB8YJ5+on
aCdG4IptxHBuJq2yl0ur+T73yjvLkL+NGIQ5ZXsV3Ff5E67jiQoQOvHBH1518fhfmLzDy4VD
I9JXaDFRuw5eieRdWDnWXMYZ6sQ+g1xHo3oSswbBN44jXFv9Ij62rn+mLQutsTRC5aO6OCKl

At least these first four lines should have been included in this log file.

Comment 16

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #15)
> Parts of the logfile around the first lines of the attachment

For Tb, data arrives one byte each, even though Tb requests receive with 4096 bytes buffer.  

> 2010-08-02 15:32:42.830525 UTC - -1603500256[150ab20]: RECV: (null)
> 2010-08-02 15:32:42.830537 UTC - -1341116416[1523170]: nsSocketInputStream::OnSocketReady [this=1c5e2ce0 cond=0]
> 2010-08-02 15:32:42.830571 UTC - -1341116416[1523170]: STS dispatch [1a9773e8]
> 2010-08-02 15:32:42.830586 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4096]
> 2010-08-02 15:32:42.830594 UTC - -1341116416[1523170]:   calling PR_Read [count=4096]
> 2010-08-02 15:32:42.830606 UTC - -1341116416[1523170]:   PR_Read returned [n=1]
> 2010-08-02 15:32:42.830613 UTC - -1341116416[1523170]: nsSocketTransport::SendStatus [this=1c5e2c00 status=804b0006]
> 2010-08-02 15:32:42.830622 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4095]
> 2010-08-02 15:32:42.830630 UTC - -1341116416[1523170]:   calling PR_Read [count=4095]
> 2010-08-02 15:32:42.830681 UTC - -1341116416[1523170]:   PR_Read returned [n=-1]
>(snip)
> 2010-08-02 15:32:42.830772 UTC - -1341116416[1523170]: nsSocketInputStream::OnSocketReady [this=1c5e2ce0 cond=0]
> 2010-08-02 15:32:42.830796 UTC - -1341116416[1523170]: STS dispatch [1a9773e8]
> 2010-08-02 15:32:42.830810 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4095]
> 2010-08-02 15:32:42.830819 UTC - -1341116416[1523170]:   calling PR_Read [count=4095]
> 2010-08-02 15:32:42.830830 UTC - -1341116416[1523170]:   PR_Read returned [n=1]
> 2010-08-02 15:32:42.830838 UTC - -1341116416[1523170]: nsSocketTransport::SendStatus [this=1c5e2c00 status=804b0006]
> 2010-08-02 15:32:42.830854 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4094]
> 2010-08-02 15:32:42.830863 UTC - -1341116416[1523170]:   calling PR_Read [count=4094]
> 2010-08-02 15:32:42.830918 UTC - -1341116416[1523170]:   PR_Read returned [n=-1]
> 2010-08-02 15:32:42.830929 UTC - -1341116416[1523170]: nsSocketInputStream::AsyncWait [this=1c5e2ce0]
>(snip)
> 2010-08-02 15:32:42.830999 UTC - -1341116416[1523170]: nsSocketInputStream::OnSocketReady [this=1c5e2ce0 cond=0]
> 2010-08-02 15:32:42.831007 UTC - -1341116416[1523170]: STS dispatch [1a9773e8]
> 2010-08-02 15:32:42.831020 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4094]
> 2010-08-02 15:32:42.831028 UTC - -1341116416[1523170]:   calling PR_Read [count=4094]
> 2010-08-02 15:32:42.831040 UTC - -1341116416[1523170]:   PR_Read returned [n=1]
> 2010-08-02 15:32:42.831048 UTC - -1341116416[1523170]: nsSocketTransport::SendStatus [this=1c5e2c00 status=804b0006]
> 2010-08-02 15:32:42.831056 UTC - -1341116416[1523170]: nsSocketInputStream::Read [this=1c5e2ce0 count=4093]
> 2010-08-02 15:32:42.831064 UTC - -1341116416[1523170]:   calling PR_Read [count=4093]
> 2010-08-02 15:32:42.831078 UTC - -1603500256[150ab20]: Entering NET_ProcessPop3 2
> 2010-08-02 15:32:42.831090 UTC - -1603500256[150ab20]: POP3: Entering state: 19
> 2010-08-02 15:32:42.831099 UTC - -1603500256[150ab20]: RECV: (null)

Client side(Tb side) TCP Window size is too large for router?
Have you checked with small maxsockbuf?
  ( sudo sysctl -w kern.ipc.maxsockbuf=???? may be required )
Can you check with small maxsockbuf such as 4096, 8192 16384?

Comment 17

[quazgar]

I tried with lower values for maxsockbuf (originally at 8388608), I was able to go down to 512 kiB, lower values would seemingly not allow DNS resolution any more.  Even that value didn't change anything about the download speed.

Comment 18

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #17)
> I tried with lower values for maxsockbuf (originally at 8388608), I was able to
> go down to 512 kiB, lower values would seemingly not allow DNS resolution any more.

I see.
As no problem in SMTP sending, if TCP Window size related and router related issue, it may be server side router issue. 
Can you check with Gmail's POP3? (get free Gmail account, please)

Comment 19

[quazgar]

Gmail works as expected, i.e. it needs only a few seconds to download this 1MB message.  I would have been surprised if it had been different, since if Apple Mail manages that, it should be no problem for another client like whatever Google uses as back end.

Comment 20

[WADA:World Anti-bad-Duping Agency]

Following is greeting in POP3 log.
> 2010-06-21 15:39:11.686866 UTC - -1603500256[150ab20]: RECV: +OK Cubic Circle's v1.31 1998/05/13 POP3 ready <a81a00009f871f4c@mailbox>

Is the POP3 server maintained well? No maintenance since 1998?
AFAIK, GMX provides POP3 server access and SMTP server access even for free GMX account. Can you check with GMX's POP3 server?

Comment 21

[quazgar]

(In reply to comment #18)
> Can you check with Gmail's POP3? (get free Gmail account, please)

Sorry, I think I misunderstood that request at first.  I thought you wanted to ask to check if gmail can fetch mails from our mail server in the expected time (which it did).

But indeed you probably rather wanted to test if my Thunderbird can download mails from gmail without problems?

I just tested this and it seems that there's no speed problem involved in that case.

Thank you for the hints so far, I think that now it's time to contact our mail server admins and ask if they have any idea about this.  (Unfortunately the only alternative they offer to the (old indeed) unix server is an MS Exchange server...)

Comment 22

[quazgar]

I checked with our mail server admins and they assured me that they had not changed anything about their configurations.  To me this looks as if the bug is back to Thunderbird again now.

(IMAP works without issues, but that's irrelevant here I think.)

Comment 23

[Wayne Mery (:wsmwk)]

daniel, has the situation changed?

Comment 24

[quazgar]

(In reply to Wayne Mery (:wsmwk) from comment #23)
> daniel, has the situation changed?

I'm sorry I can't answer that since I don't have any Thunderbird in use currently. UNCONFIRMED seems appropriate in this state, I think.