Subject: Re: More information on TCP response of netBSD tcp stack? =]
To: Marc Tooley <sudog@sudog.com>
From: venkat venkatsubra <venkats@austin.ibm.com>
List: tech-net
Date: 09/19/2000 10:02:43
Marc,
I haven't looked at your earlier mails so
i don't know if window scaling is used.
But looking at the traces here, the sender
stops sending because the window of
17520 bytes is full. And seems like  packets
are dropped in all the cases.  The 'Fast Retransmit'
feature on the sender side tcp waits for 3 duplicate
ACKs before it decides to retransmit the packet.
You changed the recv space on the sending side
or the receiving side ? It should be changed on the receiving
side. But you might still see the same delay for recovering
from a dropped packet.
Venkat


Marc Tooley wrote:

> NetBSD-1.5_ALPHA2:
>
> Me again. So I have a tcpdump from the netbsd server side of a
> transfer of data and a tcp desync. Same behaviour--weirdnesses abound:
>
> 16:45:16.399119 216.86.104.111.57379 > 24.66.169.45.60312: . 34329:35777(1448) ack 1 win 34020 <nop,nop,timestamp 2376509 0> (DF)
> 16:45:16.407344 24.66.169.45.60312 > 216.86.104.111.57379: . ack 19849 win 17520 <nop,nop,timestamp 3814217 2376508> [tos 0x8]
> 16:45:16.407427 216.86.104.111.57379 > 24.66.169.45.60312: . 35777:37225(1448) ack 1 win 34020 <nop,nop,timestamp 2376509 0> (DF)
> 16:45:16.423354 24.66.169.45.60312 > 216.86.104.111.57379: . ack 19849 win 17520 <nop,nop,timestamp 3814217 2376508> [tos 0x8]
> 16:45:16.428693 24.66.169.45.60312 > 216.86.104.111.57379: . ack 19849 win 17520 <nop,nop,timestamp 3814217 2376508> [tos 0x8]
> 16:45:16.432438 24.66.169.45.60312 > 216.86.104.111.57379: . ack 19849 win 17520 <nop,nop,timestamp 3814217 2376508> [tos 0x8]
> 16:45:16.432507 216.86.104.111.57379 > 24.66.169.45.60312: . 19849:21297(1448) ack 1 win 34020 <nop,nop,timestamp 2376509 0> (DF)
>
> So the sender here is dishing out data at a good clip--until a packet
> or two goes missing..  client is returning ack for last known good
> packet, but some of the timings don't feel right to me. Of course,
> I've never touched a TCP stack and am looking at it from a user's
> perspective..  but still:
>
> The server appears to halt sending data at 16.407427..  it receives a
> repeated ack.. and doesn't send out another packet for a full 25 ms.
>
> Seems to me this is a lot of wasted time that could otherwise be used
> for data transmission..?
>
> I thought that perhaps this was due to a 34K send/recv space. Changing
> it with sysctl -w and I get (this is a tcpdump from the server-side
> now):
>
> 17:20:21.939942 216.86.104.111.57213 > 24.66.169.45.60355: . 50257:51705(1448) ack 1 win 65535 <nop,nop,timestamp 2380720 0> (DF)
> 17:20:21.944103 24.66.169.45.60355 > 216.86.104.111.57213: . ack 35777 win 17520 <nop,nop,timestamp 3818429 2380720> [tos 0x8]
> 17:20:21.944168 216.86.104.111.57213 > 24.66.169.45.60355: . 51705:53153(1448) ack 1 win 65535 <nop,nop,timestamp 2380720 0> (DF)
> 17:20:21.948490 24.66.169.45.60355 > 216.86.104.111.57213: . ack 35777 win 17520 <nop,nop,timestamp 3818429 2380720> [tos 0x8]
> 17:20:21.952273 24.66.169.45.60355 > 216.86.104.111.57213: . ack 35777 win 17520 <nop,nop,timestamp 3818429 2380720> [tos 0x8]
> 17:20:21.955752 24.66.169.45.60355 > 216.86.104.111.57213: . ack 35777 win 17520 <nop,nop,timestamp 3818429 2380720> [tos 0x8]
> 17:20:21.955794 216.86.104.111.57213 > 24.66.169.45.60355: . 35777:37225(1448) ack 1 win 65535 <nop,nop,timestamp 2380720 0> (DF)
>
> Similar thing: time between the two transmissions is 21.955794 -
> 21.944168 = 11.6 ms..
>
> It varies..  sometimes it's as low as 10 ms, sometimes it's up around
> 45 ms..  seems to me the server could be sending data during this
> period.
>
> One more for completeness (similar tcpdump running server-side, same
> big net.inet.tcp.sendspace = 65535):
>
> 17:37:21.457582 216.86.104.111.57129 > 24.66.169.45.60372: . 18401:19849(1448) ack 1 win 65535 <nop,nop,timestamp 2382759 0> (DF)
> 17:37:21.484328 24.66.169.45.60372 > 216.86.104.111.57129: . ack 9713 win 17520 <nop,nop,timestamp 3820468 2382759> [tos 0x8]
> 17:37:21.484403 216.86.104.111.57129 > 24.66.169.45.60372: . 19849:21297(1448) ack 1 win 65535 <nop,nop,timestamp 2382759 0> (DF)
> 17:37:21.484433 216.86.104.111.57129 > 24.66.169.45.60372: . 21297:22745(1448) ack 1 win 65535 <nop,nop,timestamp 2382759 0> (DF)
> 17:37:21.493893 24.66.169.45.60372 > 216.86.104.111.57129: . ack 9713 win 17520 <nop,nop,timestamp 3820468 2382759> [tos 0x8]
> 17:37:21.505460 24.66.169.45.60372 > 216.86.104.111.57129: . ack 9713 win 17520 <nop,nop,timestamp 3820468 2382759> [tos 0x8]
> 17:37:21.520176 24.66.169.45.60372 > 216.86.104.111.57129: . ack 9713 win 17520 <nop,nop,timestamp 3820468 2382759> [tos 0x8]
> 17:37:21.520221 216.86.104.111.57129 > 24.66.169.45.60372: . 9713:11161(1448) ack 1 win 65535 <nop,nop,timestamp 2382759 0> (DF)
>
> Time between transfers is different here--quite a bit larger:
> 21.520221 - 21.484433 = 35.7 ms..  pretty nasty with these pauses..
>
> It's just a plain ol' ftp transfer..  could my RAIDFrame disks not be
> supplying data fast enough? Nope..  there's no block i/o, all zeros.
>
> So is there other information I could provide perhaps?
>
> Built-in Intel i82557
> Celeron-type, (686-class)
> 256 MB ram, 100 mbit connection directly into a cisco catalyst 3500..
>
> Suggestions? Is this a problem I can help with? Can no one duplicate
> this behaviour? Should I just wait for the 1.5 release and hope these
> weird pauses clear up?
>
> (take a flying leap, with your tcpdumps!) =]
>
> marc tooley
> marc@sudog.com