tcptrace-bugs Potential rexmit undercount

From: Slava Kritov (Slava.kritov@veritas.com)
Date: 08/04/04


Message-ID: <B78ECA1C29CAD4119E0C0008C7866678096225B1@mtvxch08.veritas.com>
From: Slava Kritov <Slava.kritov@veritas.com>
Subject: tcptrace-bugs Potential rexmit undercount
Date: Wed, 4 Aug 2004 19:16:06 -0700 

Hello,

I've been using tcptrace to analyze captures of the following environment:

[sun240, solaris8]-[1G eth]-[Compaq 2xPIII, linux kernel v. 2.4.18 +
NIST]-[1G eth]-[sun240, solaris8]

Nist was set to 100 Mbps, 10 ms and 1% packet loss

I was capturing either on linux or on sun boxes, and I see the following
irregularity:

For all packets coming from remote machine (as opposite to a segment where I
capture) I would see dups - but not rexmits. The numbers also are too varied

Please consider results of analyzing iperf dualtest below (my comments are
marked by ***):

1 arg remaining, starting with 'eth2100-1loss10msdump-iperf.dmp'
Ostermann's tcptrace -- version 6.6.1 -- Wed Nov 19, 2003

80648 packets seen, 80648 TCP packets traced
elapsed wallclock time: 0:00:00.368683, 218746 pkts/sec analyzed
trace file elapsed time: 0:01:00.232135
TCP connection info:
2 TCP connections traced:
TCP connection 1:
      host a: 192.168.10.4:45084
      host b: 192.168.20.4:5001
      complete conn: yes
      first packet: Wed Aug 4 11:41:15.796775 2004
      last packet: Wed Aug 4 11:42:16.028910 2004
      elapsed time: 0:01:00.232135
      total packets: 33985
      filename: eth2100-1loss10msdump-iperf.dmp
   a->b: b->a:
     total packets: 17615 total packets: 16370
     ack pkts sent: 17614 ack pkts sent: 16370
     pure acks sent: 2 pure acks sent: 16366
     sack pkts sent: 0 sack pkts sent: 3109
     dsack pkts sent: 0 dsack pkts sent: 0
     max sack blks/ack: 0 max sack blks/ack: 2
     unique bytes sent: 24043544 unique bytes sent: 0
     actual data pkts: 17612 actual data pkts: 0
     actual data bytes: 24045004 actual data bytes: 0
     rexmt data pkts: 1 rexmt data pkts: 2
     rexmt data bytes: 1460 rexmt data bytes: 2
     zwnd probe pkts: 0 zwnd probe pkts: 0
     zwnd probe bytes: 0 zwnd probe bytes: 0
     outoforder pkts: 186 outoforder pkts: 0
     pushed data pkts: 1216 pushed data pkts: 0
     SYN/FIN pkts sent: 1/1 SYN/FIN pkts sent: 2/2
     req sack: Y req sack: Y
     sacks sent: 0 sacks sent: 3109
     urgent data pkts: 0 pkts urgent data pkts: 0
pkts
     urgent data bytes: 0 bytes urgent data bytes: 0
bytes
     mss requested: 1460 bytes mss requested: 1460
bytes
     max segm size: 1460 bytes max segm size: 0
bytes
     min segm size: 24 bytes min segm size: 0
bytes
     avg segm size: 1365 bytes avg segm size: 0
bytes
     max win adv: 24820 bytes max win adv: 64240
bytes
     min win adv: 24820 bytes min win adv: 64240
bytes
     zero win adv: 0 times zero win adv: 0
times
     avg win adv: 24820 bytes avg win adv: 64240
bytes
     initial window: 24 bytes initial window: 0
bytes
     initial window: 1 pkts initial window: 0
pkts
     ttl stream length: 24043544 bytes ttl stream length: 0
bytes
     missed data: 0 bytes missed data: 0
bytes
     truncated data: 22178214 bytes truncated data: 0
bytes
     truncated packets: 17611 pkts truncated packets: 0
pkts
     data xmit time: 60.187 secs data xmit time: 0.000
secs
     idletime max: 410.1 ms idletime max: 410.2 ms
     hardware dups: 0 segs hardware dups: 7590
segs
*** even if I use no_hw_dups option there should be much more rexmits in the
left column ***

       ** WARNING: presence of hardware duplicates makes these figures
suspect!
     throughput: 399181 Bps throughput: 0 Bps

     RTT samples: 6582 RTT samples: 0
     RTT min: 0.1 ms RTT min: 0.0 ms
     RTT max: 99.8 ms RTT max: 0.0 ms
     RTT avg: 1.3 ms RTT avg: 0.0 ms
     RTT stdev: 5.8 ms RTT stdev: 0.0 ms

     RTT from 3WHS: 3.8 ms RTT from 3WHS: 0.0 ms

     RTT full_sz smpls: 6546 RTT full_sz smpls: 0
     RTT full_sz min: 0.2 ms RTT full_sz min: 0.0 ms
     RTT full_sz max: 99.8 ms RTT full_sz max: 0.0 ms
     RTT full_sz avg: 1.2 ms RTT full_sz avg: 0.0 ms
     RTT full_sz stdev: 5.3 ms RTT full_sz stdev: 0.0 ms

     post-loss acks: 181 post-loss acks: 0
        For the following 5 RTT statistics, only ACKs for
        multiply-transmitted segments (ambiguous ACKs) were
        considered. Times are taken from the last instance
        of a segment.
     ambiguous acks: 0 ambiguous acks: 2
     RTT min (last): 0.0 ms RTT min (last): 20.2 ms
     RTT max (last): 0.0 ms RTT max (last): 20.4 ms
     RTT avg (last): 0.0 ms RTT avg (last): 20.3 ms
     RTT sdv (last): 0.0 ms RTT sdv (last): 0.0 ms
     segs cum acked: 10849 segs cum acked: 0
     duplicate acks: 3123 duplicate acks: 0
     triple dupacks: 212 triple dupacks: 0
     max # retrans: 1 max # retrans: 1
     min retr time: 431.0 ms min retr time: 0.0 ms
     max retr time: 431.0 ms max retr time: 0.0 ms
     avg retr time: 430.9 ms avg retr time: 0.0 ms
     sdv retr time: 0.0 ms sdv retr time: 0.0 ms
