CC3235SF: sl_Recv seems to return data with a long delay for non blocking sockets.

Hi Keith,

Are you using the most recent CC32XX SDK and service pack?

Best regards,

Jesse

The application was originally written with 4.3.  It has the newest service pack but is still using 4.3 SDK.  I will test it with 6.1 SDK in the morning.

Hey Keith,

Thanks for the additional info. Let me know if you see the same results with the updated SDK.

Best regards,

Jesse

Jesse,

I created a small demo application so it was easier to upgrade to all of the latest code.  I am still seeing this issue.

Using SDK 6.1, FreeRTOS 202112.00, CCS 11.2

The delay between the TCP message being seen by wireshark and being processed by the code seems to vary from 60ms to about 1.5 seconds.

Transmits however are very fast less than 1ms.

I need to be able to receive frames much faster than this for my application.

Hey Keith,

Thanks for checking with the updated SDK.

Can you provide the code for your Process_TCP_Server()? Is there anything in the loop there that could be causing the delay? Also, do you need to use non-blocking sockets here, or could you use blocking sockets?

Best regards,

Jesse

void Process_TCP_Server()
{
    bool ipv6 = false;
    static int16_t socketHandleTCP = -1;
    static int16_t connectedHandleTCP = -1;
    static SlSockAddr_t    *sa;  /* Contains the local ip address and port */
    static SlSockAddr_t    *csa; /* Contains the ip address and port of the connected peer. */
    static sockAddr_t sAddr;
    static int32_t addrSize;
    static uint16_t portNumber = 13400;
    static int16_t doip_tcp_socketState = 0;


    int16_t socketStatus = 0;
    int16_t sent_bytes = 0;
    uint32_t msgSize = 0;
    uint16_t msgType = 0xFFFF;
    bool tcpReadError = false;
    bool tcpFirstPacket = true;

    //Variables created to track unused time when socket connection exists, but it is idle and there is no traffic.
    static bool unused = false;
    static time_t unused_time = 0;
    struct timespec tsStartTime;
    clock_gettime(CLOCK_MONOTONIC, &tsStartTime);
    static time_t prev_time = 0;

    if (deviceConnected)
    {

        /* To make sure the socket is closed and reopened in case it is unused for some time defined by UNUSED_TIMEOUT */
        if(unused == false)      //if unused is ever set to false, unused_time is cleared and set to 0 seconds
        {
            unused_time = 0;
            prev_time = tsStartTime.tv_sec;
        }
        else
        {
            unused_time+= tsStartTime.tv_sec - prev_time;    //if unused time remains true, the time is kept track of and updated
            prev_time = tsStartTime.tv_sec;
        }

        if(unused_time>=UNUSED_TIMEOUT && connectedHandleTCP >= 0)
        {
            sl_Close(socketHandleTCP);
            sl_Close(connectedHandleTCP);
            doip_tcp_socketState = 0;
        }


        switch(doip_tcp_socketState)
        {
        case 0: // Create Socket

            if(ipv6)
            {
                sAddr.in6.sin6_family = SL_AF_INET6;
                sAddr.in6.sin6_port = sl_Htons(portNumber);
                memset(sAddr.in6.sin6_addr._S6_un._S6_u32, SL_INADDR_ANY,
                       sizeof(sAddr.in6.sin6_addr._S6_un._S6_u32));

                sa = (SlSockAddr_t*)&sAddr.in6;
                csa = (SlSockAddr_t*)&sAddr.in6;
                addrSize = sizeof(SlSockAddrIn6_t);
            }
            else
            {
                /* filling the TCP server socket address */
                sAddr.in4.sin_family = SL_AF_INET;

                /* Set the server's port:
                   We'll receive connection requests on this port */
                sAddr.in4.sin_port = sl_Htons((unsigned short)portNumber);
                sAddr.in4.sin_addr.s_addr = SL_INADDR_ANY;

                sa = (SlSockAddr_t*)&sAddr.in4;
                csa = (SlSockAddr_t*)&sAddr.in4;
                addrSize = sizeof(SlSockAddrIn_t);
            }

            socketHandleTCP = sl_Socket(sa->sa_family, SL_SOCK_STREAM , SL_IPPROTO_TCP);
            if (socketHandleTCP >= 0) {
                // bind port
                socketStatus = sl_Bind(socketHandleTCP, sa, addrSize);
                if(socketStatus != 0)
                {
                 // error
                    sl_Close(socketHandleTCP);
                    doip_tcp_socketState = 0;
                }
                else
                {
                    // listen on port
                    socketStatus = sl_Listen(socketHandleTCP, 0);
                    if(doip_tcp_socketState != 0)
                    {
                    // error
                        sl_Close(socketHandleTCP);
                        doip_tcp_socketState = 0;
                    }
                    else
                    {
                        int32_t nonBlocking = 1;
                        socketStatus = sl_SetSockOpt(socketHandleTCP, SL_SOL_SOCKET, SL_SO_NONBLOCKING, &nonBlocking, sizeof(nonBlocking));
                        if(socketStatus < 0)
                        {
                            sl_Close(socketHandleTCP);
                            //sl_Close(connectedHandleTCP);
                            doip_tcp_socketState = 0;
                        }
                        doip_tcp_socketState++;
                        unused = false;  //Unused set to false since socket is in use at the moment
                    }
                }
            }
            else
            {
                sl_Close(socketHandleTCP);
            }
            break;
        case 1: // accept connection
            connectedHandleTCP = sl_Accept(socketHandleTCP, csa, (SlSocklen_t*)&addrSize);
            if (connectedHandleTCP == SL_ERROR_BSD_EAGAIN)
            {
                // timeout do nothing.
                unused = true;  //Unused set to true since socket is not in use at the moment
            }
            else if (connectedHandleTCP < 0)
            {
                sl_Close(socketHandleTCP);
                sl_Close(connectedHandleTCP);
                doip_tcp_socketState = 0;
            }
            else
            {

                int32_t nonBlocking = 1;
                socketStatus = sl_SetSockOpt(connectedHandleTCP, SL_SOL_SOCKET, SL_SO_NONBLOCKING, &nonBlocking, sizeof(nonBlocking));
                if(socketStatus < 0)
                {
                    sl_Close(socketHandleTCP);
                    sl_Close(connectedHandleTCP);
                    doip_tcp_socketState = 0;
                }
                else
                {
                    doip_tcp_socketState++;
                    unused = false;  //Unused set to false since socket is in use at the moment
                }
            }
            break;
        case 2: // send
            if (doip_TCP_Msg_To_Send())
            {

//                while((sent_bytes < bytes_to_send) && (socketState == 2))
//                {
//                    if(bytes_to_send - sent_bytes >= BUF_LEN)
//                    {
//                        bufferSize = BUF_LEN;
//                    }
//                    else
//                    {
//                        bufferSize = bytes_to_send - sent_bytes;
//                    }

                    /* Send packets to server */
                    socketStatus = sl_Send(connectedHandleTCP, tcpTxMsgQueue->msgData, tcpTxMsgQueue->msgDataLength, 0);
                    if(socketStatus < 0)
                    {
                        sl_Close(socketHandleTCP);
                        sl_Close(connectedHandleTCP);
                        doip_tcp_socketState = 0;
                    }
                    else
                    {
                        sent_bytes += socketStatus;
                        doip_tcp_socketState = 3;
                        unused = false;  //Unused set to false since socket is in use at the moment
                    }
                    popItemFromTxMsgQueue(&tcpTxMsgQueue);
//                }
            }
            else
            {
                doip_tcp_socketState = 3;
                unused = true;  //Unused set to true since socket is not in use at the moment
            }
            break;
        case 3: // receive
            doipTcpMsgReceivedSize = 0;
            tcpReadError = false;
            tcpFirstPacket = true;
            do {
                socketStatus = sl_Recv(connectedHandleTCP, &doipTcpMsgReceived[doipTcpMsgReceivedSize], MAX_BUF_SIZE, 0);
                if (socketStatus == SL_ERROR_BSD_EAGAIN)
                {
                    doip_tcp_socketState = 2;
                    tcpReadError = true;
                    unused = true;  //Unused set to true since socket is not in use at the moment
                }
                else if(socketStatus < 0)
                {
                    sl_Close(socketHandleTCP);
                    sl_Close(connectedHandleTCP);
                    doip_tcp_socketState = 0;
                    tcpReadError = true;
                }
                else if(socketStatus == 0)
                {
                    // client closed connection
                    sl_Close(socketHandleTCP);
                    sl_Close(connectedHandleTCP);
                    doip_tcp_socketState = 0;
                    tcpReadError = true;
                }
                else
                {
                    // Get Message Size,
                    if (tcpFirstPacket) {
                        // 8 message header + payload length.
                        msgType = ((doipTcpMsgReceived[2] << 8) + doipTcpMsgReceived[3]);
                        msgSize = 8 + ((doipTcpMsgReceived[4] << 24) + (doipTcpMsgReceived[5] << 16) + (doipTcpMsgReceived[6] << 8) + doipTcpMsgReceived[7]);
                        tcpFirstPacket = false;
                    }
                    doipTcpMsgReceivedSize += socketStatus;
                    unused = false;  //Unused set to false since socket is in use at the moment
                    // If there are more bytes remaining read again and continue to fill the array
                    // When all bytes are read then process the message.
                }
            } while ((doipTcpMsgReceivedSize < msgSize) && (tcpReadError == false));
            if (tcpReadError == false) {
                doip_tcp_socketState = 2;
                doip_ProcessReceiveMsg(TCP, msgType, msgSize);
                socketStatus = sl_Send(connectedHandleTCP, tcpTxMsgQueue->msgData, tcpTxMsgQueue->msgDataLength, 0);
                unused = false;  //Unused set to false since socket is in use at the moment
            }

            break;
        case 4: // close socket
            sl_Close(socketHandleTCP);
            sl_Close(connectedHandleTCP);
            doip_tcp_socketState = 0;
            break;
        default: // close return to state 0;
            // doip_tcp_socketState = 0;
            break;
        }
    }
}

 The send after the receive is there only for my testing purposes to test the lag of the loops.

