|
| From: | bill |
| Subject: | RE: [lwip-users] Significant overhead periodically during TCP receive transfers |
| Date: | Tue, 7 Oct 2008 17:58:11 -0400 |
> I don't know of any timers that have that periodicity in lwIP. It
> might be useful to get a packet capture from just before the poor
> performance that we could look at in ethereal - that might give a clue
> about why the performance is poor.
Below is the start of the problem. There were 49995 prior packets with smaller datablock inbound packets received one per second without any errors. You can see the returned 864 byte ACK packet 49992 and then there are 2 ARP packets. The next packet contains an error. If I knew any better it looks to me like the outgoing ARP reply to the PC overwrote the outbound TCP ACK. I don't know why after 9:30 minutes of connect time this is happening.
This set of errors causes an error recovery which looks to take many milliseconds to unwind.
> I've no idea what sort of OS you're running lwIP in, but is it
> possible that it takes 9.5 minutes for something like memory to become
> badly fragmented, and then an allocation after that point triggering a
> clean- up which takes some time?
Oh sorry. This is with a cooperative multitasker, however, I rolled back to a polled version of the code that still exhibits the problem. The sending PC is using Winsock - the send function is passed the full data block and length in one call.
In case it's pertinent, in order to get the 836 ack packet back to the PC ASAP, I used a tcp_write followed by a tcp_output. Also, I have tried all 4 combinations of flags on the tcp_write call hoping for some change in behavior. Nothing made a difference.
I am using a malloc/free library and the pointers to and from malloc and free are checked. The returned pointers from pbuf_alloc are also checked in the low level driver.
Thank you again!
Bill
No. Time Source Destination Protocol Info
49986 353.846759 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086526762 Win=65532 Len=0
Frame 49986 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9a (40346)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa604 [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086526762, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086526762
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x429c [validation disabled]
No. Time Source Destination Protocol Info
49987 353.846784 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086528222 Win=65532 Len=0
Frame 49987 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9b (40347)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa603 [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086528222, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086528222
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x3ce8 [validation disabled]
No. Time Source Destination Protocol Info
49988 353.846809 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086529682 Win=65532 Len=0
Frame 49988 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9c (40348)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa602 [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086529682, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086529682
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x3734 [validation disabled]
No. Time Source Destination Protocol Info
49989 353.846827 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086531142 Win=65532 Len=0
Frame 49989 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9d (40349)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa601 [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086531142, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086531142
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x3180 [validation disabled]
No. Time Source Destination Protocol Info
49990 353.846846 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086532602 Win=65532 Len=0
Frame 49990 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9e (40350)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa600 [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086532602, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086532602
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x2bcc [validation disabled]
No. Time Source Destination Protocol Info
49991 353.846872 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [ACK] Seq=507105 Ack=4086532834 Win=65532 Len=0
Frame 49991 (60 bytes on wire, 60 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 40
Identification: 0x9d9f (40351)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa5ff [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086532834, Len: 0
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
Acknowledgement number: 4086532834
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 65532
Checksum: 0x2ae4 [validation disabled]
[SEQ/ACK analysis]
[This is an ACK to the segment in frame: 49946]
[The RTT to ACK the segment was: 0.001023000 seconds]
No. Time Source Destination Protocol Info
49992 354.862631 192.168.123.113 192.168.123.110 TCP 50507 > 3096 [PSH, ACK] Seq=507105 Ack=4086532834 Win=65532 Len=864
Frame 49992 (918 bytes on wire, 918 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Internet Protocol, Src: 192.168.123.113 (192.168.123.113), Dst: 192.168.123.110 (192.168.123.110)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 904
Identification: 0x9da0 (40352)
Flags: 0x00
Fragment offset: 0
Time to live: 255
Protocol: TCP (0x06)
Header checksum: 0xa29e [correct]
Source: 192.168.123.113 (192.168.123.113)
Destination: 192.168.123.110 (192.168.123.110)
Transmission Control Protocol, Src Port: 50507 (50507), Dst Port: 3096 (3096), Seq: 507105, Ack: 4086532834, Len: 864
Source port: 50507 (50507)
Destination port: 3096 (3096)
Sequence number: 507105
[Next sequence number: 507969]
Acknowledgement number: 4086532834
Header length: 20 bytes
Flags: 0x18 (PSH, ACK)
Window size: 65532
Checksum: 0xc561 [validation disabled]
Data (864 bytes)
0000 de ad be ef 00 00 00 20 ff ff ff df 88 65 e9 a2 ....... .....e..
No. Time Source Destination Protocol Info
49993 354.862861 00:1e:c9:35:34:4a Broadcast ARP Who has 192.168.123.113? Tell 192.168.123.110
Frame 49993 (42 bytes on wire, 42 bytes captured)
Ethernet II, Src: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a), Dst: Broadcast (ff:ff:ff:ff:ff:ff)
Address Resolution Protocol (request)
Hardware type: Ethernet (0x0001)
Protocol type: IP (0x0800)
Hardware size: 6
Protocol size: 4
Opcode: request (0x0001)
Sender MAC address: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Sender IP address: 192.168.123.110 (192.168.123.110)
Target MAC address: 00:00:00_00:00:00 (00:00:00:00:00:00)
Target IP address: 192.168.123.113 (192.168.123.113)
No. Time Source Destination Protocol Info
49994 354.862911 IeeeRegi_8d:80:02 00:1e:c9:35:34:4a ARP 192.168.123.113 is at 00:50:c2:8d:80:02
Frame 49994 (64 bytes on wire, 64 bytes captured)
Ethernet II, Src: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02), Dst: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Address Resolution Protocol (reply)
Hardware type: Ethernet (0x0001)
Protocol type: IP (0x0800)
Hardware size: 6
Protocol size: 4
Opcode: reply (0x0002)
Sender MAC address: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02)
Sender IP address: 192.168.123.113 (192.168.123.113)
Target MAC address: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a)
Target IP address: 192.168.123.110 (192.168.123.110)
No. Time Source Destination Protocol Info
49995 354.862916 192.168.123.110 192.168.123.113 TCP [TCP Previous segment lost] 3096 > 50507 [ACK] Seq=4086562034 Ack=507969 Win=64671 Len=1460
Frame 49995 (1514 bytes on wire, 1514 bytes captured)
Ethernet II, Src: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a), Dst: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02)
Internet Protocol, Src: 192.168.123.110 (192.168.123.110), Dst: 192.168.123.113 (192.168.123.113)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 1500
Identification: 0x04de (1246)
Flags: 0x04 (Don't Fragment)
Fragment offset: 0
Time to live: 128
Protocol: TCP (0x06)
Header checksum: 0x780d [correct]
Source: 192.168.123.110 (192.168.123.110)
Destination: 192.168.123.113 (192.168.123.113)
Transmission Control Protocol, Src Port: 3096 (3096), Dst Port: 50507 (50507), Seq: 4086562034, Ack: 507969, Len: 1460
Source port: 3096 (3096)
Destination port: 50507 (50507)
Sequence number: 4086562034
[Next sequence number: 4086563494]
Acknowledgement number: 507969
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 64671
Checksum: 0x7dff [validation disabled]
[SEQ/ACK analysis]
[This is an ACK to the segment in frame: 49992]
[The RTT to ACK the segment was: 0.000285000 seconds]
[TCP Analysis Flags]
[A segment before this frame was lost]
Data (1460 bytes)
0000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ................
No. Time Source Destination Protocol Info
49996 354.862916 192.168.123.110 192.168.123.113 TCP 3096 > 50507 [ACK] Seq=4086563494 Ack=507969 Win=64671 Len=1460
Frame 49996 (1514 bytes on wire, 1514 bytes captured)
Ethernet II, Src: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a), Dst: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02)
Internet Protocol, Src: 192.168.123.110 (192.168.123.110), Dst: 192.168.123.113 (192.168.123.113)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 1500
Identification: 0x04df (1247)
Flags: 0x04 (Don't Fragment)
Fragment offset: 0
Time to live: 128
Protocol: TCP (0x06)
Header checksum: 0x780c [correct]
Source: 192.168.123.110 (192.168.123.110)
Destination: 192.168.123.113 (192.168.123.113)
Transmission Control Protocol, Src Port: 3096 (3096), Dst Port: 50507 (50507), Seq: 4086563494, Ack: 507969, Len: 1460
Source port: 3096 (3096)
Destination port: 50507 (50507)
Sequence number: 4086563494
[Next sequence number: 4086564954]
Acknowledgement number: 507969
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 64671
Checksum: 0x7dff [validation disabled]
Data (1460 bytes)
0000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ................
No. Time Source Destination Protocol Info
49997 354.862926 192.168.123.110 192.168.123.113 TCP 3096 > 50507 [ACK] Seq=4086564954 Ack=507969 Win=64671 Len=1460
Frame 49997 (1514 bytes on wire, 1514 bytes captured)
Ethernet II, Src: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a), Dst: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02)
Internet Protocol, Src: 192.168.123.110 (192.168.123.110), Dst: 192.168.123.113 (192.168.123.113)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 1500
Identification: 0x04e0 (1248)
Flags: 0x04 (Don't Fragment)
Fragment offset: 0
Time to live: 128
Protocol: TCP (0x06)
Header checksum: 0x780b [correct]
Source: 192.168.123.110 (192.168.123.110)
Destination: 192.168.123.113 (192.168.123.113)
Transmission Control Protocol, Src Port: 3096 (3096), Dst Port: 50507 (50507), Seq: 4086564954, Ack: 507969, Len: 1460
Source port: 3096 (3096)
Destination port: 50507 (50507)
Sequence number: 4086564954
[Next sequence number: 4086566414]
Acknowledgement number: 507969
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 64671
Checksum: 0x7dff [validation disabled]
Data (1460 bytes)
0000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ................
No. Time Source Destination Protocol Info
49998 354.862933 192.168.123.110 192.168.123.113 TCP 3096 > 50507 [ACK] Seq=4086566414 Ack=507969 Win=64671 Len=1460
Frame 49998 (1514 bytes on wire, 1514 bytes captured)
Ethernet II, Src: 00:1e:c9:35:34:4a (00:1e:c9:35:34:4a), Dst: IeeeRegi_8d:80:02 (00:50:c2:8d:80:02)
Internet Protocol, Src: 192.168.123.110 (192.168.123.110), Dst: 192.168.123.113 (192.168.123.113)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
Total Length: 1500
Identification: 0x04e1 (1249)
Flags: 0x04 (Don't Fragment)
Fragment offset: 0
Time to live: 128
Protocol: TCP (0x06)
Header checksum: 0x780a [correct]
Source: 192.168.123.110 (192.168.123.110)
Destination: 192.168.123.113 (192.168.123.113)
Transmission Control Protocol, Src Port: 3096 (3096), Dst Port: 50507 (50507), Seq: 4086566414, Ack: 507969, Len: 1460
Source port: 3096 (3096)
Destination port: 50507 (50507)
Sequence number: 4086566414
[Next sequence number: 4086567874]
Acknowledgement number: 507969
Header length: 20 bytes
Flags: 0x10 (ACK)
Window size: 64671
Checksum: 0x7dff [validation disabled]
Data (1460 bytes)
0000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ................
| [Prev in Thread] | Current Thread | [Next in Thread] |