Ethernet reception delays and unwanted behaviours

[maximekli]

Hello,

I am currently working on a project where an ESP32 based board is used in a legged robot as a bridge between a control computer using Ethernet and a set of sensors and actuators using SPI. The control loop is working at 1kHz.

Sometimes, we are clearly seeing that some packets are lost or delayed, and this has become even more common since going to ESP-IDF v4.0.x. Also, we are using raw ethernet frames at MAC level, so no TCP/IP layer or anything. As we are talking about a control loop, we really want to be as close as possible to a perfect 1kHz reception.

In order to test this, I used another ESP32 as the "command sender" so that I'm leaving the computer and the OS out of responsibility for some of these delays. I also isolated part of the code used in the project so only the communication is used. The code can be found below.

We are sending a message every millisecond, so we should receive a message every millisecond, but this weird thing happens now and then where a message is not dealt with when expected but rather packed with the next one, or even the next few ones. You can see it easily on the following logic analyser screenshot, where a gpio is set HIGH during the reception callback function.

eth_receive_gap.png (9.51 KiB) Viewed 4089 times

Markers A, B, C are normal receptions, 1ms apart.
D is the weird behaviour I was talking about, 6ms from C
E is another one of them, 2ms from D

eth_receive_gap_zoom.png (8.66 KiB) Viewed 4089 times

Here is a zoom on D where you can see that the missed packets in the 6ms gap are packed and dealt with together, ~12µs apart.

Any ideas on why this is behaving like this ? Is it a known issue ?
Can there possibly be that kind of delay between the esp_eth_transmit call and the sending itself or is it more of a receiving related issue ?

Thank you for your help,

Maxime

The project : https://open-dynamic-robot-initiative.github.io/
The ESP32 firmware : https://github.com/maximekli/master-boa ... r/firmware


CODE USED FOR THE TESTS :
direct_ethernet.h (ethernet library)

Code: Select all

#ifndef DIRECT_ETHERNET_H
#define DIRECT_ETHERNET_H

#include <stdint.h>
#include <string.h>

#include <stdio.h>
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_eth.h"
#include "esp_event.h"
#include "esp_log.h"

#include "sdkconfig.h"

#define ETHERTYPE 0xb588

typedef struct {
  uint8_t dst_mac[6];
  uint8_t src_mac[6];
  uint16_t ethertype;

  /* Custom payload*/
  uint16_t data_len;
  uint8_t data[CONFIG_MAX_ETH_DATA_LEN];
} eth_frame;

extern uint8_t eth_src_mac[6];
extern uint8_t eth_dst_mac[6];

void (*eth_recv_cb)(uint8_t src_mac[6], uint8_t *data, int len);

void (*eth_link_state_cb)(bool link_state);

void eth_init();
esp_err_t eth_send_frame(eth_frame *p_frame);
void eth_init_frame(eth_frame *p_frame);
void eth_send_data(uint8_t* data, int len);
void eth_attach_recv_cb(void (*cb)(uint8_t src_mac[6], uint8_t *data, int len));
void eth_detach_recv_cb();
void eth_attach_link_state_cb(void (*eth_link_state_cb)(bool link_state));
void eth_detach_link_state_cb();

void reset_counts();

#endif

direct_ethernet.c

Code: Select all

#include "direct_ethernet.h"

uint8_t eth_src_mac[6] = {0};
uint8_t eth_dst_mac[6] = {0xFF, 0xFF, 0xFF, 0xFF, 0xFF, 0xFF};

void (*eth_recv_cb)(uint8_t src_mac[6], uint8_t *data, int len) = NULL;

void (*eth_link_state_cb)(bool link_state) = NULL;

static const char *ETH_TAG = "Direct_Ethernet";
static esp_eth_handle_t eth_handle = NULL;

