129364 - Mac: ftp file download painfully slow

Status: VERIFIED FIXED

(Core Graveyard :: File Handling, defect, P1)

Description

[sairuh (rarely reading bugmail)]

i have recently noticed that downloading files onto my mac --a blue/white 450mhz
G3, 384M RAM, mac os x 10.1.3-- is quite slow!

not sure if this is the same as bug 128553, since the download here doesn't
actually fail. it just takes an awfully long time.

the following tests are using a 35M file (the mozilla source in a gzip file)
located at:

FTP link:
ftp://ftp.mozilla.org/pub/mozilla/nightly/2002-03-06-08-trunk/mozilla-source.tar.gz

HTTP link (sorry, internal only):
http://hopey.mcom.com/tests/mozilla-source.tar.gz

i did a "save link as" (from context menu) for the above links and saved the
file to the desktop.

i'll post the numbers shortly...

Comment 1

[sairuh (rarely reading bugmail)]

here are some data...will get today's info in a bit, but i imagine they're
pretty similar to the 2/21 data below. these are based on commercial OS X verif
builds, except where noted.

                 FTP               HTTP
-----------------------------------------------
IE 5.1           20.76sec          15.89sec
2002.02.04.17    13.51sec          27.84sec
2002.02.14.08    15.09sec          24.53sec
2002.02.21.08    3min 48.56sec     24.64sec

Comment 2

[Bradley Baetz (:bbaetz)]

I checked in something to ftp at 6pm on the 19th, but that would only affect
directory listings.

Is this reproducable? Can you work out when it started? Looking at checkins to
necko doesn't show anything suspicious, really.

Comment 3

[sairuh (rarely reading bugmail)]

yes, this is reproducible. looks like it's limited to Mac, too, as i haven't
seen similar behavior on linux or win2k.

i'll try to narrow down the time period (2/14-2/21) later on.

Comment 4

[Boris Zbarsky [:bzbarsky]]

see also bug 128927

Comment 5

[Simon Fraser [no longer active]]

If I were to hazard a guess, I'd point at the fix for bug 121951 as the cause.
Does the timing check out?

Comment 6

[sairuh (rarely reading bugmail)]

it does look like this occurred after bug 121951 was fixed. over to sfraser for
the nonce...

                      FTP                     HTTP
------------------------------------------------------
2002.02.18.12         15.64sec                25.40sec
2002.02.19.11         3min 48.53sec           24.61sec
2002.03.06.08 (today) 7min 53.64sec (ouch!)   25.29sec

Comment 7

[Asa Dotzler [:asa]]

would like to get this into 0.9.9. adding it to the tracker so we don't forget.

Comment 8

[Arthur]

Do we already have a bug for the bad http-performance compared to IE as to be
seen in comment #1? I couldn't find one.

Comment 9

[Simon Fraser [no longer active]]

*** Bug 128553 has been marked as a duplicate of this bug. ***

Comment 10

[Simon Fraser [no longer active]]

This is regression from the checkin for bug 121951. The problem is this:

There is a window of time in _MD_poll when an OT notifer can hit, but we still go 
ahead and sleep the thread anyway. This happens because we don't call 
SetDescPollThread(pds, npds, thread) early enough, so the poll descriptors have 
no read or writing thread set on them, and thus the NotifierRoutine has no thread 
to wake up, or set flags on.

Comment 11

[Paul Bergsagel]

I am questioning if bug 128553 is a duplicate of this bug. I did not report a
painfully slow download, but a download which stopped part way through the
download and will not restart. If by painfully slow, you mean the download can
be restarted by clicking on another link, maybe, but in a few seconds the
download stalls again. If you are claiming my original bug can be reworded as "a
painfully slow download", this is not the bug I reported. I reported a bug in
downloads which stoped and would not start again on their own, although possibly
by clicking another link.  

IMHO this bug is not a dupe of bug 128553 . It may be similar enough to warrant
working on their fix together, but the bug 126553 is definitely not a dupe of
this bug! I did not report a slow download, but a stalled (stopped) download.

Comment 12

[Simon Fraser [no longer active]]

Attachment: First cut at a patch

Comment 13

[Simon Fraser [no longer active]]

Whole of _MD_Poll() with patch in attachment 73292 [details] [diff] [review], for clarity:

PRInt32 _MD_poll(PRPollDesc *pds, PRIntn npds, PRIntervalTime timeout)
{
    PRInt16     readFlagsArray[DESCRIPTOR_FLAGS_ARRAY_SIZE];
    PRInt16     writeFlagsArray[DESCRIPTOR_FLAGS_ARRAY_SIZE];
    
    PRInt16     *readFlags  = readFlagsArray;
    PRInt16     *writeFlags = writeFlagsArray;

    PRInt16     *ioFlags = NULL;
    
    PRThread    *thread = _PR_MD_CURRENT_THREAD();
    PRInt32     ready;
    
    if (npds > DESCRIPTOR_FLAGS_ARRAY_SIZE)
    {
        // we allocate a single double-size array. The first half is used
        // for read flags, and the second half for write flags.
        ioFlags = (PRInt16*)PR_Malloc(sizeof(PRInt16) * npds * 2);
        if (!ioFlags)
        {
            PR_SetError(PR_OUT_OF_MEMORY_ERROR, 0);
            return -1;
        }
        
        readFlags = ioFlags;
        writeFlags = &ioFlags[npds];
    }
    
    (void)CheckPollDescMethods(pds, npds, readFlags, writeFlags);
    (void)CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);
    ready = CountReadyPollDescs(pds, npds);

    if (timeout != PR_INTERVAL_NO_WAIT) {
        if (ready == 0) {
            intn        is;
            
            // It's important here that we don't wait after a notification
            // has come in, so we have to disable interrupts and enter the
            // lock (see comments in DoneWaitingOnThisThread()) while we
            // check a second time to see if any endpoints have data.
            // Note that we need to set up the poll thread on the poll descs
            // before checking endpoint state, to ensure that notifications
            // are not missed.
            
            _PR_INTSOFF(is);
            PR_Lock(thread->md.asyncIOLock);
            PrepareForAsyncCompletion(thread, 0);
            
            SetDescPollThread(pds, npds, thread);
            
            ready = CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);

            PR_Unlock(thread->md.asyncIOLock);
            _PR_INTSON(is);

            if (ready == 0) {
                WaitOnThisThread(thread, timeout);

                // since we may have been woken by a pollable event
                // firing, we have to check both poll methods and
                // endpoints.
                (void)CheckPollDescMethods(pds, npds, readFlags, writeFlags);
                (void)CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);
                ready = CountReadyPollDescs(pds, npds);

                SetDescPollThread(pds, npds, NULL);
            }
            else {
                thread->io_pending = PR_FALSE;            
            }

            SetDescPollThread(pds, npds, NULL);
        }
    }

    if (readFlags != readFlagsArray)
        PR_Free(ioFlags);
    
    return ready;
}