2458 121.637169 192.168.1.35 192.168.1.245 UDS 68 Request Diagnostic Session Control Default Session
2461 121.824488 192.168.1.245 192.168.1.35 DoIP 67 Diagnostic message ACK
2462 121.824589 192.168.1.245 192.168.1.35 DoIP 67 Diagnostic message ACK

As you can see the first transmit happens once the frame is received and the second happens very quickly following.

Hi Keith,

I've tested non-blocking sockets using the network terminal demo in the SDK and haven't been able to replicate this issue. I'm still looking into it.

Best regards,

Jesse

Hey Keith,

Have you taken a look at the socket code from an example like the network terminal demo in the SDK (code for TCPClient() and TCPServer() in socket_cmd.c)?

Do you see a similar delay when using blocking sockets?

Best regards,

Jesse

Jesse,

I based the Socket code on the TCP server in the network demo from sdk 4.3.  I have not tested the behavior with blocking sockets as I am both sending and receiving data on that socket based on data from another source in my device.  I did not want the socket to be stuck waiting to read when I need to transmit data.  I could rebuild the application using multiple TCP sockets one for sending and one for receiving if that is my only solution.

Hey Keith,

I don't see these kinds of delays coming from the CC3235. Can you provide WiFi sniffer logs so we can see all the WiFi traffic?

