FreeRTOS+TCP slow to accept TCP connections

Libraries
1

I have a TCP server demo running on a STM32H7 Nucleo board. It seems to be working correctly for the most part: I can flood ping and there is no packet loss, I see ARP working correctly, and so on. But for some reason, when I try to connect to the stack over TCP, it takes a long and variable time to reply with SYN ACK—anywhere from a few SYN packets ignored to perhaps ten of them, before the stack suddenly ACKs and the connection is open. Once the TCP connection is established, everything seems fine again. Here is a packet trace using tcpdump; 192.168.15.1 is a Linux PC and 192.168.15.2 is the Nucleo board running FreeRTOS+TCP:

09:52:03.380033 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 192.168.15.2 tell 192.168.15.2, length 46
09:52:10.363374 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 192.168.15.2 tell 192.168.15.1, length 28
09:52:10.363685 ARP, Ethernet (len 6), IPv4 (len 4), Reply 192.168.15.2 is-at 00:11:22:33:44:55, length 50
09:52:10.363696 IP (tos 0x0, ttl 64, id 46606, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xe57b), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797594838 ecr 0,nop,wscale 7], length 0
09:52:11.365802 IP (tos 0x0, ttl 64, id 46607, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xe190), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797595841 ecr 0,nop,wscale 7], length 0
09:52:12.389672 IP (tos 0x0, ttl 64, id 46608, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xdd90), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797596865 ecr 0,nop,wscale 7], length 0
09:52:13.413779 IP (tos 0x0, ttl 64, id 46609, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xd990), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797597889 ecr 0,nop,wscale 7], length 0
09:52:14.437746 IP (tos 0x0, ttl 64, id 46610, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xd590), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797598913 ecr 0,nop,wscale 7], length 0
09:52:15.462046 IP (tos 0x0, ttl 64, id 46611, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xd190), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797599937 ecr 0,nop,wscale 7], length 0
09:52:17.511420 IP (tos 0x0, ttl 64, id 46612, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xc98e), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797601987 ecr 0,nop,wscale 7], length 0
09:52:21.541423 IP (tos 0x0, ttl 64, id 46613, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xb9d0), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797606017 ecr 0,nop,wscale 7], length 0
09:52:29.989755 IP (tos 0x0, ttl 64, id 46614, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0x98d0), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797614465 ecr 0,nop,wscale 7], length 0
09:52:33.218868 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 192.168.15.2 tell 192.168.15.2, length 46
09:52:35.109489 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 192.168.15.2 tell 192.168.15.1, length 28
09:52:35.109871 ARP, Ethernet (len 6), IPv4 (len 4), Reply 192.168.15.2 is-at 00:11:22:33:44:55, length 50
09:52:46.373435 IP (tos 0x0, ttl 64, id 46615, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0x58d0), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797630849 ecr 0,nop,wscale 7], length 0
09:53:03.060471 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 192.168.15.2 tell 192.168.15.2, length 46
09:53:18.629464 IP (tos 0x0, ttl 64, id 46616, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [S], cksum 0x9f82 (incorrect -> 0xdacf), seq 2741833246, win 64240, options [mss 1460,sackOK,TS val 797663105 ecr 0,nop,wscale 7], length 0
09:53:18.630286 IP (tos 0x0, ttl 128, id 0, offset 0, flags [none], proto TCP (6), length 52)
    192.168.15.2.23 > 192.168.15.1.37436: Flags [S.], cksum 0x238c (correct), seq 536886496, ack 2741833247, win 2920, options [mss 1460,nop,wscale 0,nop,nop,sackOK], length 0
09:53:18.630400 IP (tos 0x0, ttl 64, id 46617, offset 0, flags [DF], proto TCP (6), length 40)
    192.168.15.1.37436 > 192.168.15.2.23: Flags [.], cksum 0x6dc9 (correct), seq 1, ack 1, win 502, length 0

and here is the debugging output from the stack, on my serial terminal:

FreeRTOS_AddEndPoint: MAC: 44-55 IPv4: c0a80f02ip
main: starting scheduler
prvIPTask started
PHY ID 7C130
TCP listen: in task func
TCP listen: socket created
TCP listen: sockopts set
xPhyReset: phyBMCR_RESET 0 ready
+TCP: advertise: 01E1 config 3100
Autonego ready: 00000004: full duplex 100 mbit high status
TCP listen: socket bound
TCP listen: in loop
pxEasyFit: ARP c0a80f01ip -> c0a80f02ip
ipARP_REQUEST from c0a80f01ip to c0a80f02ip end-point c0a80f02ip
pxEasyFit: ARP c0a80f01ip -> c0a80f02ip
ipARP_REQUEST from c0a80f01ip to c0a80f02ip end-point c0a80f02ip
Gain: Socket 23 now has 1 / 20 child me: 20004ad0 parent: 20003fb8 peer: 20004ad0
prvSocketSetMSS: 1460 bytes for c0a80f01ip port 37436
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
TCP: passive 23 => 1.15.168.192 port 37436 set ESTAB (scaling 1)
prvAcceptWaitClient: client 20004ad0 parent 20003fb8
TCP listen: accepted! creating task

(The lines starting with “TCP listen:” are ones I added.) There is a minute-long delay between the ARP messages and the “Gain: Socket 23 now has 1 / 20 child”, during which time the stack is ignoring TCP SYN packets from timestamp 09:52:10.4 until 09:53:18.6, when it finally ACKs and the connection is suddenly established. From that time on there is basically zero latency and everything is perfectly snappy.

Any idea what might be going on, and how to debug it? Thanks.

2

Whats the priority of tasks in your system? Do you have any other tasks that are running with priority higher than FreeRTOS+TCP tasks that might block network tasks?

3

I’m seeing this:

name            state   prio    stack   num
Green LED       X       1       272     1
Yellow LED      R       1       100     2
Red LED         R       1       100     3
IDLE            R       0       104     6
EMAC_STM32      B       6       272     7
IP-task         B       5       2274    5
TCP Debug Liste B       1       551     4

(The “LED” tasks are simple blinkys with varying delays. The task list is obtained and printed as part of the “green LED” task.)
So I’m not seeing anything unexpected here. The IP-task is running at the highest priority except for the EMAC, and it is waiting on something, for many seconds. And during that time, it is ignoring SYN packets. But it will, for example, respond to an unlimited number of pings (ICMP) with practically zero latency (I see about 0.2 ms) and no dropped packets.

It does seem that other activity on the network “modulates” the deafness of the stack to TCP SYN packets. For example, if I run pings and then try to connect, it typically takes longer to SYN ACK, and the connection often times out completely. When trying to connect without pings running, it usually takes between 30-60 seconds.

Is there some way to turn up the debugging verbosity so I can see incoming packets traversing the various processing stages inside the stack?

4

See here: FreeRTOS-Plus-TCP Configuration - FreeRTOS™.

5

So basically, make all of the trace macros print something? A bit of a chore, but probably worth it. I’ll report back next week with findings.

6

No, that is not what I meant. I wanted you to define ipconfigHAS_DEBUG_PRINTF and ipconfigHAS_PRINTF to 1.

7

Oh, but I’ve already done that, as you can see from the trace messages above. I was asking if there was any additional logging / verbosity that I could turn on, since the basic debugging output isn’t hinting at why the stack goes deaf for TCP SYN packets for a while. Maybe I need to add some debug output in the lowest level code in NetworkInterface.c…

8

Yes, that seems like a good idea. It would help us determine if the SYN packet was received by the stack in time or not.

9

Ok, so far I’ve found that every packet is causing a call to HAL_ETH_RxLinkCallback() in STM32 NetworkInterface.c. There, prvAcceptPacket() is called and returns pdTRUE as expected. So the packets are making it through the software filters, but a lot of TCP SYN packets are failing to progress beyond that point. (ICMP and ARP have no trouble.)

HAL_ETH_RxLinkCallback() does nothing else except manipulate the network buffer descriptors. I don’t understand the driver well enough to know what is supposed to happen next. I expected a function call of some sort to trigger the next stage of rx packet processing, but no. Where should I look to see if the packet is “coming out the other side”?

[Small update: I dug into the HAL driver (the one provided in the FreeRTOS+TCP distribution) and added some debug output in HAL_ETH_ReadData(), after HAL_ETH_RxLinkCallback() is called. There is a while loop which seems to execute multiple times, then eventually a call to ETH_UpdateDescriptor(), all of which seems to be happening on the ignored packets as well as the one which finally “clicks” and sets up the connection.]

Paging @htibosch :slight_smile:

10

Ugh, please disregard (maybe?) most of what I wrote above. I thought the problem was likely to be in the low-level code and spent too much time tracing through it when I should have started looking at the IP task itself.

I’ve managed to trace the problem to prvProcessEthernetPacket(), sort of… I added debugging output to prvSendRxEvent() and xSendEventStructToIPTask(), to see which event types were being queued for the IP task. Everything looked normal, i.e. there were eNetworkRxEvent events being queued for all of the TCP SYN packets that were subsequently ignored by the stack.

I then turned my attention to prvProcessEthernetPacket(), and added a FreeRTOS_debug_printf call just before these lines:

    /* Interpret the received Ethernet packet. */
    switch( pxEthernetHeader->usFrameType )

to show me the frame type. As soon as I added the debug printf, everything started working perfectly. I commented it out, and was back to the same symptoms as before. In fact, adding the debug printf anywhere inside prvProcessEthernetPacket(), even at the end, makes the stack behave correctly.

I’m not sure where to go from here. Am I seeing a weird race condition? I tried replacing the debug printf with a short busy-wait, and also with a vTaskDelay(2), and those did not “fix” the problem like the printf. I thought maybe it had to do with the serial port output (not sure why), so I disabled that part; the printf was then just filling a buffer and returning. And it still made the stack work. So I’m baffled. Any ideas?

I may need to remove the printfs and use GPIO debugging in prvProcessEthernetPacket(), assuming that doesn’t magically make it work like the printf does…

11

Can you try turning off any compiler optimizations? Do you have any other tasks running at the same priority as the IP task? Using Tracelyzer may be beneficial here to understand what is going on.

12

@mark03

As soon as I added the debug printf, everything started working perfectly.

Could it be that accidentally, your .ethernet_data memory is cacheable? And that your debugging statement tries to access the cached memory?

So this could be enough to solve the problem:

if( pxEthernetHeader->usFrameType )
{
    _nop();
}

Just calling vTaskDelay(2) didn’t help, possibly because it didn’t try to access the cached memory?

Here is how I defined/used the memories, just as an example:

STM32H747XIHX_FLASH.ld
main.c

Note that AXI_RAM is used to store Ethernet packets.

1 Like