This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

AM2434: Sporadic communication interruption

Part Number: AM2434

Tool/software:

During long term tests with multiple Ethernet/IP devices, we detected a sporadic communication interruption. In case of the issue,  wireshark showed that the PLC was sending the EIP-Frames, but the affected device had stopped sending frames (switch functionality was still working). After timeout, the PLC automatically initiated a forward open and the communication runs again (without the need for a device restart).

Further investigations - with internal logging - showed that in case of the issue, the EIP-Stack is handling already processed frames an additional time (See Following log lines in yellow show repetition). Because the LWIPIF_input_cb is the callback for the icssg_emac for the rx packages, we are thinking there might be an issue with the data transfer PRU -> SRAM -> Application.

In case of the error, the Ethernet/IP device internally creates its process data, but did not receive the PLC frames (the opposite behaviour we can see on wireshark).

My questions are:

- is this a known issue? We are using SDK 9.00.00 recent SDK is 9.02.00. Comparing the PRU firmwares we can see modifications in code. Is it possible to fix it with the recent PRU firmware? What was changed between these two versions?

- what mechanism is used to avoid concurrent access to SRAM of PRU and R5F. Reading the code of icssg_emac.c I found no hint how the memory is locked to avoid multiple access.

- what happens in case of an overflow if a queue was not read out fast enough? Could this lead to such an behaviour?