================================
TCP connection 2:
      host c: 192.168.20.4:33514
      host d: 192.168.10.4:5001
      complete conn: yes
      first packet: Wed Aug 4 11:41:15.823068 2004
      last packet: Wed Aug 4 11:42:15.946688 2004
      elapsed time: 0:01:00.123620
      total packets: 46663
      filename: eth2100-1loss10msdump-iperf.dmp
   c->d: d->c:
     total packets: 37910 total packets: 8753
     ack pkts sent: 37908 ack pkts sent: 8753
     pure acks sent: 4 pure acks sent: 8751
     sack pkts sent: 0 sack pkts sent: 1547
     dsack pkts sent: 0 dsack pkts sent: 0
     max sack blks/ack: 0 max sack blks/ack: 2
     unique bytes sent: 25747456 unique bytes sent: 0
     actual data pkts: 37904 actual data pkts: 0
     actual data bytes: 51754056 actual data bytes: 0
     rexmt data pkts: 19047 rexmt data pkts: 0
*** This seems to be way more than expected on 1% loss ***

     rexmt data bytes: 26006602 rexmt data bytes: 0
     zwnd probe pkts: 0 zwnd probe pkts: 0
     zwnd probe bytes: 0 zwnd probe bytes: 0
     outoforder pkts: 0 outoforder pkts: 0
     pushed data pkts: 2345 pushed data pkts: 0
     SYN/FIN pkts sent: 2/2 SYN/FIN pkts sent: 1/1
     req sack: Y req sack: Y
     sacks sent: 0 sacks sent: 1547
     urgent data pkts: 0 pkts urgent data pkts: 0
pkts
     urgent data bytes: 0 bytes urgent data bytes: 0
bytes
     mss requested: 1460 bytes mss requested: 1460
bytes
     max segm size: 1460 bytes max segm size: 0
bytes
     min segm size: 892 bytes min segm size: 0
bytes
     avg segm size: 1365 bytes avg segm size: 0
bytes
     max win adv: 24820 bytes max win adv: 64240
bytes
     min win adv: 24820 bytes min win adv: 64240
bytes
     zero win adv: 0 times zero win adv: 0
times
     avg win adv: 24820 bytes avg win adv: 64240
bytes
     initial window: 4380 bytes initial window: 0
bytes
     initial window: 3 pkts initial window: 0
pkts
     ttl stream length: 25747456 bytes ttl stream length: 0
bytes
     missed data: 0 bytes missed data: 0
bytes
     truncated data: 47736232 bytes truncated data: 0
bytes
     truncated packets: 37904 pkts truncated packets: 0
pkts
     data xmit time: 60.082 secs data xmit time: 0.000
secs
     idletime max: 428.6 ms idletime max: 428.5 ms
     hardware dups: 11138 segs hardware dups: 0
segs
*** again - very strange stats above

       ** WARNING: presence of hardware duplicates makes these figures
suspect!
     throughput: 428242 Bps throughput: 0 Bps

     RTT samples: 0 RTT samples: 2
     RTT min: 0.0 ms RTT min: 0.1 ms
     RTT max: 0.0 ms RTT max: 0.1 ms
     RTT avg: 0.0 ms RTT avg: 0.1 ms
     RTT stdev: 0.0 ms RTT stdev: 0.0 ms

     RTT from 3WHS: 0.0 ms RTT from 3WHS: 0.1 ms

     RTT full_sz smpls: 0 RTT full_sz smpls: 1
     RTT full_sz min: 0.0 ms RTT full_sz min: 0.1 ms
     RTT full_sz max: 0.0 ms RTT full_sz max: 0.1 ms
     RTT full_sz avg: 0.0 ms RTT full_sz avg: 0.1 ms
     RTT full_sz stdev: 0.0 ms RTT full_sz stdev: 0.0 ms

     post-loss acks: 184 post-loss acks: 0
        For the following 5 RTT statistics, only ACKs for
        multiply-transmitted segments (ambiguous ACKs) were
        considered. Times are taken from the last instance
        of a segment.
     ambiguous acks: 7133 ambiguous acks: 0
     RTT min (last): 20.3 ms RTT min (last): 0.0 ms
     RTT max (last): 120.2 ms RTT max (last): 0.0 ms
     RTT avg (last): 21.3 ms RTT avg (last): 0.0 ms
     RTT sdv (last): 3.8 ms RTT sdv (last): 0.0 ms
     segs cum acked: 11542 segs cum acked: 0
     duplicate acks: 1436 duplicate acks: 1
     triple dupacks: 175 triple dupacks: 0
     max # retrans: 2 max # retrans: 0
     min retr time: 0.0 ms min retr time: 0.0 ms
     max retr time: 440.3 ms max retr time: 0.0 ms
     avg retr time: 0.5 ms avg retr time: 0.0 ms
     sdv retr time: 8.8 ms sdv retr time: 0.0 ms

Thanks a lot

Slava



This archive was generated by hypermail 2.1.7 : 08/05/04 EDT