TM4C1294 NDK EMAC Hangs

Tom,

Can you check the EMAC module in ROV?  There are some stats there that may provide some insight.  In particular, there is a stat for the number of dropped frames.

It sounds like the Ethernet driver is dropping incoming Ethernet frames (which means that the IP packets within those frames wouldn’t be making it up into the stack, consistent with what you're saying).  If we can confirm this, it would point us in the right direction.

Regards,

- Rob

Dropped frames = 0.

I did a bit more digging into EMACSnow.c. I put a breakpoint at line 497 which is in the EMACIntStatus function:

if (status & EMAC_INT_ABNORMAL_INT) {
EMACSnow_private.abnormalInts++; <--- I put a breakpoint here
}

The board seems to run fine until it hits the breakpoint. The first time it hits, EMACSnow_private.abnormalInts = 0. Immediately hitting run, it keeps going back to the breakpoint and incrementing EMACSnow_private.abnormalInts.

For reference, the EMAC_DMARIS register typically seems to return 0x00010040 when things are running normally and the interrupt handler is entered. But when in the "hung" state, the EMAC_DMARIS register returns 0x000180C0. The difference is that apparently a Receive Buffer Unavailable event has occurred. (Bit 7 and Bit 15).

I am not sure this is correlated, but I looked at the Printf logs just after the breakpoint hits the first time. For most of the prior time the sequence seems to be (repeating):

EMACSnow_handlePackets handling packets status = 0x10040
EMACSnow_handlePackets Rx ones...
EMACSnow_handleRx: Enqueued recv packet 0x2001d5ac, length =nn
EMACSnow_handlePackets re-enable peripheral...
EMACSnow_pkt_service: give packet 0x2001d5ac to NDK bia NIMUReceivePacket
EMACSnow_emacSend: enqueued hPkt = 0x2001d5ac, len = nn
EMACSnow_hwiIntFxn Posting Swi status - 0x10001
EMACSnow_handlePackets handling packets status - 0x10001
EMACSnow_handlePackets Tx ones...
EMACSnow_handlePackets re-enable peripheral...


Just prior to the breakpoint tripping, the following appears:

EMACSnow_handlePackets handling packets status = 0x10040
EMACSnow_handlePackets Rx ones...
EMACSnow_handleRx: Enqueued recv packet 0x2001d514, length = nn
EMACSnow_handlePackets re-enable peripheral...
EMACSnow_pkt_service: give packet 0x2001d514 to NDK bia NIMUReceivePacket
EMACSnow_hwiIntFxn Posting Swi status - 0x10040
EMACSnow_handlePackets handling packets status - 0x10040
EMACSnow_handlePackets Rx ones...
EMACSnow_handlePackets re-enable peripheral...
EMACSnow_hwiIntFxn Posting Swi status - 0x10040
EMACSnow_handlePackets handling packets status - 0x10040
EMACSnow_handlePackets Rx ones...
EMACSnow_handlePackets re-enable peripheral...
EMACSnow_hwiIntFxn Posting Swi status - 0x10040
EMACSnow_handlePackets handling packets status - 0x10040
EMACSnow_handlePackets Rx ones...
EMACSnow_handlePackets re-enable peripheral... <--- This is the last line of the log

nn = a two digit number

My interpretation is that something stopped, but I don't know what....

Suggestions?
Tom

Tom,

That's some good debug info, thanks for that.

I will present this to our NDK expert and get back to you on the analysis (I confess, I don't know NDK).

Regards,

- Rob

Tom,

Tom Farmer said:

I did a bit more digging into EMACSnow.c. I put a breakpoint at line 497 which is in the EMACIntStatus function:

if (status & EMAC_INT_ABNORMAL_INT) {
EMACSnow_private.abnormalInts++; <--- I put a breakpoint here
}

Do you recall if you saw the abnormalInts count go up before putting the break point there?  Put another way, if you remove that break point, re-run to the problem scenario, then halt, what's the value of abnormalInts?

Steve

Hi Steve,

After the problem appears, EMACSnow_private.abnormalInts starts incrementing; with what seems to be every received packet.

I did a bit more digging and found that the problem may related to the PBM_alloc function returning a NULL (maining not able allocate a buffer) when called at EMACSnow.c line 364:

            else {
                /* Allocate a new buffer for this descriptor */
                hPktNew = PBM_alloc(ETH_MAX_PAYLOAD);
                if (hPktNew == NULL) {
                    /*
                     *  Leave the packet in the descriptor and owned by the driver.
                     *  Process when the next interrupt occurs.
                     */
                    break;
                }
The if condition does not seem to be true when things are running correctly.

Digging further, I put a breakpoint on the PBM_alloc function in pbm.c.  When things are running fine, PBMQ_free.count is between 0x6 and 0x10.  {I set the GLOBAL | BUFFER | PBM Buffers | Number of Frames to 16 in XCONF.}  When the target stops responding to packets, PBMQ_free.count is always 0.

Hi Steve,

Actually, I think it is a memory leak of some kind because the PBMQ_free.Count seems to be gradually dropping. It maybe related to a race condition.

I did some checking and it seems like the failure, with 16 frames, occurs consistently between 60 and 70 seconds after communications between the target and the PC application begin. While the exact time varies, it is almost always in this range. Increasing the frames to 32 moved the MTTF from 65 seconds to 170 seconds.

To try and see what is happening, I inserted the following statement as the first executable line in PBM_alloc and set the number of frames back to 16:

Log_print2(Diags_USER2, "PBM_alloc: PBMQ_free.Count = 0x%x, IsOpen = 0x%x", PBMQ_free.Count, IsOpen);

When I manually stop the code, the value of PCMQ_free.Count is always 0xa or 0x9 at ten seconds after connecting to the PC application, 0x7 at 30 seconds after connecting to the PC application, and 0x3 at 50 seconds after connecting to the PC application.

Just out of curiosity, I changed the Log_print2 to a System_printf and PBMQ_free.Count stayed at 0xa/0x9.

My conclusion is that there is some kind of buffer "memory leak" that may have a timing-related component to it.



For background, here is some information on what is happening in out application:

1. The target has multiple threads. One of these is a "discovery" task. Another is a "TelnetCmd" task.

2. Every 6 seconds, the PC application sends a broadcast UDP packet from its port23 to port 23. The discovery task is sitting on a "wait forever" select statement using a datagram SO_REUSEADDR SO_REUSEPORT socket. Once the discovery receives the broadcast packet, it sends a response UDP packet from a different datagram | SO_REUSEADDR SO_REUSEPORT socket (also on port 23) to the PC.

3. The "TelnetCmd" task is running at the same time. It uses an instance of telnet set up via XGCONF on port 23 with a callback function of TelnetCmdTask_Open. Once communications with the PC application are established, the TelnetCmd task sits on an fdSelect waiting for something to come out of the pipe. The fdSelect times out periodically. When this occurs the TelnetCmd task will check to see if another task has commanded it to send something via some flags in global memory. If there is something to be sent, it is sent via the same socket monitored by the fdSelect. In either case, the TelnetCmd task then resumes waiting on the fdSelect.

Do you suppose the problem could be that the TelnetCmd task's socket is being created without the SO_REUSEADDR SO_REUSEPORT?

For reference, here is how I set up the socket connection:

SOCKET TelnetCmdTask_Open( PSA pClient )
{
    // Check for error condition -- attempt to connect while already connected
    if (TRUE == bLogon)
    {
        // Close the existing connection.  (It probably was hung.)
        TelnetCmdTask_Close();

        // Tell the originator that something went wrong
        return( INVALID_SOCKET );
    }

    // Create the local pipe - abort on error
    if ( 0 != pipe( &fd1, &fd2 )) return ( INVALID_SOCKET );

    // fd2 will be the socket connection in the TelnetCmd task
    scon = fd2;

    // Set a semaphore to tell the TelnetCmd task to open a connection
    Semaphore_post(TelnetConnRqstSem);

    // Return the local fd
    return( fd1 );
}

What next?
Tom

Tom,

I have just looked through the code a couple of weeks ago and am pretty sure that every PBM_alloc() has a matching PBM_free(). I'm wondering, thinking out loud really, if PBM buffers are getting held up in the TCP layer, for whatever reason, leading to the eventual PBM_alloc() failure.

Is your app opening and closing sockets often?  A recent issue revealed that there is a possible memory leak when a socket is closed, related to the TCP tranmit buffer not being flushed out upon close.

Can you check the NDK stats for TCP, UDP and IP?  You can do this in CCS, via the expressions window.  The stats are global variables called "tcps", "udps" and "ips", respectively.

Please post what you see here.  Perhaps those stats will reveal something.

Steve

E.g.:

Hi Steve,

The code running on the TIVA device leaves the UDP broadcast receive socket on Port 23 and the port 23 UDP transmit socket open forever.

Opening and closing of the telnet sockets is done within NDK / TI-RTOS / TIVAWARE code.  The intent of my code is that it open a pipe and never close it; this seems to be working correctly.  That said, I monitored all of the network traffic from start to the failure using wireshark.  I did not see any TCP packets with SYN flag set beyond those during the first couple of seconds related to startup.

The only thing that seems interesting is that we do have the two UDP discovery packets (1 broadcast from the PC and a response from the target) every six seconds interleaved with the telnet traffic that is taking place.  (The UDP and telnet communications are handled by different tasks in the TIVA board.)  While I have not confirmed it, the earlier tests seemed to indicate that the buffer count was getting permanently decremented about  once per six seconds.  My understanding is that the PC application is also handling the UDP and telnet traffic by different threads but I have not confirmed this.  Could we have a problem with reentry into the alloc or free functions?

Anyway, to fulfill your request, here is the watch data under two circumstances, 10 seconds into the connection and after the failure.

First, after 10 seconds:

5861.tcp_10sec.docx

0763.udp_ip_10sec.docx

And here is after the failure:

3022.udp_ip_80sec.docx

7380.tcp_80sec.docx

Hi Tom,

Thanks for attaching those stats.  I noticed that the TCP stat "SndNoBufs" jumps from 0 to 60 (0x3c).  That stat is incremented when TcpOutput() cannot allocate a packet.  If anything, it just confirms that an allocation issue is part of this problem, as already suspected (and in this case, it's on the TX side).

My colleague and I have been pouring through the code today, trying to find where a leak can be coming from.  Can you try updating the driver to add another print, as well as a new count to see how many PBM_alloc()'s are failing?

The change would be in EMACSnow.c, in the function EMACSnow_handleRx(). Can you add the code in green/bold?

static void EMACSnow_handleRx()
{
    PBM_Handle       hPkt;
    PBM_Handle       hPktNew;
    int32_t          len;
    tDescriptorList *pDescList;
    uint32_t         ulDescEnd;
    static int numAllocFails = 0;

...

                /* Allocate a new buffer for this descriptor */
                hPktNew = PBM_alloc(ETH_MAX_PAYLOAD);
                if (hPktNew == NULL) {

                    numAllocFails++;

                    Log_print1(Diags_USER1,"numAllocFails = %d", numAllocFails);

                    Log_print1(Diags_USER1,"status = 0x%x", g_ulStatus);

                    /*
                     *  Leave the packet in the descriptor and owned by the driver.
                     *  Process when the next interrupt occurs.
                     */
                    break;
                }

Lastly, we are wondering about your priorities.  Have you changed any of the NDK's priorities in you application?  Also, what priorities are your application tasks running at?

One thing we wanted to make sure is that recv() is being called frequently enough to consume all of the incoming data.

Steve

Hi Steve,

The log info you requested is here:

6786.numAllocFails (2016-02-23).docx

I also left in some debug outputs of my own; you can see the source code in the right pane.

As for priorities, here is how they are set up:

#define HandpadAction_Task_Priority        0x01   <--  Deals with a USB device peripheral, when it is connected {not currently connected}
#define Housekeeping_Task_Priority        0x02   <--  Applications idle task.  This runs every millisecond or so and sleeps to let TI-RTOS kernal run
#define I2C_Eeprom_Task_Priority        0x03  <-- Handles an external I2C device.  Only accessed at boot; remains blocked on a mailbox forever after booting
//        NDK Low Task Priority            0x04  <-- Set via XGCONF
#define RS485Scan_Task_Priority            0x05  <-- Runs upon connect to PC application, but blocks forever afterwards. {Simplified explanation}
#define TrajectGen_Task_Priority        0x06  <-- Target is a motor control.  This task handles ramp-up / ramp-down during motion.  Otherwise blocked.
//        NDK Normal Task Priority        0x09   <-- Set via XGCONF
#define TelnetCmd_Task_Priority            0x0A  <-- This handles the PC application interface TELNET communicatiosn
#define Parser_Task_Priority            0x0B  <-- parses commands and generates responses from any interface.  Blocked otherwise
#define USBResponse_Task_Priority        0x0B  <-- handles TX/RX USB interface when connected as a device {not currently connected}
#define TelnetResponse_Task_Priority    0x0B <-- Handles the Telnet command / response communications via ethernet. 
#define HTTPResponse_Task_Priority        0x0B <-- Currently stubbed out.
#define RS485Response_Task_Priority        0x0B <-- Handles RS485 command/response communications (not currently connected)
#define Netbios_Task_Priority            0x0C  <-- Handles the UDP broadcast discovery command / response
//        NDK High Task Priority            0x0D   <-- Set via XGCONF
//        NDK Kernal Task Priority        0x0F  <-- Set via XGCONF

The NDK is configured to run at high priority via XGCONF.

I doubt the problem is recv not getting called frequently enough.  The protocol is described in my earlier postings.  The commands are always under 50 bytes and frequently less than 10.  The responses are under 128 bytes in length.  From wireshark I can see that the total packet rate is less than 20-30 packets per second including all handshakes (TCP-ACK, etc).

Don't know if this is correlated, but there frequently is a TCP retransmit of a telnet response or ACK packet about the time that a broadcast UDP is received and processed.  Perhaps the order of the response handling between the TCP Telnet retransmission and the UDP response is getting swapped so that only one transmit buffer is getting decremented (or maybe the two decrements are fumbled and the count is only decremented once)?  just a thought...

Tom

Hi Steve,

Have you made any progress on this issue? Are you still working on this issue?  My project has been basically on hold for more than a month by this issue.

Tom