TCP Inflight Debug

Wed Nov 17 12:42:43 PST 2004

Dan,

  Thanks for the pointers

So that's

Address       bits/sec          ms      ms      bits/window ?

  Looks like this confirms something funny happening to my network
inflight (RTT's gone mad with some QoS policy).

  Is there a spot in the source tree where I can take a look at the
algorithm or is it documented in detail elsewhere?

  I'm also wondering if my issues are due to packet loss.. any idea if
there are easy debug handles for the following features? 

net.inet.tcp.path_mtu_discovery: 1

net.inet.tcp.rfc3042: 1

net.inet.tcp.newreno: 1

TCP Slowstart

.. I guess I'm on the wrong mailing list here.

Debug details for those so inclined...

  Transfer starts off with an initial high throughput rate but drop very
quickly due to RTT and jitter. This doesn't seem to be related to the
inflight code but the debugs did give me a peak at whats going on:

0xc8394a10 bw 934798617 rttbest 11 srtt 11 bwnd 3216266

0xc8394a10 bw 787533009 rttbest 10 srtt 11 bwnd 2463936

0xc8394a10 bw 25800063 rttbest 170 srtt 145 bwnd 1268511

0xc8394a10 bw 4975437 rttbest 117 srtt 114 bwnd 181500

0xc8394a10 bw 906420 rttbest 102 srtt 103 bwnd 31588

0xc8394a10 bw 277643 rttbest 99 srtt 151 bwnd 13541

0xc8394a10 bw 177763 rttbest 99 srtt 172 bwnd 10195

Looks sorta like Im filling up a queue someplace, see those increased
RTT's?

Socket   Proto Recv-Q Send-Q  Local Address      Foreign Address
(state)

c8394a10 tcp4       0  33700  lugus.http         citronella.corp.12
ESTABLISHED

0xc8394a10 bw 670537240 rttbest 10 srtt 7 bwnd 1679239

0xc8394a10 bw 808029360 rttbest 10 srtt 11 bwnd 2527987

0xc8394a10 bw 815044808 rttbest 10 srtt 7 bwnd 2040508

0xc8394a10 bw 849174434 rttbest 10 srtt 7 bwnd 2125832

0xc8394a10 bw 839233587 rttbest 10 srtt 11 bwnd 2625500

0xc8394a10 bw 958812207 rttbest 11 srtt 7 bwnd 2699555

0xc8394a10 bw 1050863920 rttbest 10 srtt 7 bwnd 2630055

0xc8394a10 bw 863471031 rttbest 10 srtt 7 bwnd 2161573

0xc8394a10 bw 578048423 rttbest 10 srtt 11 bwnd 1809297

0xc8394a10 bw 934798617 rttbest 11 srtt 11 bwnd 3216266

0xc8394a10 bw 787533009 rttbest 10 srtt 11 bwnd 2463936

0xc8394a10 bw 25800063 rttbest 170 srtt 145 bwnd 1268511

0xc8394a10 bw 4975437 rttbest 117 srtt 114 bwnd 181500

0xc8394a10 bw 906420 rttbest 102 srtt 103 bwnd 31588

0xc8394a10 bw 277643 rttbest 99 srtt 151 bwnd 13541

0xc8394a10 bw 177763 rttbest 99 srtt 172 bwnd 10195

0xc8394a10 bw 201483 rttbest 99 srtt 96 bwnd 8803

0xc8394a10 bw 146560 rttbest 97 srtt 178 bwnd 8970

0xc8394a10 bw 243478 rttbest 88 srtt 107 bwnd 10076

0xc8394a10 bw 164005 rttbest 88 srtt 120 bwnd 8026

0xc8394a10 bw 125747 rttbest 88 srtt 127 bwnd 6900

0xc8394a10 bw 126271 rttbest 88 srtt 130 bwnd 6997

0xc8394a10 bw 146851 rttbest 88 srtt 104 bwnd 7101

0xc8394a10 bw 200383 rttbest 88 srtt 94 bwnd 8394

0xc8394a10 bw 154673 rttbest 88 srtt 118 bwnd 7674

0xc8394a10 bw 131923 rttbest 88 srtt 244 bwnd 9539

0xc8394a10 bw 231036 rttbest 88 srtt 214 bwnd 13598

0xc8394a10 bw 158995 rttbest 88 srtt 152 bwnd 8658

0xc8394a10 bw 278506 rttbest 87 srtt 80 bwnd 9919

0xc8394a10 bw 184478 rttbest 87 srtt 146 bwnd 9383

0xc8394a10 bw 155947 rttbest 87 srtt 239 bwnd 10639

0xc8394a10 bw 163013 rttbest 87 srtt 117 bwnd 7892

0xc8394a10 bw 187565 rttbest 87 srtt 108 bwnd 8381

0xc8394a10 bw 334999 rttbest 84 srtt 105 bwnd 12536

0xc8394a10 bw 231616 rttbest 84 srtt 152 bwnd 11236

0xc8394a10 bw 152561 rttbest 84 srtt 237 bwnd 10324

0xc8394a10 bw 155724 rttbest 84 srtt 156 bwnd 8535

0xc8394a10 bw 217493 rttbest 84 srtt 132 bwnd 10036

0xc8394a10 bw 343983 rttbest 84 srtt 172 bwnd 16455

0xc8394a10 bw 220480 rttbest 84 srtt 109 bwnd 9310

0xc8394a10 bw 228430 rttbest 84 srtt 109 bwnd 9548

0xc8394a10 bw 171126 rttbest 84 srtt 114 bwnd 7990

0xc8394a10 bw 141827 rttbest 84 srtt 195 bwnd 8856

0xc8394a10 bw 206136 rttbest 84 srtt 116 bwnd 9137

0xc8394a10 bw 286588 rttbest 84 srtt 97 bwnd 10756

0xc8394a10 bw 200720 rttbest 84 srtt 100 bwnd 8466

0xc8394a10 bw 194855 rttbest 83 srtt 137 bwnd 9394

0xc8394a10 bw 154884 rttbest 83 srtt 225 bwnd 10149

0xc8394a10 bw 276378 rttbest 83 srtt 102 bwnd 10641

0xc8394a10 bw 253500 rttbest 83 srtt 191 bwnd 13548

0xc8394a10 bw 216431 rttbest 83 srtt 133 bwnd 10000

0xc8394a10 bw 138191 rttbest 83 srtt 191 bwnd 8612

0xc8394a10 bw 120812 rttbest 83 srtt 172 bwnd 7490

0xc8394a10 bw 219063 rttbest 83 srtt 141 bwnd 10363

0xc8394a10 bw 155081 rttbest 83 srtt 189 bwnd 9286

0xc8394a10 bw 254920 rttbest 83 srtt 106 bwnd 10184

0xc8394a10 bw 221753 rttbest 83 srtt 93 bwnd 8794

0xc8394a10 bw 208913 rttbest 83 srtt 151 bwnd 10334

0xc8394a10 bw 180663 rttbest 83 srtt 165 bwnd 9696

0xc8394a10 bw 193660 rttbest 83 srtt 147 bwnd 9655

0xc8394a10 bw 142513 rttbest 83 srtt 186 bwnd 8663

0xc8394a10 bw 139919 rttbest 83 srtt 176 bwnd 8336

0xc8394a10 bw 207366 rttbest 83 srtt 209 bwnd 12157

0xc8394a10 bw 177299 rttbest 83 srtt 93 bwnd 7571

0xc8394a10 bw 193066 rttbest 83 srtt 169 bwnd 10297

0xc8394a10 bw 170165 rttbest 83 srtt 117 bwnd 8013

0xc8394a10 bw 142363 rttbest 83 srtt 153 bwnd 7945

0xc8394a10 bw 169626 rttbest 83 srtt 159 bwnd 9109

0xc8394a10 bw 179288 rttbest 83 srtt 125 bwnd 8522

0xc8394a10 bw 195701 rttbest 83 srtt 104 bwnd 8383

0xc8394a10 bw 208023 rttbest 83 srtt 160 bwnd 10561

0xc8394a10 bw 135700 rttbest 83 srtt 124 bwnd 7063

0xc8394a10 bw 167106 rttbest 83 srtt 120 bwnd 7970

0xc8394a10 bw 150675 rttbest 83 srtt 151 bwnd 8205

0xc8394a10 bw 208737 rttbest 83 srtt 119 bwnd 9284

0xc8394a10 bw 158252 rttbest 83 srtt 174 bwnd 9026

0xc8394a10 bw 140138 rttbest 83 srtt 112 bwnd 6943

0xc8394a10 bw 134152 rttbest 83 srtt 153 bwnd 7642

0xc8394a10 bw 178937 rttbest 83 srtt 145 bwnd 9070

-----Original Message-----
From: Dan Nelson [mailto:dnelson at allantgroup.com] 
Sent: Wednesday, November 17, 2004 3:05 PM
To: Fisch, Matthew
Cc: questions at freebsd.org
Subject: Re: TCP Inflight Debug

In the last episode (Nov 16), Fisch, Matthew said:

> Im trying to debug slow tcp transfers on a 100mbit link with a large

> variable bandwidth delay product. Can someone describe the meaning of

> the inflight debugging output?

>  

> net.inet.tcp.inflight_debug: 1

>  

> 0xca2702e0 bw 885887956 rttbest 10 srtt 7 bwnd 2217615

> 0xc8394170 bw 840998588 rttbest 10 srtt 7 bwnd 2105392

> 0xc836ab80 bw 842026536 rttbest 10 srtt 7 bwnd 2107962

> 0xca270a10 bw 232052 rttbest 84 srtt 109 bwnd 9657

> 0xc87fb450 bw 902405694 rttbest 10 srtt 7 bwnd 2258910

> 0xc8394170 bw 880116973 rttbest 10 srtt 11 bwnd 2753261

> 0xca270a10 bw 300922 rttbest 84 srtt 163 bwnd 14262

> 0xca270000 bw 988204579 rttbest 12 srtt 11 bwnd 3399849

> 0xca270a10 bw 170910 rttbest 84 srtt 145 bwnd 8784

> 0xca270a10 bw 202413 rttbest 84 srtt 193 bwnd 11425

> 0xc8394a10 bw 983212216 rttbest 10 srtt 7 bwnd 2460926

> 0xca270a10 bw 179225 rttbest 84 srtt 127 bwnd 8576

> 0xca270a10 bw 150860 rttbest 84 srtt 132 bwnd 7787

> 0xc87fb2e0 bw 917529420 rttbest 11 srtt 11 bwnd 3156903

> 0xca270cf0 bw 969682982 rttbest 13 srtt 11 bwnd 3639207

The first number is the socket address (match it up with netstat -a).

bw is the estimated bandwidth of the link; those large values are

probably from localhost sockets, so you can ignore them.  Printing the

destination IP address here would probably be useful.  rttbest is the

lowest round-trip time seen, srtt is an average of recent rtt values,

and bwnd is the window size the inflight code wants to use (which may

be capped by other settings).

The 0xca270a10 socket, for example, looks like it's doing around

175KB/sec to a host with an 84ms ideal ping time (although the current

average is 150ms), and the inflight code is limiting the window to

between 8 and 16KB.

There are lots of comments in tcp_subr.c explaining the inflight code.

The idea is to limit the window to prevent too many packets from

getting buffered/dropped at intermediate routers.  Graphing the window

size on both ends of the link (with ethereal or tcptrace) may help

also.

-- 

      Dan Nelson

      dnelson at allantgroup.com