Can Someone Explain This Odd TTCP Behavior

Thu Aug 30 19:33:15 UTC 2007

Hi,

I hate to have to resort to sending this to the
list but surely someone out there can explain this
behavior to me.

I have been investigating an odd behavior in a
TCP application that I ended up duplicating in
an unmodified TTCP.  I only changed it to enable
automatically starting the sender on RTEMS.

If the "ttcp -r -s" process is waiting for the
connection on Linux before the "ttcp -s -t .."
is initiated on RTEMS, most of the time there
is a 5 to 7 second delay between the first 2-3
TCP packets in the sequence and the rest
of them.  The rest of the packets stream out
quickly as expected. 

If the Tx side is started first and the Rx side
second, there is never a delay.

I have investigated enough on the application to
believe that the system is nearly completely idle
and blocked inside write(socket).

Attached is a fragment gathered by tcpdump while running
the application on an MPC5200 with just it and my laptop
(Dell) on the LAN.  I have gotten similar logs with ttcp. 
This log shows the gap.

192.168.1.14  is the DNS server,
192.168.1.210 is the Dell laptop (Fedora 7).
192.168.1.245 is the Freescale MPC5200 board.
Adtran is our firewall.

1188501829.144415 192.168.1.210 -> 192.168.1.245 TFTP Data Packet, 
Block: 427 (last)
1188501829.144817 192.168.1.245 -> 192.168.1.210 TFTP Acknowledgement, 
Block: 427
1188501829.219924 Dell_ef:82:6a -> Adtran_1c:ee:28 ARP Who has 
192.168.1.14?  Tell 192.168.1.210
1188501829.885923 192.168.1.210 -> 209.85.133.18 TCP [TCP 
Retransmission] [TCP segment of a reassembled PDU]
1188501830.219922 Dell_ef:82:6a -> Adtran_1c:ee:28 ARP Who has 
192.168.1.14?  Tell 192.168.1.210
1188501833.526897 Freescal_00:5b:41 -> Broadcast    ARP Who has 
192.168.1.210?  Tell 192.168.1.245
1188501833.526919 Dell_ef:82:6a -> Freescal_00:5b:41 ARP 192.168.1.210 
is at 00:14:22:ef:82:6a
1188501833.527082 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [SYN] Seq=0 Len=0 MSS=1460 WS=0 TSV=6 TSER=0
1188501833.527109 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=23846380 TSER=6 WS=6
1188501833.543224 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=1 Ack=1 Win=17376 Len=0 TSV=7 TSER=23846380
  *** start of ~8 second gap
1188501835.075941 192.168.1.210 -> 192.168.1.3  SSH [TCP Retransmission] 
Encrypted request packet len=192
1188501836.766910 Dell_ef:82:6a -> Broadcast    ARP Who has 
192.168.1.14?  Tell 192.168.1.210
1188501837.766898 Dell_ef:82:6a -> Broadcast    ARP Who has 
192.168.1.14?  Tell 192.168.1.210
1188501838.766922 Dell_ef:82:6a -> Broadcast    ARP Who has 
192.168.1.14?  Tell 192.168.1.210
1188501840.669881 Dell_ef:82:6a -> Broadcast    ARP Who has 
192.168.1.14?  Tell 192.168.1.210
  *** end of ~8 second gap
1188501841.543158 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=1 Ack=1 Win=17376 Len=1448 TSV=22 TSER=23846380
1188501841.543206 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=1449 Win=8704 Len=0 TSV=23854396 TSER=22
1188501841.543769 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=1449 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854396
1188501841.543797 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=2897 Win=11584 Len=0 TSV=23854396 TSER=23
1188501841.543903 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=2897 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854396
1188501841.543918 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=4345 Win=14528 Len=0 TSV=23854397 TSER=23
1188501841.544435 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=4345 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854396
1188501841.544455 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=5793 Win=17408 Len=0 TSV=23854397 TSER=23
1188501841.544603 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=5793 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854397
1188501841.544619 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=7241 Win=20288 Len=0 TSV=23854397 TSER=23
1188501841.545100 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=7241 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854397
1188501841.545131 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=8689 Win=23168 Len=0 TSV=23854398 TSER=23
1188501841.545184 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=8689 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854397
1188501841.545205 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=10137 Win=26112 Len=0 TSV=23854398 TSER=23
1188501841.545336 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=10137 Ack=1 Win=17376 Len=1448 TSV=23 TSER=23854397
1188501841.545360 192.168.1.210 -> 192.168.1.245 TCP commplex-link > 
1024 [ACK] Seq=1 Ack=11585 Win=28992 Len=0 TSV=23854398 TSER=23
1188501841.545762 192.168.1.245 -> 192.168.1.210 TCP 1024 > 
commplex-link [ACK] Seq=11585 Ack=1 Win=17376 Len=1448 TSV=23 TSER=2385398

Any ideas?

--joel