Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
Date: Mon, 25 Aug 2003 11:43:36 -0700 (PDT)
From: Teng Xu <txu@cse.ucsc.edu>
To: "William A. Rowe, Jr." <wrowe@rowe-clan.net>
cc: dev@httpd.apache.org, Greg Stein <gstein@lyra.org>, <fielding@apache.org>,
        <txu@soe.ucsc.edu>, <ejw@cse.ucsc.edu>
Subject: Re: Strangely long poll() times
In-Reply-To: <5.2.0.9.2.20030823013018.0164e058@pop3.rowe-clan.net>
Message-ID: <Pine.GSO.4.44.0308242159090.17623-100000@kaiken.cse.ucsc.edu>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII


On Sat, 23 Aug 2003, William A. Rowe, Jr. wrote:

> At 06:59 PM 8/22/2003, Jim Whitehead wrote:
>
> >>From what we can tell, the call sequence looks like this:
> >
> >method_propfind --> ap_xml_parse_input --> ap_get_brigade -->
> >core_input_filter --> apr_bucket_read --> socket_bucket_read -->
> >apr_socket_recv --> apr_wait_for_io_or_timeout --> apr_poll --> poll
> >
> >What we found was that just poll() was taking about 31milliseconds, and the
> >rest of the functions took only microseconds. Poll acts somewhat like
> >select(), and we verified that there was only one file description active at
> >the time. Both client and server were on the same local subnet (100Base-T
> >wiring), and the PROPFIND request body was relatively small, around
> >1500-2500 bytes (we tested for different numbers of properties being
> >requested by PROPFIND, hence the variation).
> >
> >Strangely, when we request 1, 2, 3, ... or 14 properties per request, we see
> >this behavior (long poll() response times). But, as soon as we request 15
> >properties, things speed up dramatically, to appx. 3-5ms.
>
> Sure sounds like nagling is turned on on the client side.

I seems not the effect of nagling, as the experiment data almost didn't
change after the nagle algorithm was disabled (the TCP_NODELAY is "on").
To make clear what happened in the client side, I dived into neon library and
found the call sequence looks like this:

ne_request_dispatch --> ne_begin_request --> send_request -->
open_connection --> do_connect --> ne_sock_connect --> select

As you can imagine, the strange behavior on the client side is very
similar to that on server side, as the select() call was taking about
35 milliseconds and the rest of the functions took only microseconds.


-Teng