Best regards,

Jesse

Jesse,

I started with the localtime demo in the 6.1 sdk using freertos

I have two threads, the first one is the sl_task thread

the second is the TCP/ UDP server thread

All other code from that demo is not called.

The UDP server for my testing was disabled after the initial message for connecting to the device.

I have tried this in the debugger and in uniflash.

1516 -12.259548 192.168.1.35 192.168.1.245 UDS 68 Request Diagnostic Session Control Default Session
1517 -12.010529 52.96.163.2 192.168.1.35 TLSv1.2 91 Application Data
1518 -11.998197 192.168.1.245 192.168.1.35 TCP 60 13400 → 53697 [ACK] Seq=53 Ack=43 Win=32120 Len=0
1519 -11.991943 192.168.1.245 192.168.1.35 DoIP 67 Diagnostic message ACK
1520 -11.991741 192.168.1.245 192.168.1.35 DoIP 67 Diagnostic message ACK
1521 -11.970608 192.168.1.35 52.96.163.2 TCP 54 61217 → 443 [ACK] Seq=1 Ack=149 Win=1024 Len=0
1522 -11.968651 192.168.1.35 192.168.1.245 TCP 54 53697 → 13400 [ACK] Seq=43 Ack=79 Win=32648 Len=0

int main(void)
{

    int retc;
    int detachState;
    pthread_t doipTcpServerThread;
    pthread_attr_t pthreadAttrs;
    struct sched_param  priParam;
    pthread_t slThread;

    /* Call board init functions */
    Board_init();
    GPIO_init();
    SPI_init();

    pthread_attr_init(&pthreadAttrs);

    priParam.sched_priority = SPAWN_TASK_PRIORITY;
    retc = pthread_attr_setschedparam(&pthreadAttrs, &priParam);
    retc = pthread_attr_setstacksize(&pthreadAttrs, 2048);
    if (retc != 0) {
        // Error setting stack size
        while (1);
    }

    retc = pthread_create(&slThread, &pthreadAttrs, sl_Task, NULL);
    if (retc != 0) {
        // Failed to create sl_Task thread
        while (1);
    }

    // Create DoIP TCP Server Thread
    retc = pthread_attr_setstacksize(&pthreadAttrs, 4096);
    if (retc != 0) {
        // Error setting stack size
        while (1);
    }

    retc = pthread_create(&doipTcpServerThread, &pthreadAttrs, doipTcpServerThreadFxn, NULL);
    if (retc != 0) {
        // Failed to create ISM thread
        while (1);
    }

    pthread_attr_destroy(&pthreadAttrs);




    /* Start the FreeRTOS scheduler */
    vTaskStartScheduler();

    return (0);

}

