Subject: More information on TCP response of netBSD tcp stack? =]
To: None <tech-net@netbsd.org>
From: Marc Tooley <sudog@sudog.com>
List: tech-net
Date: 09/18/2000 18:11:05
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