Subject: Linux tcpdump for comparison with prev. note..
To: None <tech-net@netbsd.org>
From: Marc Tooley <sudog@sudog.com>
List: tech-net
Date: 09/13/2000 18:47:32
Allo..  since I've received a very courteous reply to my last note
and it's been requested that I put up a Linux tcpdump with some
de-sync behaviour, here it is.. (ip changed of course--to be revealed
later when I finally get this prob solved):

Connection opens up:

11:40:29.631553 10.0.0.4.20 > 234.234.234.234.1056: S 2506514756:2506514756(0) win 16384 <mss 1460,nop,wscale 0,nop,nop,timestamp[|tcp]> [tos 0x8]
11:40:29.685702 234.234.234.234.1056 > 10.0.0.4.20: S 1533365959:1533365959(0) ack 2506514757 win 32120 <mss 1460,nop,nop,timestamp 421889646[|tcp]> (DF)
11:40:29.685772 10.0.0.4.20 > 234.234.234.234.1056: . ack 1 win 17520 <nop,nop,timestamp 2913486 421889646> [tos 0x8]

So in negotiations, looks like 10.0.0.4 (our trusty 1.4.2 stand-by) is
requesting wscale TCP option..  the linux box refuses.. and netbsd
says, "fine be that way" and the data commences..  everything looks
good, data ack, data ack.. data data ack etc until our first desync:

11:40:30.793400 234.234.234.234.1056 > 10.0.0.4.20: . 178105:179553(1448) ack 1 win 32120 <nop,nop,timestamp 421889755 2913488> (DF) [tos 0x8]
11:40:30.795016 10.0.0.4.20 > 234.234.234.234.1056: . ack 179553 win 17096 <nop,nop,timestamp 2913488 421889755> [tos 0x8]
11:40:30.822956 234.234.234.234.1056 > 10.0.0.4.20: . 182449:183897(1448) ack 1 win 32120 <nop,nop,timestamp 421889759 2913488> (DF) [tos 0x8]
11:40:30.823007 10.0.0.4.20 > 234.234.234.234.1056: . ack 179553 win 17520 <nop,nop,timestamp 2913488 421889755> [tos 0x8]
11:40:30.827557 234.234.234.234.1056 > 10.0.0.4.20: . 183897:185345(1448) ack 1 win 32120 <nop,nop,timestamp 421889759 2913488> (DF) [tos 0x8]
11:40:30.827596 10.0.0.4.20 > 234.234.234.234.1056: . ack 179553 win 17520 <nop,nop,timestamp 2913488 421889755> [tos 0x8]

so the data from 179553:183897 is missing.. looks like three packets.

NetBSD valiantly acks at 179553 all the way up to:

11:40:30.898394 234.234.234.234.1056 > 10.0.0.4.20: P 195481:196929(1448) ack 1 win 32120 <nop,nop,timestamp 421889766 2913488> (DF) [tos 0x8]
11:40:30.898456 10.0.0.4.20 > 234.234.234.234.1056: . ack 179553 win 17520 <nop,nop,timestamp 2913488 421889755> [tos 0x8]
11:40:30.922535 234.234.234.234.1056 > 10.0.0.4.20: P 179553:181001(1448) ack 1 win 32120 <nop,nop,timestamp 421889769 2913488> (DF) [tos 0x8]

Linux answers..  and netbsd reads in the good stuff:

11:40:30.922612 10.0.0.4.20 > 234.234.234.234.1056: . ack 181001 win 16072 <nop,nop,timestamp 2913488 421889769> [tos 0x8]
11:40:30.924223 10.0.0.4.20 > 234.234.234.234.1056: . ack 181001 win 17096 <nop,nop,timestamp 2913488 421889769> [tos 0x8]
11:40:30.991336 234.234.234.234.1056 > 10.0.0.4.20: . 181001:182449(1448) ack 1 win 32120 <nop,nop,timestamp 421889776 2913488> (DF) [tos 0x8]

NetBSD reads in (now) all the way up to 196929:

6: . ack 196929 win 1592 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 2616 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 3640 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 4664 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 5688 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 6712 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 7736 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 8760 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 9784 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
6: . ack 196929 win 10808 <nop,nop,timestamp 2913488 421889776> [tos 0x8]
[...etc...]

Timestamps for the catch-up are:
11:40:30.991406 -> 11:40:30.993117

so there's barely any elapsed time there..  finally, quite literally
an instant later, linux picks up the ack and continues:

11:40:31.065832 234.234.234.234.1056 > 10.0.0.4.20: . 196929:198377(1448) ack 1 win 32120 <nop,nop,timestamp 421889783 2913488> (DF) [tos 0x8]
11:40:31.065918 10.0.0.4.20 > 234.234.234.234.1056: . ack 198377 win 17096 <nop,nop,timestamp 2913489 421889783> [tos 0x8]
11:40:31.068527 234.234.234.234.1056 > 10.0.0.4.20: . 198377:199825(1448) ack 1 win 32120 <nop,nop,timestamp 421889783 2913488> (DF) [tos 0x8]
11:40:31.068587 10.0.0.4.20 > 234.234.234.234.1056: . ack 199825 win 17096 <nop,nop,timestamp 2913489 421889783> [tos 0x8]

and data flows as normal.

But notice the timestamps! this whole de-sync (of more packets
than went missing with the netbsd1.5->netbsd1.4.2 communications) took
quite literally a mere instant.

First hint of de-sync timestamp sits at: 11:40:30.823007
Final re-sync and continuation: 11:40:31.065918
Total elapsed time: 0.242911 seconds..
Total data transferred through the problem: 198377 - 179553 = 18824

Notice that the amount of data (about 20k) is equivalent to the NetBSD
transferred data..  yet the amount of time it took to re-sync is a
fraction..  

Total throughput (approx, esp when dealing with sub-second timing):
78K.. and because throughput picks up pretty much where it left off,
the overall data rate for the entire transfer sits high up around
250K/sec, which is where it should be.

Not much else to say with this dump: all the de-sync's I've looked at
(four now) all end up this way--dealt with and eliminated in a timely
fashion.

I realize the picture from the other end would be useful here as well,
but of these two snapshots I only had the foresight to capture the
receiving end's idea of what happen(ed/s).

Here's what I've tried to tweak in userland:

sysctl:
net.inet.tcp.rfc1323 .sendspace .recvspace .init_win .win_scale
	.timestamps .cwm .ack_on_push .newreno
net.inet.ip.ttl (pulled down to 32, back up to 64) .mtudisc

on the 3com:
	exphy: changed to 10baseT, 100baseT, half and full duplex
on the intel:
	same.

For reference, the tcpdump is from a pure default setup.

What else have I done..  changed cabling, changed routers (cisco 7200,
cisco catalyst 3500, and a cisco catalyst..  2900? i don't know the
third one's make actually) and monkeyed about with the router's idea
of full/half 10/100 line..

There are few-to-no collisions, routers say no probs with the line.

Quite frankly I'm at a complete loss..  I have no idea what's going
on.. is there a problem with 1.5 networking code? Have there been
major changes? What might cause NetBSD to respond so slowly?

Finally, latency between server and client sits at ~ 37 ms. (Which in
itself is interesting--since that's pretty much the exact time of a
round-trip.)

Help?

Sincerely,

Marc Tooley
marc@sudog.com