Hey Keith,

Thanks for the update. I'm still looking into this and will provide an update tomorrow.

Best regards,

Jesse

Hi Keith,

When testing again on my end using non-blocking sockets from the network terminal demo and LAUNCHXL-3235SF, I consistently see responses (ACK) from the device within tens of milliseconds, never near 1 second.

It is likely that the delay is coming from your environment or your application. If you can provide a WiFi sniffer log of all the traffic over the air using a network sniffer that would be helpful.

Best regards,

Jesse

Jesse,  

The last log I sent is from wireshark of all traffic during that time, there was not much.  What about settings required in sysconfig for having both the UDP and TCP server sockets running at the same time where both are non blocking.

I Have checked lots of things on my side and am fairly certain there are no network issues.  The network I test on regularly only has my PC and the device on it so there is very little traffic.

Is there a way for us to set up a meeting on zoom where we could review the code and the project and I could show your team the issues we are seeing?

Hi Keith,

There shouldn't be any issues with having UDP and TCP server sockets running at the same time when both are non-blocking. Chapter 6 and Section 6.7.1 of the Network Processor User's Guide have more socket information and code examples. We do typically recommend blocking sockets for OS applications with separate threads for send/receive and non-blocking sockets for non-OS applications.

A Wi-Fi sniffer log of the delays, if you can capture one, would be helpful because we could see the packets as they pass through the network (from your PC to the AP to CC3235SF and then ACKs sent back to your PC by our device) to see where the delay is coming from.

Are you enabling any low power modes? If so, could you disable them and re-test. This could be a possible source of the delay.

The delay could also come from the receive buffer of the CC3235SF filling up. When the buffer is full, the NWP will not receive additional packets on the socket until the host reads from the buffer, which will cause retransmission and slow the TCP stream. 

I am not able to set up a zoom meeting, but I can continue to provide support here.

Best regards,

Jesse

Jesse,

I would to recreate the tests you are running.  If I start with the network app running FREERTOS.  And use the TCP server code that I posted here in place of the base code in the app.  Modified to just send a default response to a received frame should it work?  What steps did you take to create your test environment?

Hi Keith,

I used the standard network terminal demo from the SDK, connected to local AP and configured the CC3235SF as a server receiving on a non-blocking socket (recv -s -nb) and sent tcp packets to the C3235SF from my PC.

I examined the time between when a packet was sent by the PC and when that packet was ACKed by the CC3235SF. This is the delay you are measuring, right (the time between a packet being sent to the CC3235 and the packet being ACKed by the CC3235)?

Best,

Jesse

Hi Keith,

Were you able to recreate the tests? Is the delay you are measuring the time between a packet being sent to the CC3235 and the packet being ACKed by the CC3235, or a different delay?

Best regards,

Jesse

Jesse,

I was not able to easily reproduce your test case.  I did however provide Jacob with the a zipped up copy of the entire workspace for you along with an email with two logs from Wireshark.  One with the messages to send and receive to the application and another with ALL traffic to and from the application from power up until stopping the test.  This should help you be able to reproduce my issue and better assist.

The delay I am measuring is the one from the packet being received on the network until the CC3235 is able to send a response message ACK from the socket code.