/** Event handler for Ethernet events */
static void eth_event_handler(void *arg, esp_event_base_t event_base,
                              int32_t event_id, void *event_data)
{
  /* we can get the ethernet driver handle from event data */
  eth_handle = *(esp_eth_handle_t *)event_data;

  switch (event_id)
  {
  case ETHERNET_EVENT_CONNECTED:
    if (eth_link_state_cb == NULL)
    {
    ESP_LOGW(ETH_TAG, "Ethernet link Up but no callback function is set");
    }
    else
    {
      eth_link_state_cb(true);
    }

    esp_eth_ioctl(eth_handle, ETH_CMD_G_MAC_ADDR, eth_src_mac);

    ESP_LOGI(ETH_TAG, "Ethernet Link Up");
    ESP_LOGI(ETH_TAG, "Ethernet HW Addr %02x:%02x:%02x:%02x:%02x:%02x",
             eth_src_mac[0], eth_src_mac[1], eth_src_mac[2], eth_src_mac[3], eth_src_mac[4], eth_src_mac[5]);
    break;
  case ETHERNET_EVENT_DISCONNECTED:
    if (eth_link_state_cb == NULL)
    {
    ESP_LOGW(ETH_TAG, "Ethernet link Down but no callback function is set");
    }
    else
    {
      eth_link_state_cb(false);
    }
    
    ESP_LOGI(ETH_TAG, "Ethernet Link Down");
    break;
  case ETHERNET_EVENT_START:
    ESP_LOGI(ETH_TAG, "Ethernet Started");
    break;
  case ETHERNET_EVENT_STOP:
    ESP_LOGI(ETH_TAG, "Ethernet Stopped");
    break;
  default:
    ESP_LOGI(ETH_TAG, "Unhandled Ethernet event (id = %d)", event_id);
    break;
  }
}

static esp_err_t eth_recv_func(esp_eth_handle_t eth_handle, uint8_t *buffer, uint32_t len)
{
  eth_frame *frame = (eth_frame *)buffer;
  if (eth_recv_cb == NULL)
  {
    //ESP_LOGW(ETH_TAG, "Ethernet frame received but no callback function is set on received...");
  }
  else if (len < sizeof(eth_frame) - CONFIG_MAX_ETH_DATA_LEN)
  {
    //ESP_LOGW(ETH_TAG, "The ethernet frame received is too short : frame length = %dB / minimum length expected (for header) = %dB", len, sizeof(eth_frame) - CONFIG_MAX_ETH_DATA_LEN);
  }
  else if (len > sizeof(eth_frame))
  {
    //ESP_LOGW(ETH_TAG, "The ethernet frame received is too long : frame length = %dB / maximum length = %dB", len, sizeof(eth_frame));
  }
  else if (frame->ethertype != ETHERTYPE)
  {
    //ESP_LOGW(ETH_TAG, "Unexpected frame ethertype : got %d instead of %d", frame->ethertype, ETHERTYPE);
  }
  else if (frame->data_len > len - sizeof(eth_frame) + CONFIG_MAX_ETH_DATA_LEN)
  {
    //ESP_LOGW(ETH_TAG, "Data longer than available frame length : data length = %d / available frame length = %d", frame->data_len, len - sizeof(eth_frame) + CONFIG_MAX_ETH_DATA_LEN);
  }
  else
  {
    eth_recv_cb(frame->dst_mac, frame->data, frame->data_len);
  }
  free(buffer);
  return ESP_OK;
}

void eth_init_frame(eth_frame *p_frame)
{
  p_frame->ethertype = ETHERTYPE;
  memcpy(p_frame->dst_mac, eth_dst_mac, sizeof(uint8_t) * 6);
  memcpy(p_frame->src_mac, eth_src_mac, sizeof(uint8_t) * 6);
}

esp_err_t eth_send_frame(eth_frame *p_frame)
{
  int err = esp_eth_transmit(eth_handle, (uint8_t *)p_frame, sizeof(eth_frame) + (p_frame->data_len) - CONFIG_MAX_ETH_DATA_LEN);

  if (err != 0)
  {
    ESP_LOGE(ETH_TAG, "Error occurred while sending eth frame: error code 0x%x", err);
    return ESP_FAIL;
  }

  return ESP_OK;
}

void eth_send_data(uint8_t *data, int len)
{
  eth_frame frame;
  eth_init_frame(&frame);
  frame.data_len = len;
  memcpy(&(frame.data), data, len);
  eth_send_frame(&(frame));
}

void eth_detach_recv_cb()
{
  eth_recv_cb = NULL;
}

void eth_attach_recv_cb(void (*cb)(uint8_t src_mac[6], uint8_t *data, int len))
{
  eth_recv_cb = cb;
}

void eth_detach_link_state_cb()
{
  eth_link_state_cb = NULL;
}

void eth_attach_link_state_cb(void (*cb)(bool link_state))
{
   eth_link_state_cb = cb;
}