25009: 3832756395: LWIPIF_input_cb sequenzNr (4506626), first
25010: 3832756601: USER_NetworkUDPReceive sequenzNr (4506626)
25011: 3832756980: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506626) - (Status:0x70096F78 0)
25012: 3832757291: IO_Produce_Action (CID=0x7957AED:4506659)
25013: 3832757789: SO_API_SendTo produce sequenzNr (4506659)
25014: 3832757849: EIP_OS_txPacket produce sequenzNr (4506659)
25015: 3832758541: LWIPIF_input_cb sequenzNr (4506627), first
25016: 3832758986: USER_NetworkUDPReceive sequenzNr (4506627)
25017: 3832759470: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506627) - (Status:0x70096F78 0)
25018: 3832759563: IO_Produce_Action (CID=0x7957AED:4506660)
25019: 3832759902: SO_API_SendTo produce sequenzNr (4506660)
25020: 3832759955: EIP_OS_txPacket produce sequenzNr (4506660)
25021: 3832760462: LWIPIF_input_cb sequenzNr (4506628), first
25022: 3832760670: USER_NetworkUDPReceive sequenzNr (4506628)
25023: 3832761059: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506628) - (Status:0x70096F78 0)
25024: 3832761354: IO_Produce_Action (CID=0x7957AED:4506661)
25025: 3832761637: SO_API_SendTo produce sequenzNr (4506661)
25026: 3832761683: EIP_OS_txPacket produce sequenzNr (4506661)
25027: 3832762973: LWIPIF_input_cb sequenzNr (4506629), first
25028: 3832763250: IO_Produce_Action (CID=0x7957AED:4506662)
25029: 3832763448: USER_NetworkUDPReceive sequenzNr (4506629)
25030: 3832763829: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506629) - (Status:0x70096F78 0)
25031: 3832764003: SO_API_SendTo produce sequenzNr (4506662)
25032: 3832764055: EIP_OS_txPacket produce sequenzNr (4506662)
25033: 3832764504: LWIPIF_input_cb sequenzNr (4506630), first
25034: 3832764688: USER_NetworkUDPReceive sequenzNr (4506630)
25035: 3832765056: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506630) - (Status:0x70096F78 0)
25036: 3832765328: IO_Produce_Action (CID=0x7957AED:4506663)
25037: 3832765689: SO_API_SendTo produce sequenzNr (4506663)
25038: 3832765752: EIP_OS_txPacket produce sequenzNr (4506663)
25039: 3832766382: LWIPIF_input_cb sequenzNr (4506631), first
25040: 3832766581: USER_NetworkUDPReceive sequenzNr (4506631)
25041: 3832766984: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506631) - (Status:0x70096F78 0)
25042: 3832767299: IO_Produce_Action (CID=0x7957AED:4506664)
25043: 3832767807: SO_API_SendTo produce sequenzNr (4506664)
25044: 3832767853: EIP_OS_txPacket produce sequenzNr (4506664)
25045: 3832768515: LWIPIF_input_cb sequenzNr (4506632), first
25046: 3832768966: USER_NetworkUDPReceive sequenzNr (4506632)
25047: 3832769474: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506632) - (Status:0x70096F78 0)
25048: 3832769569: IO_Produce_Action (CID=0x7957AED:4506665)
25049: 3832769893: SO_API_SendTo produce sequenzNr (4506665)
25050: 3832769939: EIP_OS_txPacket produce sequenzNr (4506665)
25051: 3832770446: LWIPIF_input_cb sequenzNr (4506633), first
25052: 3832770629: USER_NetworkUDPReceive sequenzNr (4506633)
25053: 3832771022: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506633) - (Status:0x70096F78 0)
25054: 3832771337: IO_Produce_Action (CID=0x7957AED:4506666)
25055: 3832771612: SO_API_SendTo produce sequenzNr (4506666)
25056: 3832771663: EIP_OS_txPacket produce sequenzNr (4506666)
25057: 3832772352: LWIPIF_input_cb sequenzNr (4506634), first
25058: 3832772515: USER_NetworkUDPReceive sequenzNr (4506634)
25059: 3832772855: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506634) - (Status:0x70096F78 0)
25060: 3832773310: IO_Produce_Action (CID=0x7957AED:4506667)
25061: 3832773574: SO_API_SendTo produce sequenzNr (4506667)
25062: 3832773618: EIP_OS_txPacket produce sequenzNr (4506667)
25063: 3832774468: LWIPIF_input_cb sequenzNr (4506635), first
25064: 3832774646: USER_NetworkUDPReceive sequenzNr (4506635)
25065: 3832775039: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506635) - (Status:0x70096F78 0)
25066: 3832775323: IO_Produce_Action (CID=0x7957AED:4506668)
25067: 3832775652: SO_API_SendTo produce sequenzNr (4506668)
25068: 3832775694: EIP_OS_txPacket produce sequenzNr (4506668)
25069: 3832776400: LWIPIF_input_cb sequenzNr (4506636), first
25070: 3832776588: USER_NetworkUDPReceive sequenzNr (4506636)
25071: 3832776943: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506636) - (Status:0x70096F78 0)
25072: 3832777297: IO_Produce_Action (CID=0x7957AED:4506669)
25073: 3832777795: SO_API_SendTo produce sequenzNr (4506669)
25074: 3832777849: EIP_OS_txPacket produce sequenzNr (4506669)
25075: 3832778527: LWIPIF_input_cb sequenzNr (4506637), first
25076: 3832778777: USER_NetworkUDPReceive sequenzNr (4506637)
25077: 3832779298: IO_NotifyFrame: Consumption OK! (Cons=0x700638D8/CID=0x80CA0001:4506637) - (Status:0x70096F78 0)
25078: 3832779386: IO_Produce_Action (CID=0x7957AED:4506670)
25079: 3832779691: SO_API_SendTo produce sequenzNr (4506670)
25080: 3832779745: EIP_OS_txPacket produce sequenzNr (4506670)
25081: 3832780592: LWIPIF_input_cb sequenzNr (0), first
25082: 3832781320: IO_Produce_Action (CID=0x7957AED:4506671)
25083: 3832781624: SO_API_SendTo produce sequenzNr (4506671)
25084: 3832781674: EIP_OS_txPacket produce sequenzNr (4506671)
25085: 3832782580: LWIPIF_input_cb sequenzNr (0), counter (24)
25086: 3832782605: LWIPIF_input_cb sequenzNr (289406976), first
25087: 3832783287: IO_Produce_Action (CID=0x7957AED:4506672)
25088: 3832783528: SO_API_SendTo produce sequenzNr (4506672)
25089: 3832783580: EIP_OS_txPacket produce sequenzNr (4506672)
25091: 3832783758: LWIPIF_input_cb sequenzNr (0), first
25092: 3832785351: IO_Produce_Action (CID=0x7957AED:4506673)
25093: 3832785633: SO_API_SendTo produce sequenzNr (4506673)
25094: 3832785684: EIP_OS_txPacket produce sequenzNr (4506673)
25095: 3832786776: LWIPIF_input_cb sequenzNr (0), counter (40)
25096: 3832786803: LWIPIF_input_cb sequenzNr (4506628), first
25097: 3832786984: USER_NetworkUDPReceive sequenzNr (4506628)
25098: 3832787119: IO_NotifyFrame : Old Transaction Number Frame(4506628) Cons(4506637)
25099: 3832787285: IO_Produce_Action (CID=0x7957AED:4506674)
25100: 3832787514: LWIPIF_input_cb sequenzNr (4506629), first
25101: 3832787878: SO_API_SendTo produce sequenzNr (4506674)
25102: 3832787929: EIP_OS_txPacket produce sequenzNr (4506674)
25103: 3832788070: USER_NetworkUDPReceive sequenzNr (4506629)
25104: 3832788289: IO_NotifyFrame : Old Transaction Number Frame(4506629) Cons(4506637)
25105: 3832788546: LWIPIF_input_cb sequenzNr (4506630), first
25106: 3832788826: USER_NetworkUDPReceive sequenzNr (4506630)
25107: 3832788922: IO_NotifyFrame : Old Transaction Number Frame(4506630) Cons(4506637)
25108: 3832788988: LWIPIF_input_cb sequenzNr (4506631), first
25109: 3832789140: USER_NetworkUDPReceive sequenzNr (4506631)
25110: 3832789287: IO_Produce_Action (CID=0x7957AED:4506675)
25111: 3832789537: LWIPIF_input_cb sequenzNr (4506632), first
25112: 3832789665: IO_NotifyFrame : Old Transaction Number Frame(4506631) Cons(4506637)
25113: 3832789740: LWIPIF_input_cb sequenzNr (4506633), first
25114: 3832789878: SO_API_SendTo produce sequenzNr (4506675)
25115: 3832789919: EIP_OS_txPacket produce sequenzNr (4506675)
25116: 3832790029: USER_NetworkUDPReceive sequenzNr (4506632)
25117: 3832790126: IO_NotifyFrame : Old Transaction Number Frame(4506632) Cons(4506637)
25118: 3832790501: USER_NetworkUDPReceive sequenzNr (4506633)
25119: 3832790590: IO_NotifyFrame : Old Transaction Number Frame(4506633) Cons(4506637)
25120: 3832790676: LWIPIF_input_cb sequenzNr (4506634), first
25121: 3832790842: USER_NetworkUDPReceive sequenzNr (4506634)
25122: 3832790930: IO_NotifyFrame : Old Transaction Number Frame(4506634) Cons(4506637)
25123: 3832791008: LWIPIF_input_cb sequenzNr (4506635), first
25124: 3832791124: USER_NetworkUDPReceive sequenzNr (4506635)
25125: 3832791335: IO_NotifyFrame : Old Transaction Number Frame(4506635) Cons(4506637)
25126: 3832791387: IO_Produce_Action (CID=0x7957AED:4506676)
25127: 3832791633: LWIPIF_input_cb sequenzNr (4506636), first
25128: 3832791796: SO_API_SendTo produce sequenzNr (4506676)
25129: 3832791842: EIP_OS_txPacket produce sequenzNr (4506676)
25130: 3832791968: USER_NetworkUDPReceive sequenzNr (4506636)
25131: 3832792090: IO_NotifyFrame : Old Transaction Number Frame(4506636) Cons(4506637)
25132: 3832792382: LWIPIF_input_cb sequenzNr (4506637), first
25133: 3832792539: USER_NetworkUDPReceive sequenzNr (4506637)
25134: 3832792790: LWIPIF_input_cb sequenzNr (0), first
25135: 3832793285: IO_Produce_Action (CID=0x7957AED:4506677)
25136: 3832793579: SO_API_SendTo produce sequenzNr (4506677)
25137: 3832793628: EIP_OS_txPacket produce sequenzNr (4506677)
25138: 3832794860: LWIPIF_input_cb sequenzNr (0), counter (24)
25139: 3832794889: LWIPIF_input_cb sequenzNr (289406976), first
25140: 3832795304: IO_Produce_Action (CID=0x7957AED:4506678)
25141: 3832795664: SO_API_SendTo produce sequenzNr (4506678)
25142: 3832795715: EIP_OS_txPacket produce sequenzNr (4506678)
25143: 3832796660: LWIPIF_input_cb sequenzNr (289406976), counter (17)
25144: 3832796690: LWIPIF_input_cb sequenzNr (0), first

  • Hi Robert,

    I have assigned this query to our EthernetIP Stack Expert. He will be able to help you better here.

    Your patience is appreciated.

    Regards
    Archit Dev

  • Hey Archit Dev,

    Is there anything new on this topic yet?

    Regards

    Benjamin

  • Hi Benjamin,

    Regarding your questions:

    - is this a known issue? We are using SDK 9.00.00 recent SDK is 9.02.00. Comparing the PRU firmwares we can see modifications in code. Is it possible to fix it with the recent PRU firmware? What was changed between these two versions?

    No, this is not a known issue. Regarding the changes in the different versions, the "Release Notes" page in the SDK documentation can be referred : https://software-dl.ti.com/processor-industrial-sw/esd/ind_comms_sdk/am243x/09_02_00_08/docs/api_guide_am243x/RELEASE_NOTES_PAGE.html 

    - what mechanism is used to avoid concurrent access to SRAM of PRU and R5F. Reading the code of icssg_emac.c I found no hint how the memory is locked to avoid multiple access.

    The Queue descriptors have read and write pointers.

    Read pointer : This points to the last buffer descriptor that points to valid data, when Rx task in the firmware puts data it increments the Read pointer.

    Write pointer : This points to the bottom of the first buffer descriptor that contains the data, when Rx task on driver reads the data it increments this. When read pointer equals write pointer there is no data in the buffers

    Using the queue descriptor both firmware and driver know which is the buffer descriptor which points to the current data

    - what happens in case of an overflow if a queue was not read out fast enough? Could this lead to such an behaviour?

    In case of a Queue overflow, the packet is dropped. No, we do not expect this to lead to the behavior observed.

    Apart from this, can you please answer the following questions:

    1. What is the test setup and the topology of the test?
    2. How are you getting the logs that you shared - is it something you implemented?
    3. Can you share the Wireshark log of the failure observed?

    Regards
    Archit Dev
  • We have now investigated the issue further. It seams the recent PRU firmware 9.1 or better 9.2 solves the issue, and the previous version 9.0 has an issue with the collision queue.

    One way to increase the occurrence of the issue is to configure Ethernet/IP to use multicast. Multicast operation makes every frame sent to an multicast address, every other Ethernet/IP device can consume. The switch will always route this kind of frame to the host port. This significantly increases the possibility of simultaneous frames from both switch ports to the host port. For this special case the collision queues of the PRUs are being used. --> So for our understanding, the collision queue handling is the most probable cause of the issue

    Nevertheless, with the recent PRU firmware, the problem was not seen again. Long term test are still running, but we are hopeful that the new PRU firmware has solved the issue.