High-resolution timer period is drifted when WiFi is active

[dizcza]

I've set up a periodic high-resolution timer with the period 1000 us and it gets executed on average at 1000 us with three-sigma about 20 us. A few unheavy FreeRTOS tasks are running aside. The FreeRTOS tick rate is 100 Hz though I don't think it should matter - I ain't using a soft timer.
When I turn on either WiFi (I'm using a websocket client example) or Bluetooth classic, the timer is sometimes delayed for 7000 us. Even when the Bluetooth is idling, the timer period id drifted a lot - it gets executed at 400...2000 us period.

How do you deal with such a problem? I also don't find anything related to the priority of a high-resolution timer - I guess, there is no such an option.

It looks like the problem is more severe: not only high-resolution timers but also GPIO interrupts get delayed for a few milliseconds when I connect an external device that sends interrupts at a specified pin at a frequency of 2000 Hz with the WiFI/Bluetooth on.

[hustenhabas]

dont be shy, post some code

[dizcza]

Here is the code. The "websocket_app_start()" function is taken from https://github.com/espressif/esp-idf/tr ... /websocket

Code: Select all

int64_t last_tick = 0;
int64_t timer_dt_min = INT64_MAX;
int64_t timer_dt_max = 0;

static void timer_callback()
{
    int64_t tick = esp_timer_get_time();
    if (last_tick != 0) {
        int64_t dt = tick - last_tick;
        if (dt < timer_dt_min) timer_dt_min = dt;
        if (dt > timer_dt_max) timer_dt_max = dt;
    }
    last_tick = tick;
}

void task_send() {
     char data[512];
     
     while (1) {
	    printf("dt_min = %lld us, dt_max = %lld us\n", timer_dt_min, timer_dt_max);
            esp_websocket_client_send_bin(client, data, sizeof(data), portMAX_DELAY);
            vTaskDelay(pdMS_TO_TICKS(1000));
     }
}

void app_main() {
    websocket_app_start();
    
    const esp_timer_create_args_t sdp_timer_args = {
            .callback = &timer_callback,
    };
    ESP_ERROR_CHECK(esp_timer_create(&sdp_timer_args, &sdp_timer));
    ESP_ERROR_CHECK(esp_timer_start_periodic(sdp_timer, 1000));

    xTaskCreatePinnedToCore(task_send, "task_send", 4096, NULL, 0, NULL, PRO_CPU_NUM);
}

The output:

Code: Select all

I (5004) websocket: WEBSOCKET_EVENT_CONNECTED
dt_min = 305 us, dt_max = 1286 us
dt_min = 305 us, dt_max = 1286 us
dt_min = 305 us, dt_max = 1286 us
dt_min = 305 us, dt_max = 1286 us
W (8174) wifi:<ba-add>idx:0 (ifx:0, 60:aa:ef:13:aa:68), tid:0, ssn:10, winSize:64
dt_min = 3 us, dt_max = 4065 us
dt_min = 3 us, dt_max = 4065 us

If I don't start the websocket client, the timer period is preserved: 1000 ± 20 us.

[WiFive]

Use a hardware timer with isr in iram

[ESP_Sprite]

wifive is (as usual) right. The issue with esp_timer specifically is that it executes all the callbacks it has scheduled in series, in other words, if there's a callback scheduled from e.g. the wifi driver just before your callback is scheduled, your callback will only get called when the wifi driver callback is done. Additionally, non-IRAM interrupts and tasks get suspended on flash writes, in other words, flash writes can also delay your callback.

[dizcza]

Thanks for your replies but I don't think a hardware timer will solve the problem. My mistake though - I've oversimplified the code in the description. Let me dive deeper into the problem.

I don't have a hardware timer with me but I have an SDP sensor with an IRQ pin that sends a "measurement ready" signal (high) to a pin of my ESP32 board. I've attached a callback with the IRAM_ATTR attribute to these interrupts and it does not solve the problem. Therefore, I conclude that a hardware timer won't solve it either. Below are the timings with and without a websocket active.

• Normally, the sensor sends interrupts at [470, 480] us period - that's precisely the "timer_dt_min" and "timer_dt_max" I see in a terminal when WiFi is inactive.

  Code: Select all

  dt_min = 470 us, dt_max = 480 us
  

• When a websocket is functioning, the delay between successive events is drifted X2. It's already a problem, but not as severe as in the following example.

  Code: Select all

  dt_min = 349 us, dt_max = 953 us
  

• Lastly, when the socket is disconnected, the delay is shifted dramatically (but only once)

  Code: Select all

  W (3910) wifi:<ba-add>idx:0 (ifx:0, 60:aa:ef:13:aa:68), tid:0, ssn:10, winSize:64
  dt_min = 349 us, dt_max = 953 us
  dt_min = 349 us, dt_max = 953 us
  dt_min = 349 us, dt_max = 953 us
  dt_min = 349 us, dt_max = 953 us
  E (5730) TRANSPORT_WS: Error transport_poll_write
  E (5740) WEBSOCKET_CLIENT: Network error: esp_transport_write() returned 0, errno=0
  E (5770) TRANSPORT_BASE: poll_read select error 0, errno = Success, fd = 54
  I (5770) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  E (5770) WEBSOCKET_CLIENT: Network error: esp_transport_poll_read() returned -1, errno=9
  I (5780) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  I (5790) websocket: WEBSOCKET_EVENT_DISCONNECTED
  I (5800) websocket: WEBSOCKET_EVENT_DISCONNECTED
  dt_min = 349 us, dt_max = 8099 us
  dt_min = 349 us, dt_max = 8099 us
  dt_min = 349 us, dt_max = 8099 us
  

Here is the code I modified for external pin interrupts. Note the timings in the updated "task_send()" function and a new size for the sent "data" buffer.

Code: Select all

int64_t last_tick = 0;
int64_t timer_dt_min = INT64_MAX;
int64_t timer_dt_max = 0;

char data[5120];

// This task is needed only to trigger the "the next measurement ready" IRQs
// sent by the sensor when the I2C reading in "read_sdpsensor()" is done
static void sdptask_read_sensor() {
	while (1) {
		ulTaskNotifyTake(pdTRUE, portMAX_DELAY);
		read_sdpsensor();  // simple I2C reading
	}
}

static void IRAM_ATTR timer_callback() {
    int64_t tick = esp_timer_get_time();
    if (last_tick != 0) {
        int64_t dt = tick - last_tick;
        if (dt < timer_dt_min) timer_dt_min = dt;
        if (dt > timer_dt_max) timer_dt_max = dt;
    }
    last_tick = tick;

    // notify the "sdptask_read_sensor" task
    BaseType_t xHigherPriorityTaskWoken = pdFALSE;
    vTaskNotifyGiveFromISR(read_sensor_task_handle, &xHigherPriorityTaskWoken);
    portYIELD_FROM_ISR(xHigherPriorityTaskWoken);
}

void task_send() {
     while (1) {
	    printf("dt_min = %lld us, dt_max = %lld us\n", timer_dt_min, timer_dt_max);
            esp_websocket_client_send_bin(client, data, sizeof(data), pdMS_TO_TICKS(10));
            vTaskDelay(pdMS_TO_TICKS(10));
     }
}

void SDPSensor_AttachIRQ(gpio_num_t irq_gpio, void* irq_handler) {
    gpio_config_t irq_io_conf = {
    		.pin_bit_mask = 1ULL << irq_gpio,           // IRQ pin
			.mode = GPIO_MODE_INPUT,                    // input mode
			.pull_up_en = GPIO_PULLUP_ENABLE,           // enable pull-up
			.pull_down_en = GPIO_PULLDOWN_DISABLE,      // disable pull-down
			.intr_type = GPIO_INTR_NEGEDGE              // falling edge interrupt
    };
    ESP_ERROR_CHECK(gpio_config(&irq_io_conf));
    // install the GPIO ISR service
    ESP_ERROR_CHECK(gpio_install_isr_service(0));
    // hook an ISR handler for the specific GPIO pin
    ESP_ERROR_CHECK(gpio_isr_handler_add(irq_gpio, irq_handler, NULL));
}


void app_main() {
    websocket_app_start();

    SDPSensor_AttachIRQ(4, timer_callback);  // attach a callback to sensor IRQ signal
    xTaskCreatePinnedToCore(task_send, "task_send", 4096, NULL, 0, NULL, PRO_CPU_NUM);
    xTaskCreatePinnedToCore(sdptask_read_sensor, "sdp_read", 2048, NULL, 4, &read_sensor_task_handle, APP_CPU_NUM);
    
    xTaskNotifyGive(read_sensor_task_handle);  // trigger the first measurement
}

When the websocket is awaited for portMAX_DELAY rather than pdMS_TO_TICKS(10), the problem disappears - the delay is in the [349, 953] us range.

Full code for the "websocket_app_start()" is here https://github.com/dizcza/esp32-sdpsens ... ebsocket.c.

[dizcza]

All right, gotta answer my own question.

I've bought a hardware timer (DS3231), set up SQW at 1024 Hz connected to pin 22 and the code boils down to:

Code: Select all

/* ESP HTTP Client Example

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/


#include <stdio.h>
#include "esp_wifi.h"
#include "esp_system.h"
#include "nvs_flash.h"
#include "esp_event.h"
#include "protocol_examples_common.h"

#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "freertos/event_groups.h"

#include "esp_log.h"
#include "esp_websocket_client.h"
#include "esp_event.h"

#define NO_DATA_TIMEOUT_SEC  5
#define IRQ_GPIO             18

static const char *TAG = "WEBSOCKET";

int64_t last_tick = 0;
int64_t timer_dt_min = INT64_MAX;
int64_t timer_dt_max = 0;

esp_websocket_client_handle_t client;


void IRAM_ATTR handler() {
    int64_t tick = esp_timer_get_time();
    if (last_tick != 0) {
        int64_t dt = tick - last_tick;
        if (dt < timer_dt_min) timer_dt_min = dt;
        if (dt > timer_dt_max) timer_dt_max = dt;
    }
    last_tick = tick;
}


void attachIRQ(gpio_num_t irq_gpio, void* irq_handler) {
    gpio_config_t irq_io_conf = {
            .pin_bit_mask = 1ULL << irq_gpio,           // IRQ pin
            .mode = GPIO_MODE_INPUT,                    // input mode
            .pull_up_en = GPIO_PULLUP_ENABLE,           // enable pull-up
            .pull_down_en = GPIO_PULLDOWN_DISABLE,      // disable pull-down
            .intr_type = GPIO_INTR_NEGEDGE              // falling edge interrupt
    };
    ESP_ERROR_CHECK(gpio_config(&irq_io_conf));
    // install the GPIO ISR service
    ESP_ERROR_CHECK(gpio_install_isr_service(0));
    // hook an ISR handler for the specific GPIO pin
    ESP_ERROR_CHECK(gpio_isr_handler_add(irq_gpio, irq_handler, NULL));
}


static void websocket_event_handler(void *handler_args, esp_event_base_t base, int32_t event_id, void *event_data)
{
    switch (event_id) {
    case WEBSOCKET_EVENT_CONNECTED:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_CONNECTED");
        break;
    case WEBSOCKET_EVENT_DISCONNECTED:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_DISCONNECTED");
        break;
    case WEBSOCKET_EVENT_DATA:
        break;
    case WEBSOCKET_EVENT_ERROR:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_ERROR");
        break;
    }
}

void task_send() {
    char data[512];

    while (1) {
        if (esp_websocket_client_is_connected(client)) {
            esp_websocket_client_send_bin(client, data, sizeof(data), pdMS_TO_TICKS(10));
            printf("dt_min = %lld us, dt_max = %lld us\n", timer_dt_min,
                    timer_dt_max);
        }
        vTaskDelay(pdMS_TO_TICKS(10));
    }
}


static void websocket_app_start(void)
{
    esp_websocket_client_config_t websocket_cfg = {};
    websocket_cfg.uri = "ws://echo.websocket.events";
    ESP_LOGI(TAG, "Connecting to %s...", websocket_cfg.uri);

    client = esp_websocket_client_init(&websocket_cfg);
    esp_websocket_register_events(client, WEBSOCKET_EVENT_ANY, websocket_event_handler, (void *)client);
    esp_websocket_client_start(client);

    attachIRQ(IRQ_GPIO, handler);

    xTaskCreatePinnedToCore(task_send, "task_send", 4096, NULL, 0, NULL, PRO_CPU_NUM);
}

void app_main(void)
{
    ESP_LOGI(TAG, "[APP] Startup..");
    ESP_LOGI(TAG, "[APP] Free memory: %d bytes", esp_get_free_heap_size());
    ESP_LOGI(TAG, "[APP] IDF version: %s", esp_get_idf_version());
    esp_log_level_set("*", ESP_LOG_INFO);
    esp_log_level_set("WEBSOCKET_CLIENT", ESP_LOG_DEBUG);
    esp_log_level_set("TRANSPORT_WS", ESP_LOG_DEBUG);
    esp_log_level_set("TRANS_TCP", ESP_LOG_DEBUG);

    ESP_ERROR_CHECK(nvs_flash_init());
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());

    /* This helper function configures Wi-Fi or Ethernet, as selected in menuconfig.
     * Read "Establishing Wi-Fi or Ethernet Connection" section in
     * examples/protocols/README.md for more information about this function.
     */
    ESP_ERROR_CHECK(example_connect());

    websocket_app_start();
}