void eth_init()
{
  ESP_ERROR_CHECK(esp_event_loop_create_default());
  ESP_ERROR_CHECK(esp_event_handler_register(ETH_EVENT, ESP_EVENT_ANY_ID, &eth_event_handler, NULL));

  eth_mac_config_t mac_config = ETH_MAC_DEFAULT_CONFIG();
  mac_config.rx_task_prio = configMAX_PRIORITIES - 1;

  eth_phy_config_t phy_config = ETH_PHY_DEFAULT_CONFIG();

  esp_eth_mac_t *mac = esp_eth_mac_new_esp32(&mac_config);
  esp_eth_phy_t *phy = esp_eth_phy_new_lan8720(&phy_config);

  esp_eth_config_t config = ETH_DEFAULT_CONFIG(mac, phy);

  config.stack_input = eth_recv_func;

  ESP_ERROR_CHECK(esp_eth_driver_install(&config, &eth_handle));
  printf("Driver installed\n");
  ESP_ERROR_CHECK(esp_eth_start(eth_handle));
  printf("Driver started\n");
}

sender_main.c (sends a packet every ms)

Code: Select all

#include <stdio.h>
#include <stdint.h>
#include <unistd.h>

#include "freertos/FreeRTOS.h"
#include "freertos/timers.h"

#include "driver/uart.h"
#include "nvs_flash.h"

#include "esp_timer.h"

#include "direct_ethernet.h"
#include "defines.h"

enum State current_state = SETUP; // updated by the 1000 Hz cb

struct wifi_eth_packet_command wifi_eth_tx_command = {.session_id = SESSION_ID, .command_index = 0};

static void periodic_timer_callback(void *arg)
{
    if (current_state == SENDING_COMMAND)
    {
        /* Send command msg to MB */
        eth_send_data((uint8_t *)(&wifi_eth_tx_command), sizeof(struct wifi_eth_packet_command));
    }
}

//function that will be called on a link state change
void wifi_eth_link_state_cb(bool new_state)
{
    // transitioning to the corresponding state
    if (new_state)
    {
        current_state = SENDING_COMMAND;
        printf("new state: SENDING_COMMAND\n");
    }
    else
    {
        current_state = WIFI_ETH_LINK_DOWN;
        printf("new state: WIFI_ETH_LINK_DOWN\n");
    }
}

void app_main()
{
    uart_set_baudrate(UART_NUM_0, 230400);

    printf("ETH frame size %u\n", sizeof(eth_frame));
    printf("ETH/WIFI command size %u\n", sizeof(struct wifi_eth_packet_command));

    memset(&(wifi_eth_tx_command.command), 0, CONFIG_N_SLAVES * sizeof(struct command_data));
    
    // timer setup
    const esp_timer_create_args_t periodic_timer_args = {
        .callback = &periodic_timer_callback,
        .name = "main_1kHz"};
    esp_timer_handle_t periodic_timer;
    ESP_ERROR_CHECK(esp_timer_create(&periodic_timer_args, &periodic_timer));
    ESP_ERROR_CHECK(esp_timer_start_periodic(periodic_timer, 1000));
    
    // ethernet setup
    eth_attach_link_state_cb(wifi_eth_link_state_cb);
    eth_init();

    current_state = WIFI_ETH_LINK_DOWN; // link is down just after setup

    printf("Setup done\n");

    while (1)
    {
        vTaskDelay(1);
    }
}

receiver_main.c (measures the delay between incoming packets)

Code: Select all

#include <stdio.h>
#include <stdint.h>
#include <unistd.h>

#include "freertos/FreeRTOS.h"
#include "freertos/timers.h"

#include "driver/gpio.h"
#include "driver/uart.h"
#include "nvs_flash.h"

#include "esp_timer.h"

#include "direct_ethernet.h"
#include "defines.h"

//#define GPIO_WIFI_ETH_RECEIVE_CB 33

enum State current_state = SETUP; // updated by the 1000 Hz cb

uint16_t n = 0;
int64_t last_time = 0;
int64_t curr_time = 0;
uint64_t delta_time_n = 0;

uint64_t min_delta_time = -1;
uint64_t max_delta_time = 0;

