Date: Thu, 6 Jun 2002 12:21:13 -0700 From: Luigi Rizzo <rizzo@icir.org> To: Emmanuel Duros <Emmanuel.Duros@udcast.com> Cc: freebsd-net@FreeBSD.ORG Subject: Re: Weird TCP behavior with RTT of 1000 ms Message-ID: <20020606122113.A13808@iguana.icir.org> In-Reply-To: <3CFF90A3.7000400@udcast.com>; from Emmanuel.Duros@udcast.com on Thu, Jun 06, 2002 at 06:41:07PM %2B0200 References: <3CFF90A3.7000400@udcast.com>
next in thread | previous in thread | raw e-mail | index | archive | help
one thing that comes to mind is that FreeBSD caches the initial TCP parameters in the route table, storing something computed in the previous connection. I am not sure about the details, but depending on what happens when you abort (or close) the previous connection, you might start with a very low ssthresh which would explain the behaviour. deleting the route entry might help in making the behaviour more deterministic. On top of this I think i remember 4.4 had some annoying bug in handling timeouts or something like that, so you should really try and see if the same problem still occurs with 4.5 or more recent -- you can easily try that by building a picobsd image based on the newer sources for the two boxes to test, if you do not want to upgrade the entire system. You just need to upgrade crunchgen to the one in RELENG_4, grab the picobsd script and the manpage, and read it. cheers luigi On Thu, Jun 06, 2002 at 06:41:07PM +0200, Emmanuel Duros wrote: > Dear All, > > I am currently evaluating TCP with Freebsd 4.4 boxes simulating a very > high latency link. For some reasons, I can get a TCP throughput > extremely close to what is expected and sometimes, *without* changing > any setting in my configuration I can get very poor performance ! > > Here is my setup: > > box 1 Router box 2 > | | | | > ------------------ ------------------- > LAN 1 (100BT) LAN 2 (100BT) > > box 1, Router, and box 2 use FreeBSD 4.4. > Router adds 1000ms (1 second) delay to all packets going *from* LAN 1 > *to* LAN 2 using dummynet. > > I changed the TCP window sizes on box 1 and box 2 using sysctl command: > > box 1 box 2 > sendspace 200000 default > recvspace default 200000 > > I use ttcp to transfer data over tcp from box 1 to box 2. > > (1) When the transfer goes well, I get a 200Kbyte throughput after the > slowstart period. This can be seen here with a 'netstat -I xl0 -w 1' on > box 2: > > input (xl0) output > packets errs bytes packets errs bytes colls > 0 0 0 0 0 0 0 > 1 0 74 1 0 74 0 > 2 0 1580 2 0 132 0 > 2 0 3028 1 0 66 0 > 3 0 4542 2 0 132 0 > 5 0 7570 4 0 264 0 > 9 0 13626 6 0 396 0 > 15 0 22710 10 0 660 0 > 25 0 37850 17 0 1122 0 > 42 0 63588 28 0 1848 0 > 70 0 105980 47 0 3102 0 > 117 0 177138 78 0 5148 0 > 138 0 208932 92 0 6072 0 > 137 0 207418 91 0 6006 0 > 137 0 207418 92 0 6072 0 > 138 0 208932 92 0 6072 0 > > > (2) However, very often the transfer does not happen so well... The > transfer starts and gets stuck at 3Kbytes/s, and this can go up to 2 > minutes and the slowstart operates again and the troughtput reaches > 200KB/s. The netstat looks like: > > input (xl0) output > packets errs bytes packets errs bytes colls > 0 0 0 0 0 0 0 > 0 0 0 0 0 0 0 > 0 0 0 0 0 0 0 > 0 0 0 0 0 0 0 > 1 0 74 1 0 74 0 > 2 0 1580 2 0 132 0 > 3 0 4542 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > 2 0 3028 2 0 132 0 > [... for 2 minutes or more ! and then ...] > 2 0 3028 1 0 66 0 > 3 0 4542 2 0 132 0 > 5 0 7570 4 0 264 0 > input (xl0) output > packets errs bytes packets errs bytes colls > 9 0 13626 6 0 396 0 > 15 0 22710 10 0 660 0 > 25 0 37850 17 0 1122 0 > 42 0 63588 28 0 1848 0 > 70 0 105980 47 0 3102 0 > 117 0 177138 78 0 5148 0 > 138 0 208932 92 0 6072 0 > 137 0 207418 91 0 6006 0 > 138 0 208932 92 0 6072 0 > 134 0 202876 89 0 5874 0 > > I really want to point out that I am not changing anything in my > settings between 2 transfers. I am just starting ttcp again and again on > my boxes and TCP behave like (1) or (2). It looks like this behavior is > not deterministic. > > I attached the tcpdump ouput that showes the beginning of the transfer > on box 1. As you can see there is no packet loss and this cannot be the > reason why the congestion window does not increase... > > I also noticed that with a 500ms delay instead of 1000ms I have not seen > this problem. > > Is this a bug, a 'feature', ... ??? > > Thanks a lot and regards, > Emmanuel > -- > Emmanuel Duros http://www.udcast.com > 2455 Route des Dolines BP355 | Tel : +33 (0)4 93 00 16 60 > 06906 Sophia Antipolis France | Fax : +33 (0)4 93 00 16 61 > ** Full IP over Broadcast Media ** > tcpdump -n -i fxp0 host 192.168.132.2 > tcpdump: listening on fxp0 > 17:34:09.151317 192.168.99.102.1416 > 192.168.132.2.5001: S 3748748564:3748748564(0) win 16384 <mss 1460,nop,wscale 0,nop,nop,timestamp 8667492 0> (DF) > 17:34:10.143720 192.168.132.2.5001 > 192.168.99.102.1416: S 2021053759:2021053759(0) ack 3748748565 win 65535 <mss 1460,nop,wscale 2,nop,nop,timestamp 8846829 8667492> (DF) > 17:34:10.143792 192.168.99.102.1416 > 192.168.132.2.5001: . ack 1 win 17376 <nop,nop,timestamp 8667591 8846829> (DF) > 17:34:10.144883 192.168.99.102.1416 > 192.168.132.2.5001: . 1:1449(1448) ack 1 win 17376 <nop,nop,timestamp 8667591 8846829> (DF) > 17:34:11.143652 192.168.132.2.5001 > 192.168.99.102.1416: . ack 1 win 50318 <nop,nop,timestamp 8846929 8667591> (DF) > 17:34:11.230230 192.168.99.102.1416 > 192.168.132.2.5001: . 1:1449(1448) ack 1 win 17376 <nop,nop,timestamp 8667700 8846929> (DF) > 17:34:11.234687 192.168.132.2.5001 > 192.168.99.102.1416: . ack 1449 win 50318 <nop,nop,timestamp 8846939 8667591> (DF) > 17:34:11.234737 192.168.99.102.1416 > 192.168.132.2.5001: . 1449:2897(1448) ack 1 win 17376 <nop,nop,timestamp 8667700 8846939> (DF) > 17:34:11.234760 192.168.99.102.1416 > 192.168.132.2.5001: . 2897:4345(1448) ack 1 win 17376 <nop,nop,timestamp 8667700 8846939> (DF) > 17:34:12.223754 192.168.132.2.5001 > 192.168.99.102.1416: . ack 1449 win 50318 <nop,nop,timestamp 8847037 8667700> (DF) > 17:34:12.233813 192.168.132.2.5001 > 192.168.99.102.1416: . ack 4345 win 49956 <nop,nop,timestamp 8847038 8667700> (DF) > 17:34:12.233870 192.168.99.102.1416 > 192.168.132.2.5001: . 4345:5793(1448) ack 1 win 17376 <nop,nop,timestamp 8667800 8847038> (DF) > 17:34:12.233894 192.168.99.102.1416 > 192.168.132.2.5001: . 5793:7241(1448) ack 1 win 17376 <nop,nop,timestamp 8667800 8847038> (DF) > 17:34:13.353855 192.168.132.2.5001 > 192.168.99.102.1416: . ack 5793 win 50318 <nop,nop,timestamp 8847150 8667800> (DF) > 17:34:13.353940 192.168.99.102.1416 > 192.168.132.2.5001: . 7241:8689(1448) ack 1 win 17376 <nop,nop,timestamp 8667912 8847150> (DF) > 17:34:13.444788 192.168.132.2.5001 > 192.168.99.102.1416: . ack 7241 win 50318 <nop,nop,timestamp 8847160 8667800> (DF) > 17:34:13.444835 192.168.99.102.1416 > 192.168.132.2.5001: . 8689:10137(1448) ack 1 win 17376 <nop,nop,timestamp 8667921 8847160> (DF) > 17:34:14.443749 192.168.132.2.5001 > 192.168.99.102.1416: . ack 10137 win 49956 <nop,nop,timestamp 8847259 8667912> (DF) > 17:34:14.443811 192.168.99.102.1416 > 192.168.132.2.5001: . 10137:11585(1448) ack 1 win 17376 <nop,nop,timestamp 8668021 8847259> (DF) > 17:34:14.443835 192.168.99.102.1416 > 192.168.132.2.5001: . 11585:13033(1448) ack 1 win 17376 <nop,nop,timestamp 8668021 8847259> (DF) > 17:34:15.443816 192.168.132.2.5001 > 192.168.99.102.1416: . ack 11585 win 50318 <nop,nop,timestamp 8847359 8668021> (DF) > 17:34:15.443870 192.168.99.102.1416 > 192.168.132.2.5001: . 13033:14481(1448) ack 1 win 17376 <nop,nop,timestamp 8668121 8847359> (DF) > 17:34:15.534760 192.168.132.2.5001 > 192.168.99.102.1416: . ack 13033 win 50318 <nop,nop,timestamp 8847369 8668021> (DF) > 17:34:15.534803 192.168.99.102.1416 > 192.168.132.2.5001: . 14481:15929(1448) ack 1 win 17376 <nop,nop,timestamp 8668130 8847369> (DF) > 17:34:16.533773 192.168.132.2.5001 > 192.168.99.102.1416: . ack 15929 win 49956 <nop,nop,timestamp 8847468 8668121> (DF) > 17:34:16.533831 192.168.99.102.1416 > 192.168.132.2.5001: . 15929:17377(1448) ack 1 win 17376 <nop,nop,timestamp 8668230 8847468> (DF) > 17:34:16.533854 192.168.99.102.1416 > 192.168.132.2.5001: . 17377:18825(1448) ack 1 win 17376 <nop,nop,timestamp 8668230 8847468> (DF) > 17:34:17.533793 192.168.132.2.5001 > 192.168.99.102.1416: . ack 17377 win 50318 <nop,nop,timestamp 8847568 8668230> (DF) > 17:34:17.533846 192.168.99.102.1416 > 192.168.132.2.5001: . 18825:20273(1448) ack 1 win 17376 <nop,nop,timestamp 8668330 8847568> (DF) > 17:34:17.624800 192.168.132.2.5001 > 192.168.99.102.1416: . ack 18825 win 50318 <nop,nop,timestamp 8847578 8668230> (DF) > 17:34:17.624851 192.168.99.102.1416 > 192.168.132.2.5001: . 20273:21721(1448) ack 1 win 17376 <nop,nop,timestamp 8668339 8847578> (DF) > 17:34:18.623755 192.168.132.2.5001 > 192.168.99.102.1416: . ack 21721 win 49956 <nop,nop,timestamp 8847677 8668330> (DF) > 17:34:18.623882 192.168.99.102.1416 > 192.168.132.2.5001: . 21721:23169(1448) ack 1 win 17376 <nop,nop,timestamp 8668439 8847677> (DF) > 17:34:18.623910 192.168.99.102.1416 > 192.168.132.2.5001: . 23169:24617(1448) ack 1 win 17376 <nop,nop,timestamp 8668439 8847677> (DF) > 17:34:19.623854 192.168.132.2.5001 > 192.168.99.102.1416: . ack 23169 win 50318 <nop,nop,timestamp 8847777 8668439> (DF) > 17:34:19.623913 192.168.99.102.1416 > 192.168.132.2.5001: . 24617:26065(1448) ack 1 win 17376 <nop,nop,timestamp 8668539 8847777> (DF) > 17:34:19.714848 192.168.132.2.5001 > 192.168.99.102.1416: . ack 24617 win 50318 <nop,nop,timestamp 8847787 8668439> (DF) > 17:34:19.714903 192.168.99.102.1416 > 192.168.132.2.5001: . 26065:27513(1448) ack 1 win 17376 <nop,nop,timestamp 8668548 8847787> (DF) > 17:34:20.713755 192.168.132.2.5001 > 192.168.99.102.1416: . ack 27513 win 49956 <nop,nop,timestamp 8847886 8668539> (DF) > 17:34:20.713810 192.168.99.102.1416 > 192.168.132.2.5001: . 27513:28961(1448) ack 1 win 17376 <nop,nop,timestamp 8668648 8847886> (DF) > 17:34:20.713831 192.168.99.102.1416 > 192.168.132.2.5001: . 28961:30409(1448) ack 1 win 17376 <nop,nop,timestamp 8668648 8847886> (DF) > 17:34:21.713862 192.168.132.2.5001 > 192.168.99.102.1416: . ack 28961 win 50318 <nop,nop,timestamp 8847986 8668648> (DF) > 17:34:21.713923 192.168.99.102.1416 > 192.168.132.2.5001: . 30409:31857(1448) ack 1 win 17376 <nop,nop,timestamp 8668748 8847986> (DF) > 17:34:21.811503 192.168.132.2.5001 > 192.168.99.102.1416: . ack 30409 win 50318 <nop,nop,timestamp 8847996 8668648> (DF) > 17:34:21.811550 192.168.99.102.1416 > 192.168.132.2.5001: . 31857:33305(1448) ack 1 win 17376 <nop,nop,timestamp 8668758 8847996> (DF) > 17:34:22.803753 192.168.132.2.5001 > 192.168.99.102.1416: . ack 33305 win 49956 <nop,nop,timestamp 8848095 8668748> (DF) > 17:34:22.803813 192.168.99.102.1416 > 192.168.132.2.5001: . 33305:34753(1448) ack 1 win 17376 <nop,nop,timestamp 8668857 8848095> (DF) > 17:34:22.803838 192.168.99.102.1416 > 192.168.132.2.5001: . 34753:36201(1448) ack 1 win 17376 <nop,nop,timestamp 8668857 8848095> (DF) > 17:34:23.803873 192.168.132.2.5001 > 192.168.99.102.1416: . ack 34753 win 50318 <nop,nop,timestamp 8848195 8668857> (DF) > 17:34:23.803979 192.168.99.102.1416 > 192.168.132.2.5001: . 36201:37649(1448) ack 1 win 17376 <nop,nop,timestamp 8668957 8848195> (DF) > 17:34:23.894946 192.168.132.2.5001 > 192.168.99.102.1416: . ack 36201 win 50318 <nop,nop,timestamp 8848205 8668857> (DF) > 17:34:23.894997 192.168.99.102.1416 > 192.168.132.2.5001: . 37649:39097(1448) ack 1 win 17376 <nop,nop,timestamp 8668966 8848205> (DF) To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-net" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20020606122113.A13808>