The console output:

• When WiFi is disabled (commented out):

  Code: Select all

  dt_min = 970 us, dt_max = 983 us
  

• When WiFi is enabled but no websocket is running:

  Code: Select all

  dt_min = 487 us, dt_max = 1466 us
  

• When WiFi is enabled and a websocket is running:

  Code: Select all

  I (10112) WEBSOCKET: WEBSOCKET_EVENT_CONNECTED
  dt_min = 406 us, dt_max = 1547 us
  ...
  E (10972) TRANSPORT_WS: Error transport_poll_write
  E (10972) WEBSOCKET_CLIENT: Network error: esp_transport_write() returned 0, errno=0
  E (10972) TRANSPORT_BASE: poll_read select error 0, errno = Success, fd = 54
  E (10982) WEBSOCKET_CLIENT: Network error: esp_transport_poll_read() returned -1, errno=119
  I (10992) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  I (10992) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  I (11002) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
  I (11002) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
  dt_min = 381 us, dt_max = 1572 us
  I (21372) WEBSOCKET: WEBSOCKET_EVENT_CONNECTED
  dt_min = 381 us, dt_max = 1572 us
  ...
  E (319582) TRANSPORT_WS: Error transport_poll_write
  E (319582) WEBSOCKET_CLIENT: Network error: esp_transport_write() returned 0, errno=0
  E (319582) TRANSPORT_BASE: poll_read select error 0, errno = Success, fd = 54
  E (319592) WEBSOCKET_CLIENT: Network error: esp_transport_poll_read() returned -1, errno=119
  I (319602) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  I (319602) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
  I (319612) WEBSOCKET_CLIENT: Reconnect after 10000 ms
  I (319612) WEBSOCKET: WEBSOCKET_EVENT_DISCONNECTED
  dt_min = 226 us, dt_max = 1728 us
  