void wifi_eth_receive_cb(uint8_t src_mac[6], uint8_t *data, int len)
{
    // received a command msg while waiting for one
    if (len == sizeof(struct wifi_eth_packet_command) && current_state == RECEIVING_COMMAND)
    {
        //gpio_set_level(GPIO_WIFI_ETH_RECEIVE_CB, 1);

        curr_time = esp_timer_get_time();

        if (last_time != 0)
        {
            n++;

            delta_time_n = curr_time - last_time;

            // update min and max delays
            min_delta_time = delta_time_n < min_delta_time ? delta_time_n : min_delta_time;
            max_delta_time = delta_time_n > max_delta_time ? delta_time_n : max_delta_time;

            last_time = curr_time;
        }
        else
        {
            last_time = curr_time;
            printf("First received!\n");
        }

        // print time mesurments every ~60s
        if (n == 60000)
        {

            printf("Minimum delta time %3llu µs\tMaximum delta time %3llu µs\n",
                   min_delta_time, max_delta_time);

            // reset counts for time stats
            n = 0;
            last_time = 0;
            curr_time = 0;
            delta_time_n = 0;

            min_delta_time = -1;
            max_delta_time = 0;
        }

        //gpio_set_level(GPIO_WIFI_ETH_RECEIVE_CB, 0);
    }
}

//function that will be called on a link state change
void wifi_eth_link_state_cb(bool new_state)
{
    // transitioning to the corresponding state
    if (new_state)
    {
        // reset counts for time stats
        n = 0;
        last_time = 0;
        curr_time = 0;
        delta_time_n = 0;

        min_delta_time = -1;
        max_delta_time = 0;

        current_state = RECEIVING_COMMAND;
        printf("new state: RECEIVING_COMMAND\n");
    }
    else
    {
        current_state = WIFI_ETH_LINK_DOWN;
        printf("new state: WIFI_ETH_LINK_DOWN\n");
    }
}

void app_main()
{
    uart_set_baudrate(UART_NUM_0, 2000000);

    //gpio_set_direction(GPIO_WIFI_ETH_RECEIVE_CB, GPIO_MODE_OUTPUT);
    //gpio_set_level(GPIO_WIFI_ETH_RECEIVE_CB, 0);

    printf("ETH frame size %u\n", sizeof(eth_frame));
    printf("ETH/WIFI command size %u\n", sizeof(struct wifi_eth_packet_command));
    
    // ethernet setup
    eth_attach_link_state_cb(wifi_eth_link_state_cb);
    eth_attach_recv_cb(wifi_eth_receive_cb);
    eth_init();

    current_state = WIFI_ETH_LINK_DOWN; // link is down just after setup

    printf("Setup done\n");

    while (1)
    {
        vTaskDelay(1);
    }
}

sdkconfig.defaults

Code: Select all

# baudrates
CONFIG_ESPTOOLPY_BAUD_115200B=
CONFIG_ESPTOOLPY_BAUD_2MB=y

CONFIG_ESPTOOLPY_MONITOR_BAUD_115200B=
CONFIG_ESPTOOLPY_MONITOR_BAUD_2MB=y

# CPU frequency
CONFIG_ESP32_DEFAULT_CPU_FREQ_160=
CONFIG_ESP32_DEFAULT_CPU_FREQ_240=y
CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ=240

# ethernet stuff
CONFIG_ETH_RMII_CLK_INPUT=
CONFIG_ETH_RMII_CLK_OUTPUT=y
CONFIG_ETH_RMII_CLK_OUT_GPIO=17

[tosemusername]

I'll risk a guess and say it's something related to the OS scheduler plus the fact that `spi_device_queue_trans`, as implied by the name, queues interrupt transactions providing non-blocking transactions, at the expense of time to service the interrupt when the transactions are done.
Also, your pre and post transaction callbacks are not in IRAM.

[maximekli]

Hi, thank you for your reply.

it's something related to the OS scheduler

We are already investigating the guilt of the scheduler and RT capabilities of the OS in that matter, but the issues are still present (even though less frequent) with 2 ESP32s (one sending, one receiving) so Linux is not the only issue.

The ethernet reception task is pinned to core 1 whereas the SPI transactions are using core 0 so using SPI polling instead of interrupt was also an idea, but it doesn't seem to make that much of a difference regarding these reception delays.

Also, your pre and post transaction callbacks are not in IRAM.

Thanks for pointing that out, I'll look into it! Are there any benefits of doing that other than speed?

But again, the tests I presented in my previous post were done without any other components that ethernet, so no SPI or anything (see code pasted at the end of the post), so there must be something else...

Any other ideas?

Maxime

[maximekli]

Hello all !

Any insight on this ? Is there something I am missing about the ESP32 ethernet API ?