You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Paul Sutton <pa...@eu.c2.net> on 1998/01/11 17:43:16 UTC
Win32 network glitch
Help! Every so often Apache in Win32 slows down for a few seconds when
subject to serial repeated hits. I've taken a tcpdump but I'm not familiar
enough with TCP to know whether this is a bug in NT's tcp stuff. Could
someone have a look please?
In more detail, I've written a perl script which repeatly connects to a
server, requests a document, reads the response, and disconnections. I've
been using this to test for resource leaks etc on Apache NT. But every so
often (say around 50-300 requests, although it doesn't seem to be
determinable), the "connect" call will take several seconds to complete.
Sometimes it goes back to normal after the connect completes, at other
times serveral more connects (up to about ten) will also be "slow" before
it goes back to normal speed. The client here is running on Linux 2.0.29.
Now I thought I'd use tcpdump to see what part of the connection is slow,
and the result is in the attachment. The first request is ok, then at
16:17:27.290000 it starts a new connect. The next few lines logged are
(ecstasy.localnet is the Linux client, beavis.localnet is the NT Apache
server, the request is 12 bytes long, the response 46750):
16:17:27.290000 ecstasy.localnet.1819 > beavis.localnet.8001: S 769576620:769576
620(0) win 512 <mss 1460>
16:17:27.290000 beavis.localnet.8001 > ecstasy.localnet.1819: . ack 13 win 8749
(DF)
16:17:27.290000 ecstasy.localnet.1819 > beavis.localnet.8001: R 745127567:745127
567(0) win 0
16:17:30.290000 ecstasy.localnet.1819 > beavis.localnet.8001: S 769576620:769576
620(0) win 31744 <mss 1460>
16:17:30.290000 beavis.localnet.8001 > ecstasy.localnet.1819: S 79075915:7907591
5(0) ack 769576621 win 8760 <mss 1460> (DF)
16:17:30.290000 ecstasy.localnet.1819 > beavis.localnet.8001: . ack 1 win 31744
It looks to me like the Linux client (ecstasy) is initiating the
connection, but the NT server is not acknowledging it correctly -- the ack
13 is the sequence number of the _previous_ connection which has just been
closed down... here are the tcpdump lines just prior to the above lines:
16:17:27.270000 beavis.localnet.8001 > ecstasy.localnet.1814: F 46751:46751(0) a
ck 12 win 8749 (DF)
16:17:27.270000 ecstasy.localnet.1814 > beavis.localnet.8001: . ack 46752 win 31
744
16:17:27.270000 ecstasy.localnet.1814 > beavis.localnet.8001: F 12:12(0) ack 467
52 win 31744
16:17:27.270000 beavis.localnet.8001 > ecstasy.localnet.1814: . ack 13 win 8749
(DF)
Note that the last line is identical to the one that the NT server sends
again at 16:17:27.290000 -- except that the second time it goes to port
1819 on the Linux client rather than 1814. This is obviously out of
sequence on port 1819 since no data has been sent, so Linux sends a reset
for this connection, and tries again three seconds later. The time the
connection works -- NT acknowledges with a SYN package.
Is this a correct interpretation? If so, does it mean that this is an NT
winsock bug because it is sending an ack to the wrong port after the
closedown of a previous connection? But if that was the case surely every
network service would have hit this problem and it would be widely known?
//pcs
Re: Win32 network glitch
Posted by Marc Slemko <ma...@worldgate.com>.
On Mon, 12 Jan 1998, Paul Sutton wrote:
> Oh, ok. Thanks for the analysis. So it is not something to get
> particularly upset about, then? But is does make stress testing more
Right.
> difficult -- is there any way to force Linux to use a larger range of
> ports for the connection requests? Are other operating systems better for
> this?
It depends what it is using. You can pick the port you want to (try to)
use and cycle through them that way.
You could also try decreasing the 2*MSL timer on your NT box, but that is
bogus to have to do and is seldom a good idea.
Re: Win32 network glitch
Posted by Paul Sutton <pa...@eu.c2.net>.
On Sun, 11 Jan 1998, Marc Slemko wrote:
> On Sun, 11 Jan 1998, Paul Sutton wrote:
> > 16:17:27.290000 beavis.localnet.8001 > ecstasy.localnet.1819: . ack 13 win 8749
> > (DF)
>
> This looks like there is a connection in TIME_WAIT on the server so it
> sends an ACK on the old connection since the SYN isn't in the window.
Um, I should have used netstat on NT I guess to see how many TIME_WAITs
there were.
> > 1819 on the Linux client rather than 1814. This is obviously out of
> > sequence on port 1819 since no data has been sent, so Linux sends a reset
> > for this connection, and tries again three seconds later. The time the
> > connection works -- NT acknowledges with a SYN package.
> >
> > Is this a correct interpretation? If so, does it mean that this is an NT
> > winsock bug because it is sending an ack to the wrong port after the
> > closedown of a previous connection? But if that was the case surely every
> > network service would have hit this problem and it would be widely known?
>
> No, the two connections are unrelated. You are being tricked by tcpdump's
> relative sequence numbers. Use -S to see the real story.
>
> Take a longer term tcpdump and see when the _previous_ connection from the
> client to the server on that port was. I would bet it is <2*MSL so you
> still have it hanging around in TIME_WAIT.
>
> Nothing that you would normally see unless one client is making a lot of
> requests to one server.
Oh, ok. Thanks for the analysis. So it is not something to get
particularly upset about, then? But is does make stress testing more
difficult -- is there any way to force Linux to use a larger range of
ports for the connection requests? Are other operating systems better for
this?
//pcs
Re: Win32 network glitch
Posted by Paul Sutton <pa...@eu.c2.net>.
On Sun, 11 Jan 1998, Dean Gaudet wrote:
> On Sun, 11 Jan 1998, Marc Slemko wrote:
> > Nothing that you would normally see unless one client is making a lot of
> > requests to one server.
>
> I believe It's essentially a 15-bit counter that has to be wrapped around
> on the linux side, but I'm not sure. Given that and the length of the
> test you could figure out how many r/s this amounts to.
Ah, well, I don't think I did more than about 10,000 requests against a
particular remote port on NT (I changed the server's listen port several
times to see if the problem with repeatable on a "fresh" port). I'll have
another go.
> One way around the problem would be to add some aliases to eth0 on the
> linux box and bind your client to multiple local addresses directly and
> use all the sockets in a round robin fashion.
Oh yeah, good idea. I'll try that. I guess I could also get Apache NT to
listen on multiple ports and cycle through them (although I deliberately
avoiding used multiple listens in my recent tests, to avoid any problems
related to that).
//pcs
Re: Win32 network glitch
Posted by Dean Gaudet <dg...@arctic.org>.
On Sun, 11 Jan 1998, Marc Slemko wrote:
> Nothing that you would normally see unless one client is making a lot of
> requests to one server.
I believe It's essentially a 15-bit counter that has to be wrapped around
on the linux side, but I'm not sure. Given that and the length of the
test you could figure out how many r/s this amounts to.
One way around the problem would be to add some aliases to eth0 on the
linux box and bind your client to multiple local addresses directly and
use all the sockets in a round robin fashion.
Dean
Re: Win32 network glitch
Posted by Marc Slemko <ma...@worldgate.com>.
On Sun, 11 Jan 1998, Paul Sutton wrote:
> Help! Every so often Apache in Win32 slows down for a few seconds when
> subject to serial repeated hits. I've taken a tcpdump but I'm not familiar
> enough with TCP to know whether this is a bug in NT's tcp stuff. Could
> someone have a look please?
>
> In more detail, I've written a perl script which repeatly connects to a
> server, requests a document, reads the response, and disconnections. I've
> been using this to test for resource leaks etc on Apache NT. But every so
> often (say around 50-300 requests, although it doesn't seem to be
> determinable), the "connect" call will take several seconds to complete.
> Sometimes it goes back to normal after the connect completes, at other
> times serveral more connects (up to about ten) will also be "slow" before
> it goes back to normal speed. The client here is running on Linux 2.0.29.
>
> Now I thought I'd use tcpdump to see what part of the connection is slow,
> and the result is in the attachment. The first request is ok, then at
> 16:17:27.290000 it starts a new connect. The next few lines logged are
> (ecstasy.localnet is the Linux client, beavis.localnet is the NT Apache
> server, the request is 12 bytes long, the response 46750):
>
> 16:17:27.290000 ecstasy.localnet.1819 > beavis.localnet.8001: S 769576620:769576
> 620(0) win 512 <mss 1460>
Good.
> 16:17:27.290000 beavis.localnet.8001 > ecstasy.localnet.1819: . ack 13 win 8749
> (DF)
This looks like there is a connection in TIME_WAIT on the server so it
sends an ACK on the old connection since the SYN isn't in the window.
In this case, most BSD stacks would follow section 4.2.2.13 of RFC-1122:
When a connection is closed actively, it MUST linger in
TIME-WAIT state for a time 2xMSL (Maximum Segment Lifetime).
However, it MAY accept a new SYN from the remote TCP to
reopen the connection directly from TIME-WAIT state, if it:
(1) assigns its initial sequence number for the new
connection to be larger than the largest sequence
number it used on the previous connection incarnation,
and
(2) returns to TIME-WAIT state if the SYN turns out to be
an old duplicate.
so you don't have this problem. Although I don't think Linux implements
this either...
> 16:17:27.290000 ecstasy.localnet.1819 > beavis.localnet.8001: R 745127567:745127
> 567(0) win 0
The Linux box logically says "what the heck is this?"
> 16:17:30.290000 ecstasy.localnet.1819 > beavis.localnet.8001: S 769576620:769576
> 620(0) win 31744 <mss 1460>
...and resends the syn once it times out.
> 16:17:30.290000 beavis.localnet.8001 > ecstasy.localnet.1819: S 79075915:7907591
> 5(0) ack 769576621 win 8760 <mss 1460> (DF)
This time it is ok because the previous connection attempt has (bogusly)
assasinated the TIME_WAIT connection. Well, I guess it could have just
timed out but ISTR that NT does early assassination.
> 16:17:30.290000 ecstasy.localnet.1819 > beavis.localnet.8001: . ack 1 win 31744
>
> It looks to me like the Linux client (ecstasy) is initiating the
> connection, but the NT server is not acknowledging it correctly -- the ack
> 13 is the sequence number of the _previous_ connection which has just been
> closed down... here are the tcpdump lines just prior to the above lines:
No, it isn't. Do a tcpdump -S and you will probably find them wildly
different.
>
> 16:17:27.270000 beavis.localnet.8001 > ecstasy.localnet.1814: F 46751:46751(0) a
> ck 12 win 8749 (DF)
> 16:17:27.270000 ecstasy.localnet.1814 > beavis.localnet.8001: . ack 46752 win 31
> 744
> 16:17:27.270000 ecstasy.localnet.1814 > beavis.localnet.8001: F 12:12(0) ack 467
> 52 win 31744
> 16:17:27.270000 beavis.localnet.8001 > ecstasy.localnet.1814: . ack 13 win 8749
> (DF)
>
> Note that the last line is identical to the one that the NT server sends
> again at 16:17:27.290000 -- except that the second time it goes to port
> 1819 on the Linux client rather than 1814. This is obviously out of
> sequence on port 1819 since no data has been sent, so Linux sends a reset
> for this connection, and tries again three seconds later. The time the
> connection works -- NT acknowledges with a SYN package.
>
> Is this a correct interpretation? If so, does it mean that this is an NT
> winsock bug because it is sending an ack to the wrong port after the
> closedown of a previous connection? But if that was the case surely every
> network service would have hit this problem and it would be widely known?
No, the two connections are unrelated. You are being tricked by tcpdump's
relative sequence numbers. Use -S to see the real story.
Take a longer term tcpdump and see when the _previous_ connection from the
client to the server on that port was. I would bet it is <2*MSL so you
still have it hanging around in TIME_WAIT.
Nothing that you would normally see unless one client is making a lot of
requests to one server.