The reason why I saw 8000+ us delays in the previous post is that, as @ESP_Sprite described, the line "ulTaskNotifyTake(pdTRUE, portMAX_DELAY);" is executed after the lock has been released in the timer callback much further in time due to WiFi things scheduled right before my task.

Hope I got it right. And I don't see any solution how to bring the gap of 8000+ us down. Also, WiFi severely influences the delay on its own.

[ESP_Sprite]

So, with a 'hardware timer', we mean one inside of the ESP32 itself. You wanna look here for instance. That should give you similar results as the DS3231 but without external components. (Probably even better as there's no GPIO subsystem 'in the way') Furthermore, you can probably get a bit less jitter by putting the initialization routines / non-interrupt handling stuff for that timer in a task that runs off the app CPU: that makes sure the interrupt is also tied to that app CPU, and as the WiFi stuff is going on on the pro cpu, it should interfere less.

[dizcza]

Furthermore, you can probably get a bit less jitter by putting the initialization routines / non-interrupt handling stuff for that timer in a task that runs off the app CPU: that makes sure the interrupt is also tied to that app CPU, and as the WiFi stuff is going on on the pro cpu, it should interfere less.

True, thanks for the advice. I've set up an onboard hardware timer at 1024 Hz freq (976 us period). Having the timer interrupt routine bound to the APP CPU core significantly reduces the jitter of the period at which the timer callback is executed - now it's in the [899, 1054] us range. Full code for the notice:

Code: Select all

#include <stdio.h>
#include "esp_wifi.h"
#include "esp_system.h"
#include "nvs_flash.h"
#include "esp_event.h"
#include "protocol_examples_common.h"

#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "freertos/event_groups.h"
#include "driver/timer.h"

#include "esp_log.h"
#include "esp_websocket_client.h"
#include "esp_event.h"

#define NO_DATA_TIMEOUT_SEC  5
#define IRQ_GPIO             18

static const char *TAG = "WEBSOCKET";

int64_t last_tick = 0;
int64_t timer_dt_min = INT64_MAX;
int64_t timer_dt_max = 0;

esp_websocket_client_handle_t client;

BaseType_t core_id = 0;


static bool IRAM_ATTR irq_handler() {
    int64_t tick = esp_timer_get_time();
    if (last_tick != 0) {
        int64_t dt = tick - last_tick;
        if (dt < timer_dt_min) timer_dt_min = dt;
        if (dt > timer_dt_max) timer_dt_max = dt;
    }
    last_tick = tick;

    core_id = xPortGetCoreID();

    return pdFALSE;
}


static void websocket_event_handler(void *handler_args, esp_event_base_t base, int32_t event_id, void *event_data)
{
    switch (event_id) {
    case WEBSOCKET_EVENT_CONNECTED:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_CONNECTED");
        break;
    case WEBSOCKET_EVENT_DISCONNECTED:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_DISCONNECTED");
        break;
    case WEBSOCKET_EVENT_DATA:
        break;
    case WEBSOCKET_EVENT_ERROR:
        ESP_LOGI(TAG, "WEBSOCKET_EVENT_ERROR");
        break;
    }
}


void task_send() {
    char data[512];

    while (1) {
        printf("[CPU core=%d] dt_min = %lld us, dt_max = %lld us\n", core_id, timer_dt_min, timer_dt_max);
        if (esp_websocket_client_is_connected(client)) {
            esp_websocket_client_send_bin(client, data, sizeof(data), pdMS_TO_TICKS(10));
        }
        vTaskDelay(pdMS_TO_TICKS(10));
    }
}


static void websocket_app_start(void)
{
    esp_websocket_client_config_t websocket_cfg = {};
    websocket_cfg.uri = "ws://echo.websocket.events";
    ESP_LOGI(TAG, "Connecting to %s...", websocket_cfg.uri);

    client = esp_websocket_client_init(&websocket_cfg);
    esp_websocket_register_events(client, WEBSOCKET_EVENT_ANY, websocket_event_handler, (void *)client);
    esp_websocket_client_start(client);
}


static void timer_start_task() {
    /* Select and initialize basic parameters of the timer */
    timer_config_t config = {
        .divider = 25,
        .counter_dir = TIMER_COUNT_UP,
        .counter_en = TIMER_PAUSE,
        .alarm_en = TIMER_ALARM_EN,
        .auto_reload = TIMER_AUTORELOAD_EN,
    }; // default clock source is APB
    timer_init(0, 0, &config);

    /* Timer's counter will initially start from value below.
       Also, if auto_reload is set, this value will be automatically reload on alarm */
    timer_set_counter_value(0, 0, 0);  // <-- don't really know if this is needed

    /* Configure the alarm value and the interrupt on alarm. */
    timer_set_alarm_value(0, 0, 3125);  // 1024 Hz
    timer_enable_intr(0, 0);

    timer_isr_callback_add(0, 0, irq_handler, NULL, 0);

    timer_start(0, 0);

    vTaskDelete(NULL);
}


void app_main(void)
{
    ESP_ERROR_CHECK(nvs_flash_init());
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());
    ESP_ERROR_CHECK(example_connect());

    websocket_app_start();

    xTaskCreatePinnedToCore(task_send, "task_send", 4096, NULL, 0, NULL, PRO_CPU_NUM);

    xTaskCreatePinnedToCore(timer_start_task, "timer_start", 4096, NULL, 0, NULL, APP_CPU_NUM);
}

You're also right that an onboard HW timer is expected to tick at a more stable frequency. I'm getting the min/max period of [976, 977] us (the true period is 976.5625 us) compared to an external DS3231 which yields [970, 983] us, as I've already posted.

Thanks. Problem closed.