Comment 14

[Simon Fraser [no longer active]]

Paul: the cause is almost certainly the same.

Comment 15

[Simon Fraser [no longer active]]

Attachment: Somewhat condensed version of the code

Comment 16

[Simon Fraser [no longer active]]

Wanted for 99

Comment 17

[sairuh (rarely reading bugmail)]

when i saw this bug, download appeared to stall for a long time, then continue,
then stall again, then continue... i did not click anywhere like a link while
observing this --just started the download, turned on the timer and watched and
watched...till it finally completed.

Comment 18

[Simon Fraser [no longer active]]

Attachment: Final patch

This patch differs from previous one only in using PR_FAST_INTSON() rather than
PR_INTSON() which fixes a stalling issue on Mac OS X (which may actually have
been a somewhat unrelated bug and more like bug 129364). I tested lots of big
FTP downloads, secure sites, IMAP, SMTP. Everything works.

Comment 19

[Wan-Teh Chang]

Comment on attachment 73325 [details] [diff] [review]
Final patch

r=wtc.

Comment 20

[Simon Fraser [no longer active]]

Entire function with the final patch:

PRInt32 _MD_poll(PRPollDesc *pds, PRIntn npds, PRIntervalTime timeout)
{
    PRInt16     readFlagsArray[DESCRIPTOR_FLAGS_ARRAY_SIZE];
    PRInt16     writeFlagsArray[DESCRIPTOR_FLAGS_ARRAY_SIZE];
    
    PRInt16     *readFlags  = readFlagsArray;
    PRInt16     *writeFlags = writeFlagsArray;

    PRInt16     *ioFlags = NULL;
    
    PRThread    *thread = _PR_MD_CURRENT_THREAD();
    PRInt32     ready;
    
    if (npds > DESCRIPTOR_FLAGS_ARRAY_SIZE)
    {
        // we allocate a single double-size array. The first half is used
        // for read flags, and the second half for write flags.
        ioFlags = (PRInt16*)PR_Malloc(sizeof(PRInt16) * npds * 2);
        if (!ioFlags)
        {
            PR_SetError(PR_OUT_OF_MEMORY_ERROR, 0);
            return -1;
        }
        
        readFlags = ioFlags;
        writeFlags = &ioFlags[npds];
    }
    
    if (timeout != PR_INTERVAL_NO_WAIT) {
        intn        is;
        
        // we have to be outside the lock when calling this, since
        // it can call arbitrary user code (including other socket
        // entry points)
        (void)CheckPollDescMethods(pds, npds, readFlags, writeFlags);

        _PR_INTSOFF(is);
        PR_Lock(thread->md.asyncIOLock);
        PrepareForAsyncCompletion(thread, 0);

        SetDescPollThread(pds, npds, thread);

        (void)CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);
        
        PR_Unlock(thread->md.asyncIOLock);
        _PR_FAST_INTSON(is);

        ready = CountReadyPollDescs(pds, npds);

        if (ready == 0) {
            WaitOnThisThread(thread, timeout);

            // since we may have been woken by a pollable event firing,
            // we have to check both poll methods and endpoints.
            (void)CheckPollDescMethods(pds, npds, readFlags, writeFlags);
            (void)CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);
            ready = CountReadyPollDescs(pds, npds);
        }

        thread->io_pending = PR_FALSE;
        SetDescPollThread(pds, npds, NULL);
    }
    else {
        (void)CheckPollDescMethods(pds, npds, readFlags, writeFlags);
        (void)CheckPollDescEndpoints(pds, npds, readFlags, writeFlags);
        ready = CountReadyPollDescs(pds, npds);    
    }

    if (readFlags != readFlagsArray)
        PR_Free(ioFlags);
    
    return ready;
}

Comment 21

[Simon Fraser [no longer active]]

Checked in on the Mozilla 0.9.9 branch and NSPR tip. Awaiting driver approval
for the Mozilla trunk.

Comment 22

[Asa Dotzler [:asa]]

Comment on attachment 73325 [details] [diff] [review]
Final patch

a=asa (on behalf of drivers) for checkin to the 0.9.9 branch and the 1.0 trunk

Comment 23

[Simon Fraser [no longer active]]

Checked into the trunk (NSPRPUB_PRE_4_2_CLIENT_BRANCH)

Comment 24

[Chris Petersen]

Verified in the 2003-01-12-03 CFM trunk build.