Strangely long poll() times

[Jim Whitehead <ej...@cse.ucsc.edu>]

All,

Teng Xu, a graduate student working with me, has been developing a WebDAV
performance testing client. Some of the results he received were a bit
puzzling -- small PROPFIND operations were taking far longer (appx. 40-45ms)
than we had expected. So, we started looking into the components of this
time on the server side. We initially suspected the problem might be XML
parsing, but quickly found this not to be the case.

>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.

So, the good news is that XML parsing isn't hosing our performance. But, it
does seem that there is some problem in poll() for relatively small request
bodies that is a large impact on performance. But, the silver lining is that
fixing this problem (assuming it's real, and we're not smoking something)
could result in an order of magnitude improvement in several important
WebDAV methods (PROPFIND is used to get directory listings, for example).

I imagine there will be follow-up questions -- please address them to Teng
(cc'ed), as I will be out of email contact for the next week, attending the
ACM Hypertext conference.

- Jim Whitehead

Re: Strangely long poll() times

[gr...@apache.org]

Jim Whitehead wrote:
> All,
> 
> Teng Xu, a graduate student working with me, has been developing a WebDAV
> performance testing client. Some of the results he received were a bit
> puzzling -- small PROPFIND operations were taking far longer (appx. 40-45ms)
> than we had expected. So, we started looking into the components of this
> time on the server side. We initially suspected the problem might be XML
> parsing, but quickly found this not to be the case.
> 
>>>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

A packet trace (i.e. tcpdump) would help.  It is network i/o related for sure. 
My first guess was the same as wrowe's - nagle.

Greg

Re: Strangely long poll() times

[Teng Xu <tx...@cse.ucsc.edu>]

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

Re: Strangely long poll() times

["William A. Rowe, Jr." <wr...@rowe-clan.net>]

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.

Bill

Re: Strangely long poll() times

[Teng Xu <tx...@cse.ucsc.edu>]

We made experiments on two different machines. Here are some experiment
setups, hope they will be helpful:

#MachineOne - Dell OptiPlex GX240
- O/S: Red Hat Linux 2.4.20
- CPU: P4 1.7GHZ
- MEM: 512M
- NIC: Integrated 3Com Fast EtherLink 10/100
- Hard Drives: WDC 40GB

#MachineTwo - Dell Dimension 4100
- O/S: Red Hat Linux 2.4.18
- CPU: P3 1GHZ
- MEM: 256M
- NIC: Integrated Ethernet 10/100
- Hard Drives: Maxtor 50GB


Regards,

-Teng



One is Dell Dimension 4100
with Redhat Linux 2.4.18, the other is Dell OptiPlex GX240

On Fri, 22 Aug 2003, Aaron Bannert wrote:

> Can you tell us more about the operating systems and the hardware
> (drivers,
> network cards, etc)?
>
> -aaron
>
>
> On Friday, August 22, 2003, at 04:59  PM, Jim Whitehead wrote:
> > Teng Xu, a graduate student working with me, has been developing a
> > WebDAV
> > performance testing client. Some of the results he received were a bit
> > puzzling -- small PROPFIND operations were taking far longer (appx.
> > 40-45ms)
> > than we had expected. So, we started looking into the components of
> > this
> > time on the server side. We initially suspected the problem might be
> > XML
> > parsing, but quickly found this not to be the case.
> > [...]
>

Re: Strangely long poll() times

[Aaron Bannert <aa...@clove.org>]

Can you tell us more about the operating systems and the hardware 
(drivers,
network cards, etc)?

-aaron


On Friday, August 22, 2003, at 04:59  PM, Jim Whitehead wrote:
> Teng Xu, a graduate student working with me, has been developing a 
> WebDAV
> performance testing client. Some of the results he received were a bit
> puzzling -- small PROPFIND operations were taking far longer (appx. 
> 40-45ms)
> than we had expected. So, we started looking into the components of 
> this
> time on the server side. We initially suspected the problem might be 
> XML
> parsing, but quickly found this not to be the case.
> [...]