Hey Keith,

Thanks for providing that information. I will take a look and plan to provide you with an update within the next two days.

Best,

Jesse

Hi Keith,

After looking closely at the Wireshark captures you provided, I put together the diagram below to visualize the traffic as they are sent between your PC and the CC3235, and see where the delay could be coming from.

From my understanding, you are using Wireshark to monitor the local Wi-Fi interface of your PC. The green lines in the diagram indicate the traffic we can see from your Wireshark capture (packets being sent from and received at your PC's Wi-Fi interface), while the red lines indicate traffic we cannot see without a Wi-Fi sniffer log. There is also additional 802.11 traffic that we cannot currently see.

Looking at the diagram above, you will see I've split the CC3235 into the host MCU and the network processor (NWP) to distinguish between the TCP ACKs and the DoIP ACKs from the CC3235. When the TCP client send a DoIP or UDS request to the CC3235, the NWP receives the packet, places it in a receive buffer, and the NWP sends the TCP ACK. When sl_Recv is called from the host MCU, the packet is removed from the buffer and processed, at which point sl_Send is called to send the DoIP Message ACK from the CC3235 to your PC. 

I've included screenshots of two Wireshark captures of my own--one monitoring the Wi-Fi interface on my PC and one using a Wi-Fi sniffer--to show the differences in information provided by each of them. Each of these Wireshark captures are using nonblocking sockets in the network terminal demo I mentioned previously--I'm still working on building your project in my workspace. A wireless sniffer capture would help us get a full picture of what's going on.

PC Wi-Fi interface:

Wi-Fi sniffer log:

Also, can you make sure you have the power policy of the CC3235 set to Always On to make sure that traffic destined for the CC3235 isn't being buffered by the AP while the CC3235 is sleeping--this could be a possible source of the delay.

Best regards,

Jesse

Jesse,  were you able to run the application I sent and reproduce the issue or did it work fine on your side?  I am still working on these tasks as we had some other high priority tasks come up.

Hey Keith,

I was able to get your application to build and flash it but I haven't been able to verify it is running properly. I see that you commented out the UART_PRINT() statements.

• Is anything being output to the terminal in your application, or any LEDs on the board that should toggle?
• Once the CC3235 is connected to the AP, what are you using to send and receive packets to and from the CC3235 from your laptop?

Also, I sent directions to Jacob on how to use a Mac or Linux machine as a Wi-Fi sniffer, which would help with examining the wireless traffic in your setup.

Best regards,

Jesse

Hey Keith,

I just wanted to confirm that I do have your application running on my end. Could you explain how you are sending packets to the CC3235 from your PC and receiving the responses to finish reproducing the behavior?

Let me know if you are able to take Wi-Fi sniffer captures of your setup using a Mac or Linux machine.

Best regards,

Jesse

We are using a tool called Vehicle Spy,  However any tool that will let you send TCP and UDP messages should work. You could even configure the network terminal demo to reproduce the traffic in the logs that I sent.

Hey Keith,

Could you provide an example of what the DoIP/TCP packets that the CC3235 is expecting (that would be sent from Vehicle Spy) should look like so that it responds appropriately?

Also, if you could share the saved Wireshark file that would make it easier to review than the plaintext from the capture. Have you been able to set up a Mac or Linux machine as a wireless sniffer to get a full picture of what's going on in your environment?

Best regards,

Jesse

Hey Keith,

Just checking in here:

• Can you provide an example of what the DoIP/TCP packets that the CC3235 is expecting (that would normally be sent from Vehicle Spy) should look like so that the CC3235 responds appropriately?
  
  
• Have you had a chance to set up a Mac or Linux machine as a wireless sniffer to get a full picture of what's going on in your environment?

Best regards,

Jesse

I had to work on another project,  I did add commands in the code to ensure full on mode.

    sl_WlanPolicySet(SL_WLAN_POLICY_PM , SL_WLAN_ALWAYS_ON_POLICY, NULL,0);

I will email the wireshark Log of the messages.

Hey Keith,

Thanks for the update. I look forward to your email and will let you know when I've had a chance to look through the Wireshark logs

Best regards,

Jesse

Jesse,

Did Jacob forward my email to you?  If not how should I send it to you?

Hi Keith,

I have not received it yet. I just sent you a friend request on E2E and you should be able to direct message it to me privately.

Best regards,

Jesse