xQueueReceive is timing out early

[william.ferguson.au]

I have a task that is either grabbing events from a queue or timing out after 500ms. But I am finding that when `xQueueReceive` times out is it sometimes timing out before the 500ms have expired.

I can add code to work around that, but I would like to know why that is occurring as according to the docs t should wait until at least 500ms have expired (or it has received an event). NB it doesn't always expire early and is non-deterministic. Approximately once every 3 times I run this code it will expire early on the first iteration.

Here is some log showing the 2nd xQueueReceive invocation timing out after 497 (at 3984). NB I have seen as low as 490ms.

Code: Select all

I (734) serial: Starting serial tasks
D (744) serial: Waiting for TX message timeout_ms=-1 now=127 free_heap=288220 free_stack=3792
D (3484) serial: Received TX queue event - sending msg_id==128
D (3484) serial: Doing something
D (3484) serial: Waiting for TX message timeout_ms=500 now=2860 free_heap=291600 free_stack=2432
D (3984) serial: TX queue timed out - then=3357 then_and_now_diff_ms=497
D (3984) serial: Doing somethingelse
D (3984) serial: Waiting for TX message timeout_ms=500 now=3357 free_heap=291600 free_stack=2432
D (4484) serial: TX queue timed out - then=3857 then_and_now_diff_ms=500
D (4484) serial: Doing somethingelse

And here is the code

Code: Select all

static void do_something() {
    ESP_LOGD(TAG, "Doing something");
}

static void do_somethingelse() {
    ESP_LOGD(TAG, "Doing somethingelse");
}

/**
 * Testing why xQueueReceive doesn't always wait the full timeout even when no event is received.
 */
static void tx_task_test(__attribute__((unused)) void *arg) {

    application_message_t *application_message;
    TickType_t queue_timeout_ms = -1;

    while (true) {
        int64_t now = wt_millis();
        const TickType_t queue_timeout_ticks = (queue_timeout_ms == -1) ? portMAX_DELAY : queue_timeout_ms / portTICK_PERIOD_MS;
        ESP_LOGD(TAG, "Waiting for TX message timeout_ms=%d now=%lld free_heap=%d free_stack=%d", queue_timeout_ms, now, heap_caps_get_free_size(MALLOC_CAP_DEFAULT), uxTaskGetStackHighWaterMark(NULL));
        if (xQueueReceive(tx_queue, &application_message, queue_timeout_ticks)) {
            ESP_LOGD(TAG, "Received TX queue event - sending msg_id==%d", application_message->msg_id);
            do_something();
        } else {
            // Timed out.
            const int64_t then = wt_millis();
            ESP_LOGD(TAG, "TX queue timed out - then=%lld then_and_now_diff_ms=%lld", then, then - now);
            do_somethingelse();
        }
        queue_timeout_ms = 500;
    }
}

void init_serial() {
    ESP_LOGI(TAG, "Starting serial tasks");
    tx_queue = xQueueCreate(MAX_TX_QUEUE_SIZE, sizeof(application_message_t *));
    xTaskCreate(tx_task_test, "uart_tx_task", STACK_SIZE_SMALL, NULL, configMAX_PRIORITIES-2, NULL);
}

I send an event from a button press to kick off the processing on the task.

[william.ferguson.au]

OK, looks like this is being caused by CONFIG_FREERTOS_HZ defaulting to 100 (Hz) which means that a request to wait for 497ms will be rounded down to 49 ticks (490ms) and we will wake up 7ms too early.

Changing CONFIG_FREERTOS_HZ to 1000 fixed the issue.

[MicroController]

You could also just round the tick value up:

Code: Select all

const TickType_t queue_timeout_ticks = (queue_timeout_ms == -1) ?
	portMAX_DELAY :
	((queue_timeout_ms + portTICK_PERIOD_MS-1) / portTICK_PERIOD_MS);