[OpenAFS-devel] .35 sec rx delay bug?

chas williams - CONTRACTOR chas@cmf.nrl.navy.mil
Mon, 06 Nov 2006 12:04:45 -0500


looking at the trace is certainly puzzling.  just a guess, but the
trace is from the client side right?  there are some retransmits at
for packets 47 and 70 initially.  these seem to correspond to the 350ms
retransmit timer.  however, aro ack 86 and ack 102 there are some 
huge delays.  what really puzzles me is the following sequence though:

1162490885.647853 IP 141.211.43.106.7000 > 141.211.133.51.7001: [udp sum ok]  rx data cid 14f395a8 call# 7 seq 92 ser 149 (1440)
1162490885.647913 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 105 <client-init>,<slow-start> first 90 serial 147 reason ack requested acked 90 ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (66)
1162490885.647952 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 106 <client-init>,<slow-start> first 90 serial 149 reason idle acked 90-92 ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (68)
1162490885.648008 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 107 <client-init>,<slow-start> first 93 serial 0 reason delay ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (65)
1162490885.648569 IP 141.211.43.106.7000 > 141.211.133.51.7001: [udp sum ok]  rx data cid 14f395a8 call# 7 seq 93 ser 150 (1440)
1162490885.935554 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 108 <client-init>,<slow-start> first 94 serial 0 reason delay ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (65)
1162490887.986681 IP 141.211.43.106.7000 > 141.211.133.51.7001: [udp sum ok]  rx data cid 14f395a8 call# 7 seq 94 ser 155 <req-ack> (1440)
1162490887.986811 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 109 <client-init>,<slow-start> first 94 serial 155 reason ack requested acked 94 ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (66)
1162490887.987410 IP 141.211.43.106.7000 > 141.211.133.51.7001: [udp sum ok]  rx data cid 14f395a8 call# 7 seq 95 ser 156 <req-ack> (1440)
1162490887.987458 IP 141.211.133.51.7001 > 141.211.43.106.7000: [udp sum ok]  rx ack cid 14f395a8 call# 7 seq 0 ser 110 <client-init>,<slow-start> first 95 serial 156 reason ack requested acked 95 ifmtu 5692 maxmtu 1444 rwind 32 maxpackets 4 (66)

it looks like the acks are being sent for data packets before they have been
seen.  the ack for packet 93 is sent before packet #93 is seen.  same goes
for packet 94.  i dont understand this really.  i suppose tcpdump could
have lost the first packet and we are seeing a retransmit.

can we get a trace from the server side (along with a trace from the
client side)?